Why does an application using the Bluemix Single Sign On service return a 404 when it is horizontally scaled?

Question

I have a simple Node.js application using express 4.12 and express-session 1.11.2 using the Single Sign On (SSO) service for Bluemix. It works fine when there is a single application instance, but when the application is scaled to two instances either manually or with auto-scaling, it returns a 404 after the user provides their credentials.

I used cf logs to check the logs for the application and in both cases the application callback is being invoked as expected after authentication:

working (one application instance):

2015-07-02T10:11:38.45-0700 [RTR]     OUT ssolab-20150601tor.mybluemix.net - [02/07/2015:17:11:38 +0000] "GET /auth/sso/callback?scope=openid&code=JaoWziZSyRNNwrBDECRiWBSNHSl0CF HTTP/1.1" 302 0 68 "https://bestssoever-2zgs9sg44w-cge7.iam.ibmcloud.com/idaas/mtfim/sps/default/oidc/consent" "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko" 75.126.70.43:34370 x_forwarded_for:"-" vcap_request_id:ec975656-70ae-44d8-4071-5b2d3b92e041 response_time:0.185715429 app_id:8b9f5b57-fbbd-4387-9cda-3737ad1f02ad

not working (two application instances):

2015-07-02T10:21:38.64-0700 [RTR]     OUT ssolab-20150601tor.mybluemix.net - [02/07/2015:17:21:38 +0000] "GET /auth/sso/callback?scope=openid&code=wR2FhOFxZnowIIggOqyytf9DzNmwSq HTTP/1.1" 404 0 83 "https://bestssoever-2zgs9sg44w-cge7.iam.ibmcloud.com/idaas/mtfim/sps/default/oidc/consent" "Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko" 75.126.70.43:39545 x_forwarded_for:"-" vcap_request_id:f1b75539-b02e-4217-4e3a-b3f6f1fc1c67 response_time:0.259509247 app_id:8b9f5b57-fbbd-4387-9cda-3737ad1f02ad

I would expect a different code parameter in the GET requests to the callback, so that is ok.

To get more debugging information, I added a console.log statement that is run before the user is directed to the SSO service for authentication. When processing in the callback, the passport openid connect node module (strategy.js) also logs output to the console. When all is working correctly, the output looks like:

2015-07-06T16:22:40.99-0700 [RTR]     OUT ssolab-20150601tor.mybluemix.net - [06/07/2015:23:22:40 +0000] "GET /hello HTTP/1.1" 302 0 68 "https://ssolab-20150601tor.mybluemix.net/" "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)" 75.126.70.46:15290 x_forwarded_for:"-" vcap_request_id:fe3c942d-7ae2-4500-6274-b1ecf95f24e5 response_time:0.009553663 app_id:8b9f5b57-fbbd-4387-9cda-3737ad1f02ad
2015-07-06T16:22:41.01-0700 [App/0]   OUT Request by unauthenticated user

followed by:

2015-07-06T16:22:54.67-0700 [RTR]     OUT ssolab-20150601tor.mybluemix.net - [06/07/2015:23:22:54 +0000] "GET /auth/sso/callback?scope=openid&code=QkXlFtOEpBkNBJdo4tSvQA6qUlw7Q7 HTTP/1.1" 302 0 68 "https://bestssoever-2zgs9sg44w-cge7.iam.ibmcloud.com/idaas/mtfim/sps/default/oidc/consent" "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)" 75.126.70.46:29117 x_forwarded_for:"-" vcap_request_id:ca85eb7a-8b54-4bc1-43a7-2cff279de499 response_time:0.223288172 app_id:8b9f5b57-fbbd-4387-9cda-3737ad1f02ad
2015-07-06T16:22:54.68-0700 [App/0]   OUT TOKEN

With two application instances it looks like the initial application traffic is going to one instance:

2015-07-06T16:37:17.68-0700 [RTR]     OUT ssolab-20150601tor.mybluemix.net - [06/07/2015:23:37:17 +0000] "GET /hello HTTP/1.1" 302 0 68 "https://ssolab-20150601tor.mybluemix.net/" "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)" 75.126.70.42:24841 x_forwarded_for:"-" vcap_request_id:491b5a52-653d-4fdc-6364-f604b3da395b response_time:0.008679282 app_id:8b9f5b57-fbbd-4387-9cda-3737ad1f02ad
2015-07-06T16:37:17.68-0700 [App/0]   OUT Request by unauthenticated user

whereas the callback invocation seems to be handled by the other instance:

2015-07-06T16:37:51.01-0700 [RTR]     OUT ssolab-20150601tor.mybluemix.net - [06/07/2015:23:37:50 +0000] "GET /auth/sso/callback?scope=openid&code=ylZKV3IPWMZgo2MNvwt9JxJzjU2Lsj HTTP/1.1" 404 0 83 "https://bestssoever-2zgs9sg44w-cge7.iam.ibmcloud.com/idaas/mtfim/sps/default/oidc/consent" "Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; WOW64; Trident/6.0)" 75.126.70.43:48635 x_forwarded_for:"-" vcap_request_id:44b7893c-b185-4651-5384-7957a598bc20 response_time:0.273983071 app_id:8b9f5b57-fbbd-4387-9cda-3737ad1f02ad
2015-07-06T16:37:51.00-0700 [App/1]   OUT TOKEN

timro timro · Accepted Answer · 2015-07-07T04:18:41

The cause for the 404 is that the express-session middleware used by Passport with Express has a default store that is in memory and doesn't scale past a single process (see warning at: https://github.com/expressjs/session )

In the failing debug log snippet, before the authentication is delegated to SSO, Passport uses a session object managed by express-session in App/0. However, when the callback is invoked, the request is handled by App/1, and express-session in that instance doesn't have visibility to the original session.

I tested this hypothesis by implementing an alternate (and persistent) session store for express-session using connect-redis and the Redis Cloud service for Bluemix.

After configuring express-session to persist sessions to this store, the 404 errors went away when more than one instance of the application was active.

Why does an application using the Bluemix Single Sign On service return a 404 when it is horizontally scaled?

1 Answers