Transactions using OpenAPI C# is not showing up

kaushas · February 28, 2020, 9:44pm

Kibana version:7.6.0

Elasticsearch version:7.6.0

APM Server version:7.6.0

APM Agent language and version: OpenAPI using C# in a console app, manually instrumented using Transactions.

Browser version: IE 11.1685 and Chrome 8003987

Original install method (e.g. download page, yum, deb, from source, etc.) and version: Download and install (all 7.6 version)

Fresh install or upgraded from other version? Fresh Install

Is there anything special in your setup? No Logstash, no customization

Description of the problem including expected versus actual behavior. Please include screenshots (if relevant): I have install and configure ElasticServer, Kiabana and APM-Server. Everything is working fine from server side.

Have instrumented the C# console app and can see that .net agent is sending transactions to APM-Server. Ran APM-Server in publish mode and debug mode no errors reported, I see that transactions from the agent with correct client machine IP and response code of 200 from APM Server, occasionally 304.
No errors are reported in ElasticSearch either.
When looking in discover mode, I see transactions, but label values are missing.

When I go to APM/Setting the new Service name is not registering with Kibana and nothing shows in the APM view except 1 old service and even that service does not show any APM details. I am using all standard templates OOB, no customization.

Any clue as to what is going on?

Steps to reproduce:
1.
2.
3.

Errors in browser console (if relevant):

Provide logs and/or server output (if relevant):
APM-Server Output
2020-02-28T15:38:06.835-0500 DEBUG [publisher] memqueue/eventloop.go:535 broker ACK events: count=1, start-seq=1, end-seq=1

2020-02-28T15:38:06.838-0500 DEBUG [publisher] memqueue/ackloop.go:128 ackloop: return ack to broker loop:1
2020-02-28T15:38:06.839-0500 DEBUG [publisher] memqueue/ackloop.go:131 ackloop: done send ack
2020-02-28T15:38:56.505-0500 INFO [request] middleware/log_middleware.go:97 request ok {"request_id": "17a94442-2682-4051-8cb8-81d1a2c73c87", "method": "GET", "URL": "/config/v1/agents?service.name=WriteP", "content_length": 0, "remote_address": "1***********", "user-agent": "elasticapm-dotnet/1.3 System.Net.Http/4.7.3062.0 .NET_Framework/4.7.3468.0", "response_code": 200}
2020-02-28T15:44:10.534-0500 INFO [request] middleware/log_middleware.go:97 request ok {"request_id": "bed7a70b-ac05-4cd1-8ec4-83e10d8524d6", "method": "GET", "URL": "/config/v1/agents?service.name=WriteP", "content_length": 0, "remote_address": "1***********", "user-agent": "elasticapm-dotnet/1.3 System.Net.Http/4.7.3062.0 .NET_Framework/4.7.3468.0", "response_code": 200}
2020-02-28T15:51:33.517-0500 INFO [request] middleware/log_middleware.go:97 request ok {"request_id": "a595ac1d-17b1-4ec3-b5ba-2007d0be442f", "method": "GET", "URL": "/config/v1/agents?service.name=WriteP", "content_length": 0, "remote_address": "1***********", "user-agent": "elasticapm-dotnet/1.3 System.Net.Http/4.7.3062.0 .NET_Framework/4.7.3468.0", "response_code": 200}
2020-02-28T15:53:30.197-0500 INFO [request] middleware/log_middleware.go:97 request ok {"request_id": "daab0e02-6752-4b6a-8b6a-f7984ed0ac1b", "method": "GET", "URL": "/config/v1/agents?service.name=WriteP", "content_length": 0, "remote_address": "1***********", "user-agent": "elasticapm-dotnet/1.3 System.Net.Http/4.7.3062.0 .NET_Framework/4.7.3468.0", "response_code": 200}
2020-02-28T15:54:01.494-0500 INFO [request] middleware/log_middleware.go:97 not modified {"request_id": "92b637a3-735d-4519-9687-f878c33cee2e", "method": "GET", "URL": "/config/v1/agents?service.name=WriteP", "content_length": 0, "remote_address": "1***********", "user-agent": "elasticapm-dotnet/1.3 System.Net.Http/4.7.3062.0 .NET_Framework/4.7.3468.0", "response_code": 304}
2020-02-28T15:57:01.392-0500 INFO [request] middleware/log_middleware.go:97 request ok {"request_id": "4f53fc88-aa40-495c-a2c9-769dd36c1d8c", "method": "GET", "URL": "/config/v1/agents?service.name=WriteP", "content_length": 0, "remote_address": "1***********", "user-agent": "elasticapm-dotnet/1.3 System.Net.Http/4.7.3062.0 .NET_Framework/4.7.3468.0", "response_code": 200}

GregKalapos · March 2, 2020, 9:31am

Hi @kaushas, welcome on our forum

