Session data not saved before redirect

[JimBacon]

When redirecting between pages using hostsite_goto_page() in iform.hostsite_api.inc, the source page is quit abruptly without saving session data or form data.

This became an issue for https://github.com/BiologicalRecordsCentre/UKBMS-online/issues/285 where the easy_login module was setting information about resolving multiple users in session data and then redirecting to another page to display that information. Because the session data was not saved, nothing could be displayed.

[JimBacon]

There seems to be more to this than I first thought. While the session data is now saved via one database connection, when the page we are redirected to requests the session data via another database connection it sometimes gets the wrong result.

From the log:

15:01:26.329474021Z            336 Query    UPDATE "sessions" SET "uid"='30228', "hostname"='172.20.0.2', "session"='_sf2_attributes|a:3:{s:3:\"uid\";s:5:\"30228\";s:36:\"easy_login_multiple_users_to_resolve\";a:8:{i:0;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:3:\"118\";s:5:\"title\";s:4:\"EBMS\";}i:1;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:3:\"134\";s:5:\"title\";s:9:\"FIT Count\";}i:2;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:2:\"16\";s:5:\"title\";s:10:\"Moth Night\";}i:3;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:2:\"46\";s:5:\"title\";s:14:\"ICP Vegetation\";}i:4;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:2:\"10\";s:5:\"title\";s:3:\"ORS\";}i:5;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:3:\"113\";s:5:\"title\";s:32:\"National Honey Monitoring Scheme\";}i:6;O:8:\"stdClass\":3:{s:7:\"user_id\";s:6:\"150616\";s:10:\"website_id\";s:2:\"23\";s:5:\"title\";s:7:\"iRecord\";}i:7;O:8:\"stdClass\":3:{s:7:\"user_id\";s:6:\"150616\";s:10:\"website_id\";s:2:\"46\";s:5:\"title\";s:14:\"ICP Vegetation\";}}s:25:\"easy_login_uid_to_resolve\";s:5:\"30704\";}_sf2_meta|a:4:{s:1:\"u\";i:1664981957;s:1:\"c\";i:1664976852;s:1:\"l\";i:2000000;s:1:\"s\";s:43:\"am_oJCqTFYiZ1mFM7RaMrXrgiWI53Fu-AT1qC_g-4jc\";}multiple_users_to_resolve|a:8:{i:0;r:4;i:1;r:8;i:2;r:12;i:3;r:16;i:4;r:20;i:5;r:24;i:6;r:28;i:7;r:32;}uid_to_resolve|s:5:\"30704\";', "timestamp"='1664982057'
15:01:26.329515660Z WHERE "sid" = 'iId0mGeZjByEk8DP3t03Gpu-HWJ3yDd59OD-Nkh-lxI'
15:01:51.472921808Z            336 Query    SELECT "name", "value" FROM "key_value" WHERE "name" IN ( 'system.cron_last' ) AND "collection" = 'state'
15:01:58.838544318Z            337 Connect  pantheon@172.22.0.4 as anonymous on pantheon
15:01:58.838578238Z            337 Query    SET NAMES utf8
15:01:58.838583648Z            337 Query    SELECT count(*) FROM users
15:01:58.838589583Z            337 [Warning] Aborted connection 337 to db: 'pantheon' user: 'pantheon' host: '172.22.0.4' (Got an error reading communication packets)
15:01:58.846465096Z            338 Connect  pantheon@172.22.0.4 as anonymous on pantheon
15:01:58.846529448Z            338 Query    SET NAMES utf8
15:01:58.846644649Z            338 Query    SET NAMES utf8mb4
15:01:58.846885633Z            338 Query    SET sql_mode = 'ANSI,TRADITIONAL'
15:01:58.847404352Z            338 Query    SELECT "cid", "data", "created", "expire", "serialized", "tags", "checksum" FROM "cache_container" WHERE "cid" IN ( 'service_container:prod:9.4.7::Linux:a:1:{i:0;s:35:\"/app/web/sites/default/services.yml\";}' ) ORDER BY "cid"
15:01:58.856909366Z            338 Query    SELECT "session" FROM "sessions" WHERE "sid" = 'iId0mGeZjByEk8DP3t03Gpu-HWJ3yDd59OD-Nkh-lxI' LIMIT 0, 1

There is nothing in the log to show that transactions are being used or that auto commit has been disabled so the update should be visible. Even from a command prompt, a query on the sessions table returns the old data.

Another time it works and the log shows

