Failing to read/write session data to redis
mdavis332 opened this issue · 3 comments
Just upgraded from MISP v2.4.188 to v2.4.189 and rebuilt container image based on latest NUKIB/misp. In a local host using docker compose as well as in AWS I'm seeing session errors I've never observed before. Posting them here first since this project uses redis as session handler by default and wondering if you all are seeing the same thing. Here's an example trying to load the main page while authenticated in a web browser:
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Warning (2): session_start(): Failed to acquire session lock in [/var/www/MISP/app/Vendor/cakephp/cakephp/lib/Cake/Model/Datasource/CakeSession.php, line 745]
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Trace:
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: ErrorHandler::handleError() - APP/Vendor/cakephp/cakephp/lib/Cake/Error/ErrorHandler.php, line 230
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Configure::{closure}() - APP/Config/core.php, line 61
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: session_start - [internal], line ??
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: CakeSession::_startSession() - APP/Vendor/cakephp/cakephp/lib/Cake/Model/Datasource/CakeSession.php, line 745
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: CakeSession::start() - APP/Vendor/cakephp/cakephp/lib/Cake/Model/Datasource/CakeSession.php, line 219
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: CakeSession::read() - APP/Vendor/cakephp/cakephp/lib/Cake/Model/Datasource/CakeSession.php, line 404
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: SessionComponent::read() - APP/Vendor/cakephp/cakephp/lib/Cake/Controller/Component/SessionComponent.php, line 69
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: AppController::beforeFilter() - APP/Controller/AppController.php, line 243
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: EventsController::beforeFilter() - APP/Controller/EventsController.php, line 68
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: BetterCakeEventManager::dispatch() - APP/Lib/Tools/BetterCakeEventManager.php, line 23
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Controller::startupProcess() - APP/Vendor/cakephp/cakephp/lib/Cake/Controller/Controller.php, line 682
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Dispatcher::_invoke() - APP/Vendor/cakephp/cakephp/lib/Cake/Routing/Dispatcher.php, line 189
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Dispatcher::dispatch() - APP/Vendor/cakephp/cakephp/lib/Cake/Routing/Dispatcher.php, line 167
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: [main] - APP/webroot/index.php, line 101
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning:
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Warning (2): session_start() [<a href='http://php.net/function.session-start'>function.session-start</a>]: Failed to read session data: redis (path: tcp://redis:6379?database=12) in [/var/www/MISP/app/Vendor/cakephp/cakephp/lib/Cake/Model/Datasource/CakeSession.php, line 745]
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Trace:
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: ErrorHandler::handleError() - APP/Vendor/cakephp/cakephp/lib/Cake/Error/ErrorHandler.php, line 230
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Configure::{closure}() - APP/Config/core.php, line 61
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: session_start - [internal], line ??
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: CakeSession::_startSession() - APP/Vendor/cakephp/cakephp/lib/Cake/Model/Datasource/CakeSession.php, line 745
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: CakeSession::start() - APP/Vendor/cakephp/cakephp/lib/Cake/Model/Datasource/CakeSession.php, line 219
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: CakeSession::read() - APP/Vendor/cakephp/cakephp/lib/Cake/Model/Datasource/CakeSession.php, line 404
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: SessionComponent::read() - APP/Vendor/cakephp/cakephp/lib/Cake/Controller/Component/SessionComponent.php, line 69
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: AppController::beforeFilter() - APP/Controller/AppController.php, line 243
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: EventsController::beforeFilter() - APP/Controller/EventsController.php, line 68
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: BetterCakeEventManager::dispatch() - APP/Lib/Tools/BetterCakeEventManager.php, line 23
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Controller::startupProcess() - APP/Vendor/cakephp/cakephp/lib/Cake/Controller/Controller.php, line 682
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Dispatcher::_invoke() - APP/Vendor/cakephp/cakephp/lib/Cake/Routing/Dispatcher.php, line 189
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: Dispatcher::dispatch() - APP/Vendor/cakephp/cakephp/lib/Cake/Routing/Dispatcher.php, line 167
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning: [main] - APP/webroot/index.php, line 101
misp | Apr 11 14:01:43 045b3f00eac1 MISP: warning:
misp | Apr 11 14:01:44 045b3f00eac1 php-fpm-access - ZhftOg4FjoFLBowIwHokCwAAAMo - 11/Apr/2024:14:01:30 +0000 "GET /index.php" 200 14510.261 2048 1.24%
Later on I see something similar in the logs when it tries to write the session:
misp | Apr 11 14:07:33 045b3f00eac1 MISP: warning: Warning (2): session_write_close() [<a href='http://php.net/function.session-write-close'>function.session-write-close</a>]: Failed to write session data (redis). Please verify that the current setting of session.save_path is correct (tcp://redis:6379?database=12) in [/var/www/MISP/app/Lib/Tools/CakeResponseFile.php, line 54]
I've heard from one other person now who's seen this same behavior. No one here though?
Hello, this is expected behavior. If sessions are stored in Redis, PHP will wait 5 seconds to check if current session is still used. If session is still locked, page is loaded and the warning log is generated. This behavior allows to load page even if another page is still loading and stuck.
Hello, this is expected behavior. If sessions are stored in Redis, PHP will wait 5 seconds to check if current session is still used. If session is still locked, page is loaded and the warning log is generated. This behavior allows to load page even if another page is still loading and stuck.
Interesting, thanks. I hadn't seen these entries in my logs prior to v2.4.189 so it seemed like a(nother) new issue.