Search code examples
asp.net-mvcasp.net-identityidentityserver3

IdentityServer3 not generating subject id when a user is logging in


In our company we use IdentityServer3 to authenticate and authorize all our ASP.NET MVC 5 apps. Since last week we are having issues with user autentication with some apps, sometimes it's the same app, some time it's another one. To be able to fix the login issue we need to restart IIS in which the app was deployed.

When an app fails, identity server does not generate SubjectId and SessionId values (looks after "Authorize request validation success" in the logs files)

When the apps fails to log in, this is identityserver's log:

w3wp.exe Information: 0 : 2017-12-26 11:01:40.495 -05:00 [Information] Start authorize request
w3wp.exe Information: 0 : 2017-12-26 11:01:40.495 -05:00 [Information] Start authorize request protocol validation
w3wp.exe Information: 0 : 2017-12-26 11:01:40.557 -05:00 [Information] "Authorize request validation success"
 "{
  \"ClientId\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
  \"ClientName\": \"Application 1\",
  \"RedirectUri\": \"http://server1/app1/\",
  \"AllowedRedirectUris\": [
    \"http://server1/app1/\"
  ],
  \"SubjectId\": \"unknown\",
  \"ResponseType\": \"id_token token\",
  \"ResponseMode\": \"form_post\",
  \"Flow\": \"Implicit\",
  \"RequestedScopes\": \"openid profile roles\",
  \"State\": \"OpenIdConnect.AuthenticationProperties=C8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg\",
  \"Nonce\": \"636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0\",
  \"Raw\": {
    \"client_id\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
    \"redirect_uri\": \"http://server1/app1/\",
    \"response_mode\": \"form_post\",
    \"response_type\": \"id_token token\",
    \"scope\": \"openid profile roles\",
    \"state\": \"OpenIdConnect.AuthenticationProperties=C8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg\",
    \"nonce\": \"636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0\"
  }
 }"
