Intermittent NoState Errors

81 views
Skip to first unread message

Dustin Lactin

unread,
Sep 29, 2016, 11:34:46 AM9/29/16
to SimpleSAMLphp
I am attempting to track down the cause of intermittent nostate errors, approximately 1100 per day of 38000 total. At this point I have been unable to consistently replicate it but we are still seeing a significant amount of daily errors. 

Environment: 
Six application servers configured with simplesamlphp 1.14.4 as service providers behind a load balancer, all using the same memcache as a backend for storing sessions.
Our identity provider is also simplesamlphp. The session duration, datastore timeout, state, and lifetime are all the defaults. 
I have changed the cookie names to avoid conflicts with other services we run. 
Memcache does not appear to be under any significant load and is not removing any items. 

Debug Logs: 

New Request - Broken

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 7 [6ce0cb2d3f] Loading state: '_3edde738bd226de8178373eca8ba20401f4f05a06b'

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 3 [6ce0cb2d3f] SimpleSAML_Error_NoState: NOSTATE

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 3 [6ce0cb2d3f] Backtrace:

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 3 [6ce0cb2d3f] 2 /var/simplesamlphp/lib/SimpleSAML/Auth/State.php:263 (SimpleSAML_Auth_State::loadState)

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 3 [6ce0cb2d3f] 1 /var/simplesamlphp/modules/saml/www/sp/saml2-acs.php:78 (require)

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 3 [6ce0cb2d3f] 0 /var/simplesamlphp/www/module.php:137 (N/A)

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 3 [6ce0cb2d3f] Error report with id 679470d6 generated.

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 7 [6ce0cb2d3f] Template: Reading [/var/simplesamlphp/dictionaries/errors]

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 7 [6ce0cb2d3f] Template: Reading [/var/simplesamlphp/modules/core/dictionaries/no_state]

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 7 [6ce0cb2d3f] loading key SimpleSAMLphp.session.63cc7a3a6ef884dbab3ba0e0a0d17207 from memcache

Sept 26 16:03:10 removed-server-name simplesamlphp[13301]: 7 [6ce0cb2d3f] saving key SimpleSAMLphp.session.63cc7a3a6ef884dbab3ba0e0a0d17207 to memcache


New Request - Working

Sept 26 16:07:02 removed-server-name simplesamlphp[13309]: 7 [a673725620] Session: 'default-sp' not valid because we are not authenticated.

Sept 26 16:07:02 removed-server-name simplesamlphp[13309]: 7 [a673725620] Saved state: '_b555ae5a198d555c4c3f03c33551172cb2af171881'

Sept 26 16:07:02 removed-server-name simplesamlphp[13309]: 7 [a673725620] Sending SAML 2 AuthnRequest to 'https://my-idp

Sept 26 16:07:02 removed-server-name simplesamlphp[13309]: 7 [a673725620] Redirect to 746 byte URL: https://my-idp

Sept 26 16:07:02 removed-server-name simplesamlphp[13309]: 7 [a673725620] loading key SimpleSAMLphp.session.614d11772d7ac365fca443b27ebe354a from memcache

Sept 26 16:07:02 removed-server-name simplesamlphp[13309]: 7 [a673725620] key SimpleSAMLphp.session.614d11772d7ac365fca443b27ebe354a not found in memcache

Sept 26 16:07:02 removed-server-name simplesamlphp[13309]: 7 [a673725620] saving key SimpleSAMLphp.session.c8b498080e8895a28d17df79dd137084 to memcache

Sept 26 16:07:03 removed-server-name simplesamlphp[13300]: 7 [a673725620] Session: Valid session found with 'default-sp'.

Sept 26 16:07:03 removed-server-name simplesamlphp[13300]: 7 [a673725620] Session: Valid session found with 'default-sp'.

Sept 26 16:07:03 removed-server-name simplesamlphp[13300]: 7 [a673725620] Session: Valid session found with 'default-sp'.

