Identityserver4: Logging error "Index was outside the bounds of the array"

[jasonycw]

Issue / Steps to reproduce the problem

We just upgraded IdentityServer to 2.5.0
When we return InvalidGrant from our custom ResourceOwnerPasswordValidator, TokenRequestValidator will throw exception from here

https://github.com/IdentityServer/IdentityServer4/blob/d942a4fc80a36f97e5765dd6175c79a2f370db3d/src/IdentityServer4/src/Validation/Default/TokenRequestValidator.cs#L789-L792

Relevant parts of the log file

{
    "Timestamp": "2019-07-26T06:21:41.0526930+00:00",
    "Level": "Error",
    "MessageTemplate": "Error logging Index was outside the bounds of the array., request details: {@details}",
    "exception": "Index was outside the bounds of the array.",
    "details": {
        "ClientId": "Api",
        "ClientName": null,
        "GrantType": "password",
        "Scopes": "Api offline_access",
        "AuthorizationCode": null,
        "RefreshToken": null,
        "UserName": "[email protected]",
        "AuthenticationContextReferenceClasses": null,
        "Tenant": null,
        "IdP": null,
        "Raw": {
            "PasswordType": "user_password",
            "grant_type": "password",
            "username": "[email protected]",
            "password": "***REDACTED***", //Invalid password
            "scope": "Api offline_access",
            "client_id": "Api",
            "client_secret": "***REDACTED***"
        },
        "$type": "TokenRequestValidationLog"
    },
    "SourceContext": "IdentityServer4.Validation.TokenRequestValidator",
    "RequestId": "0HLOHI5ISU29O:00000001",
    "RequestPath": "/connect/token",
    "Application": "IdentityApi.Application",
    "ServerName": "85ad6b6b6e72",
    "Url": "http://identity.corp-prd.vpc/connect/token",
    "QueryString": "",
    "Method": "POST",
    "UserAgent": "",
    "X-Forwarded-For": "172.31.11.32"
}

Can confirm the same issue is not happening when using 2.4.0

[jasonycw]

My guess is related to this change https://github.com/IdentityServer/IdentityServer4/commit/a4748a7211a001d826838cf5fe59d1c7f6b56711

This changed the Error
https://github.com/IdentityServer/IdentityServer4/blob/a4748a7211a001d826838cf5fe59d1c7f6b56711/src/IdentityServer4/src/Validation/Default/TokenRequestValidator.cs#L418-L420

And then this log cause the exception
https://github.com/IdentityServer/IdentityServer4/blob/a4748a7211a001d826838cf5fe59d1c7f6b56711/src/IdentityServer4/src/Validation/Default/TokenRequestValidator.cs#L436

---

Our ResourceOwnerPasswordValidator
is returning this as the context.Result
C# context.Result = new GrantValidationResult( TokenRequestErrors.InvalidGrant, "The specified username or password is incorrect.");

[jasonycw]

I pulled IdentityServer4 2.5.0 tag and run the code directly

``` C#
message = "User authentication failed: {error}";
logLevel = Information;
values = "The specified username or password is incorrect.";

The log message `message + "{@values}, details: {@details}"` become `"User authentication failed: {error}{@values}, details: {@details}"`
`error`, `values`, `details` are needed for the string format, but there are only **2** args

Call stack shows it is caused by this line
https://github.com/IdentityServer/IdentityServer4/blob/a4748a7211a001d826838cf5fe59d1c7f6b56711/src/IdentityServer4/src/Validation/Default/TokenRequestValidator.cs#L436
``` C#
errorDescription = "The specified username or password is incorrect.";
resourceOwnerContext.Result.Error = invalid_grant;

In 2.4.0, that line was not using LogInformation, but using ILogger directly
https://github.com/IdentityServer/IdentityServer4/blob/44651bea9b02c992902639b21205f433aad47d03/src/IdentityServer4/src/Validation/Default/TokenRequestValidator.cs#L432

[leastprivilege]

OK. Thanks. Do you want to send a PR to fix it?

[jasonycw]

@leastprivilege you prefer changing that line back to _logger or any specific suggestion for code consistency?
If you cool with waiting a few days, I will have a look after finishing some other works.

[jasonycw]

PR is created https://github.com/IdentityServer/IdentityServer4/pull/3494

I didn't change it back to _logger, instead I just leave the LogInformation to do the mapping, I think that what the original commit intended to do.

[leastprivilege]

Thanks. I totally missed this this morning and published a 2.5.1 :(

Will do a 2.5.2 soon.

[mpyclikcorp]

Hmm... on Kestler from Ctrl+F5 it work fine. Problem is on IIS. Also wait for thix fix... 👍

[jasonycw]

@mpyclikbpsc it's not breaking bug, but it will generate a false error log every time a user authentication fail.

[mpyclikcorp]

@jasonycw Hmm... why not breaking??? I can't get token cause that... :(

[squizee]

So it will be added to 2.5.2 or not?

[leastprivilege]

yes

[lock[bot]]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.