Issue Deion When we enabled Serilog.SelfDebug we found out t

<a class="user-mention notranslate" data-hovercard-type="user" data-hovercard-url="/us

Enricher is throwing System.InvalidCastException,about rehansaeed/serilog.exceptions

Comments (18)

RehanSaeed commented on May 30, 2024

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

from serilog.exceptions.

krajek commented on May 30, 2024

@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?

from serilog.exceptions.

videokojot commented on May 30, 2024

@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());
                }
            }
        }
    }
}

from serilog.exceptions.

krajek commented on May 30, 2024

@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.

from serilog.exceptions.

videokojot commented on May 30, 2024

@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?

from serilog.exceptions.

krajek commented on May 30, 2024

@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?

from serilog.exceptions.

RehanSaeed commented on May 30, 2024

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.

from serilog.exceptions.

krajek commented on May 30, 2024

@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.

from serilog.exceptions.

RehanSaeed commented on May 30, 2024

Feel free to reopen if you have more information!

from serilog.exceptions.

videokojot commented on May 30, 2024

@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)

from serilog.exceptions.

krajek commented on May 30, 2024

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

from serilog.exceptions.

videokojot commented on May 30, 2024

@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.

from serilog.exceptions.

krajek commented on May 30, 2024

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.

from serilog.exceptions.

videokojot commented on May 30, 2024

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.

from serilog.exceptions.

krajek commented on May 30, 2024

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.

from serilog.exceptions.

videokojot commented on May 30, 2024

Ok, thank you very much for your effort.

from serilog.exceptions.

RehanSaeed commented on May 30, 2024

Any movement on this?

from serilog.exceptions.

krajek commented on May 30, 2024

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

from serilog.exceptions.

Enricher is throwing System.InvalidCastException about serilog.exceptions HOT 18 CLOSED

Comments (18)

Related Issues (20)

Recommend Projects

React

Vue.js

Typescript

TensorFlow

Django

Laravel

D3

Recommend Topics

javascript

web

server

Machine learning

Visualization

Game

Recommend Org

Facebook

Microsoft

Google

Alibaba

D3

Tencent