w3wp.exe Information: 0 : 2017-12-26 11:01:40.557 -05:00 [Information] User is not authenticated. Redirecting to login.
w3wp.exe Information: 0 : 2017-12-26 11:01:40.557 -05:00 [Information] End authorize request
w3wp.exe Information: 0 : 2017-12-26 11:01:40.557 -05:00 [Information] Redirecting to login page
2017-12-26 11:01:40.557 -05:00 [Debug] Protecting message: "{\"ReturnUrl\":\"http://server1/IdentityServer/core/connect/authorize?client_id=37B27AF6-BEB4-4C8B-92B0-46D51CF72201&redirect_uri=http%3A%2F%2Fserver1%2Fapp1%2F&response_mode=form_post&response_type=id_token%20token&scope=openid%20profile%20roles&state=OpenIdConnect.AuthenticationProperties%3DC8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg&nonce=636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0\",\"ClientId\":\"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",\"AcrValues\":[],\"Created\":636499009004950453}"
w3wp.exe Information: 0 : 2017-12-26 11:01:40.573 -05:00 [Information] Login page requested
2017-12-26 11:01:40.573 -05:00 [Debug] signin message passed to login: "{
  \"ReturnUrl\": \"http://server1/IdentityServer/core/connect/authorize?client_id=37B27AF6-BEB4-4C8B-92B0-46D51CF72201&redirect_uri=http%3A%2F%2Fserver1%2Fapp1%2F&response_mode=form_post&response_type=id_token%20token&scope=openid%20profile%20roles&state=OpenIdConnect.AuthenticationProperties%3DC8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg&nonce=636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0\",
  \"ClientId\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
  \"IdP\": null,
  \"Tenant\": null,
  \"LoginHint\": null,
  \"DisplayMode\": null,
  \"UiLocales\": null,
  \"AcrValues\": [],
  \"Created\": 636499009004950453
}"
w3wp.exe Information: 0 : 2017-12-26 11:01:40.604 -05:00 [Information] rendering login page
w3wp.exe Information: 0 : 2017-12-26 11:01:46.229 -05:00 [Information] Login page submitted
w3wp.exe Information: 0 : 2017-12-26 11:01:46.307 -05:00 [Information] Login credentials successfully validated by user service
w3wp.exe Information: 0 : 2017-12-26 11:01:46.307 -05:00 [Information] Calling PostAuthenticateAsync on the user service
w3wp.exe Information: 0 : 2017-12-26 11:01:46.307 -05:00 [Information] issuing primary signin cookie
w3wp.exe Information: 0 : 2017-12-26 11:01:46.307 -05:00 [Information] redirecting to: http://server1/IdentityServer/core/connect/authorize?client_id=37B27AF6-BEB4-4C8B-92B0-46D51CF72201&redirect_uri=http:%2F%2Fserver1%2Fapp1%2F&response_mode=form_post&response_type=id_token token&scope=openid profile roles&state=OpenIdConnect.AuthenticationProperties%3DC8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg&nonce=636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0
w3wp.exe Information: 0 : 2017-12-26 11:01:46.338 -05:00 [Information] Start authorize request
w3wp.exe Information: 0 : 2017-12-26 11:01:46.338 -05:00 [Information] Start authorize request protocol validation
w3wp.exe Information: 0 : 2017-12-26 11:01:46.385 -05:00 [Information] "Authorize request validation success"
 "{
  \"ClientId\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
  \"ClientName\": \"Application 1\",
  \"RedirectUri\": \"http://server1/app1/\",
  \"AllowedRedirectUris\": [
    \"http://server1/app1/\"
  ],
  \"SubjectId\": \"unknown\",
  \"ResponseType\": \"id_token token\",
  \"ResponseMode\": \"form_post\",
  \"Flow\": \"Implicit\",
  \"RequestedScopes\": \"openid profile roles\",
  \"State\": \"OpenIdConnect.AuthenticationProperties=C8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg\",
  \"Nonce\": \"636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0\",
  \"Raw\": {
    \"client_id\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
    \"redirect_uri\": \"http://server1/app1/\",
    \"response_mode\": \"form_post\",
    \"response_type\": \"id_token token\",
    \"scope\": \"openid profile roles\",
    \"state\": \"OpenIdConnect.AuthenticationProperties=C8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg\",
    \"nonce\": \"636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0\"
  }
}"
w3wp.exe Information: 0 : 2017-12-26 11:01:46.385 -05:00 [Information] User is not authenticated. Redirecting to login.
w3wp.exe Information: 0 : 2017-12-26 11:01:46.385 -05:00 [Information] End authorize request
w3wp.exe Information: 0 : 2017-12-26 11:01:46.385 -05:00 [Information] Redirecting to login page
2017-12-26 11:01:46.385 -05:00 [Debug] Protecting message: "{\"ReturnUrl\":\"http://server1/IdentityServer/core/connect/authorize?client_id=37B27AF6-BEB4-4C8B-92B0-46D51CF72201&redirect_uri=http%3A%2F%2Fserver1%2Fapp1%2F&response_mode=form_post&response_type=id_token%20token&scope=openid%20profile%20roles&state=OpenIdConnect.AuthenticationProperties%3DC8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg&nonce=636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0\",\"ClientId\":\"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",\"AcrValues\":[],\"Created\":636499009063389220}"
w3wp.exe Information: 0 : 2017-12-26 11:01:46.401 -05:00 [Information] Login page requested
2017-12-26 11:01:46.401 -05:00 [Debug] signin message passed to login: "{
  \"ReturnUrl\": \"http://server1/IdentityServer/core/connect/authorize?client_id=37B27AF6-BEB4-4C8B-92B0-46D51CF72201&redirect_uri=http%3A%2F%2Fserver1%2Fapp1%2F&response_mode=form_post&response_type=id_token%20token&scope=openid%20profile%20roles&state=OpenIdConnect.AuthenticationProperties%3DC8PH70Hdb4J3A3hSB2GLY9nw-luFnJOpwPMQTDT8_veTFgUvb1qovs556SDjqJK946BF3cyLSkiLkvFSaJxOlgijPKABAmqXn6hqzeM16XcfC5Aw_74mtN0KVaY6zWy3dWXmJawSbDY1qi5VQ1SrB_IV7FFovt2TWvGA1ShTh3qgCTF2NIgNrvw_CR98W-8LZ-y8Yzg539qZdKp8hOZgAY6G2xWBbiHP6duZ03ZXCuuqCwReDhhl4-sPSM9b49FJxBy2F4fZEI68OcRIR29NJg&nonce=636499009004794376.MTcwZDU5MzctNzFjMS00ZjU5LTg0MDItODlmZDUxYzFiY2E3MWE1YjQwNjEtYmE2NC00MGYxLWJjNDYtNzMyMWFlYWYzYjc0\",
  \"ClientId\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
  \"IdP\": null,
  \"Tenant\": null,
  \"LoginHint\": null,
  \"DisplayMode\": null,
  \"UiLocales\": null,
  \"AcrValues\": [],
  \"Created\": 636499009063389220
}"
w3wp.exe Information: 0 : 2017-12-26 11:01:46.432 -05:00 [Information] rendering login page

