Redirect all NLog output to Serilog with a custom Target
Asked Answered
D

1

8

As a step in switching from NLog to Serilog, I want to redirect the standard wiring underlying standard invocations of NLog's LogManager.GetLogger(name) to Bridge any code logging to NLog to forward immediately to the ambient Serilog Log.Logger - i.e. I want to just one piece of config that simply forwards the message, without buffering as Log4net.Appender.Serilog does for Log4net.

Can anyone concoct or point me to a canonical snippet that does this correctly and efficiently please? Requirements I can think of:

  • Maintain the level, i.e. NLog.Warn should be equivalent to serilog.Warning
  • It's ok for Serilog to generate the time anew
  • materializing the message in the appender - i.e., there's no need to maintain any properties associated with the 'message' (the LogEvent in Serilog terms)
  • no buffering
  • I don't need any other NLog Target to be used (i.e. mutating/deleting the message would be fine)
Delly answered 31/3, 2018 at 20:59 Comment(24)
Curious why you want to get away from NLog. Is something missing in NLog?Moneywort
The way the Async wrapper coordinates among threads caused issues, also I had a leak related to the same mechanism. The Serilog sinks are very clean and you'd trust what they do by reading them. There's also a good gitter community. It also gave me a 30% increase in capacity under load to switch in my contextDelly
Do you have an example config (or example code) that shows this bad behavior in NLog ? (Doesn't have to compile, but just give an idea how you are using NLog). My own testing of NLog and Serilog gives me a different picture.Moneywort
Never boiled it down properly but we were on a ~1.5yo version of NLog's async wrapper and the newer one looked even scarier to me. Both leaked objects relating to the Async transition. The NLog config was all programmatic. In more recent times, I looked at a mem dump that showed 60+ threads all in an async write action (all hitting same file target). My scanning of the NLog code suggested there isnt a simple passing of the info over to a writer thread but instead a complex arrangements of awaiting the handoff (which facilitates the blocking/ grow behaviors and doubtless other power features)Delly
My testing consisted of back to back runs attempting to feed up to 600 rps into a local web server doing interesting work requiring parallelism internally (reading/writing EventStore) with a minthreads settings of default, 100 and 768. Throughput under load (not saturated, but high) went from ~100 to ~130 krps in 10 mins - it writes ~10mbps across about 4 files, with probably 10-15 hits per transaction. My serilog config set the sinks to (wrapped in async) buffer and roll and dump once per second. (the nlog equivalents where half async, half sync without any specific buffering config)Delly
To be clear: I did not set out to do back to back comparisons or benchmark things - the actual issue was behaviour of the nlog async wrapper when saturated and/or file writing gets blocked/interruped (and formerly the leaking behavior - I can't say 100% its actually the fault of NLog, but removing the NLog wrapper and writing sync fixed the problem and took it off the agenda)Delly
Sounds like the same problems I was having, that caused me to file several pullrequests that was included in NLog 4.4.2 (With a hidden feature that AsyncWrapper timeToSleepBetweenBatches=0 would give a very nice performance boost). I find that Serilog is also having concurrency issues in its message template cache. Think more performance can be squeezed out of NLog by optimizing the layout logic for concurrency and using ConcurrentQueue in AsyncWrapper on NetCore2 and Net472. What version of NLog were you using?Moneywort
It was using a relatively old version with webapi+katana 5.2.3+3.0 and have not used a profiler. As long as writing is batched, 10ish log entries (even if one is massive, as it was in my case) should not be interesting compared to an out of process hop. Regarding seriolog concurrency issues, my load test was not terribly mixed in nature so there could be lurking fun. I dont think there's any reason why NLog and/or Serilog can't steal sink impl techniques from each other and/or achieve similar perf, but it does seem the Async scheme in NLog is fairly deep baked - it is also more powerful.Delly
You're obviously way deeper in, and there are always many levels to understanding/being able to grok a codebase than what it scans like before you try to do something. However my sense is Serilog has easier to grok and simpler schemes wrt how sinks and their buffering compose. I'll have the real answer for you in about 6 months ;)Delly
@RolfKristensen NuGet version I was/am testing with is 4.4.12 [from 20170808]. The leak first presented with a version which was ~1y olderDelly
If you can post an example config (and maybe code) at github.com/NLog/NLog/issues/new then I would be interested.Moneywort
@RolfKristensen Unfortunately, moving it to sync solved the leak at the time and there are way too many moving parts for me to generate an isolated repro. It is not clear that there necessarily is a specific leak or bug in NLog, although there 100% was a leak in our system which went away by removing the async. We continued to use the async wrapper in other contexts for some time without leaks (aside from the queueing effect under load) for a long time after. Now I'm using Serilog. Please treat above as unvalidated hearsay - I have not even looked at the Concurrency Visualizer view after allDelly
Made a comparison of Serilog.Async 1.3.0 (blockWhenFull=true) and NLog 4.5.5 (overflowAction=Block) with 4 threads to a single file with default Serilog JsonFormatter and similar NLog JsonLayout. Serilog handled 60.000 msgs/sec while NLog handled 105.000 msgs/sec and used 5 time less CPU-time and less allocations.Moneywort
@rolfkristensen I was/am using RenderedCompactJsonformatter (cheaper; see benchmarks in github.com/serilog/serilog-formatting-compact) and hundreds of threads, also NLog < 4.5. Another key thing is that I do periodic batching of 1s on the file sink which can help a lot (though its behind async so should not matter too much). Less allocations from NLog is possible but also having no pauses/p99 effects is also important. If you can post a benchmark.net repo I'd be happy to have a look as I'm definitely seeing throughput on in-app benchmarks. I'm personally only interested in drop mode.Delly
My performance test shows that RenderedCompactJsonformatter allocates twice the memory as Serilog JsonFormatter, and both are same speed when 4 threads logging to the same file. But CompactJsonFormatter is 30 pct faster and allocates 50 pct less than Serilog JsonFormatter. But when adding Serilog Async-wrapper then performance becomes 100 pct slower, while NLog-Async becomes 50 pct faster. Serilog CompactJsonFormatter without Async is a little faster than NLog. When using drop-mode then NLog wins because it discards 80 pct and Serilog discards 50 pct :)Moneywort
Now see that both Serilog JsonFormatter and CompactJsonFormatter doesn't render the log-message but just outputs the input-template. NLog performs the same whether it has to output log-message or input-template.Moneywort
@RolfKristensen It's all trade-offs; I'm referring to the Rendered version; I believe (based on reading the source of NLog about a year ago) that the perf diff is based on how it hands to the background thread. I don't doubt that NLog can beat it in a variety of circumstances, but it all depends on the exact topology. Serilog definitely has significant scope to remove allocations. Regarding 4 threads writing to file, that's not my test (and there are ways of marshalling it efficiently) - again, if you have a test repo, I'd be happy to have a look. Def have zero interest in dropping events;)Delly
Have just made some minor modifications to exercise Serilog: github.com/NLog/NLog-Performance-tests/tree/master/…Moneywort
@rolfkristensen hm, there's a lot in there; in order to meaningfully compare, I'd be looking to have a test which logs from a variable number of threads testing various logger configurations, and let benchmark.net do the comparisons in order to remove a lot of opportunities for variation due to issues of methodology. I thought I saw someone had done such a comparison. For Serilog, there are definitely multiple ways to rig things, and showing exactly how the config looks is critical.Delly
I have no reason to doubt you, and am not questioning you, but a proper rig and iterative to/fro to ensure comparison is of something meaningful that is doing something representative using the best approaches possible per logger is critical to the exercise. This is a non-trivial undertaking though; my intention neither to goad you into anything or chuck loads of FUD, just to caution against us or any onlookers trying to conclude anything from this. I am testing my app in Katana from ~300 client threads and seeing differences due to contention impacts, you are doing something different.Delly
I'm guessing you don't have 300 cores, so maybe "only" 48 threads are actively logging at the same time depending on your hardware. I sadly don't have such hardware on my home computer :)Moneywort
I have a 2015 MacBook with Parallels and about 10G allocated to the VM; I generate all the load locally (which is debatable too), but I'm using a pretty battle tested (but homespun) load test rig. My only point is that the specifics of how one wires a logging configuration matter a lot on all loggers - there are differing strengths of each logger, and it's very easy to configure one suboptimally and/or set up a test which is very far away from the sweet spot of the use case something is optimising for.Delly
I was using a version of NLog that was 1.5yo and am writing to 4+ logs and the problem observed in prod was when lots of threads were in play - I understand exactly what Serilog is doing and why it might be efficient given how I am using it. Its entirely possible that the problem was solvable with NLog; I'm not trying to claim that everyone must move to Serilog because the perf is different class. Both are top class loggers with a huge amount of features and maturity and for most normal usage the variance in perf will never show up in any perf trace or load test result - lets leave it lie ;)Delly
Yes it is very difficult to setup a performance tests that fits all scenarios. Which you can also see from the single NLog benchmark project. Many different scenario parameters can be tweaked. And many different NLog-configurations are included for testing. Low memory allocation is a very important requirement in my world. So yes lets leave it lie :)Moneywort
C
12