Sept 26 16:07:03 removed-server-name simplesamlphp[13300]: 7 [a673725620] loading key SimpleSAMLphp.session.c8b498080e8895a28d17df79dd137084 from memcache


Authenticated elsewhere first - Working

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Loading state: '_f4204a52479a00582c9f803f447821f3423d8b5c77'

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Received SAML2 Response from 'https://my-idp

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Has 1 candidate keys for validation.

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Validation with key #0 succeeded.

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Has 1 candidate keys for validation.

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Validation with key #0 succeeded.

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] loading key SimpleSAMLphp.saml.AssertionReceived._0a781ae83b8313c44403c815626a393a0b01857e5e from memcache

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] key SimpleSAMLphp.saml.AssertionReceived._0a781ae83b8313c44403c815626a393a0b01857e5e not found in memcache

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] saving key SimpleSAMLphp.saml.AssertionReceived._0a781ae83b8313c44403c815626a393a0b01857e5e to memcache

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] saving key SimpleSAMLphp.saml.LogoutStore.6030c696c5eac66680bf216adfff7e7c59f91ed7:_eed1eff627e3e67863bda0816a934beef5abe8745c to memcache

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Filter config for https://my-idp->https://my-service-provider: array (  0 =>   sspmod_core_Auth_Process_AttributeMap::__set_state(array(        ),     'duplicate' => false,     'priority' => 50,  )),  1 =>   sspmod_core_Auth_Process_LanguageAdaptor::__set_state(array(     'langattr' => 'preferredLanguage',     'priority' => 90,  )),)

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Deleting state: '_f4204a52479a00582c9f803f447821f3423d8b5c77'

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] Session: doLogin("default-sp")

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] loading key SimpleSAMLphp.session.7b5b0ef10abbfca2ed67f4d9499d67b8 from memcache

Sept 26 16:13:16 removed-server-name simplesamlphp[13318]: 7 [78fc61e4d3] saving key SimpleSAMLphp.session.7b5b0ef10abbfca2ed67f4d9499d67b8 to memcache


I have looked through the suggested fixes here: https://simplesamlphp.org/docs/development/simplesamlphp-nostate and I don't believe any of those causes apply to us. We have another environment with and older version of simplesamlphp (1.13.x) and a postgres backend experiencing the same issues. 


Users are reporting these errors while in the middle of using the service after already authenticating, first logging in, and while logging out. We are investigate other saml plugins in case the issue is not with simplesaml itself but the plugin not handling these errors properly. 


Any idea's on what to try next? 



Jaime Perez Crespo

unread,
Sep 29, 2016, 1:37:37 PM9/29/16
to simple...@googlegroups.com
Hi Dustin,

There are many possible reasons for this kind of error. A typical reason is bookmarked URLs, though that doesn’t seem to be the case according to what your users report. Sometimes, it’s just an SP misbehaving. In your case, I think it could be related to this:

https://github.com/simplesamlphp/simplesamlphp/pull/260

The problem there is that the fix is not really effective if you don’t have an updated version of PHP. What version are you running? Note that versions prior to 5.4 don’t include the function that fixes the race condition, and versions lower than 5.6 (even some of the 5.6.x) have a faulty implementation of the function used, and could cause your server to segfault.

I would upgrade SimpleSAMLphp and PHP, and then look at the web server logs. First, error logs to see if there’s something there. If not, I’d suggest looking into the access logs to try to reproduce the sequence of requests (including the original referrer) that lead to the error.

Unfortunately, this is an error that’s quite difficult to hunt down...
--
Jaime Pérez
UNINETT / Feide

jaime...@uninett.no
jaime...@protonmail.com
9A08 EA20 E062 70B4 616B 43E3 562A FE3A 6293 62C2

"Two roads diverged in a wood, and I, I took the one less traveled by, and that has made all the difference."
- Robert Frost

Dustin Lactin

unread,
Sep 29, 2016, 3:59:10 PM9/29/16
to SimpleSAMLphp
We are running php 5.5.37. I will look into upgrading php and simplesamlphp. 

Thanks!
Reply all
Reply to author
Forward
0 new messages