Session id is being found as empty string

[tomascharad]

Hi Nat,

After CAS emits the single sign out signal, some client apps (2/4) display the following log:

Processing by Devise::CasSessionsController#single_sign_out as */*
Parameters: {"logoutRequest"=>"<samlp:LogoutRequest xmlns:samlp=\"urn:oasis:names:tc:SAML:2.0:protocol\" xmlns:saml=\"urn:oasis:names:tc:SAML:2.0:assertion\" ID=\"13e9fe85-94a5-4eef-be1d-b4495bdafbe6\" Version=\"2.0\" IssueInstant=\"2015-10-09 15:02:42 +0000\">\n  <saml:NameID>@NOT_USED@</saml:NameID>\n  <samlp:SessionIndex>ST-14444029573823-15h6UlLwCJxqMmP7ofbvKl9R9rjISFMI4ydVAyZm</samlp:SessionIndex>\n</samlp:LogoutRequest>\n"}
Intercepted single-sign-out request for CAS session ST-14444029573823-15h6UlLwCJxqMmP7ofbvKl9R9rjISFMI4ydVAyZm.
2015-10-09T15:02:44.023279+00:00 app[web.2]:   Rendered text template (0.0ms)
Found session id  for index ST-14444029573823-15h6UlLwCJxqMmP7ofbvKl9R9rjISFMI4ydVAyZm

Please take a look where it says "Found session id for index". It seems that this line (

devise_cas_authenticatable/lib/devise_cas_authenticatable/single_sign_out/strategies/rails_cache.rb

Line 12 in 26b2d82

logger.debug("Found session id #{sid} for index #{session_index}")

) has the variable "sid" as an empty (probably string) and that this method "Rails.cache.read(cache_key(session_index))" May not be working as expected right?

[tomascharad]

It could be nil rather than empty:

After debugging a sign in:

Storing 69feda1f73faa2d75b40d1751cdc14fa for index ST-14444063957494-GwQp70KGeT7FXoHSjGC7l8RXoVFLParn8sFxYNpH

I tried this on console

Rails.cache.read("devise_cas_authenticatable:ST-14444063957494-GwQp70KGeT7FXoHSjGC7l8RXoVFLParn8sFxYNpH")

And got nil... But maybe debugging the cache through the console doesn't access the same cache than the application?

[nbudin]

Re debugging the cache through the console, my guess would be that you're not starting the console in the same environment as the app is running in. If this is production, make sure to do rails c production, for example. If you do that, it should be using the same cache.

[tomascharad]

Hi Nat,

I have just runned console in production mode and still cannot find the key:

Another example:

2015-10-14T22:11:32.153702+00:00 app[web.3]: Storing Session ID 1a0e9f1325f7008e59c2137554fc1eff for ticket ST-14448606902089-HC1GMTHqaxjfxddwx8V2jwPm5aE2lNA6mDzfAHMB
2015-10-14T22:11:32.153755+00:00 app[web.3]: Storing 1a0e9f1325f7008e59c2137554fc1eff for index ST-14448606902089-HC1GMTHqaxjfxddwx8V2jwPm5aE2lNA6mDzfAHMB

Tomass-MBP:dashboard_buzz_assist tomascharad$ heroku run rails console production

irb(main):001:0> Rails.cache.read("devise_cas_authenticatable:ST-14448606902089-HC1GMTHqaxjfxddwx8V2jwPm5aE2lNA6mDzfAHMB")
=> nil

