benaadams / Ben.Demystifier

High performance understanding for stack traces (Make error logs more productive)
Apache License 2.0
2.76k stars 118 forks source link

Demystified stack trace is slightly more confusing... it eliminates a line that my code is actually calling. #217

Open LorneCash opened 1 year ago

LorneCash commented 1 year ago

This stack trace:

{
  ActionException: {
    Type: ObjectDisposedException,
    Message: Cannot access a disposed object.,
    ObjectName: ,
    StackTrace:
at System.Threading.TimerQueueTimer.Change(UInt32 dueTime, UInt32 period)
at System.Threading.Timer.Change(Int64 dueTime, Int64 period)
at System.Threading.Timer.Change(TimeSpan dueTime, TimeSpan period)
at Nied.Logging.Test.Methods.ExampleException()
at Nied.Utility.Get.ActionException(Action action)
  }
}

Is Demystified to this:

{
  ActionException: {
    Type: ObjectDisposedException,
    Message: Cannot access a disposed object.,
    ObjectName: ,
    StackTrace:
at bool System.Threading.TimerQueueTimer.Change(uint dueTime, uint period)
at bool System.Threading.Timer.Change(long dueTime, long period)
at void Nied.Logging.Test.Methods.ExampleException()
at Exception Nied.Utility.Get.ActionException(Action action)
  }
}

But the actual code is this:

internal static void ExampleException()
{
    var test = new Timer(_ => { });
    test.Dispose();
    test.Change(TimeSpan.Zero, TimeSpan.Zero);
}

So the Demystified full stack trace should be this:

  ActionException: {
    Type: ObjectDisposedException,
    Message: Cannot access a disposed object.,
    ObjectName: ,
    StackTrace:
at bool System.Threading.TimerQueueTimer.Change(uint dueTime, uint period)
at bool System.Threading.Timer.Change(long dueTime, long period)
at bool System.Threading.Timer.Change(TimeSpan dueTime, TimeSpan period)
at void Nied.Logging.Test.Methods.ExampleException()
at Exception Nied.Utility.Get.ActionException(Action action)
  }

OR if the overloads are eliminated, the Demystified stack trace could possibly be simplified to this:

  ActionException: {
    Type: ObjectDisposedException,
    Message: Cannot access a disposed object.,
    ObjectName: ,
    StackTrace:
at bool System.Threading.TimerQueueTimer.Change(uint dueTime, uint period)
at bool System.Threading.Timer.Change(TimeSpan dueTime, TimeSpan period)
at void Nied.Logging.Test.Methods.ExampleException()
at Exception Nied.Utility.Get.ActionException(Action action)
  }

Here's my thoughts: You can see from the ExampleException() code provided that it does actually call the overload with two TimeSpan parameters and not the one with two long parameters. I'm assuming that behind the scenes it's an overload so maybe the intent was to only show the stack of the overload that was actually called and not all the overload methods for simplification in understanding especially when it's not my code. That makes sense to me but its keeping the last overload called not the first one which is the one that's actually called in my code and that makes it confusing when investigating the stack trace.

TLDR It's either missing the line: at bool System.Threading.Timer.Change(TimeSpan dueTime, TimeSpan period)

or it included the wrong one. This one: at bool System.Threading.Timer.Change(long dueTime, long period)