[BUG] Random 403 for random users at random time.

[goryn-clade]

[BUG] Random 403 for random users at random time.

[samoneilll]

This has been an issue in PF since v1.x. It's common for users to get booted out with a random 403 from time to time. We have noticed that it happens more often when the browser tab is idle. If we could get more reports we could try to look into it.

[Shadow-230]

I can ask to give me details every time it's occure, just need info what details you need.

[TyrHeimdalEVE]

@samoneilll I think this could be related to that hard-coded limit which isn't really configurable.

Let's keep this open and see if we can optimize the session age and how it's handled in the UI as a milestone.

Would be better if it visually said the user was thrown out due to a timeout than throwing an error.

[Shadow-230]

Could we include some catch in the code to see this?

[samoneilll]

Well, the default of that hardcoded limit is 8 hours, but I regularly see it kick me out after 20-30 minutes, or even less in some cases. I'm not 100% sure that it's related to session handling, the errors I see from my containers don't include that read-error from redis in the original report.

@Shadow-230 we can definitely improve how it's handled to give a better reason than just "403", but at this stage we actually don't understand the root cause of the issue, your logs there don't match with what I've seen historically, so it could be a separate issue.

To collect more reports what we need is the browser console errors, and any stdout from the container, just like in the original report here.

[samoneilll]

I believe that the uncaught promise error can be ignored. This is just js that's running on the page failing since it can no longer access map properties. If 403 and then leave it open you'll have pages for those uncaught promise errors because the js keeps executing with no map object to work with.

[Shadow-230]

I'm just checking Network from DevTools on Chrome and see that even if I have PF tab in backgroud it still communicating with map so not sure why suddenly we can't access map properties at some time and getting 403.

[samoneilll]

What I'm saying is that at the point where the 403 occurs the map disappears and you see a black page with the error message in the middle. At this point, there's still map related JS functions that are running, but no longer have a map object to work with and start filling the console log with errors that we can ignore because they're not actually related to the 403, just zombie processes in the browser.

[Shadow-230]

I have some new errors:.

[29-Oct-2021 11:56:38] WARNING: [pool www] child 390001 said into stderr: "NOTICE: PHP message: PHP Fatal error:  Uncaught RuntimeException: Write timed-out, no data sent for `10` seconds, probably we got disconnected (sent 0 of 856) in /var/www/html/pathfinder/vendor/monolog/monoldler/SocketHandler.php:389"
[29-Oct-2021 11:56:38] WARNING: [pool www] child 390001 said into stderr: "Stack trace:"
[29-Oct-2021 11:56:38] WARNING: [pool www] child 390001 said into stderr: "#0 /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/SocketHandler.php(72): Monolog\Handler\SocketHandler->writeToSocket('{"task":"logDat...')"
[29-Oct-2021 11:56:38] WARNING: [pool www] child 390001 said into stderr: "#1 /var/www/html/pathfinder/app/Lib/Logging/Handler/SocketHandler.php(58): Monolog\Handler\SocketHandler->write(Array)"
[29-Oct-2021 11:56:38] WARNING: [pool www] child 390001 said into stderr: "#2 /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/Handler.php(27): Exodus4D\Pathfinder\Lib\Logging\Handler\SocketHandler->handle(Array)"
[29-Oct-2021 11:56:38] WARNING: [pool www] child 390001 said into stderr: "#3 /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/BufferHandler.php(99): Monolog\Handler\Handler->handleBatch(Array)"
[29-Oct-2021 11:56:38] WARNING: [pool www] child 390001 said into stderr: "#4 /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/BufferHandler.php(115): Monolog\Handler\BufferHandler->flush()"
[29-Oct-2021 11:56:38] WARNING: [pool www] child 390001 said into stderr: "#5 [internal function]: Monolog\Handler\Buffer..."