I think the best option is indeed a custom NLog target. Something like this: (C#)

using NLog;
using NLog.Targets;
using Serilog;
using Serilog.Events;

namespace MyNamespace
{
    [Target("SerilogTarget")]
    public sealed class SerilogTarget : TargetWithLayout
    {
        protected override void Write(LogEventInfo logEvent)
        {
            var log = Log.ForContext(Serilog.Core.Constants.SourceContextPropertyName, logEvent.LoggerName);
            var logEventLevel = ConvertLevel(logEvent.Level);
            if ((logEvent.Parameters?.Length ?? 0) == 0)
            {
                // NLog treats a single string as a verbatim string; Serilog treats it as a String.Format format and hence collapses doubled braces
                // This is the most direct way to emit this without it being re-processed by Serilog (via @nblumhardt)
                var template = new Serilog.Events.MessageTemplate(new[] { new Serilog.Parsing.TextToken(logEvent.FormattedMessage) });
                log.Write(new Serilog.Events.LogEvent(DateTimeOffset.Now, logEventLevel, logEvent.Exception, template, Enumerable.Empty<Serilog.Events.LogEventProperty>()));
            }
            else
                // Risk: tunneling an NLog format and assuming it will Just Work as a Serilog format
#pragma warning disable Serilog004 // Constant MessageTemplate verifier
                log.Write(logEventLevel, logEvent.Exception, logEvent.Message, logEvent.Parameters);
#pragma warning restore Serilog004
        }

        static Serilog.Events.LogEventLevel ConvertLevel(LogLevel logEventLevel)
        {
            if (logEventLevel == LogLevel.Info)
                return Serilog.Events.LogEventLevel.Information;
            else if (logEventLevel == LogLevel.Trace)
                return Serilog.Events.LogEventLevel.Verbose;
            else if (logEventLevel == LogLevel.Debug)
                return Serilog.Events.LogEventLevel.Debug;
            else if (logEventLevel == LogLevel.Warn)
                return Serilog.Events.LogEventLevel.Warning;
            else if (logEventLevel == LogLevel.Error)
                return Serilog.Events.LogEventLevel.Error;
            return Serilog.Events.LogEventLevel.Fatal;
        }
    }
}

register it in your main() or app_start:

// Register so it can be used by config file parsing etc
Target.Register<MyNamespace.SerilogTarget>("SerilogTarget"); 

Before any logging takes place, the Target needs to be wired in so LogManager.GetLogger() can actually trigger a call to SerilogTarget.Write

    public static void ReplaceAllNLogTargetsWithSingleSerilogForwarder()
    {
        // sic: blindly overwrite the forwarding rules every time
        var target = new SerilogTarget();
        var cfg = new NLog.Config.LoggingConfiguration();
        cfg.AddTarget(nameof(SerilogTarget), target);
        cfg.LoggingRules.Add(new NLog.Config.LoggingRule("*", LogLevel.Trace, target));
        // NB assignment must happen last; rules get ingested upon assignment
        LogManager.Configuration = cfg;
    }

See also: https://github.com/nlog/nlog/wiki/How-to-write-a-custom-target

the optimal way to do this without inducing any avoidable perf impact etc.

This is the optimal way in NLog and has no performance impact on the NLog's site.

what does the TargetAttribute buy me ?

Well in this case you don't need it. The TargetAttribute is used when registering a full assembly, but because we register manually, it's not needed. I think it's best practice, but you could leave it out.

Also what does the Register buy me

This is indeed not needed when using programmatically config. But if you have XML config, you need the register.

I've the habit to write targets that works in all ways (register manually, register by assembly, config from code, config from XML). I could understand that could be confusing.


F# port:

module SerilogHelpers =

    let private mapLevel = function
        | x when x = NLog.LogLevel.Info -> LogEventLevel.Information
        | x when x = NLog.LogLevel.Off || x = NLog.LogLevel.Trace -> LogEventLevel.Verbose
        | x when x = NLog.LogLevel.Debug -> LogEventLevel.Debug
        | x when x = NLog.LogLevel.Warn -> LogEventLevel.Warning
        | x when x = NLog.LogLevel.Error ->  LogEventLevel.Error
        | _ -> LogEventLevel.Fatal

    // via https://mcmap.net/q/1292239/-redirect-all-nlog-output-to-serilog-with-a-custom-target
    [<NLog.Targets.Target("SerilogTarget")>]
    type SerilogTarget() =
        inherit NLog.Targets.Target()

        static member InitializeAsGlobalTarget() =
            // sic: blindly overwrite the forwarding rules every time
            // necessary as Azure Startup establishes a different config as a bootstrapping step
            // see: LogModule.To.target("rollingFile", create, "*", LogLevel.Trace)
            let cfg, target = NLog.Config.LoggingConfiguration(), SerilogTarget()
            cfg.AddTarget("SerilogTarget", target)
            cfg.LoggingRules.Add(NLog.Config.LoggingRule("*", NLog.LogLevel.Trace, target))
            // NB assignment must happen last; rules get ingested upon assignment
            NLog.LogManager.Configuration <- cfg

        override __.Write(logEvent : NLog.LogEventInfo) =
            let log = Log.ForContext(Serilog.Core.Constants.SourceContextPropertyName, logEvent.LoggerName)
            match logEvent.Parameters with
            | xs when isNull xs || xs.Length = 0 ->
                // NLog treats a single string as a verbatim string; Serilog treats it as a String.Format format and hence collapses doubled braces
                // This is the most direct way to emit this without it being re-processed by Serilog (via @nblumhardt)
                let template = MessageTemplate [| Serilog.Parsing.TextToken(logEvent.FormattedMessage) |]
                log.Write(new LogEvent(DateTimeOffset.Now, mapLevel logEvent.Level, logEvent.Exception, template, Seq.empty<LogEventProperty>))
            | _ ->
                // Risk: tunneling an NLog format and assuming it will Just Work as a Serilog format
                log.Write(mapLevel logEvent.Level, logEvent.Exception, logEvent.Message, logEvent.Parameters)
Clavicorn answered 3/4, 2018 at 20:54 Comment(13)
Thanks so much - will be deleting my answer shortly. I can't actually think of a use for my Inner so will use your idea of using Log directly.Delly
what does the TargetAttribute buy me ? Also what does the Register buy me ? my planned initialization was to do: LogManager.Configuration = new NLog.Config.LoggingConfiguration(); LogManager.Configuration.AddTarget(new SerilogTarget()); ... would I be guessing right that the .Register would have the same effect but still leave it open for others to attach targets?Delly
i've updated my answer. I'm not sure if it's OK for you if I copy the changes from your post.Clavicorn
Thank you, and thanks for the politeness; but please take any and all of it - nothing would give me more pleasure than deleting it! My outstanding question is how much of LogManager.Configuration = new NLog.Config.LoggingConfiguration(); LogManager.Configuration.AddTarget("SerilogTarget",new SerilogTarget()); NLog.Targets.Target.Register<SerilogTarget>("SerilogTarget"); I need in my apps startup to wire it in as a default target in the LogManager. I'm going to take a liberty and paste it into your post; please feel free to clean as you see fit.Delly
I updated my answer - I can't actually make it hit the Write method (obviously as I'm missing something obvious!) and am going to park it for a while...Delly
You need the register before setting logmanager.configuration.Clavicorn
Will update post later; I eventually figured out the problem - cant mutate the config after setting it into the logmanager.configuration (IOW LogManager.Configuration = needs to be last after doing full rigging) - the register does not matter. Thanks again for the help!Delly
Well you can, but you have to set it again. (Yes its a bit clumsy)Clavicorn
Edited the solution as I applied it into your answer. Thanks ;)Delly
In the C# code, the static method ConvertLevel is missing the case for log events with level "warning"Protestation
Thanks @TysonWilliams, added itClavicorn
Where should I put ReplaceAllNLogTargetsWithSingleSerilogForwarder I don't find it how is it relevant @RubenBartelinkPreform
@Preform The host app needs to trigger that at some point so that things that use the NLog LogManager get forwarded to Serilog (if it's not called, then the NLog stuff won't go anywhere). If you want to get fancy, you can use a ModuleInitializer. Of course you can do it other ways by having NLog config referencing the SerilogTargetDelly

© 2022 - 2024 — McMap. All rights reserved.