Array passed as template argument leads to incorrect log message

[MarcusKohnert]

The statement ... logger.Logger.TimeOperation("Test {Identifier}", new object[] { "a", "b" });

... leads to the following incorrect log message: Test a b in "completed" ms

Expected log message: Test ["a", "b"] "completed" in 42.42 ms

[nblumhardt]

Thanks for the note!

Is the incorrect example above precisely what you get from the logger? I would expect (having seen this kind of problem before :-)) that the message should look like:

Test "a" "b" in "completed" ms

...or something along those lines.

[nblumhardt]

Serilog has special handling for object[] because it ends up binding as the params rather than a single item, but I suspect Timings doesn't replicate this. We may need to do the same dynamic type check and patch-up job that Serilog does...

[MarcusKohnert]

You are right. The incorrect message I get contains quotation marks.

So if there are two elements in the array I'll get: Test "a" "b" in "completed" ms

If there are three elements I'll even get: Test "a" "b" in "c" ms

Which makes sense to me.

The PR #25 contains a test case for playing around. https://github.com/nblumhardt/serilog-timings/pull/25/files#diff-225f706e993b9489f69f94757add786b

[nblumhardt]

The problem is that a literal object[] is bound as the single params argument, rather than being the first element itself within an outer params array. It's unfortunately a perennial problem when using the params keyword, and comes in a few variants.

You can work around it with:

logger.Logger.TimeOperation("Test {Identifier}", new object[] { new object[] { "a", "b" } });

I don't think there's much we can do directly in this library to fix it; the proposed fix in #25 will fail on multi-parameter templates like this, I think:

logger.Logger.TimeOperation("Test {A} then {B}", "a", "b");

[MarcusKohnert]

You are right, of course. 😅 Thanks for the workaround. It fixes the issue.

[nblumhardt]

Thanks for the follow-up :-) 👍