[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: HTTP 403 (POST /api/User/getCookieCharacter)"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [vendor/bcosca/fatfree-core/db/sql/session.php:77] Base->error()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:448] Base->exists()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:410] Exodus4D\Pathfinder\Controller\Controller->getUser()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:436] Exodus4D\Pathfinder\Controller\Controller->getSessionCharacter()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [app/Controller/Api/User.php:133] Exodus4D\Pathfinder\Controller\Controller->getCharacter()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [index.php:27] Base->run()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: session_start(): Failed to read session data: user (path: tcp://pf-redis:6379)"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:448] Base->exists()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:410] Exodus4D\Pathfinder\Controller\Controller->getUser()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:436] Exodus4D\Pathfinder\Controller\Controller->getSessionCharacter()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [app/Controller/Api/User.php:133] Exodus4D\Pathfinder\Controller\Controller->getCharacter()"
[29-Oct-2021 12:05:51] WARNING: [pool www] child 394730 said into stderr: "NOTICE: PHP message: [index.php:27] Base->run()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: HTTP 403 (GET /api/Map/getAccessData)"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [vendor/bcosca/fatfree-core/db/sql/session.php:77] Base->error()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:448] Base->exists()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:410] Exodus4D\Pathfinder\Controller\Controller->getUser()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:436] Exodus4D\Pathfinder\Controller\Controller->getSessionCharacter()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:47] Exodus4D\Pathfinder\Controller\Controller->getCharacter()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:27] Exodus4D\Pathfinder\Controller\AccessController->isLoggedIn()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [index.php:27] Base->run()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: session_start(): Failed to read session data: user (path: tcp://pf-redis:6379)"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:448] Base->exists()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:410] Exodus4D\Pathfinder\Controller\Controller->getUser()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:436] Exodus4D\Pathfinder\Controller\Controller->getSessionCharacter()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:47] Exodus4D\Pathfinder\Controller\Controller->getCharacter()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:27] Exodus4D\Pathfinder\Controller\AccessController->isLoggedIn()"
[29-Oct-2021 12:05:53] WARNING: [pool www] child 392625 said into stderr: "NOTICE: PHP message: [index.php:27] Base->run()"

[28-Oct-2021 21:53:51] WARNING: [pool www] child 357518 said into stderr: "NOTICE: PHP message: HTTP 403 (GET /)"
[28-Oct-2021 21:53:51] WARNING: [pool www] child 357518 said into stderr: "NOTICE: PHP message: [vendor/bcosca/fatfree-core/db/sql/session.php:77] Base->error()"
[28-Oct-2021 21:53:51] WARNING: [pool www] child 357518 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:128] Preview->render()"
[28-Oct-2021 21:53:51] WARNING: [pool www] child 357518 said into stderr: "NOTICE: PHP message: [app/Controller/AppController.php:55] Exodus4D\Pathfinder\Controller\Controller->afterroute()"
[28-Oct-2021 21:53:51] WARNING: [pool www] child 357518 said into stderr: "NOTICE: PHP message: [index.php:27] Base->run()"
[28-Oct-2021 21:53:51] WARNING: [pool www] child 357518 said into stderr: "NOTICE: PHP message: session_commit(): Cannot call session save handler in a recursive manner"

[29-Oct-2021 11:55:08] NOTICE: [pool www] child 389143 exited with code 0 after 2395.146601 seconds from start
[29-Oct-2021 11:55:08] NOTICE: [pool www] child 394072 started
[29-Oct-2021 11:55:38] WARNING: [pool www] child 394072 said into stderr: "NOTICE: PHP message: PHP Fatal error:  Uncaught RuntimeException: Write timed-out, no data sent for `10` seconds, probably we got disconnected (sent 0 of 856) in /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/SocketHandler.php:389"

[Shadow-230]

I just get info that user was kicked and see this log:

[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: HTTP 403 (POST /api/Map/updateUserData)"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [vendor/bcosca/fatfree-core/db/sql/session.php:77] Base->error()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:448] Base->exists()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:410] Exodus4D\Pathfinder\Controller\Controller->getUser()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:436] Exodus4D\Pathfinder\Controller\Controller->getSessionCharacter()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:47] Exodus4D\Pathfinder\Controller\Controller->getCharacter()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:27] Exodus4D\Pathfinder\Controller\AccessController->isLoggedIn()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [index.php:27] Base->run()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: session_start(): Failed to read session data: user (path: tcp://pf-redis:6379)"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:448] Base->exists()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:410] Exodus4D\Pathfinder\Controller\Controller->getUser()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:436] Exodus4D\Pathfinder\Controller\Controller->getSessionCharacter()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:47] Exodus4D\Pathfinder\Controller\Controller->getCharacter()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:27] Exodus4D\Pathfinder\Controller\AccessController->isLoggedIn()"
[29-Oct-2021 12:31:42] WARNING: [pool www] child 398862 said into stderr: "NOTICE: PHP message: [index.php:27] Base->run()"
2021-10-29 12:32:00,935 INFO reaped unknown pid 400252
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: HTTP 403 (GET /map/Mw%3D%3D)"
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: [vendor/bcosca/fatfree-core/db/sql/session.php:77] Base->error()"
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:448] Base->exists()"
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:410] Exodus4D\Pathfinder\Controller\Controller->getUser()"
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: [app/Controller/Controller.php:436] Exodus4D\Pathfinder\Controller\Controller->getSessionCharacter()"
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:47] Exodus4D\Pathfinder\Controller\Controller->getCharacter()"
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: [app/Controller/AccessController.php:27] Exodus4D\Pathfinder\Controller\AccessController->isLoggedIn()"
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: [index.php:27] Base->run()"
[29-Oct-2021 12:32:07] WARNING: [pool www] child 399852 said into stderr: "NOTICE: PHP message: session_commit(): Cannot call session save handler in a recursive manner"

