IdentityServer / IdentityServer3

OpenID Connect Provider and OAuth 2.0 Authorization Server Framework for ASP.NET 4.x/Katana
https://identityserver.github.io/Documentation/
Apache License 2.0
2.02k stars 764 forks source link

Insufficient logging #3849

Open Peperud opened 6 years ago

Peperud commented 6 years ago

Question / Issue

If for whatever reason the openid scope is not in the allowed client scopes, all that shows in the log is below. No request data info or anything else searchable to correlate. Spend a lot of time chasing this across 6 different servers in 3 data centers. Thought I'm going mad or someone messed up with the reverse proxies...

Relevant parts of the log file

2017-09-07 13:51:22.819 -07:00 [Information] Start authorize request 2017-09-07 13:51:22.819 -07:00 [Information] Start authorize request protocol validation 2017-09-07 13:51:22.970 -07:00 [Error] Requested scope not allowed: "openid" 2017-09-07 13:51:22.970 -07:00 [Information] End authorize request

brockallen commented 6 years ago

Not enough info. We need your client and scope config.

Peperud commented 6 years ago

@brockallen

Not enough info. We need your client and scope config.

Not sure what the best way to provide is. Let's try this..

{
    "table": "clients",
    "rows":
    [
        {
            "Id": 156,
            "Enabled": 1,
            "ClientId": "redacted_xamarin.client",
            "ClientName": "Xamarin Test Client",
            "ClientUri": "redacted://xamarin.client/redirect",
            "LogoUri": null,
            "RequireConsent": 0,
            "AllowRememberConsent": 0,
            "Flow": 1,
            "AllowClientCredentialsOnly": 0,
            "LogoutUri": null,
            "LogoutSessionRequired": 0,
            "AllowAccessToAllScopes": 0,
            "IdentityTokenLifetime": 300,
            "AccessTokenLifetime": 3600,
            "AuthorizationCodeLifetime": 300,
            "AbsoluteRefreshTokenLifetime": 0,
            "SlidingRefreshTokenLifetime": 0,
            "RefreshTokenUsage": 0,
            "UpdateAccessTokenOnRefresh": 0,
            "RefreshTokenExpiration": 0,
            "AccessTokenType": 1,
            "EnableLocalLogin": 1,
            "IncludeJwtId": 0,
            "AlwaysSendClientClaims": 0,
            "PrefixClientClaims": 0,
            "AllowAccessToAllGrantTypes": 0,
            "AccessType": null,
            "ShowOnDashboard": 0,
            "RequireSignOutPrompt": 0,
            "AllowAccessTokensViaBrowser": 1,
        }
    ]
}
{
    "table": "scopes",
    "rows":
    [
        {
            "Id": 9,
            "Enabled": 1,
            "Name": "openid",
            "DisplayName": "openid",
            "Description": null,
            "Required": 0,
            "Emphasize": 0,
            "Type": 0,
            "IncludeAllClaimsForUser": 0,
            "ClaimsRule": null,
            "ShowInDiscoveryDocument": 0,
            "AllowUnrestrictedIntrospection": 0
        }
    ]
}

If I don't have the openid scope associated with the client then I get the "Requested scope not allowed" message as I should, However no request details get logged, which makes it difficult to match the failure to a particular request on a busy server.

ScopeValidation.cs

image

image

brockallen commented 6 years ago

I see, so you figured it out -- the openid scope was not allowed when it should be. Yea, this is a config error that ideally would have been discovered during dev time.

As for changes to the runetime, we're not making new enhancements at this time. Sorry.

Sounds like this is sorted out -- can we close?