Transactions using OpenAPI C# is not showing up

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;
    }

   }

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;
    }

thanks, I will update and test and revert.

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.

  1. 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.
  2. 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.
  3. 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

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.

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.

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.

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}

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

[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.....

Any ideas? Will like to avoid using elevated privilege.

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.

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.

@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.

The logs from a sample run where the process waits at least 10 sec and you don't see the transaction in Kibana would be useful - I'd expect the agent to try to send the data and that seems to fail - if this is the case we'd see this in the log including more details about what's exactly happening there - so if possible please upload such a log, that'd help me to troubleshoot this.

I stand corrected, I thought I had 10 Sec wait but it was 1 sec wait, so once I increased the wait (minimum 2.5 sec), I am seeing transactions showing up and I can see the send data statements getting executed. I am not sure if we can put a 2.5 sec delay in our processes. It will have a direct impact to system performance.

Thanks for the reply @kaushas,

ok, so I think we have an explanation for this, which is that the agent did not have enough time to send the data.

This is a known issue and it's on our radar. First of all here is a GitHub issue that you can follow - we plan to come up with a good solution for this problem long term - but that's not something that helps you now.

What you can do now is to tweak some settings. The agent has the FlushInterval setting - the easiest is to set the environment variable ELASTIC_APM_FLUSH_INTERVAL and make sure it's visible to your process with the agent. You can set it to either 0 - with that the agent will send data immediately, or to some low value. I'd be careful with this in web application, but if this is a short living batch process that generates 1 transaction with a couple of spans then it's fine to set it to either 0 or to a low value. Keep in mind that this won't mean that the agent holds up the application - so if the app terminates before the agent is able to send the data, then the data won't be sent, so you'll still need to make sure the app does not terminate immediately. But with setting this to 0 you can make sure that the agent immediately starts sending the data. With that 1 sec sounds realistic.

thanks, I will play around with Flush Internal and find the optimal setting that works for us. I am also not seeing any Span data. I can create a new issue, if that is more helpful.

Hey @kaushas,

if there is still an issue with this, the troubleshooting would be the same - we could just take a look at the logs - we can do it here, too.

For spans the same apply... those are also queued similarly to transactions.

This topic was automatically closed 20 days after the last reply. New replies are no longer allowed.