Enricher is throwing System.InvalidCastException

videokojot commented 5 years ago

Issue Description

When we enabled Serilog.SelfDebug we found out that enricher is throwing exceptions like this:

System.InvalidCastException: Unable to cast object of type 'Serilog.Events.SequenceValue' to type 'Serilog.Events.ScalarValue'.
   at Serilog.Capturing.PropertyValueConverter.<TryConvertEnumerable>g__MapToDictionaryElements|14_0(IDictionary dictionaryEntries, Destructuring destructure)+MoveNext()
   at System.Linq.Enumerable.ToDictionary[TSource,TKey,TElement](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)
   at Serilog.Events.DictionaryValue..ctor(IEnumerable`1 elements)
   at Serilog.Capturing.PropertyValueConverter.TryConvertEnumerable(Object value, Destructuring destructuring, Type valueType, LogEventPropertyValue& result)
   at Serilog.Capturing.PropertyValueConverter.CreatePropertyValue(Object value, Destructuring destructuring, Int32 depth)
   at Serilog.Capturing.MessageTemplateProcessor.CreateProperty(String name, Object value, Boolean destructureObjects)

Version `Serilog.Exceptions` NuGet package?

5.3.1

RehanSaeed commented 5 years ago

Labelled as a bug. Would be willing to take a PR for this.

krajek commented 5 years ago

@videokojot could you please provide an example following principles described here: https://stackoverflow.com/help/minimal-reproducible-example ? If I could have such example I could easily fix the problem.

Why do you think it is Serilog.Exceptions throwing the exception? Nothing in the call stack suggests that, doesn't it?

videokojot commented 5 years ago

@krajek @RehanSaeed Thanks for looking into this. We are using ExceptionEnricher wrapped inside our exception sanitizer - which overwrite sensitive fields (marked with notlogged attribute) and will set those to null.

Cannot reproduce locally as the it is caused only by multiple exceptions, and I have only logs from the cloud. This is our enricher wrapper:

using Serilog.Core;
using Serilog.Events;
using Serilog.Exceptions.Core;
using System;
using System.Collections.Generic;
using System.Reflection;
using Serilog;

namespace szdxcfgv
{
    public class ExceptionSanitizerEnricher : ILogEventEnricher
    {
        private readonly ExceptionEnricher _exceptionEnricher;
        private IDestructuringOptions _destructuringOptions;
        private readonly bool _destructureExceptions;
        private MethodInfo _destructureExceptionMethod;

        public ExceptionSanitizerEnricher(IDestructuringOptions destructuringOptions, bool destructureExceptions)
        {
            _exceptionEnricher = new ExceptionEnricher(destructuringOptions);
            _destructuringOptions = destructuringOptions;
            _destructureExceptions = destructureExceptions;
            _destructureExceptionMethod = _exceptionEnricher.GetType().GetMethod("DestructureException", BindingFlags.NonPublic | BindingFlags.Instance);

            // Method signature: private IReadOnlyDictionary<string, object> DestructureException(Exception exception)
        }

        public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
        {
            if (logEvent == null)
            {
                throw new ArgumentNullException(nameof(logEvent));
            }

            if (propertyFactory == null)
            {
                throw new ArgumentNullException(nameof(propertyFactory));
            }

            if (logEvent.Exception != null)
            {
                try
                {
                    // this will erase fields marked as NotLogged
                    var sanitizedException = SanitizeException(logEvent.Exception);

                    if (_destructureExceptions)
                    {
                        var destructuredException = _destructureExceptionMethod.Invoke(_exceptionEnricher, new[] { sanitizedException });
                        var logEventProperty = propertyFactory.CreateProperty(_destructuringOptions.RootName, destructuredException, true);
                        logEvent.AddPropertyIfAbsent(logEventProperty);
                    }
                }
                catch (Exception e)
                {
                    Log.Logger.Fatal("Exception enricher failed: {EnricherException}. \nCaused by {CausedByException}", e.ToString(), logEvent.Exception.ToString());
                }
            }
        }
    }
}

krajek commented 5 years ago

@videokojot please take a look at the following code from Serilog's codebase:

https://github.com/serilog/serilog/blob/a1e9850db854cc43b2d2fff29eeb38cb1a93341b/src/Serilog/Cap turing/PropertyValueConverter.cs#L206

They clearly state that:

 // Only dictionaries with 'scalar' keys are permitted, as
 // more complex keys may not serialize to unique values for
 // representation in sinks.

My best guess is that you have an exception that contains a dictionary with a non-scalar key. Is this possible?

Later I will try to reproduce such behavior.

videokojot commented 5 years ago

@krajek thanks for quick response. That is possible.

Since ExceptionEnricher is designed to destructure abritrary exceptions so I thought it should handle this case (do not destructure those properties etc). Currently it clutters the SerilogSelfLog so we cannot see other problems.

Do not want to add filtering for every exception that could cause this, as that can be almost any exception type. Do you have some ideas how we can overcome this?

krajek commented 5 years ago

@videokojot I tried to reproduce the problem but I could not find any fault in Serilog.Exception itself. Dictionary keys are always stringified with .ToString(), so it seems like there is no way that collection would make it into a key of the dictionary.

I used following test:

public class ExceptionWithDictNonScalarKey : Exception
{
    public Dictionary<IEnumerable<int>, object> Reference { get; set; }
}

[Fact]
public void WhenExceptionContainsDictionaryWithNonScalarValue_ShouldNotThrow()
{
    // Arrange
    var exception = new ExceptionWithDictNonScalarKey()
    {
        Reference = new Dictionary<IEnumerable<int>, object>()
        {
            { new List<int>() { 1, 2, 3 }, "VALUE" }
        }
    };

    // Act
    var result = LogAndDestructureException(exception, new DestructuringOptionsBuilder());

    // Assert

}

@videokojot could you provide the code for the exception that you imagine could cause the problem?

@RehanSaeed any ideas?

RehanSaeed commented 5 years ago

It would be very helpful if we had an example or repro that could recreate this exception. Without it, it's difficult to diagnose and fix.

krajek commented 5 years ago

@RehanSaeed without any other proof my current best guess is that there is no fault in Serilog.Exceptions itself. I propose to close this one.

RehanSaeed commented 5 years ago

Feel free to reopen if you have more information!

videokojot commented 5 years ago

@krajek @RehanSaeed Hi guys, sorry for late response. I digged into logs and found three exception types which caused the Serilog.Exceptions to fail:

System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'System.Net.Sockets.NetworkStream'.
   at System.Net.Sockets.NetworkStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Security.SslStreamInternal.SslWriteAsync.WriteAsync(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Security.SslStreamInternal.WriteSingleChunk[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStreamInternal.WriteAsyncInternal[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)
   at System.Net.Security.SslStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnection.WriteToStreamAsync(ReadOnlyMemory`1 source)
   at System.Net.Http.HttpConnection.WriteWithoutBufferingAsync(ReadOnlyMemory`1 source)
   at System.Net.Http.HttpConnection.RawConnectionStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.SendFrameFallbackAsync(MessageOpcode opcode, Boolean endOfMessage, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.SendFrameFallbackAsync(MessageOpcode opcode, Boolean endOfMessage, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.SendCloseFrameAsync(WebSocketCloseStatus closeStatus, String closeStatusDescription, CancellationToken cancellationToken)

System.Net.WebSockets.WebSocketException (1342883672): The remote party closed the WebSocket connection without completing the close handshake. ---> System.ObjectDisposedException: Cannot access a disposed object. Object name: 'System.Net.Sockets.NetworkStream'.    at System.Net.Sockets.NetworkStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)    at System.Net.Security.SslStreamInternal.SslWriteAsync.WriteAsync(Byte[] buffer, Int32 offset, Int32 count)    at System.Net.Security.SslStreamInternal.WriteSingleChunk[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)    at System.Net.Security.SslStreamInternal.WriteAsyncInternal[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)    at System.Net.Security.SslStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)    at System.Net.Http.HttpConnection.WriteToStreamAsync(ReadOnlyMemory`1 source)    at System.Net.Http.HttpConnection.WriteWithoutBufferingAsync(ReadOnlyMemory`1 source)    at System.Net.Http.HttpConnection.RawConnectionStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)    at System.Net.WebSockets.ManagedWebSocket.SendFrameFallbackAsync(MessageOpcode opcode, Boolean endOfMessage, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)    at System.Net.WebSockets.ManagedWebSocket.SendFrameFallbackAsync(MessageOpcode opcode, Boolean endOfMessage, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)    at System.Net.WebSockets.ManagedWebSocket.SendCloseFrameAsync(WebSocketCloseStatus closeStatus, String closeStatusDescription, CancellationToken cancellationToken)

System.Net.WebSockets.WebSocketException (2): The remote party closed the WebSocket connection without completing the close handshake. ---> System.ObjectDisposedException: Cannot access a disposed object. Object name: 'System.Net.Sockets.NetworkStream'.    at System.Net.Sockets.NetworkStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)    at System.Net.Security.SslStreamInternal.SslWriteAsync.WriteAsync(Byte[] buffer, Int32 offset, Int32 count)    at System.Net.Security.SslStreamInternal.WriteSingleChunk[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)    at System.Net.Security.SslStreamInternal.WriteAsyncInternal[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)    at System.Net.Security.SslStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)    at System.Net.Http.HttpConnection.WriteToStreamAsync(ReadOnlyMemory`1 source)    at System.Net.Http.HttpConnection.WriteWithoutBufferingAsync(ReadOnlyMemory`1 source)    at System.Net.Http.HttpConnection.RawConnectionStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)    at System.Net.WebSockets.ManagedWebSocket.SendFrameFallbackAsync(MessageOpcode opcode, Boolean endOfMessage, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)    at System.Net.WebSockets.ManagedWebSocket.SendFrameFallbackAsync(MessageOpcode opcode, Boolean endOfMessage, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)    at System.Net.WebSockets.ManagedWebSocket.SendCloseFrameAsync(WebSocketCloseStatus closeStatus, String closeStatusDescription, CancellationToken cancellationToken)

krajek commented 5 years ago

@videokojot could you provide a minimal reproducible example? I do not understand how logs you provided convinced you it is a Serilog.Exceptions fault.

videokojot commented 5 years ago

@krajek well if you check the code I posted before, you can see that in our enricher wrapper we are using the code from actual Serilog,Exceptions. See ExceptionEnricher.cs (lines 53-72).

Here we are catching enricher exception and logging it. I am posting the code again with comments:

...
                catch (Exception e)
                {
                    //  here we catch the any exception (either from Sanitizer or exception destructuring etc)
                   //  we also log which exception caused the fail of the enricher
                    Log.Logger.Fatal("Exception enricher failed: {EnricherException}. \nCaused by {CausedByException}", e.ToString(), logEvent.Exception.ToString());
                }
...

then in the logs I can see following raw json (line numbers updated, namespace names readcted etc):

{
  "_index": "logstash-2019.10.02",
  "_type": "doc",
  "_id": "bog8i20B5pQFLwJBZU_x",
  "_version": 1,
  "_score": null,
  "_source": {
    "@version": "1",
    "EnricherExceptionStackTrace": "   at Serilog.Capturing.PropertyValueConverter.<TryConvertEnumerable>g__MapToDictionaryElements|14_0(IDictionary dictionaryEntries, Destructuring destructure)+MoveNext()\n   at System.Linq.Enumerable.ToDictionary[TSource,TKey,TElement](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)\n   at Serilog.Events.DictionaryValue..ctor(IEnumerable`1 elements)\n   at Serilog.Capturing.PropertyValueConverter.TryConvertEnumerable(Object value, Destructuring destructuring, Type valueType, LogEventPropertyValue& result)\n   at Serilog.Capturing.PropertyValueConverter.CreatePropertyValue(Object value, Destructuring destructuring, Int32 depth)\n   at Serilog.Capturing.MessageTemplateProcessor.CreateProperty(String name, Object value, Boolean destructureObjects)\n   at AppCommon.Core.Logging.ExceptionSanitizerEnricher.Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) in /app/Logging/ExceptionSanitizerEnricher.cs:line 50",
    "@m": "Exception enricher failed: ....",
    "CausedByException": "System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.ObjectDisposedException: Cannot access a disposed object.\nObject name: 'System.Net.Sockets.NetworkStream'.\n   at System.Net.Sockets.NetworkStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)\n   at System.Net.Security.SslStreamInternal.SslWriteAsync.WriteAsync(Byte[] buffer, Int32 offset, Int32 count)\n   at System.Net.Security.SslStreamInternal.WriteSingleChunk[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)\n   at System.Net.Security.SslStreamInternal.WriteAsyncInternal[TWriteAdapter](TWriteAdapter writeAdapter, ReadOnlyMemory`1 buffer)\n   at System.Net.Security.SslStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)\n   at System.Net.Http.HttpConnection.WriteToStreamAsync(ReadOnlyMemory`1 source)\n   at System.Net.Http.HttpConnection.WriteWithoutBufferingAsync(ReadOnlyMemory`1 source)\n   at System.Net.Http.HttpConnection.RawConnectionStream.WriteAsync(ReadOnlyMemory`1 buffer, CancellationToken cancellationToken)\n   at System.Net.WebSockets.ManagedWebSocket.SendFrameFallbackAsync(MessageOpcode opcode, Boolean endOfMessage, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)\n   at System.Net.WebSockets.ManagedWebSocket.SendFrameFallbackAsync(MessageOpcode opcode, Boolean endOfMessage, ReadOnlyMemory`1 payloadBuffer, CancellationToken cancellationToken)\n   at System.Net.WebSockets.ManagedWebSocket.SendCloseFrameAsync(WebSocketCloseStatus closeStatus, String closeStatusDescription, CancellationToken cancellationToken)\n   at AppBusiness.App.Common.WebSockets.General.AppChannelRunner.StopEverythingSafely(Boolean omitDisposing) in /app/AppBusiness.App/Common/WebSockets/General/AppChannelRunner.cs:line 361",
    "@timestamp": "2019-10-02T06:50:54.218Z",
    "@t": "2019-10-02T06:50:53.8859594Z",
    "InstanceId": "a89307aa-3333-419f-8436-fa427dc97331",
    "EnricherException": "System.InvalidCastException: Unable to cast object of type 'Serilog.Events.SequenceValue' to type 'Serilog.Events.ScalarValue'.\n   at Serilog.Capturing.PropertyValueConverter.<TryConvertEnumerable>g__MapToDictionaryElements|14_0(IDictionary dictionaryEntries, Destructuring destructure)+MoveNext()\n   at System.Linq.Enumerable.ToDictionary[TSource,TKey,TElement](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)\n   at Serilog.Events.DictionaryValue..ctor(IEnumerable`1 elements)\n   at Serilog.Capturing.PropertyValueConverter.TryConvertEnumerable(Object value, Destructuring destructuring, Type valueType, LogEventPropertyValue& result)\n   at Serilog.Capturing.PropertyValueConverter.CreatePropertyValue(Object value, Destructuring destructuring, Int32 depth)\n   at Serilog.Capturing.MessageTemplateProcessor.CreateProperty(String name, Object value, Boolean destructureObjects)\n   at AppCommon.Core.Logging.ExceptionSanitizerEnricher.Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory) in /app/AppCommon.Core/Logging/ExceptionSanitizerEnricher.cs:line 50"
  },
  "fields": {
    "@timestamp": [
      "2019-10-02T06:50:54.218Z"
    ],
    "@t": [
      "2019-10-02T06:50:53.885Z"
    ]
  },
  "sort": [
    1569999053885
  ]
}