17:56:46.162687382Z             48 Query    UPDATE "sessions" SET "uid"='30228', "hostname"='172.20.0.2', "session"='_sf2_attributes|a:3:{s:3:\"uid\";s:5:\"30228\";s:36:\"easy_login_multiple_users_to_resolve\";a:8:{i:0;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:3:\"118\";s:5:\"title\";s:4:\"EBMS\";}i:1;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:3:\"134\";s:5:\"title\";s:9:\"FIT Count\";}i:2;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:2:\"16\";s:5:\"title\";s:10:\"Moth Night\";}i:3;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:2:\"46\";s:5:\"title\";s:14:\"ICP Vegetation\";}i:4;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:2:\"10\";s:5:\"title\";s:3:\"ORS\";}i:5;O:8:\"stdClass\":3:{s:7:\"user_id\";s:2:\"24\";s:10:\"website_id\";s:3:\"113\";s:5:\"title\";s:32:\"National Honey Monitoring Scheme\";}i:6;O:8:\"stdClass\":3:{s:7:\"user_id\";s:6:\"150616\";s:10:\"website_id\";s:2:\"23\";s:5:\"title\";s:7:\"iRecord\";}i:7;O:8:\"stdClass\":3:{s:7:\"user_id\";s:6:\"150616\";s:10:\"website_id\";s:2:\"46\";s:5:\"title\";s:14:\"ICP Vegetation\";}}s:25:\"easy_login_uid_to_resolve\";s:5:\"30704\";}_sf2_meta|a:4:{s:1:\"u\";i:1664992551;s:1:\"c\";i:1664976852;s:1:\"l\";i:2000000;s:1:\"s\";s:43:\"am_oJCqTFYiZ1mFM7RaMrXrgiWI53Fu-AT1qC_g-4jc\";}multiple_users_to_resolve|a:8:{i:0;r:4;i:1;r:8;i:2;r:12;i:3;r:16;i:4;r:20;i:5;r:24;i:6;r:28;i:7;r:32;}uid_to_resolve|s:5:\"30704\";', "timestamp"='1664992587'
17:56:46.162746980Z WHERE "sid" = 'iId0mGeZjByEk8DP3t03Gpu-HWJ3yDd59OD-Nkh-lxI'
17:56:46.166293914Z             48 Query    SELECT "name", "value" FROM "key_value" WHERE "name" IN ( 'system.cron_last' ) AND "collection" = 'state'
17:56:46.166818988Z             48 Quit 
17:56:47.856099314Z         49 Connect  pantheon@172.18.0.2 as anonymous on pantheon
17:56:47.856175826Z             49 Query    SET NAMES utf8
17:56:47.856409336Z             49 Query    SELECT count(*) FROM users
17:56:47.856691617Z         49[Warning] Aborted connection 49 to db: 'pantheon' user: 'pantheon' host: '172.18.0.2' (Got an error reading communication packets)
17:56:47.872790217Z             50 Query    SET NAMES utf8
17:56:47.872806351Z             50 Query    SET NAMES utf8mb4
17:56:47.872813463Z             50 Query    SET sql_mode = 'ANSI,TRADITIONAL'
17:56:47.873845494Z             50 Query    SELECT "cid", "data", "created", "expire", "serialized", "tags", "checksum" FROM "cache_container" WHERE "cid" IN ( 'service_container:prod:9.4.7::Linux:a:1:{i:0;s:35:\"/app/web/sites/default/services.yml\";}' ) ORDER BY "cid"
17:56:47.893812971Z             50 Query    SELECT "session" FROM "sessions" WHERE "sid" = 'iId0mGeZjByEk8DP3t03Gpu-HWJ3yDd59OD-Nkh-lxI' LIMIT 0, 1

The difference is in the Quit command.

[JimBacon]

Lot's of difficulty around understanding this as PHP should close connections at the end of a script regardless of anything Drupal does.

There is a bad thing we are doing which is a redirect from within a hook. Other hooks may fail to run as a result. Maybe if we stop doing this it will behave

One resolution to this is to add some middleware. However, the Drupal docs say:

Middlewares run on every request. Effectively, the Middleware API is the equivalent of Drupal 7's hook_boot(). So, make sure they run at the appropriate time (i.e. the appropriate order), and ensure they do as little I/O as possible. Because every request will be impacted.

An alternative is to restructure the code so that we redirect from a form submit handler rather than from a hook.

A first attempt failed because, in Drupal/Core/EventSubscriber/RedirectResponseSubscriber.php, a destination query parameter will override the redirect target. There is a fix in progress for this but, in the meantime, the workaround is to remove the query parameter.

[JimBacon]

Closing as the fix needs to be completed in the easy_login module.