BackchannelAuthenticationRequestValidator inserts an unwanted string format item when calling LogError

[Hoddikr]

Which version of Duende IdentityServer are you using?

6.2.3

Which version of .NET are you using?

.NET 6

Describe the bug

BackchannelAuthenticationRequestValidator calls LogError with a string format item which results in an exception when LogWithRequestDetails is called.

A permalink directly to the line that causes the error:
https://github.com/DuendeSoftware/IdentityServer/blob/d933a168074d7248226241acd1b96d1910baf8bd/src/IdentityServer/Validation/Default/BackchannelAuthenticationRequestValidator.cs#LL410C9-L410C9

To Reproduce

Implement IBackchannelAuthenticationUserValidator and make a ciba request that results in any Error value that is not one of the below:

• OidcConstants.BackchannelAuthenticationRequestErrors.AccessDenied
• OidcConstants.BackchannelAuthenticationRequestErrors.ExpiredLoginHintToken
• OidcConstants.BackchannelAuthenticationRequestErrors.UnknownUserId
• OidcConstants.BackchannelAuthenticationRequestErrors.MissingUserCode
• OidcConstants.BackchannelAuthenticationRequestErrors.InvalidUserCode
• OidcConstants.BackchannelAuthenticationRequestErrors.InvalidBindingMessage

Actual behavior

LogError calls LogWithRequestDetails with the string format item "{error}" within the message which will result in the following error being logged:

Error logging An error occurred while writing to logger(s). (Index (zero based) must be greater than or equal to zero and less than the size of the argument list.), request details: 

Expected behavior

LogError logs the error with the Error value from BackchannelAuthenticationUserValidationResult.Error :

Unexpected error from IBackchannelAuthenticationUserValidator: <The error returned from the implementation of IBackchannelAuthenticationUserValidator.ValidateRequestAsync> 

Additional context

This arises when we have an implementation of IBackchannelAuthenticationUserValidator where ValidateRequestAsync populates the field BackchannelAuthenticationUserValidationResult.Error with a value that is not one of the below:

• OidcConstants.BackchannelAuthenticationRequestErrors.AccessDenied
• OidcConstants.BackchannelAuthenticationRequestErrors.ExpiredLoginHintToken
• OidcConstants.BackchannelAuthenticationRequestErrors.UnknownUserId
• OidcConstants.BackchannelAuthenticationRequestErrors.MissingUserCode
• OidcConstants.BackchannelAuthenticationRequestErrors.InvalidUserCode
• OidcConstants.BackchannelAuthenticationRequestErrors.InvalidBindingMessage

This does not cause any actual errors or unexpected behavior in the ciba flow itself, but the error logs do not log the expected errors because of the additional string format item.

[josephdecock]

Thanks for this bug report. I haven't been able to reproduce exactly the same behavior, but I suspect that the differences I'm seeing come from implementation details of the logging provider. I'm using Serilog, and what I see in my testing is that the bad log messages are simply discarded rather than getting an error written to the log. I have a fix in progress that looks like it resolves the issue.

Can you give us a sense of how often these bad log messages are showing up, and how much of an impact this is having for you? Also, which log provider are you using?

[Hoddikr]

Hi Joseph,

Thank you for taking a look at this issue. I'll address each of the questions you had for us below:

1. Can you give us a sense of how often these bad log messages are showing up?
It's not extremely common, but roughly 220 occurrences every 24h.

2. How much of an impact is this having for you?
this is not causing any actual errors in our environment but it mainly adds noise to the logs we are monitoring.

3. Which log provider are you using?
We are logging to Elastic using the ECS. The ECS logger implementation itself is maintained in-house, so it is possible that the bad error message is not being discarded in that implementation but rather thrown as an exception.

Let me know if there's anything else you need from us :)

[brockallen]

@Hoddikr please have a look at the PR to see if you feel that will address your issue. Thanks

[Hoddikr]

@brockallen @josephdecock Looks like this should do it, thanks.

[brockallen]

@Hoddikr Are you requesting that we patch this on 6.2.x, or are you ok waiting for 7.0?

[Hoddikr]

@brockallen 7.0 would be OK.