2015-10-14T22:13:46.694486+00:00 app[web.5]: Started POST "/users/service" for 54.234.233.150 at 2015-10-14 22:13:46 +0000
2015-10-14T22:13:46.697562+00:00 app[web.5]: Found session id  for index ST-14448606902089-HC1GMTHqaxjfxddwx8V2jwPm5aE2lNA6mDzfAHMB
2015-10-14T22:13:46.696790+00:00 app[web.5]: Processing by Devise::CasSessionsController#single_sign_out as */*
2015-10-14T22:13:46.696900+00:00 app[web.5]:   Parameters: {"logoutRequest"=>"<samlp:LogoutRequest xmlns:samlp=\"urn:oasis:names:tc:SAML:2.0:protocol\" xmlns:saml=\"urn:oasis:names:tc:SAML:2.0:assertion\" ID=\"69b45c9e-37ce-49a1-9474-2db931fbe4b7\" Version=\"2.0\" IssueInstant=\"2015-10-14 22:13:46 +0000\">\n  <saml:NameID>@NOT_USED@</saml:NameID>\n  <samlp:SessionIndex>ST-14448606902089-HC1GMTHqaxjfxddwx8V2jwPm5aE2lNA6mDzfAHMB</samlp:SessionIndex>\n</samlp:LogoutRequest>\n"}
2015-10-14T22:13:46.697397+00:00 app[web.5]: Intercepted single-sign-out request for CAS session ST-14448606902089-HC1GMTHqaxjfxddwx8V2jwPm5aE2lNA6mDzfAHMB.

And since it doesn't find the id it is not deleting the record on the DB.

What do you think might be happening? Maybe cache is not being written?

[tomascharad]

Could this be related to the fact that some sessions do not have a "complete" data property?

Ex (First one with maybe incomplete data property):

=> #<ActiveRecord::SessionStore::Session id: 2435, session_id: "36a8d81a49a495cff202f02cb333dbf7", data: "BAh7AA==\n", created_at: "2015-10-14 21:08:13", updated_at: "2015-10-14 21:08:13">

=> #<ActiveRecord::SessionStore::Session id: 2393, session_id: "dc360bb7cc4aac5101c17502cef23f94", data: "BAh7CkkiCmZsYXNoBjoGRVR7B0kiDGRpc2NhcmQGOwBUWwBJIg...", created_at: "2015-10-14 19:35:36", updated_at: "2015-10-14 19:35:36">

[tomascharad]

Can this issue may be related to the fact that I have multiple instances running on heroku?

[nbudin]

I don't think it is because of the incomplete data property; the code to delete sessions doesn't even look at the data. It could be related to multiple instances, if each instance is connected to a different memcached instance.

[tomascharad]

Nat,

I reduced the instances to one (I had one app with 18 and another with 12) and the problem was solved.
What alternative do I have for fixing this issue?
Do I have to write my own strategy to save this data in the DB or are there any alternatives available besides sharing the memcache?

Many thanks.

[nbudin]

I would recommend switching to the ActiveRecord-based session store: https://github.com/rails/activerecord-session_store

This will store all session data in the database so you can be sure it's in one central location.

[tomascharad]

Yes, I'm using that!

session_store.rb:

Rails.application.config.session_store :active_record_store

But I think that the gem stores the tuple in caché (cas_server_session_ticket, internal_application_ticket) even when using active record session store.

Take a look at my 5th comment of this thread (ActiveRecord::SessionStore):

=> #<ActiveRecord::SessionStore::Session id: 2435, session_id: "36a8d81a49a495cff202f02cb333dbf7", data: "BAh7AA==\n", created_at: "2015-10-14 21:08:13", updated_at: "2015-10-14 21:08:13">

[nbudin]

Ah, yes, you're right - sorry, I'd been conflating session storage with single sign-out storage strategy. The storage strategy is what's to blame here: it takes care of storing the mapping between CAS users and sessions. The only built-in one uses the Rails cache; hence why going from 12 to 1 instances fixed it.

In theory, it should be possible to implement your own strategy that uses ActiveRecord instead. You'll need a new table for this, but it doesn't have to be very complicated. For a baseline implementation, see how the cache strategy does it: https://github.com/nbudin/devise_cas_authenticatable/blob/master/lib/devise_cas_authenticatable/single_sign_out/strategies/rails_cache.rb

Once you have implemented an ActiveRecord strategy, you could then configure it using the cas_single_sign_out_mapping_strategy config setting in devise.rb.

[tomascharad]

Ok, I'm doing this today.
Let you know when is done, maybe you want to assign me this ticket.
Thanks for your help.