which means that the exception actually came from this line:

var logEventProperty = propertyFactory.CreateProperty(_destructuringOptions.RootName, destructuredException, true);

which is same code as in Serilog.Extensions in ExceptionEnricher.cs on line 67.

If there would not be the wrapper around the enricher, then this exception would end up in the SerilogSelfDebug log and clutter it.

krajek commented 5 years ago

I agree that it seems that there is a possible fault in our code. However, I could not find the problem by reviewing the code, and by trying to reproduce it on my own in our automatic tests.

Could you please provide an example following the principles described here: https://stackoverflow.com/help/minimal-reproducible-example ? If I could have such example I could easily fix the problem.

videokojot commented 5 years ago

Hi, unfortunately I am not able to reproduce when running the application locally with debugger attached (hence I cannot create the minimal repro example),

Possible reasons I cant reproduce locally:

locally I am running on Windows, while in the cloud it runs on Linux docker (so the WebSocket exception can have some different internals, which then are failing the serialization), thinking about that deep reflection inside Serilog.Extensions...
it may take a while to produce such bad exception and maybe I was not lucky
maybe the bad exceptions are produced when system is under big load and I cannot create such conditions locally?

Anyway thanks for your extension - I will keep an eye on this and if I will find anything more I will post it there.

krajek commented 5 years ago

Thanks for more information. I will try my luck and create some tests with ObjectDisposedException.

The other thing that came to my mind is to create a PR in Serilog itself, that would gently fall back to any other behavior than crashing with "Unable to cast object of type 'Serilog.Events.SequenceValue' to type 'Serilog.Events.ScalarValue'."

As a last resort, I will try to employ the property-based testing approach to generate lots of exception classes of different shapes and see if we will fail at any.

All the ideas will take some time, so let's keep this open for a month.

videokojot commented 5 years ago

Ok, thank you very much for your effort.

RehanSaeed commented 3 years ago

Any movement on this?

krajek commented 3 years ago

It has been two years. I recall I have not been able to reproduce this problem. Let's close.

RehanSaeed / Serilog.Exceptions