serilog-contrib / Serilog.Sinks.Logz.Io

Apache License 2.0
15 stars 11 forks source link

Duplicate log events #24

Closed angularsen closed 9 months ago

angularsen commented 2 years ago

Hi, I'm seeing occasional duplicate log events in logz.io. Exact same timestamp and info.

Is this a known issue? Any tips on how I can debug this?

We log to multiple sinks and this is the only sink with duplicates. I suspect maybe the use of buffering may be relevant, but I have not yet tried non-buffered since this was the recommended setup. I am currently having unrelated issues with logz.io blocking me from testing further.

This is my setup:

var logzIoUrl = $"https://{logzIoSubdomain}.logz.io:8071/?type=app&token={logzIoToken}";
loggerConfig.WriteTo.LogzIoDurableHttp(logzIoUrl,
    bufferPathFormat: Path.Combine(AppContext.BaseDirectory, "temp", "logzio-buffer-{Date}.json"),
    logzioTextFormatterOptions: new LogzioTextFormatterOptions
    {
        BoostProperties = true,
        IncludeMessageTemplate = true,
        LowercaseLevel = true,
    });
mantasaudickas commented 2 years ago

Well all heavy lifting with buffered sending is done by https://github.com/FantasticFiasco/serilog-sinks-http . I could imagine few things which might go wrong:

In order to debug - maybe you can simply enable serilog internal logging something like:

try
{
    if (!Directory.Exists($"c:/temp/logs"))
        Directory.CreateDirectory($"c:/temp/logs");
}
catch (Exception)
{
    // ignore
}

try
{
    var serilog = $"c:/temp/logs/serilog-{DateTime.UtcNow:yyyyMMddHHmm}.log";

    var writer = File.CreateText(serilog);
    writer.AutoFlush = true;

    var textWriter = TextWriter.Synchronized(writer);
    SelfLog.Enable(textWriter);
}
catch (Exception)
{
    // ignore
}

See more details here: https://github.com/serilog/serilog/wiki/Debugging-and-Diagnostics

angularsen commented 2 years ago

Thanks for the quick reply. I'll try to investigate once my logz.io instance is working again.

angularsen commented 2 years ago

I tested with a console app, 1000 log events spread over 10 concurrent workers. 0 duplicates, over a couple of runs.

In prod, 52 of 500 recent lines were duplicates (~10%). In dev, 0 og 500 recent log lines were duplicates.

Dev and prod are identically set up, except there are more instances running of each service in prod, but I don't see that is relevant. The duplicate log events are from the same instance and they don't share disk or anything.

It's mysterious, seems like I'm missing some obvious bit of information. I'll keep digging.

mantasaudickas commented 2 years ago

there are more instances running of each service in prod

Are these instances on different machines? Are you sure its not pointing to the same log folder? Maybe in some cases you are configuring serilog twice in a single instance?

angularsen commented 2 years ago

Just an update, I've tried the non-buffering sink for a few days now and can't spot any duplicates. So it is definitely related to buffering, and likely related to multiple kubernetes pods. Maybe they do share disk.