After IIS is restarted, the user is able to log in and this is IdentityServer's log:

w3wp.exe Information: 0 : 2017-12-26 11:05:22.390 -05:00 [Information] Starting IdentityAdmin configuration
w3wp.exe Information: 0 : 2017-12-26 11:05:22.937 -05:00 [Information] Starting IdentityManager configuration
w3wp.exe Information: 0 : 2017-12-26 11:05:28.031 -05:00 [Information] Start discovery request
w3wp.exe Information: 0 : 2017-12-26 11:05:29.375 -05:00 [Information] Start key discovery request
w3wp.exe Information: 0 : 2017-12-26 11:05:29.703 -05:00 [Information] Start authorize request
w3wp.exe Information: 0 : 2017-12-26 11:05:29.703 -05:00 [Information] Start authorize request protocol validation
w3wp.exe Information: 0 : 2017-12-26 11:05:30.921 -05:00 [Information] "Authorize request validation success"
 "{
  \"ClientId\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
  \"ClientName\": \"Application 1\",
  \"RedirectUri\": \"http://server1/app1/\",
  \"AllowedRedirectUris\": [
    \"http://server1/app1/\"
  ],
  \"SubjectId\": \"unknown\",
  \"ResponseType\": \"id_token token\",
  \"ResponseMode\": \"form_post\",
  \"Flow\": \"Implicit\",
  \"RequestedScopes\": \"openid profile roles\",
  \"State\": \"OpenIdConnect.AuthenticationProperties=fjwR1NWMEangVNL2EGj-KqFl8l61pubDaePaMwu4F8sIV5gc3xpAqHdby4E4AeMAXLZ_PG2-Bep_WfWIwwOHs1JbX94Vp1WXmh48k_VzxV637LimIbXNlUsQyGy9UboegL8klqamwHdJKN0jPBWkufWiUoLN4GuCePbZV9L5XmlslmLMcv9Ghge2_8X9Wyrk_zScuafOIQCe1Jl0N9bTVCME7isQND3sCrETEuexrk3wK-URVxWumr1zgLKcYOQ7WAyz21GU65Ugb0AXW7OV2A\",
  \"Nonce\": \"636499011294218688.MzBkODAxMzgtMzMzYy00YWFjLWE3NjMtZWQ3ZTNmNWY3ZWIyOTQ2OTZhN2ItZTc5NS00MWMxLWIyODgtMDMyMDI4NDNkOTJj\",
  \"Raw\": {
    \"client_id\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
    \"redirect_uri\": \"http://server1/app1/\",
    \"response_mode\": \"form_post\",
    \"response_type\": \"id_token token\",
    \"scope\": \"openid profile roles\",
    \"state\": \"OpenIdConnect.AuthenticationProperties=fjwR1NWMEangVNL2EGj-KqFl8l61pubDaePaMwu4F8sIV5gc3xpAqHdby4E4AeMAXLZ_PG2-Bep_WfWIwwOHs1JbX94Vp1WXmh48k_VzxV637LimIbXNlUsQyGy9UboegL8klqamwHdJKN0jPBWkufWiUoLN4GuCePbZV9L5XmlslmLMcv9Ghge2_8X9Wyrk_zScuafOIQCe1Jl0N9bTVCME7isQND3sCrETEuexrk3wK-URVxWumr1zgLKcYOQ7WAyz21GU65Ugb0AXW7OV2A\",
    \"nonce\": \"636499011294218688.MzBkODAxMzgtMzMzYy00YWFjLWE3NjMtZWQ3ZTNmNWY3ZWIyOTQ2OTZhN2ItZTc5NS00MWMxLWIyODgtMDMyMDI4NDNkOTJj\"
  }
}"
w3wp.exe Information: 0 : 2017-12-26 11:05:30.921 -05:00 [Information] User is not authenticated. Redirecting to login.
w3wp.exe Information: 0 : 2017-12-26 11:05:30.921 -05:00 [Information] End authorize request
w3wp.exe Information: 0 : 2017-12-26 11:05:30.921 -05:00 [Information] Redirecting to login page
2017-12-26 11:05:30.937 -05:00 [Debug] Protecting message: "{\"ReturnUrl\":\"http://server1/IdentityServer/core/connect/authorize?client_id=37B27AF6-BEB4-4C8B-92B0-46D51CF72201&redirect_uri=http%3A%2F%2Fserver1%2Fapp1%2F&response_mode=form_post&response_type=id_token%20token&scope=openid%20profile%20roles&state=OpenIdConnect.AuthenticationProperties%3DfjwR1NWMEangVNL2EGj-KqFl8l61pubDaePaMwu4F8sIV5gc3xpAqHdby4E4AeMAXLZ_PG2-Bep_WfWIwwOHs1JbX94Vp1WXmh48k_VzxV637LimIbXNlUsQyGy9UboegL8klqamwHdJKN0jPBWkufWiUoLN4GuCePbZV9L5XmlslmLMcv9Ghge2_8X9Wyrk_zScuafOIQCe1Jl0N9bTVCME7isQND3sCrETEuexrk3wK-URVxWumr1zgLKcYOQ7WAyz21GU65Ugb0AXW7OV2A&nonce=636499011294218688.MzBkODAxMzgtMzMzYy00YWFjLWE3NjMtZWQ3ZTNmNWY3ZWIyOTQ2OTZhN2ItZTc5NS00MWMxLWIyODgtMDMyMDI4NDNkOTJj\",\"ClientId\":\"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",\"AcrValues\":[],\"Created\":636499011296093553}"
w3wp.exe Information: 0 : 2017-12-26 11:05:30.984 -05:00 [Information] Login page requested
2017-12-26 11:05:30.984 -05:00 [Debug] signin message passed to login: "{
  \"ReturnUrl\": \"http://server1/IdentityServer/core/connect/authorize?client_id=37B27AF6-BEB4-4C8B-92B0-46D51CF72201&redirect_uri=http%3A%2F%2Fserver1%2Fapp1%2F&response_mode=form_post&response_type=id_token%20token&scope=openid%20profile%20roles&state=OpenIdConnect.AuthenticationProperties%3DfjwR1NWMEangVNL2EGj-KqFl8l61pubDaePaMwu4F8sIV5gc3xpAqHdby4E4AeMAXLZ_PG2-Bep_WfWIwwOHs1JbX94Vp1WXmh48k_VzxV637LimIbXNlUsQyGy9UboegL8klqamwHdJKN0jPBWkufWiUoLN4GuCePbZV9L5XmlslmLMcv9Ghge2_8X9Wyrk_zScuafOIQCe1Jl0N9bTVCME7isQND3sCrETEuexrk3wK-URVxWumr1zgLKcYOQ7WAyz21GU65Ugb0AXW7OV2A&nonce=636499011294218688.MzBkODAxMzgtMzMzYy00YWFjLWE3NjMtZWQ3ZTNmNWY3ZWIyOTQ2OTZhN2ItZTc5NS00MWMxLWIyODgtMDMyMDI4NDNkOTJj\",
  \"ClientId\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
  \"IdP\": null,
  \"Tenant\": null,
  \"LoginHint\": null,
  \"DisplayMode\": null,
  \"UiLocales\": null,
  \"AcrValues\": [],
  \"Created\": 636499011296093553
}"
w3wp.exe Information: 0 : 2017-12-26 11:05:31.015 -05:00 [Information] rendering login page
w3wp.exe Information: 0 : 2017-12-26 11:05:39.547 -05:00 [Information] Login page submitted
w3wp.exe Information: 0 : 2017-12-26 11:05:40.281 -05:00 [Information] Login credentials successfully validated by user service
w3wp.exe Information: 0 : 2017-12-26 11:05:40.281 -05:00 [Information] Calling PostAuthenticateAsync on the user service
w3wp.exe Information: 0 : 2017-12-26 11:05:40.281 -05:00 [Information] issuing primary signin cookie
w3wp.exe Information: 0 : 2017-12-26 11:05:40.297 -05:00 [Information] redirecting to: http://server1/IdentityServer/core/connect/authorize?client_id=37B27AF6-BEB4-4C8B-92B0-46D51CF72201&redirect_uri=http:%2F%2Fserver1%2Fapp1%2F&response_mode=form_post&response_type=id_token token&scope=openid profile roles&state=OpenIdConnect.AuthenticationProperties%3DfjwR1NWMEangVNL2EGj-KqFl8l61pubDaePaMwu4F8sIV5gc3xpAqHdby4E4AeMAXLZ_PG2-Bep_WfWIwwOHs1JbX94Vp1WXmh48k_VzxV637LimIbXNlUsQyGy9UboegL8klqamwHdJKN0jPBWkufWiUoLN4GuCePbZV9L5XmlslmLMcv9Ghge2_8X9Wyrk_zScuafOIQCe1Jl0N9bTVCME7isQND3sCrETEuexrk3wK-URVxWumr1zgLKcYOQ7WAyz21GU65Ugb0AXW7OV2A&nonce=636499011294218688.MzBkODAxMzgtMzMzYy00YWFjLWE3NjMtZWQ3ZTNmNWY3ZWIyOTQ2OTZhN2ItZTc5NS00MWMxLWIyODgtMDMyMDI4NDNkOTJj
w3wp.exe Information: 0 : 2017-12-26 11:05:40.328 -05:00 [Information] Start authorize request
w3wp.exe Information: 0 : 2017-12-26 11:05:40.328 -05:00 [Information] Start authorize request protocol validation
w3wp.exe Information: 0 : 2017-12-26 11:05:40.359 -05:00 [Information] "Authorize request validation success"
 "{
  \"ClientId\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
  \"ClientName\": \"Application 1\",
  \"RedirectUri\": \"http://server1/app1/\",
  \"AllowedRedirectUris\": [
    \"http://server1/app1/\"
  ],
  \"SubjectId\": \"7d7d455c-fcbf-4614-b9d6-5396b92c3a1b\",
  \"ResponseType\": \"id_token token\",
  \"ResponseMode\": \"form_post\",
  \"Flow\": \"Implicit\",
  \"RequestedScopes\": \"openid profile roles\",
  \"State\": \"OpenIdConnect.AuthenticationProperties=fjwR1NWMEangVNL2EGj-KqFl8l61pubDaePaMwu4F8sIV5gc3xpAqHdby4E4AeMAXLZ_PG2-Bep_WfWIwwOHs1JbX94Vp1WXmh48k_VzxV637LimIbXNlUsQyGy9UboegL8klqamwHdJKN0jPBWkufWiUoLN4GuCePbZV9L5XmlslmLMcv9Ghge2_8X9Wyrk_zScuafOIQCe1Jl0N9bTVCME7isQND3sCrETEuexrk3wK-URVxWumr1zgLKcYOQ7WAyz21GU65Ugb0AXW7OV2A\",
  \"Nonce\": \"636499011294218688.MzBkODAxMzgtMzMzYy00YWFjLWE3NjMtZWQ3ZTNmNWY3ZWIyOTQ2OTZhN2ItZTc5NS00MWMxLWIyODgtMDMyMDI4NDNkOTJj\",
  \"SessionId\": \"066e45ec35914c794dbcb53e5c9948d9\",
  \"Raw\": {
    \"client_id\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
    \"redirect_uri\": \"http://server1/app1/\",
    \"response_mode\": \"form_post\",
    \"response_type\": \"id_token token\",
    \"scope\": \"openid profile roles\",
    \"state\": \"OpenIdConnect.AuthenticationProperties=fjwR1NWMEangVNL2EGj-KqFl8l61pubDaePaMwu4F8sIV5gc3xpAqHdby4E4AeMAXLZ_PG2-Bep_WfWIwwOHs1JbX94Vp1WXmh48k_VzxV637LimIbXNlUsQyGy9UboegL8klqamwHdJKN0jPBWkufWiUoLN4GuCePbZV9L5XmlslmLMcv9Ghge2_8X9Wyrk_zScuafOIQCe1Jl0N9bTVCME7isQND3sCrETEuexrk3wK-URVxWumr1zgLKcYOQ7WAyz21GU65Ugb0AXW7OV2A\",
    \"nonce\": \"636499011294218688.MzBkODAxMzgtMzMzYy00YWFjLWE3NjMtZWQ3ZTNmNWY3ZWIyOTQ2OTZhN2ItZTc5NS00MWMxLWIyODgtMDMyMDI4NDNkOTJj\"
  }
}"
w3wp.exe Information: 0 : 2017-12-26 11:05:40.406 -05:00 [Information] Creating Implicit Flow response.
2017-12-26 11:05:40.406 -05:00 [Debug] Creating access token
2017-12-26 11:05:40.406 -05:00 [Debug] Creating JWT access token
2017-12-26 11:05:40.531 -05:00 [Debug] Creating identity token
w3wp.exe Information: 0 : 2017-12-26 11:05:40.531 -05:00 [Information] Getting claims for identity token for subject: 7d7d455c-fcbf-4614-b9d6-5396b92c3a1b
2017-12-26 11:05:40.531 -05:00 [Debug] Creating JWT identity token
2017-12-26 11:05:40.625 -05:00 [Debug] Adding client "37B27AF6-BEB4-4C8B-92B0-46D51CF72201" to client list cookie for subject "7d7d455c-fcbf-4614-b9d6-5396b92c3a1b"
w3wp.exe Information: 0 : 2017-12-26 11:05:40.625 -05:00 [Information] End authorize request
w3wp.exe Information: 0 : 2017-12-26 11:05:40.640 -05:00 [Information] Posting to http://server1/app1/
2017-12-26 11:05:40.640 -05:00 [Debug] Using DefaultViewService to render authorization response HTML
w3wp.exe Information: 0 : 2017-12-26 11:05:41.265 -05:00 [Information] Start userinfo request
w3wp.exe Information: 0 : 2017-12-26 11:05:41.281 -05:00 [Information] Token found: AuthorizationHeader
w3wp.exe Information: 0 : 2017-12-26 11:05:41.281 -05:00 [Information] Start access token validation
w3wp.exe Information: 0 : 2017-12-26 11:05:41.328 -05:00 [Information] "Token validation success"
"{
  \"ValidateLifetime\": true,
  \"AccessTokenType\": \"Jwt\",
  \"ExpectedScope\": \"openid\",
  \"Claims\": {
    \"iss\": \"http://server1/IdentityServer/core\",
    \"aud\": \"http://server1/IdentityServer/core/resources\",
    \"exp\": \"1514307940\",
    \"nbf\": \"1514304340\",
    \"client_id\": \"37B27AF6-BEB4-4C8B-92B0-46D51CF72201\",
    \"scope\": [
      \"openid\",
      \"profile\",
      \"roles\"
    ],
    \"sub\": \"7d7d455c-fcbf-4614-b9d6-5396b92c3a1b\",
    \"auth_time\": \"1514304340\",
    \"idp\": \"idsrv\",
    \"amr\": \"password\"
  }
}"
w3wp.exe Information: 0 : 2017-12-26 11:05:41.328 -05:00 [Information] Creating userinfo response
w3wp.exe Information: 0 : 2017-12-26 11:05:41.328 -05:00 [Information] Scopes in access token: "openid profile roles"
w3wp.exe Information: 0 : 2017-12-26 11:05:41.359 -05:00 [Information] Requested claim types: "sub name family_name given_name middle_name nickname preferred_username profile picture website gender birthdate zoneinfo locale updated_at role"
w3wp.exe Information: 0 : 2017-12-26 11:05:41.390 -05:00 [Information] Profile service returned to the following claim types: "sub preferred_username role role role given_name family_name locale role"
w3wp.exe Information: 0 : 2017-12-26 11:05:41.390 -05:00 [Information] End userinfo request
w3wp.exe Information: 0 : 2017-12-26 11:05:41.390 -05:00 [Information] Returning userinfo response.

This issue only happens when we have concurrent users in two or more apps using IdentityServer for authentication requests.


Solution

  • The issue it is generated by a lower and upper case mixing in the URL path of Identity Server and the mvc apps in IIS.

    check this: https://github.com/IdentityServer/IdentityServer3/issues/2091#issuecomment-159257951