Repository navigation
Handle session closure properly for redirecting to a controller in a post_login hook #1303
Description
Activity
Not sure whether it is of any help, by coincidence I saw that the recently reported #1282 has the same stacktrace, but in a different testing scenario. Maybe there is some correlation? If yes, one fix could close two issues 😋
@GitHubUser4234 I ran into a similar issue latly, so please retry on master, whether 2cd92d0 fixes the issue
@nickvergessen : Thanks for the hint, I just retried, but unfortunately the error is still there. Line numbers of the stacktrace remain unchanged.
As discussed with @nickvergessen in IRC, this can quickly be reproduced by adding the following lines to
:server/apps/dav/lib/HookManager.php
Line 143 in ce964f0
header('Location: '.\OC::$server->getURLGenerator()->linkToRouteAbsolute('core.login.showLoginForm')); exit();The error would then occur in the server log (NOT nc log), for instance on Apache in the error_log / ssl_error_log file.
More informations before the session issue itself happens. The default encryption module app is enabled but not used.
[Mon Nov 14 18:58:12 2016] User "tcit" removed from group "admin" [Mon Nov 14 18:58:12 2016] unlink(/home/tcit/dev/server/data/tcit/files_encryption/OC_DEFAULT_MODULE/tcit.privateKey): Permission denied at /home/tcit/dev/server/lib/private/legacy/helper.php#215 [Mon Nov 14 18:58:12 2016] unlink(/home/tcit/dev/server/data/tcit/files_encryption/OC_DEFAULT_MODULE/tcit.publicKey): Permission denied at /home/tcit/dev/server/lib/private/legacy/helper.php#215 [Mon Nov 14 18:58:12 2016] rmdir(/home/tcit/dev/server/data/tcit/files_encryption/OC_DEFAULT_MODULE): Permission denied at /home/tcit/dev/server/lib/private/legacy/helper.php#213 [Mon Nov 14 18:58:12 2016] rmdir(/home/tcit/dev/server/data/tcit/files_encryption): Directory not empty at /home/tcit/dev/server/lib/private/legacy/helper.php#213 [Mon Nov 14 18:58:12 2016] rmdir(/home/tcit/dev/server/data/tcit): Directory not empty at /home/tcit/dev/server/lib/private/legacy/helper.php#219 [Mon Nov 14 18:58:12 2016] User deleted: "tcit" [Mon Nov 14 18:58:12 2016] unlink(/home/tcit/dev/server/data/tcit/files_encryption/OC_DEFAULT_MODULE/tcit.publicKey): Permission denied at /home/tcit/dev/server/lib/private/Files/Storage/Local.php#230 [Mon Nov 14 18:58:12 2016] Logout occurred [Mon Nov 14 18:58:12 2016] session_regenerate_id(): Cannot regenerate session id - session is not active at /home/tcit/dev/server/lib/private/Session/Internal.php#115Ran into the same issue while trying to have #1893 in a separate app.
Exact the same stacktrace as in my first post appears in your logs? And also a similar situation (post_login hook -> Controller)?
@LukasReschke and @nickvergessen want to look into this again for Nextcloud 11
Exact the same stacktrace as in my first post appears in your logs?
Yes.
And also a similar situation (post_login hook -> Controller)?
No, trying to delete an user and disconnect him.
@LukasReschke and @nickvergessen want to look into this again for Nextcloud 11
Very happy, thanks guys :)
Exact the same stacktrace as in my first post appears in your logs?
Yes.
And also a similar situation (post_login hook -> Controller)?
No, trying to delete an user and disconnect him.
Interesting information, so seems the problem might have a wider impact, hm...
Minimal example is in the branch minimal-example-for-1303. See 0191995
To test this try to login and look at
/var/log/apache2/error.log:[Tue Nov 15 12:51:59.122300 2016] [:error] [pid 3689] [client 10.211.55.2:61533] PHP Fatal error: Uncaught Exception: Session has been closed - no further changes to the session are allowed in /media/psf/stable9/lib/private/Session/Internal.php:154\nStack trace:\n#0 /media/psf/stable9/lib/private/Session/Internal.php(64): OC\\Session\\Internal->validateSession()\n#1 /media/psf/stable9/lib/private/Session/CryptoSessionData.php(164): OC\\Session\\Internal->set('encrypted_sessi...', '2189243c78b2480...')\n#2 /media/psf/stable9/lib/private/Session/CryptoSessionData.php(67): OC\\Session\\CryptoSessionData->close()\n#3 [internal function]: OC\\Session\\CryptoSessionData->__destruct()\n#4 {main}\n thrown in /media/psf/stable9/lib/private/Session/Internal.php on line 154cc @rullzer
7 remaining items
Mmmm @GitHubUser4234 I think this is because we do write a requesttoken into the session. Then the second time we want to compare that but it fails hard. I will discuss with @LukasReschke and see if we can fix this.
Awesome :))
As discussed today on IRC. Lets try to solve this somewhat safe early in the 12 cycle.
'early' would be now, I suppose :D
'early' would be now, I suppose :D
Hehe, yeah would be really great if someone could have a look at it :)
@rullzer Hem, hem :)
Reacted by Morris JobkeAh yes. sorry this slipped off my radar. No promises but I have it on the list for this week... Now we just pray nothing comes up
Reacted by GitHubUser4234Reacted by Jos Poortvliet- added 2 commits that reference this issue
on Mar 13, 2017 - added a commit that references this issue
on Mar 30, 2017 Cool, it has been merged, thanks a lot!!!
When a redirect to a controller is performed within the method of a post_login hook, an internal error occurs and gets printed in the webserver log (not NC log):
Here is an example code of this happening:
Redirect in the method of a post_login hook
Target method of the controller
The problem is caused by the CryptoSessionData trying to close a session that is already closed. Even if the example code didn't include any session related code, the error would still occur (this has been tested).
The issue has been discussed with @LukasReschke with the result that further investigation would be necessary on whether session closure is actually necessary in this situation and if yes, how to handle session closure properly.
PR #1023 depends on this, any help is appreciated, thanks 😃
Edit: A subsequent call to the next method within the controller requiring CSRF fails saying "CSRF check failed", even though a request token was posted to the server correctly. Probably the token got lost somehow because for this call an attempt to close the session is made yet again, resulting in the same stacktrace as above. So it looks like not trying to close the session would be of a help?