Session has expired. Client must attach with new token

[alexlarocca]

I have 3 brokers using the demo sample code. Two of this brokers run on local virtual hosts. The third runs on an online server with HTTPS, as the sso server.

The local brokers works properly (info, login, logout). The online broker return the error "Invalid or expired bearer token". I get the same error even if I run the third broker from the same webserver (with a different context) where the sso server runs.

[alexlarocca]

the only difference seems to be the path - local virtual hosts do not have context, while the online broker is on /sso-broker

[alexlarocca]

The problem is on Server startBrokerSession() call: Bearer token isn't attached to a client session

$sessionId = $this->cache->get($this->getCacheKey($brokerId, $token));

$brokerId and $token are properly set but $sessionId is null

[alexlarocca]

Once set a different folder to store cache (rather /tmp), a different error occurs: Session has expired. Client must attach with new token.

This error occurs only with a broker while other two brokers works properly. In all cases, the cache files are created, named as SSO-(brokerId)-(token).php.cache and all have the same content. It seems that is not able to resume the session

=== First broker: success ===

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"start session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":47,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"started: 1","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":53,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"error: ","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":60,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"session: ","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":64,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"INFO","level_value":200,"message":"Attached broker token to session","context":{"broker":"Alice","token":"5m5ortumlvcw0kg4occcwgs0w40wgocs4g4ogo0kog8ko8ogw8","session":"dc6uqdbcsa1ed8cmj7l5l0k6e0"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":279,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"Validate checksum","context":{"broker":"Alice","token":"5m5ortumlvcw0kg4occcwgs0w40wgocs4g4ogo0kog8ko8ogw8","code":"44idhy7vnc4k08sks488w4cgws0co0s8ksgcggkc8kk048sk44","checksum":"368uq298cx6ogsc8kooowsc0ws4ks4080cc8w4k4gs4cok8kkg"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":109,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"Resuming","context":{"session":"dc6uqdbcsa1ed8cmj7l5l0k6e0"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":114,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"resume session dc6uqdbcsa1ed8cmj7l5l0k6e0","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":72,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"started: 1","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":77,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"error: ","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":84,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"session: ","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":86,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"Resumed","context":{"session":"dc6uqdbcsa1ed8cmj7l5l0k6e0"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":118,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":275}

{"timestamp":"1707396338","channel":"SSO","level":"DEBUG","level_value":100,"message":"Broker request with session","context":{"broker":"Alice","token":"5m5ortumlvcw0kg4occcwgs0w40wgocs4g4ogo0kog8ko8ogw8","session":"dc6uqdbcsa1ed8cmj7l5l0k6e0"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":120,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":275}

=== Second broker: error ===

{"timestamp":"1707396352","channel":"SSO","level":"DEBUG","level_value":100,"message":"start session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":47,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":275}

{"timestamp":"1707396352","channel":"SSO","level":"DEBUG","level_value":100,"message":"started: 1","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":53,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":275}

{"timestamp":"1707396352","channel":"SSO","level":"DEBUG","level_value":100,"message":"error: ","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":60,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":275}

{"timestamp":"1707396352","channel":"SSO","level":"DEBUG","level_value":100,"message":"session: ","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":64,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":275}

{"timestamp":"1707396352","channel":"SSO","level":"INFO","level_value":200,"message":"Attached broker token to session","context":{"broker":"Julius","token":"szln2zwsoqowkoowo084ok844w0csss84s0gkko4gw440cswg","session":"dc6uqdbcsa1ed8cmj7l5l0k6e0"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":279,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":275}

{"timestamp":"1707396353","channel":"SSO","level":"DEBUG","level_value":100,"message":"Validate checksum","context":{"broker":"Julius","token":"szln2zwsoqowkoowo084ok844w0csss84s0gkko4gw440cswg","code":"1tiv7k0ijbok4g4wsg0gg80s8k0ckk00888o8wog8sgw0040ko","checksum":"4zstbp2twzk0k8oc4ggksgwg4cwosgc80ocsowwsc0ss4wco8w"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":109,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":221}

{"timestamp":"1707396353","channel":"SSO","level":"DEBUG","level_value":100,"message":"Resuming","context":{"session":"dc6uqdbcsa1ed8cmj7l5l0k6e0"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":114,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":221}

{"timestamp":"1707396353","channel":"SSO","level":"DEBUG","level_value":100,"message":"resume session dc6uqdbcsa1ed8cmj7l5l0k6e0","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":72,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":221}

{"timestamp":"1707396353","channel":"SSO","level":"DEBUG","level_value":100,"message":"started: 1,"context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":77,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":221}

{"timestamp":"1707396353","channel":"SSO","level":"DEBUG","level_value":100,"message":"error: ","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":84,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":221}

{"timestamp":"1707396353","channel":"SSO","level":"DEBUG","level_value":100,"message":"session: ","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":86,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":221}

=== SSO-SSO-Alice-5m5ortumlvcw0kg4occcwgs0w40wgocs4g4ogo0kog8ko8ogw8.php.cache ===

9223372036854775807
s:26:"dc6uqdbcsa1ed8cmj7l5l0k6e0";

=== SSO-Julius-szln2zwsoqowkoowo084ok844w0csss84s0gkko4gw440cswg.php.cache ===

9223372036854775807
s:26:"dc6uqdbcsa1ed8cmj7l5l0k6e0";

[alexlarocca]

@jasny what is the reason why a broker fails to resume session while others do it properly? The session id provided is the same

[jasny]

Where is the server running? If that's locally (on your computer), the online broker won't be able to connect.

[alexlarocca]

The SSO server is running on https://test.echosistemi.it/sso while the broker with problem is running on https://www.alessandrolarocca.it/sso-broker.

[alexlarocca]

Hello @jasny, I added some log to the code in order to track the issue. When remote broker (https://www.alessandrolarocca.it/sso-broker, Julius) connect to the SSO server (https://test.echosistemi.it/sso) the broker is successfully attached to the session. Then startBrokerSession is called, the session id is retrieved properly and the checkum validated. Finally it tries to resume the session but fails ($_SESSION is empty) and throws the exception "Session has expired. Client must attach with new token".

Instead if my local broker (broker1.local, Alice) connects the SSO server, the full process including session resume completes successfully.

Please help, I'm discouraged. I don't know what else to try.

=== Broker OK (Alice) ===

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"attach","context":{"broker":"Alice","token":"5r9ygrpp1asc4scos4080ocko8g0osw8gocsww0oskgw0wskok"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":263,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"starting session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":264,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"session started","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":268,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"cache key: SSO-Alice-5r9ygrpp1asc4scos4080ocko8g0osw8gocsww0oskgw0wskok","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":273,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"INFO","level_value":200,"message":"Attached broker token to session","context":{"broker":"Alice","token":"5r9ygrpp1asc4scos4080ocko8g0osw8gocsww0oskgw0wskok","session":"qi1t40od1lrefnkdup4kss7qei"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":284,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"verification code: 3f54qamghqw4w4gwss4kkookos0k0cwsg4o480gc0008cokogk","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":288,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"starting broker session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":88,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"bearer: SSO-Alice-5r9ygrpp1asc4scos4080ocko8g0osw8gocsww0oskgw0wskok-1epxttsyxq4kcs0goow84gsw8wwwo8cscossckccggko8cwk44","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":96,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"parsed bearer: ","context":["Alice","5r9ygrpp1asc4scos4080ocko8g0osw8gocsww0oskgw0wskok","1epxttsyxq4kcs0goow84gsw8wwwo8cscossckccggko8cwk44"],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":100,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"sessionId: qi1t40od1lrefnkdup4kss7qei","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":104,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"verification code: 3f54qamghqw4w4gwss4kkookos0k0cwsg4o480gc0008cokogk","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":115,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"validating checksum","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":116,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"checksum validated","context":{"broker":"Alice","token":"5r9ygrpp1asc4scos4080ocko8g0osw8gocsww0oskgw0wskok","code":"3f54qamghqw4w4gwss4kkookos0k0cwsg4o480gc0008cokogk","checksum":"1epxttsyxq4kcs0goow84gsw8wwwo8cscossckccggko8cwk44"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":119,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"resuming session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":121,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"session resumed","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":123,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

{"timestamp":"1707468231","channel":"SSO","level":"DEBUG","level_value":100,"message":"Broker request with session","context":{"broker":"Alice","token":"5r9ygrpp1asc4scos4080ocko8g0osw8gocsww0oskgw0wskok","session":"qi1t40od1lrefnkdup4kss7qei"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":125,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":395}

=== Broker ERROR (Julius) ===

{"timestamp":"1707468255","channel":"SSO","level":"DEBUG","level_value":100,"message":"attach","context":{"broker":"Julius","token":"5vyqz6xvprk8okck8c8skocosow000ggo0sw84g08soows4gk8"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":263,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468255","channel":"SSO","level":"DEBUG","level_value":100,"message":"starting session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":264,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468255","channel":"SSO","level":"DEBUG","level_value":100,"message":"session started","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":268,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468255","channel":"SSO","level":"DEBUG","level_value":100,"message":"cache key: SSO-Julius-5vyqz6xvprk8okck8c8skocosow000ggo0sw84g08soows4gk8","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":273,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468255","channel":"SSO","level":"INFO","level_value":200,"message":"Attached broker token to session","context":{"broker":"Julius","token":"5vyqz6xvprk8okck8c8skocosow000ggo0sw84g08soows4gk8","session":"qi1t40od1lrefnkdup4kss7qei"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":284,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468255","channel":"SSO","level":"DEBUG","level_value":100,"message":"verification code: 44g2jvilkgw084kog0s88wcs0w48wc0cg0c8swgok0wog0gcs0","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":288,"class":"Jasny\\SSO\\Server\\Server","function":"attach"},"pid":395}

{"timestamp":"1707468256","channel":"SSO","level":"DEBUG","level_value":100,"message":"starting broker session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":88,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":289}

{"timestamp":"1707468256","channel":"SSO","level":"DEBUG","level_value":100,"message":"bearer: SSO-Julius-5vyqz6xvprk8okck8c8skocosow000ggo0sw84g08soows4gk8-31vayholxd0kk4ssog080s4k4c408cgk8c4gwwg4sc0w4c888g","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":96,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":289}

{"timestamp":"1707468256","channel":"SSO","level":"DEBUG","level_value":100,"message":"parsed bearer: ","context":["Julius","5vyqz6xvprk8okck8c8skocosow000ggo0sw84g08soows4gk8","31vayholxd0kk4ssog080s4k4c408cgk8c4gwwg4sc0w4c888g"],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":100,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":289}

{"timestamp":"1707468256","channel":"SSO","level":"DEBUG","level_value":100,"message":"sessionId: qi1t40od1lrefnkdup4kss7qei","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":104,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":289}

{"timestamp":"1707468256","channel":"SSO","level":"DEBUG","level_value":100,"message":"verification code: 44g2jvilkgw084kog0s88wcs0w48wc0cg0c8swgok0wog0gcs0","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":115,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":289}

{"timestamp":"1707468256","channel":"SSO","level":"DEBUG","level_value":100,"message":"validating checksum","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":116,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":289}

{"timestamp":"1707468256","channel":"SSO","level":"DEBUG","level_value":100,"message":"checksum validated","context":{"broker":"Julius","token":"5vyqz6xvprk8okck8c8skocosow000ggo0sw84g08soows4gk8","code":"44g2jvilkgw084kog0s88wcs0w48wc0cg0c8swgok0wog0gcs0","checksum":"31vayholxd0kk4ssog080s4k4c408cgk8c4gwwg4sc0w4c888g"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":119,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":289}

{"timestamp":"1707468256","channel":"SSO","level":"DEBUG","level_value":100,"message":"resuming session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/Server.php","line":121,"class":"Jasny\\SSO\\Server\\Server","function":"startBrokerSession"},"pid":289}

SSO-Alice-5r9ygrpp1asc4scos4080ocko8g0osw8gocsww0oskgw0wskok.php.cache

9223372036854775807
s:26:"qi1t40od1lrefnkdup4kss7qei";

SSO-Julius-5vyqz6xvprk8okck8c8skocosow000ggo0sw84g08soows4gk8.php.cache

9223372036854775807
s:26:"qi1t40od1lrefnkdup4kss7qei";

[jasny]

It's not clear from the log what's going wrong. I'm afraid some debugging is required.

---

Add a PHP script that dumps the content of $_SESSION on the server. That way you can check if the session is accidentally cleared.

---

The resume function is supposed to check if a new session is started and otherwise give an error. Maybe that check doesn't work as intended and session_start() returns true instead of false if another session is already started.

sso/src/Server/GlobalSession.php

Lines 59 to 74 in 1bc1619

	public function resume(string $id): void
	{
	session_id($id);
	$started = session_start($this->options);
	if (!$started) {
	$err = error_get_last() ?? ['message' => 'Failed to start session'];
	throw new ServerException($err['message'], 500);
	}
	if ($_SESSION === []) {
	session_abort();
	throw new BrokerException("Session has expired. Client must attach with new token.", 401);
	}
	}

In this function, can you add on the first line (before session_id($id))

if (session_status() === PHP_SESSION_ACTIVE) {
    throw new ServerException("Unable to resume session. A session has already started");
}

It's not clear why that would be the case for one broker and not the other, but it's worth a try.

[alexlarocca]

I changed GlobalSession.php start and resume method:

    public function start(): void
    {
        $this->logger->debug("starting session");

        $started = session_status() !== PHP_SESSION_ACTIVE
            ? session_start($this->options)
            : true;

        if (!$started) {
            $err = error_get_last() ?? ['message' => 'Failed to start session'];
            throw new ServerException($err['message'], 500);
        }

        // Session shouldn't be empty when resumed.
        $_SESSION['_sso_init'] = 1;


        $this->logger->debug("start - dump session", $_SESSION);
    }

    public function resume(string $id): void
    {
        $this->logger->debug("resuming session: " . $id);
		
		if (session_status() === PHP_SESSION_ACTIVE) {
		    throw new ServerException("Unable to resume session. A session has already started");
		}
				
        session_id($id);
        $started = session_start($this->options);

        $this->logger->debug("resume - dump session", $_SESSION);

        if (!$started) {
            $err = error_get_last() ?? ['message' => 'Failed to start session'];
            throw new ServerException($err['message'], 500);
        }

        if ($_SESSION === []) {
            session_abort();
            throw new BrokerException("Session has expired. Client must attach with new token.", 401);
        }

        $this->logger->debug("session resumed");
    }

The check you suggested at the begin of resume method has not effect. The exception never throws.

The session dump is in the log context.
I did the following test:

1. local broker Alice connects the SSO server and login: SUCCESS
2. remote broker Julius connects the SSO server: ERROR (Session has expired...)
3. local broker Greg connects the SSO server and login: SUCCESS (authenticated as john)

Note that when remote broker start the session, it includes _sso_init and user. But this fields are not availaable when resuming.
But these are not lost since the third broker resumes properly the session and retrieves them.

LOCAL BROKER (Alice)

{"timestamp":"1707478184","channel":"SSO","level":"DEBUG","level_value":100,"message":"starting session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":47,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":417}

{"timestamp":"1707478184","channel":"SSO","level":"DEBUG","level_value":100,"message":"start - dump session","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":62,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":417}

{"timestamp":"1707478184","channel":"SSO","level":"DEBUG","level_value":100,"message":"resuming session: tjknbvkepfscmfn30asosbvh2f","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":70,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478184","channel":"SSO","level":"DEBUG","level_value":100,"message":"resume - dump session","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":80,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478184","channel":"SSO","level":"DEBUG","level_value":100,"message":"session resumed","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":92,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478209","channel":"SSO","level":"DEBUG","level_value":100,"message":"resuming session: tjknbvkepfscmfn30asosbvh2f","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":70,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478209","channel":"SSO","level":"DEBUG","level_value":100,"message":"resume - dump session","context":{"_sso_init":1},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":80,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478209","channel":"SSO","level":"DEBUG","level_value":100,"message":"session resumed","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":92,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478209","channel":"SSO","level":"DEBUG","level_value":100,"message":"resuming session: tjknbvkepfscmfn30asosbvh2f","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":70,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478209","channel":"SSO","level":"DEBUG","level_value":100,"message":"resume - dump session","context":{"_sso_init":1,"user":"john"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":80,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478209","channel":"SSO","level":"DEBUG","level_value":100,"message":"session resumed","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":92,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

REMOTE BROKER (Julius)

{"timestamp":"1707478222","channel":"SSO","level":"DEBUG","level_value":100,"message":"starting session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":47,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":417}

{"timestamp":"1707478222","channel":"SSO","level":"DEBUG","level_value":100,"message":"start - dump session","context":{"_sso_init":1,"user":"john"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":62,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":417}

{"timestamp":"1707478223","channel":"SSO","level":"DEBUG","level_value":100,"message":"resuming session: tjknbvkepfscmfn30asosbvh2f","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":70,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":305}

{"timestamp":"1707478223","channel":"SSO","level":"DEBUG","level_value":100,"message":"resume - dump session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":80,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":305}

LOCAL BROKER (Greg)

{"timestamp":"1707478236","channel":"SSO","level":"DEBUG","level_value":100,"message":"starting session","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":47,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":417}

{"timestamp":"1707478236","channel":"SSO","level":"DEBUG","level_value":100,"message":"start - dump session","context":{"_sso_init":1,"user":"john"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":62,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"start"},"pid":417}

{"timestamp":"1707478236","channel":"SSO","level":"DEBUG","level_value":100,"message":"resuming session: tjknbvkepfscmfn30asosbvh2f","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":70,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478236","channel":"SSO","level":"DEBUG","level_value":100,"message":"resume - dump session","context":{"_sso_init":1,"user":"john"},"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":80,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

{"timestamp":"1707478236","channel":"SSO","level":"DEBUG","level_value":100,"message":"session resumed","context":[],"backtrace":{"file":"/web/htdocs/test.echosistemi.it/home/sso/src/Server/GlobalSession.php","line":92,"class":"Jasny\\SSO\\Server\\GlobalSession","function":"resume"},"pid":417}

[jasny]

This is very strange. The whole point is that if you start a session with the same session id, you'll get the same session data.

The only thing I'm noticing is that all logs have pid: 417 except the resume call for Julius that has pid: 305. Maybe memory caching? Have a look at your PHP FPM settings.