When I go to APM/Setting the new Service name is not registering with Kibana and nothing shows in the APM view except 1 old service and even that service does not show any APM details.

Based on this I assume you don't see your transactions in Kibana - is that correct? Is that the problem?

Unfortunately the server logs I see here don't help too much - they only show that the agent sent requests the for configuration data, but I don't see that any transaction was sent to the server.

Maybe 1 idea: how long does your console application running? One known issue is that if it terminates immediately after your transaction ends then the agent won't be able to send the data to the server. Is that maybe your problem?

There was another point in your post, that I don't fully understand. What do you mean by this?

When looking in discover mode, I see transactions, but label values are missing.

You mean you add labels to your transactions (like transaction.Labels["label1"] = "value") , but it does not show up? And where do you see the transaction?

kaushas · March 2, 2020, 6:10pm

That is correct, I do not see the transactions in Kibana -> APM. I am running the console application in VS Debug mode, so have waited for the app to close, still same results. How long the wait should be? I can retest with that wait.
Let me explain, what I meant, running APM-Server -e -d option and getting the outputs. Using these data points, I can correlate the incoming transactions in Kibana and search through data discover option. I can see that the transaction partial data is there and it is missing the the labels values (as you have pointed out), I have instrumented the code with these labels to capture additional data points.
Please let me know if this makes sense.
thanks

GregKalapos · March 2, 2020, 7:11pm

Thanks for the update @kaushas - very helpful.

so have waited for the app to close, still same results. How long the wait should be? I can retest with that wait.

With the default settings, after 10 seconds the agent will send the data to the server, so if you waited at least 10 sec, it should be fine.

partial data is there and it is missing the the labels values

Hmm, this sounds very strange to me, this should usually not happen.

I haven't asked this in my first response, but what do you exactly mean by "using OpenAPI C#" - what library is that?

The way we designed this is that you should use the Public API of the .NET Agent - here is the doc for that and this is the NuGet package containing the agent and the API. Are you using that?

kaushas · March 2, 2020, 8:26pm

Yes. I should have corrected myself, I am using the Public API....

GregKalapos · March 2, 2020, 8:28pm

Great, that sounds good, then it's definitely a setup that should work.

Could you maybe paste here a minimal version of your C# code that captured the transaction? Maybe that'd help me to spot where the error is - or at least we'll see that the C# part is fine.

kaushas · March 2, 2020, 9:15pm

Let me know if this work , obviously code will not compile, but should give you an idea as to what we are trying to do.

using Elastic.Apm;
using Elastic.Apm.Api;
using Newtonsoft.Json;
using System;
using System.Net.Http;
using System.Threading.Tasks;