[Shadow-230]

[29-Oct-2021 19:54:55] WARNING: [pool www] child 520614 said into stderr: "NOTICE: PHP message: PHP Fatal error:  Uncaught RuntimeException: Write timed-out, no data sent for `10` seconds, probably we got disconnected (sent 0 of 849) in /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/SocketHandler.php:389"
[29-Oct-2021 19:54:55] WARNING: [pool www] child 520614 said into stderr: "Stack trace:"
[29-Oct-2021 19:54:55] WARNING: [pool www] child 520614 said into stderr: "#0 /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/SocketHandler.php(72): Monolog\Handler\SocketHandler->writeToSocket('{"task":"logDat...')"
[29-Oct-2021 19:54:55] WARNING: [pool www] child 520614 said into stderr: "#1 /var/www/html/pathfinder/app/Lib/Logging/Handler/SocketHandler.php(58): Monolog\Handler\SocketHandler->write(Array)"
[29-Oct-2021 19:54:55] WARNING: [pool www] child 520614 said into stderr: "#2 /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/Handler.php(27): Exodus4D\Pathfinder\Lib\Logging\Handler\SocketHandler->handle(Array)"
[29-Oct-2021 19:54:55] WARNING: [pool www] child 520614 said into stderr: "#3 /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/BufferHandler.php(99): Monolog\Handler\Handler->handleBatch(Array)"
[29-Oct-2021 19:54:55] WARNING: [pool www] child 520614 said into stderr: "#4 /var/www/html/pathfinder/vendor/monolog/monolog/src/Monolog/Handler/BufferHandler.php(115): Monolog\Handler\BufferHandler->flush()"
[29-Oct-2021 19:54:55] WARNING: [pool www] child 520614 said into stderr: "#5 [internal function]: Monolog\Handler\Buffer..."

[Shadow-230]

New update. I have added some logs for execution. Looks like when user is kicked, session ends in $onSuspect function that is in Controller.php file. Source of invoking this function looks to me that is trigerred from AccessController.php file from beforeroute function.
I saw as well that some 403 were redirected to if($f3->get('AJAX')) part of protected function logoutCharacter from Controller.php file.

I think that F3 session handler might have some bug that is causing those problems.

[TyrHeimdalEVE]

I am nearly 100% sure this is related to PHP doing garbage collection and timing out sessions, causing it to error out because the session is no longer valid (even though it should).

Pathfinder has a hard timer set on sessions and I don't think session.gc_maxlifetime is set to a very high value at all in https://github.com/goryn-clade/pathfinder-containers

bash-5.1# php -i | grep -E 'enable_gc|\.gc_'
zend.enable_gc => On => On
session.gc_divisor => 1000 => 1000
session.gc_maxlifetime => 1440 => 1440
session.gc_probability => 1 => 1

We should probably evaluate the PHP settings for sessions in general. I'll try to hop on this in the next couple of days.

[Shadow-230]

@TyrHeimdalEVE let me know if you will have an idea for the fix, I can implement it on my server for the test.

[TyrHeimdalEVE]

@Shadow-230 You could try to add the following to your php.ini:

session.gc_maxlifetime = 86400
session.cookie_secure = 1
session.cookie_samesite = Strict

That should allow for a way longer TTL in the Redis cache. PHP handles the sessions. The last two are purely security related and can be opted out (but I would recommend it as long as it doesn't cause issues).

[Shadow-230]

Change implemented,
session.gc_maxlifetime session.cookie_secure
were already there so I just changed value
session.cookie_samesite was not in the file so new entry in php.ini was created, If this will not work I should have update 03.11.2021 if no issue will be reported, then up to two or three days.

[Shadow-230]

Nothing has changed. Still 403

[Shadow-230]

Based on DB and session_suspect log I saw that web browser Agent data were different.

Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.54 Safari/537.36 Edg/95.0.
Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/95.0.4638.54 Safari/537.36 Edg/95.0.1020.40

This looks like the first entry was not fully readed, or the cache was full?

I also saw a lot of db entries with the same Ip for different users and not sure why.

[samoneilll]

@Shadow-230 can you share the how you added hte logging for the user-agent string?

[Shadow-230]

@samoneilll This is by default in the code for session suspect. Go to logs in pathfinder location and search for session_suspect.log

Implementation of this is available in pathfinder\app\Controller\Controller.php in protected function initSession part related to $onSuspect

[samoneilll]

@Shadow-230 sorry about the very long delay. Is this something that you're still struggling with?

[TyrHeimdalEVE]

Stale, closing. Most likely related to cache being ejected from lack of memory or TTL in Redis.