Timeout exceptions are unable to be grouped due to variables not being in quotes or parentheses

[a-teece]

The general accepted behaviour in a well written Exception in .net seems to be to enclose parameters in []. This allows logging frameworks to extract the variables and group identical messages togehter.

A common example of this is the DataDog platform that tries to group the same exception for issue tracking.

The StackExchange.Redis library breaks this capability by including a large number of parameters in the Timeout (and other exceptions I suspect), but without encapsulating the parameters, leading to 1000s of unique errors/issues.

For example the exception in #3029 is currently:
Timeout awaiting response (outbound=0KiB, inbound=0KiB, 6500ms elapsed, timeout is 5000ms), command=GET, next: SET 2700758, inst: 0, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 371, last-in: 2, cur-in: 0, sync-ops: 1, async-ops: 363, serverEndpoint: 20.198.145.151:8501, conn-sec: 80376.19, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: f1fd87ec2fb3(SE.Redis-v2.10.1.65101), PerfCounterHelperkeyHashSlot: 6029, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=20,Free=32747,Min=2,Max=32767), POOL: (Threads=20,QueuedItems=69,CompletedItems=1218359,Timers=36), v: 2.10.1.65101 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)

But I would expect it to be:
Timeout awaiting response (outbound=[0]KiB, inbound=[0]KiB, [6500]ms elapsed, timeout is [5000]ms), command=[GET], next: [SET] [2700758], inst: [0], qu: [0], qs: [0], aw: [False], bw: [SpinningDown], rs: [ReadAsync], ws: [Idle], in: [371], last-in: [2], cur-in: [0], sync-ops: [1], async-ops: [363], serverEndpoint: [20.198.145.151:8501], conn-sec: [80376.19], aoc: [0], mc: [1/1/0], mgr: [10 of 10] available, clientName: [f1fd87ec2fb3(SE.Redis-v2.10.1.65101)], PerfCounterHelperkeyHashSlot: [6029], IOCP: (Busy=[0],Free=[1000],Min=[1],Max=[1000]), WORKER: (Busy=[20],Free=[32747],Min=[2],Max=[32767]), POOL: (Threads=[20],QueuedItems=[69],CompletedItems=[1218359],Timers=[36]), v: [2.10.1.65101] (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)

As a shortcut it would solve the problem by just wrapping all the data in a single pair of [], but that doesn't feel like in-keeping with .net Exception guidelines:

Timeout awaiting response [(outbound=0KiB, inbound=0KiB, 6500ms elapsed, timeout is 5000ms), command=GET, next: SET 2700758, inst: 0, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 371, last-in: 2, cur-in: 0, sync-ops: 1, async-ops: 363, serverEndpoint: 20.198.145.151:8501, conn-sec: 80376.19, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: f1fd87ec2fb3(SE.Redis-v2.10.1.65101), PerfCounterHelperkeyHashSlot: 6029, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=20,Free=32747,Min=2,Max=32767), POOL: (Threads=20,QueuedItems=69,CompletedItems=1218359,Timers=36), v: 2.10.1.65101 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)]

[mgravell]

The general accepted behaviour in a well written Exception in .net seems to be to enclose parameters in [].

I'm... not sure that's a thing at all. Citation?

Happy to try and discuss options here, but note we're already using .Data to duplicate much of this data, and substring filtering should make this fairly trivial.

[wipiano]

I think you can customize Datadog's error grouping by setting the error.fingerprint span tag in your application code, without requiring any library changes. See: https://docs.datadoghq.com/tracing/error_tracking/error_grouping/

[a-teece]

@wipiano Thanks for the suggestion. I am looking at fingerprinting, however I dont think it will work in our scenario because the problematic code path is:
AspNet --> Microsoft Rate Limiting Middleware --> 3rd Party Package --> StackExchange.Redis --> Redis

So getting into that codepath to instrument the OTel span with a fingerprint isn't easy - probably not impossible though

[a-teece]

@mgravell I think your challenge is entirely reasonable, and I significantly overstated my point by describing this as “generally accepted behaviour”. I also incorrectly referred to square brackets rather than single quotes.

That said, I still stand by the underlying principle of my argument. Exception messages from this library are not especially friendly for typical log parsers, whereas many examples set by Microsoft throughout the core .NET framework — including from its earliest days — separate metadata from prose using single quotes.

For reference, I would cite examples from the .NET source itself:

Very old:
https://github.com/dotnet/runtime/blob/main/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx

More recent:
https://github.com/dotnet/runtime/blob/main/src/libraries/System.Text.Json/src/Resources/Strings.resx

These examples are not completely consistent. If you search for [space]{0}, you will find cases without delimiters. However, particularly in the more recent example, searching for '{0}' returns significantly more matches.

So I still propose improving this to make log parsing simpler for third-party tools, while also apologising for overstating the standards-based justification for my argument.

[a-teece]

Another example, perhapse closer to this library is the MS SqlClient https://github.com/dotnet/SqlClient/blob/main/src/Microsoft.Data.SqlClient/src/Resources/Strings.resx

An interesting example in this is:

A {0} with {1} '{2}' is not contained by this {3}.

Which mixes both quoted and unquoted variables - this suggests to me there is a design-guide somewhere even though I cannot cite it. I suspect there is thinking about which variables change per code-path vs per execution of code path. Only the latter should be delimited.

Applying that logic to the Redis Timeout exception above I'd suggest data such as the "outbound=0KiB, inbound=0KiB, 6500ms elapsed, timeout is 5000ms" is all quoted, but command=GET is not quoted.

If this were to move forward, and with per-variable decisions as to what is vs is not quoted then a clear design-guide for exception variables would be required first.