namespace MWriter
{
public class Writer
{
//using data from App config file using Properties.Setting

public bool SendEventMsgToTopic(MsgEvent msgEvent)
{
//Elastic ITransaction
ITransaction tran = null;

        try
        {
            bool allGood = CheckEnvValues();

            if (allGood)
            {
                Environment.SetEnvironmentVariable("ELASTIC_APM_SERVER_URLS", Properties.Settings.Default.APMSERVERURL);
                Environment.SetEnvironmentVariable("ELASTIC_APM_SERVICE_NAME", Properties.Settings.Default.APMSERVICENAME);
                //APM agent
                tran = Agent.Tracer.StartTransaction("WriteMessage", ApiConstants.TypeExternal);

                connection = CreateConnection();

                if (connection != null)
                {
                    session = CreateWriter(connection);

                    if (session != null)
                    {
                        string message = JsonConvert.SerializeObject(msgEvent);
                   	....   
                }
                else
                {
                    errorMsg = "Null objet Error in session creation";
                    Console.WriteLine(errorMsg);
                    UpdateAPM(tran, errorMsg);
                    return success;
                }

            }
            else
            {
                errorMsg = "Invalid values in Application Config, check app config";
                Console.WriteLine(errorMsg);
                UpdateAPM(tran, errorMsg);
                return success;
            }

        }
     
        catch (Exception ex)
        {
            //errorMsg = ex.InnerException.ToString();
            errorMsg = "Error Occured";
            tran.CaptureException(ex);
            UpdateAPM(tran, errorMsg);

            throw;
        }
        finally
        {
          dispose off connection
        }


    }

    private static void UpdateAPM(ITransaction tran, string errMsg)
    {
        
        tran.Result = "Error";
        tran.End();
    }

    private static IConnection CreateConnection()
    {
        bool allValuesRead = CheckEnvValues();
        IConnection connection = null;


        ITransaction tran = Agent.Tracer.StartTransaction("CreateConnection", ApiConstants.TypeExternal);

        try
        {
            //set the domainName

            tran.Labels["Domain"] = Properties.Settings.Default.DomainName;
	.........


                     catch (Exception ex)
        {
            
            tran.CaptureException(ex);
            errorMessage = ex.InnerException.ToString();
            UpdateAPM(tran, errorMessage);
            throw;

        }

        return connection;
    }

   }

GregKalapos · March 2, 2020, 9:33pm

You only end the transaction in the UpdateAPM method, which is only called in the catch block if I see it correctly.

You should call transaction.End() in a finally block, that makes sure it always ends.

Something like this:

private static void UpdateAPM(ITransaction tran, string errMsg)
{
        
        tran.Result = "Error";
      //removed tran.End() from here
}

private static IConnection CreateConnection()
{
        bool allValuesRead = CheckEnvValues();
        IConnection connection = null;


        ITransaction tran = Agent.Tracer.StartTransaction("CreateConnection", ApiConstants.TypeExternal);

        try
        {
            //set the domainName
            tran.Labels["Domain"] = Properties.Settings.Default.DomainName;
        }
        catch (Exception ex)
        {
            
            tran.CaptureException(ex);
            errorMessage = ex.InnerException.ToString();
            UpdateAPM(tran, errorMessage);
            throw;
         }
         finally
        {
             tran.End();
        }

        return connection;
    }

kaushas · March 2, 2020, 9:34pm

thanks, I will update and test and revert.

kaushas · March 2, 2020, 10:29pm

Still no transactions showing up. Also, the APM Server received 8 transactions. Only One is showing up in Kibana, Data Discovery.....

further update. Transactions started showing, it seems if there are no error or exception in the code, transaction shows. If there is exception in the code, it does not show.

Here is what I did.

Created a new transaction name - writewitherror, there was an exception set in code. Ran the code, not transactions shows up in APM or in Kibana Discover.
Ran the same code but made sure there were no errors (changed pwd to be valid) and voila Transaction Shows up in Kibana APM and in Discover.
Then created error/exception condition again and ran the code. Transaction count did not go up and it did not show in Kibana Discover either.... finally does have tran.end and I have checked it is getting executed

GregKalapos · March 3, 2020, 8:28pm

Thanks for the update @kaushas,

Is this maybe related to the timing issue we discussed previously? I just want to make sure the agent has at least 10 seconds to send the data.

One thing we could do is that I can take a look at the agent logs - that may help us to see what happens on the agent side.

For this, could you set the log level to trace? You can do this by setting the env. var ELASTIC_APM_LOG_LEVEL to trace - logs should by default show up on the console.

kaushas · March 4, 2020, 3:54am

I have created two log files one with exceptions and one without exceptions. Where do you want me to upload these files to? Or are there specific sections that you want me to paste here.

GregKalapos · March 5, 2020, 2:26pm

You could also just paste them here - putting it between 2 lines starting with ``` and ending with the same 3 '`' character will make it format the right way.

kaushas · March 9, 2020, 3:41pm

Apologies for late response, Here is what I have figured out, When we run the console app in standard user mode Service and transactions do not show up in Kibana/APM/Services page. If we then run the same app with elevated privileges then I can see services listed under Kibana/APM/Services. is second run was done using higher privilege (admin) (which we do not want). I am pasting multiple sections as there are limitations to what you can post

[2020-03-09 11:10:11.7150|INFO|MessageWriter.Writer|Starting Transaction Send Message to Topic
[2020-03-09 11:10:11.912 -04:00][Debug] - {SystemInfoHelper} No /proc/self/cgroup found - the agent will not report container id
[2020-03-09 11:10:12.123 -04:00][Debug] - {BackendCommUtils} Building HTTP client with BaseAddress: http://1*.**.**.***:8200/ for BackendCommComponentBase (PayloadSenderV2)...
[2020-03-09 11:10:12.207 -04:00][Debug] - {ExceptionUtils.DoSwallowingExceptions} `ElasticApmPayloadSenderV2' (managed ID: 4) thread entry method entered
[2020-03-09 11:10:12.219 -04:00][Debug] - {PayloadSenderV2} Using the following configuration options: Events intake API absolute URL: http://1*.**.**.***:8200/intake/v2/events, FlushInterval: 10s, MaxBatchEventCount: 10, MaxQueueEventCount: 1000
[2020-03-09 11:10:12.240 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmPayloadSenderV2)} Adding task... Task: {ID: 1, Status: WaitingToRun, AsyncState: null}
[2020-03-09 11:10:12.240 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmPayloadSenderV2)} Added task. Task: {ID: 1, Status: WaitingToRun, AsyncState: null}
[2020-03-09 11:10:12.240 -04:00][Debug] - {BackendCommComponentBase (PayloadSenderV2)} Posted Work loop to internal task scheduler
[2020-03-09 11:10:12.240 -04:00][Debug] - {BackendCommComponentBase (PayloadSenderV2)} Waiting for work loop started event...
[2020-03-09 11:10:12.240 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmPayloadSenderV2)} Starting to execute task... Task: {ID: 1, Status: WaitingToRun, AsyncState: null}
[2020-03-09 11:10:12.244 -04:00][Debug] - {BackendCommComponentBase (PayloadSenderV2)} Signaling work loop started event...
[2020-03-09 11:10:12.244 -04:00][Debug] - {BackendCommComponentBase (PayloadSenderV2)} Work loop started signaled
[2020-03-09 11:10:12.247 -04:00][Debug] - {ExceptionUtils.DoSwallowingExceptions} BackendCommComponentBase.WorkLoop entered. Current thread: `ElasticApmPayloadSenderV2' (managed ID: 4)
[2020-03-09 11:10:12.271 -04:00][Trace] - {PayloadSenderV2} Waiting for data to send... FlushInterval: 10s
[2020-03-09 11:10:12.307 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmPayloadSenderV2)} Finished executing task. Task: {ID: 1, Status: RanToCompletion, AsyncState: null}
[2020-03-09 11:10:15.579 -04:00][Info] - {MetricsCollector} Collecting metrics in 30000 milliseconds interval
[2020-03-09 11:10:15.581 -04:00][Debug] - {BackendCommUtils} Building HTTP client with BaseAddress: http://1*.**.**.***:8200/ for BackendCommComponentBase (CentralConfigFetcher)...
[2020-03-09 11:10:15.582 -04:00][Debug] - {ExceptionUtils.DoSwallowingExceptions} `ElasticApmCentralConfigFetcher' (managed ID: 8) thread entry method entered
[2020-03-09 11:10:15.582 -04:00][Debug] - {CentralConfigFetcher} Central configuration feature is enabled because CentralConfig option's value is True (default value is True)
[2020-03-09 11:10:15.583 -04:00][Debug] - {CentralConfigFetcher} Combined absolute URL for APM Server get central configuration endpoint: `http://1*.**.**.***:8200/config/v1/agents?service.name=WritePayment'. Service: Service{Name: WritePayment, Version: null, Environment: null, Runtime: Runtime{Name: .NET Framework, Version: 4.7.3468.0}, Framework: null, Agent: AgentC{Name: dotnet, Version: 1.3}, Language: null, Node: Node{ConfiguredName: null}}.
[2020-03-09 11:10:15.584 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Adding task... Task: {ID: 3, Status: WaitingToRun, AsyncState: null}
[2020-03-09 11:10:15.584 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Added task. Task: {ID: 3, Status: WaitingToRun, AsyncState: null}
[2020-03-09 11:10:15.584 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Starting to execute task... Task: {ID: 3, Status: WaitingToRun, AsyncState: null}
[2020-03-09 11:10:15.584 -04:00][Debug] - {BackendCommComponentBase (CentralConfigFetcher)} Posted Work loop to internal task scheduler
[2020-03-09 11:10:15.584 -04:00][Debug] - {BackendCommComponentBase (CentralConfigFetcher)} Waiting for work loop started event...
[2020-03-09 11:10:15.584 -04:00][Debug] - {BackendCommComponentBase (CentralConfigFetcher)} Signaling work loop started event...
[2020-03-09 11:10:15.585 -04:00][Debug] - {ExceptionUtils.DoSwallowingExceptions} BackendCommComponentBase.WorkLoop entered. Current thread: `ElasticApmCentralConfigFetcher' (managed ID: 8)
[2020-03-09 11:10:15.585 -04:00][Debug] - {BackendCommComponentBase (CentralConfigFetcher)} Work loop started signaled
[2020-03-09 11:10:15.593 -04:00][Trace] - {CurrentExecutionSegmentsContainer.transaction} Setting value... Current thread: managed ID: 1. Current value: (null). New value: Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}.
[2020-03-09 11:10:15.595 -04:00][Trace] - {CentralConfigFetcher} Making HTTP request to APM Server... Request: Method: GET, RequestUri: 'http://1*.**.**.***:8200/config/v1/agents?service.name=WritePayment', Version: 1.1, Content: <null>, Headers:
{
}.
[2020-03-09 11:10:15.594 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} New Transaction instance created: Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}. IsSampled (True) is based on the given sampler (Sampler{ constant: True }). Start time: 2020-03-09 15:10:15.5917370 UTC (as timestamp: 1583766615591737)
[2020-03-09 11:10:15.595 -04:00][Debug] - {Tracer} Starting Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}
[2020-03-09 11:10:15.599 -04:00][Trace] - {CurrentExecutionSegmentsContainer.span} Setting value... Current thread: managed ID: 1. Current value: (null). New value: Span{Id: b0929710df28def7, TransactionId: e9b2a458b5086e8f, ParentId: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, Name: SendEventMsgToTopic, Type: external, IsSampled: True}.
[2020-03-09 11:10:15.600 -04:00][Trace] - {Span.b0929710df28def7} New Span instance created: Span{Id: b0929710df28def7, TransactionId: e9b2a458b5086e8f, ParentId: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, Name: SendEventMsgToTopic, Type: external, IsSampled: True}. Start time: 2020-03-09 15:10:15.5977430 UTC (as timestamp: 1583766615597743). Parent span: (null)
[2020-03-09 11:10:15.600 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} Starting Span{Id: b0929710df28def7, TransactionId: e9b2a458b5086e8f, ParentId: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, Name: SendEventMsgToTopic, Type: external, IsSampled: True}
[2020-03-09 11:10:15.604 -04:00][Trace] - {CurrentExecutionSegmentsContainer.transaction} Setting value... Current thread: managed ID: 1. Current value: Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}. New value: Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}.
[2020-03-09 11:10:15.604 -04:00][Trace] - {Transaction.ea79c778dd629c9e} New Transaction instance created: Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}. IsSampled (True) is based on the given sampler (Sampler{ constant: True }). Start time: 2020-03-09 15:10:15.6047370 UTC (as timestamp: 1583766615604737)
[2020-03-09 11:10:15.604 -04:00][Debug] - {Tracer} Starting Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}
[2020-03-09 11:10:15.604 -04:00][Trace] - {CurrentExecutionSegmentsContainer.span} Setting value... Current thread: managed ID: 1. Current value: Span{Id: b0929710df28def7, TransactionId: e9b2a458b5086e8f, ParentId: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, Name: SendEventMsgToTopic, Type: external, IsSampled: True}. New value: Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}.
[2020-03-09 11:10:15.604 -04:00][Trace] - {Span.3213a723715daf04} New Span instance created: Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}. Start time: 2020-03-09 15:10:15.6047370 UTC (as timestamp: 1583766615604737). Parent span: (null)
[2020-03-09 11:10:15.604 -04:00][Trace] - {Transaction.ea79c778dd629c9e} Starting Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}
Trace file path:C:\Users\s********\source\repos\MessageWriter\MessageWriter\bin\Release\
[2020-03-09 11:10:15.754 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Finished executing task. Task: {ID: 3, Status: RanToCompletion, AsyncState: null}
[2020-03-09 11:10:15.837 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Trying to execute task inline... Task: {ID: 10, Status: WaitingToRun, AsyncState: System.Action}, taskWasPreviouslyQueued: False
[2020-03-09 11:10:15.837 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Adding task... Task: {ID: 10, Status: WaitingToRun, AsyncState: System.Action}
[2020-03-09 11:10:15.837 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Added task. Task: {ID: 10, Status: WaitingToRun, AsyncState: System.Action}
[2020-03-09 11:10:15.837 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Starting to execute task... Task: {ID: 10, Status: WaitingToRun, AsyncState: System.Action}

kaushas · March 9, 2020, 3:42pm

part 2

[2020-03-09 11:10:15.595 -04:00][Trace] - {CentralConfigFetcher} Making HTTP request to APM Server... Request: Method: GET, RequestUri: 'http://1*.**.**.***:8200/config/v1/agents?service.name=WritePayment', Version: 1.1, Content: <null>, Headers:
{
}.
[2020-03-09 11:10:15.594 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} New Transaction instance created: Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}. IsSampled (True) is based on the given sampler (Sampler{ constant: True }). Start time: 2020-03-09 15:10:15.5917370 UTC (as timestamp: 1583766615591737)
[2020-03-09 11:10:15.595 -04:00][Debug] - {Tracer} Starting Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}
[2020-03-09 11:10:15.599 -04:00][Trace] - {CurrentExecutionSegmentsContainer.span} Setting value... Current thread: managed ID: 1. Current value: (null). New value: Span{Id: b0929710df28def7, TransactionId: e9b2a458b5086e8f, ParentId: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, Name: SendEventMsgToTopic, Type: external, IsSampled: True}.
[2020-03-09 11:10:15.600 -04:00][Trace] - {Span.b0929710df28def7} New Span instance created: Span{Id: b0929710df28def7, TransactionId: e9b2a458b5086e8f, ParentId: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, Name: SendEventMsgToTopic, Type: external, IsSampled: True}. Start time: 2020-03-09 15:10:15.5977430 UTC (as timestamp: 1583766615597743). Parent span: (null)
[2020-03-09 11:10:15.600 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} Starting Span{Id: b0929710df28def7, TransactionId: e9b2a458b5086e8f, ParentId: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, Name: SendEventMsgToTopic, Type: external, IsSampled: True}
[2020-03-09 11:10:15.604 -04:00][Trace] - {CurrentExecutionSegmentsContainer.transaction} Setting value... Current thread: managed ID: 1. Current value: Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}. New value: Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}.
[2020-03-09 11:10:15.604 -04:00][Trace] - {Transaction.ea79c778dd629c9e} New Transaction instance created: Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}. IsSampled (True) is based on the given sampler (Sampler{ constant: True }). Start time: 2020-03-09 15:10:15.6047370 UTC (as timestamp: 1583766615604737)
[2020-03-09 11:10:15.604 -04:00][Debug] - {Tracer} Starting Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}
[2020-03-09 11:10:15.604 -04:00][Trace] - {CurrentExecutionSegmentsContainer.span} Setting value... Current thread: managed ID: 1. Current value: Span{Id: b0929710df28def7, TransactionId: e9b2a458b5086e8f, ParentId: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, Name: SendEventMsgToTopic, Type: external, IsSampled: True}. New value: Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}.
[2020-03-09 11:10:15.604 -04:00][Trace] - {Span.3213a723715daf04} New Span instance created: Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}. Start time: 2020-03-09 15:10:15.6047370 UTC (as timestamp: 1583766615604737). Parent span: (null)
[2020-03-09 11:10:15.604 -04:00][Trace] - {Transaction.ea79c778dd629c9e} Starting Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}
Trace file path:C:\Users\s********\source\repos\MessageWriter\MessageWriter\bin\Release\
[2020-03-09 11:10:15.754 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Finished executing task. Task: {ID: 3, Status: RanToCompletion, AsyncState: null}
[2020-03-09 11:10:15.837 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Trying to execute task inline... Task: {ID: 10, Status: WaitingToRun, AsyncState: System.Action}, taskWasPreviouslyQueued: False
[2020-03-09 11:10:15.837 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Adding task... Task: {ID: 10, Status: WaitingToRun, AsyncState: System.Action}
[2020-03-09 11:10:15.837 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Added task. Task: {ID: 10, Status: WaitingToRun, AsyncState: System.Action}
[2020-03-09 11:10:15.837 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Starting to execute task... Task: {ID: 10, Status: WaitingToRun, AsyncState: System.Action}
[2020-03-09 11:10:15.838 -04:00][Trace] - {CentralConfigFetcher} Reading HTTP response body... Response: StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
{
  Access-Control-Expose-Headers: Etag
  X-Content-Type-Options: nosniff
  Cache-Control: must-revalidate, max-age=30
  Date: Mon, 09 Mar 2020 15:10:15 GMT
  ETag: "66098dd5387c079020f1306c1535decdfb7736d5"
  Content-Length: 83
  Content-Type: text/plain; charset=utf-8
}.
[2020-03-09 11:10:15.839 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Trying to execute task inline... Task: {ID: 18, Status: WaitingToRun, AsyncState: System.Action}, taskWasPreviouslyQueued: False
[2020-03-09 11:10:15.839 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Trying to execute task inline... Task: {ID: 20, Status: WaitingToRun, AsyncState: System.Action}, taskWasPreviouslyQueued: False
[2020-03-09 11:10:15.840 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Trying to execute task inline... Task: {ID: 23, Status: WaitingToRun, AsyncState: System.Action}, taskWasPreviouslyQueued: False
[2020-03-09 11:10:15.840 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Trying to execute task inline... Task: {ID: 25, Status: WaitingToRun, AsyncState: System.Action}, taskWasPreviouslyQueued: False
[2020-03-09 11:10:15.840 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Trying to execute task inline... Task: {ID: 27, Status: WaitingToRun, AsyncState: System.Action}, taskWasPreviouslyQueued: False
[2020-03-09 11:10:15.840 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Trying to execute task inline... Task: {ID: 29, Status: WaitingToRun, AsyncState: System.Action}, taskWasPreviouslyQueued: False
[2020-03-09 11:10:15.843 -04:00][Trace] - {CentralConfigFetcher} Processing HTTP response...
+-> Response:
    StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.StreamContent, Headers:
    {
      Access-Control-Expose-Headers: Etag
      X-Content-Type-Options: nosniff
      Cache-Control: must-revalidate, max-age=30
      Date: Mon, 09 Mar 2020 15:10:15 GMT
      ETag: "66098dd5387c079020f1306c1535decdfb7736d5"
      Content-Length: 83
      Content-Type: text/plain; charset=utf-8
    }
+-> Response body [length: 83]:
    {"capture_body":"off","transaction_max_spans":"500","transaction_sample_rate":"1"}

[2020-03-09 11:10:16.094 -04:00][Debug] - {AbstractConfigurationReader (CentralConfigFetcher.ConfigParser)} Using provided transaction max spans '500' parsed as '500'
[2020-03-09 11:10:16.094 -04:00][Debug] - {AbstractConfigurationReader (CentralConfigFetcher.ConfigParser)} Using provided transaction sample rate `1' parsed as 1
[2020-03-09 11:10:16.095 -04:00][Info] - {CentralConfigFetcher} Updating ConfigStore. New central configuration: [ETag: `"66098dd5387c079020f1306c1535decdfb7736d5"']{CaptureBody: off, TransactionMaxSpans: 500, TransactionSampleRate: 1}
[2020-03-09 11:10:16.096 -04:00][Info] - {ConfigStore} Replaced current snapshot. Old: local. New: local + central (ETag: `"66098dd5387c079020f1306c1535decdfb7736d5"').
[2020-03-09 11:10:16.097 -04:00][Trace] - {CentralConfigFetcher} Waiting 30s... Wait time is taken from max-age directive in Cache-Control header in APM Server's response. dbgIterationsCount: 1.
[2020-03-09 11:10:16.097 -04:00][Trace] - {SingleThreadTaskScheduler (thread: ElasticApmCentralConfigFetcher)} Finished executing task. Task: {ID: 10, Status: RanToCompletion, AsyncState: System.Action}
[2020-03-09 11:10:20.174 -04:00][Trace] - {Transaction.ea79c778dd629c9e} transform stack frames
[2020-03-09 11:10:20.176 -04:00][Trace] - {Transaction.ea79c778dd629c9e} CreateProviderConnection, 0
[2020-03-09 11:10:20.176 -04:00][Trace] - {Transaction.ea79c778dd629c9e} CreateConnection, 0
[2020-03-09 11:10:20.176 -04:00][Trace] - {Transaction.ea79c778dd629c9e} CreateConnection, 0
[2020-03-09 11:10:20.176 -04:00][Trace] - {Transaction.ea79c778dd629c9e} CreateConnection, 210
[2020-03-09 11:10:20.177 -04:00][Trace] - {Error.f14186b8ab6e17967166f0d53c53e4e6} New Error instance created: Error{Id: f14186b8ab6e17967166f0d53c53e4e6, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: ea79c778dd629c9e, TransactionId: ea79c778dd629c9e}. Time: 2020-03-09 15:10:20.1767420 UTC (as timestamp: 1583766620176742)
[2020-03-09 11:10:20.183 -04:00][Debug] - {PayloadSenderV2} Enqueued Error. newEventQueueCount: 1. MaxQueueEventCount: 1000. Error: Error{Id: f14186b8ab6e17967166f0d53c53e4e6, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: ea79c778dd629c9e, TransactionId: ea79c778dd629c9e}.
2020-03-09 11:10:20.1837|ERROR|MessageWriter.Writer|I**.XMS.XMSException: CWSMQ0006E: An exception was received during the call to the method ConnectionFactory.CreateConnection: CompCode: 2, Reason: 2035.
During execution of the specified method an exception was thrown by another component.
See the linked exception for more information.
   at I**.XMS.Client.WMQ.Factories.WmqConnectionFactory.CreateProviderConnection(XmsPropertyContext connectionProps)
   at I**.XMS.Client.Impl.XmsConnectionFactoryImpl.CreateConnection(String userID, String password)
   at I**.XMS.Client.Impl.XmsConnectionFactoryImpl.CreateConnection()
   at MessageWriter.Writer.CreateConnection() in C:\Users\s********\source\repos\MessageWriter\MessageWriter\MWriter.cs:line 210

Linked Exception : CompCode: 2, Reason: 2035
[2020-03-09 11:10:20.188 -04:00][Trace] - {Span.3213a723715daf04} Ended Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}. Start time: 2020-03-09 15:10:15.6047370 UTC (as timestamp: 1583766615604737), End time: 2020-03-09 15:10:20.1887930 UTC (as timestamp: 1583766620188793), Duration: 4584.056ms
[2020-03-09 11:10:20.199 -04:00][Trace] - {Span.3213a723715daf04} transform stack frames
[2020-03-09 11:10:20.199 -04:00][Trace] - {Span.3213a723715daf04} End, 0
[2020-03-09 11:10:20.199 -04:00][Trace] - {Span.3213a723715daf04} CreateConnection, 230
[2020-03-09 11:10:20.199 -04:00][Trace] - {Span.3213a723715daf04} SendEventMsgToTopic, 47
[2020-03-09 11:10:20.199 -04:00][Trace] - {Span.3213a723715daf04} Main, 33
[2020-03-09 11:10:20.199 -04:00][Debug] - {PayloadSenderV2} Enqueued Span. newEventQueueCount: 2. MaxQueueEventCount: 1000. Span: Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}.
[2020-03-09 11:10:20.200 -04:00][Trace] - {CurrentExecutionSegmentsContainer.span} Setting value... Current thread: managed ID: 1. Current value: Span{Id: 3213a723715daf04, TransactionId: ea79c778dd629c9e, ParentId: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, Name: CreateConnection, Type: external, IsSampled: True}. New value: (null).
[2020-03-09 11:10:20.201 -04:00][Trace] - {Transaction.ea79c778dd629c9e} Ended Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}. Start time: 2020-03-09 15:10:15.6047370 UTC (as timestamp: 1583766615604737), End time: 2020-03-09 15:10:20.2017520 UTC (as timestamp: 1583766620201752), Duration: 4597.015ms

kaushas · March 9, 2020, 3:43pm

[2020-03-09 11:10:20.201 -04:00][Debug] - {PayloadSenderV2} Enqueued Transaction. newEventQueueCount: 3. MaxQueueEventCount: 1000. Transaction: Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}.
[2020-03-09 11:10:20.201 -04:00][Trace] - {CurrentExecutionSegmentsContainer.transaction} Setting value... Current thread: managed ID: 1. Current value: Transaction{Id: ea79c778dd629c9e, TraceId: 9b527c2caccaa82b2dc58176c76fcd30, ParentId: null, Name: CreateConnection, Type: external, IsSampled: True}. New value: (null).
[2020-03-09 11:10:20.202 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} transform stack frames
[2020-03-09 11:10:20.202 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} CreateConnection, 221
[2020-03-09 11:10:20.202 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} SendEventMsgToTopic, 47
[2020-03-09 11:10:20.202 -04:00][Trace] - {Error.e96be31aa7682f7bac9646c9ba792d3e} New Error instance created: Error{Id: e96be31aa7682f7bac9646c9ba792d3e, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: e9b2a458b5086e8f, TransactionId: e9b2a458b5086e8f}. Time: 2020-03-09 15:10:20.2027540 UTC (as timestamp: 1583766620202754)
[2020-03-09 11:10:20.202 -04:00][Debug] - {PayloadSenderV2} Enqueued Error. newEventQueueCount: 4. MaxQueueEventCount: 1000. Error: Error{Id: e96be31aa7682f7bac9646c9ba792d3e, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: e9b2a458b5086e8f, TransactionId: e9b2a458b5086e8f}.
2020-03-09 11:10:20.2027|ERROR|MessageWriter.Writer|System.NullReferenceException: Object reference not set to an instance of an object.
   at MessageWriter.Writer.CreateConnection() in C:\Users\s********\source\repos\MessageWriter\MessageWriter\MWriter.cs:line 221
   at MessageWriter.Writer.SendEventMsgToTopic(MsgEvent msgEvent) in C:\Users\s********\source\repos\MessageWriter\MessageWriter\MWriter.cs:line 47
[2020-03-09 11:10:20.205 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} Ended Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}. Start time: 2020-03-09 15:10:15.5917370 UTC (as timestamp: 1583766615591737), End time: 2020-03-09 15:10:20.2057570 UTC (as timestamp: 1583766620205757), Duration: 4614.02ms
[2020-03-09 11:10:20.205 -04:00][Debug] - {PayloadSenderV2} Enqueued Transaction. newEventQueueCount: 5. MaxQueueEventCount: 1000. Transaction: Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True}.
[2020-03-09 11:10:20.205 -04:00][Trace] - {CurrentExecutionSegmentsContainer.transaction} Setting value... Current thread: managed ID: 1. Current value: (null). New value: (null).
[2020-03-09 11:10:20.205 -04:00][Trace] - {Transaction.e9b2a458b5086e8f} Ended Transaction{Id: e9b2a458b5086e8f, TraceId: 2dd039703172e7f4f80e058c27b98090, ParentId: null, Name: SendEventsStart, Type: external, IsSampled: True} (with Duration already set). Start time: 2020-03-09 15:10:15.5917370 UTC (as timestamp: 1583766615591737), Duration: 4614.02ms
Failure, writing message to Topic
Waiting for thread to complete.....

kaushas · March 11, 2020, 7:07pm

Any ideas? Will like to avoid using elevated privilege.

GregKalapos · March 11, 2020, 7:24pm

Hi @kaushas -

When these logs were created - did the transaction show up in Kibana? I assume not, right? What I see in the logs is that at 2020-03-09 11:10:20.201 -04:00][Trace] the transaction is ended and it's enqueued, but the last line from the agent is at [2020-03-09 11:10:20.205 -04:00][Trace] - nothing comes after that.

Can it be that the agent has no chance to send the data to the server? Or how long was this process running after that? The flusinterval is by default 10 sec, so worst case you'll need to wait 10 sec, so the agent can send the data to the server. What I miss in the logs is the part where the agent tries to send the data to the server, that does not happen. I'd say this could have 2 reasons - either the agent does not have the chance to try this, because the process terminates, or from some reason the agent never tries sending data, but for that I don't see any sign in the logs - First I want to make sure we don't have the 1. scenario here.

GregKalapos · March 11, 2020, 7:28pm

This really seems like the 1. scenario to me.

There is this line:

[2020-03-09 11:10:12.271 -04:00][Trace] - {PayloadSenderV2} Waiting for data to send... FlushInterval: 10s - so time is [2020-03-09 11:10:12.271, and the timespan of the last line is 2020-03-09 11:10:20.205 -04:00 - so if the process does not live 0:0:2:067 (~2 sec and a little bit) longer then the agent won't even try to send the data.

kaushas · March 11, 2020, 10:26pm

@GregKalapos, I have put in a 10 second wait before the process exists. I can increase the wait and get the logs again. However, same process with same errors does show up in Kiban. Only, if you are running the process as local admin, so I am thinking it is scenario #2.