elastic / apm-agent-dotnet

https://www.elastic.co/guide/en/apm/agent/dotnet/current/index.html
Apache License 2.0
582 stars 209 forks source link

Log4Net log correlation #662

Closed gregkalapos closed 4 years ago

gregkalapos commented 4 years ago

From elastic/apm-agent-dotnet#244

In https://github.com/elastic/apm-agent-dotnet/pull/636 we decided we don't want to add hooks into the agent to get notified about the change of the currently active transaction.

I was able to solve log correlation for Serilog with an enricher and for NLog with a LayoutRenderer.

I spent some time on Log4Net:

Based on this article I tried implementing a PatternLayout. That is definitely a no go, because during my testing I saw that it gets called when the log is formatted to be written to its destination and not when the log is written into the logger by the application. So e.g.

Agent.Tracer.CaptureTransaction("TestTransaction", "Test", t =>
{
   log.Info("InTransaction");
});

the log.Info("InTransaction"); line executes within the transaction, but the ConversionPattern is called after the transaction ends - making the current transaction null.

Another idea that came up in #636 is to use GlobalContext - which also does not seem to be a good idea, since that can be overwritten when we have multiple transactions going on, plus we can't even integrate that with the agent, I guess for that we also'd need a callback.

With this, I think for now time is better spent on finishing NLog and Serilog and close this iteration with offering support for those 2.

If someone has a solution for Log4Net, I'm happy to jump on it later. Also, if you use Log4Net and need this feature: please do not only 👎 , instead, let us know and we can reiterate, this is not a final decision.

SergeyKleyman commented 4 years ago

Another idea that came up in #636 is to use GlobalContext - which also does not seem to be a good idea, since that can be overwritten when we have multiple transactions going on

In #636 I meant to follow the same approach as in the linked documentation:

public class GCAllocatedBytesHelper
{
    public override string ToString()
    {
        return GC.GetTotalMemory(true).ToString();
    }
}

GlobalContext is set only once at startup (so no need to overwrite it for every transaction):

log4net.GlobalContext.Properties["GCAllocatedBytes"] = new GCAllocatedBytesHelper();
gregkalapos commented 4 years ago

Oh, I see what you mean. We can certainly create a similar helper class. Compared to the Serilog Enricher and the NLog LayoutRenderer this feels very odd to me - but it's definitely better than nothing...

gregkalapos commented 4 years ago

I tried it, but that suffers from the same problem I described above - in the sample code GC.GetTotalMemory(true).ToString(); is called during rendering - and not when the log line is written by the client - so our Agent.Tracer.CurrentTransaction.TraceId would be also called too late.

The doc also states this:

When this value is rendered to a string by calling the ToString method the current number of bytes allocated by the garbage collector will be returned and included in the output.