Seeing NullReferenceException running in Docker on AWS

[jstnlef]

While I'm in the process of converting my application from Serilog to ZLogger, I'm occasionally seeing the following error when I deploy my service to AWS in a linux based Docker container.

LOGGING ERROR: System.NullReferenceException: Object reference not set to an instance of an object.
at ZLogger.Internal.MagicalBox.TryReadTo(Type type, Int32 offset, Int32 alignment, String format, Utf8StringWriter`1& handler)
at ZLogger.MessageSequence.ToString(IBufferWriter`1 writer, MagicalBox box, Span`1 parameters)
at ZLogger.LogStates.InterpolatedStringLogState.ToString(IBufferWriter`1 writer)
at ZLogger.ZLoggerEntry`1.ToString(IBufferWriter`1 writer)
at ZLogger.Formatters.SystemTextJsonZLoggerFormatter.FormatLogEntry(IBufferWriter`1 writer, IZLoggerEntry entry)
at ZLogger.ZLoggerEntry`1.FormatUtf8(IBufferWriter`1 writer, IZLoggerFormatter formatter)
at ZLogger.AsyncStreamLineMessageWriter.WriteLoop()

This is causing me to miss some log lines which I expect to see. Running the locally, I never see errors of this type.

My config

builder.Logging.ClearProviders().AddZLoggerConsole(options =>
    {
      options.CaptureThreadInfo = true;
      options.IncludeScopes = true;
      options.FullMode = BackgroundBufferFullMode.Grow;
      options.InternalErrorLogger = exception => { Console.WriteLine("LOGGING ERROR: " + exception); };
      options.UseJsonFormatter(formatter =>
      {
        formatter.UseUtcTimestamp = true;
        formatter.JsonPropertyNames = JsonPropertyNames.Default with
        {
          Timestamp = JsonEncodedText.Encode("t"),
          LogLevel = JsonEncodedText.Encode("l"),
          Message = JsonEncodedText.Encode("m"),
          Category = JsonEncodedText.Encode("c")
        };
        formatter.AdditionalFormatter = (Utf8JsonWriter writer, in LogInfo info) =>
        {
          if (options.CaptureThreadInfo)
          {
            writer.WriteNumber("threadId", info.ThreadInfo.ThreadId);
            if (info.ThreadInfo.ThreadName is not null)
            {
              writer.WriteString("threadName", info.ThreadInfo.ThreadName);
            }
          }

          // Write out Datadog vars since Datadog can't automatically inject them with ZLogger
          var env = builder.Configuration["DD_ENV"];
          if (env is not null)
          {
            writer.WriteString("dd_env", env);
          }

          var service = builder.Configuration["DD_SERVICE"];
          if (service is not null)
          {
            writer.WriteString("dd_service", service);
          }

          var version = builder.Configuration["DD_VERSION"];
          if (version is not null)
          {
            writer.WriteString("dd_version", version);
          }
        };
      });
    });

Is there something specific I should be doing which I am not to prevent such an error? I'm currently using version 2.5.10 of the library.

[jstnlef]

Looking into the ZLogger.Internal.MagicalBox.TryReadTo(Type type, Int32 offset, Int32 alignment, String format, Utf8StringWriter1& handler)` method, it seems like the only value which "could" be null and is not handled is the 'type' argument.

[neuecc]

Thank you.
There have been reports about this area before, so I'm interested in it, so I'll look into it as soon as possible.

[neuecc]

I looked into a similar report at #158 (comment) , but I still don't quite understand the issue.

Simply adding a Type null check wouldn't solve the problem, as it would mean invalid parameters are being passed, which would result in missing logs.

Could I ask a few more questions about your situation?

• Is this an issue that can't be reproduced locally? If possible, I'd like to reproduce it in a local environment
• Is that the only logging configuration you're using?
• Which log method are you calling and how are you calling it when writing logs?

[jstnlef]

• I have seen the issue occur locally but it is certainly not as consistent as what I see in the deployed version. In fact, I've only seen it once locally where one of my tests failed and logged the stack trace you see above
• I posted my entire ZLogging config above. However, I did write some extension methods which all take the following form

public static void Debug(
    this ILogger logger,
    [InterpolatedStringHandlerArgument("logger")]
    ZLoggerDebugInterpolatedStringHandler message,
    RealmInfo? info = null,
    Exception? exception = null,
    object? context = null,
    [CallerMemberName] string? memberName = null,
    [CallerFilePath] string? filePath = null,
    [CallerLineNumber] int lineNumber = 0)
  {
    Log(logger, LogLevel.Debug, message.InnerHandler, info, exception, context, memberName, filePath, lineNumber);
  }

 private static void Log(
    this ILogger logger,
    LogLevel logLevel,
    [InterpolatedStringHandlerArgument("logger", "logLevel")]
    ZLoggerInterpolatedStringHandler message,
    RealmInfo? info,
    Exception? exception,
    object? context = null,
    [CallerMemberName] string? memberName = null,
    [CallerFilePath] string? filePath = null,
    [CallerLineNumber] int lineNumber = 0)
  {
    if (info is not null && logLevel < info.GetLogLevel())
    {
      return;
    }

    var scope = new Dictionary<string, string>();
    if (info is not null)
    {
      scope.Add("customerId", info.CustomerId);
      scope.Add("realmId", info.RealmId);
    }

    if (scope.Count > 0)
    {
      using (logger.BeginScope(scope))
      {
        logger.ZLog(logLevel, exception, ref message, context, memberName, filePath, lineNumber);
      }
    }
    else
    {
      logger.ZLog(logLevel, exception, ref message, context, memberName, filePath, lineNumber);
    }
  }

That said, running locally on my Mac works just fine. It's only when I build to docker and deploy it to AWS ECS that I'm fairly consistently seeing the issue. I suppose that comment you posted also is calling ZLog through an extension method with a condition. Could be something there.

[jstnlef]

Any news here?

[mollstam]

I see this issue too (I believe). I'm not in Docker or anything though. I'm in Unity on Windows and it happens "sometimes". Maybe 50% for some of my developers. I can't repro it myself so have not much more info to go on. I don't really understand much of this. 😬

ZLogger.Internal.MagicalBox.TryReadTo (System.Type type, System.Int32 offset, System.Int32 alignment, System.String format, Utf8StringInterpolation.Utf8StringWriter`1[System.Buffers.IBufferWriter`1[System.Byte]]& handler) (at <61b75ff0c191453e98b32a9064ca1468>:0)
ZLogger.MessageSequence.ToString (System.Buffers.IBufferWriter`1[T] writer, ZLogger.Internal.MagicalBox box, System.Span`1[T] parameters) (at <61b75ff0c191453e98b32a9064ca1468>:0)
ZLogger.LogStates.InterpolatedStringLogState.ToString (System.Buffers.IBufferWriter`1[T] writer) (at <61b75ff0c191453e98b32a9064ca1468>:0)
ZLogger.ZLoggerEntry`1[TState].ToString (System.Buffers.IBufferWriter`1[T] writer) (at <61b75ff0c191453e98b32a9064ca1468>:0)
ZLogger.Formatters.PlainTextZLoggerFormatter.FormatLogEntry (System.Buffers.IBufferWriter`1[T] writer, ZLogger.IZLoggerEntry entry) (at <61b75ff0c191453e98b32a9064ca1468>:0)
ZLogger.ZLoggerEntry`1[TState].FormatUtf8 (System.Buffers.IBufferWriter`1[T] writer, ZLogger.IZLoggerFormatter formatter) (at <61b75ff0c191453e98b32a9064ca1468>:0)
ZLogger.AsyncStreamLineMessageWriter.WriteLoop () (at <61b75ff0c191453e98b32a9064ca1468>:0)
UnityEngine.Debug:LogException(Exception)
ZLogger.<WriteLoop>d__14:MoveNext()
System.Threading._ThreadPoolWaitCallback:PerformWaitCallback()```