Server: Handle session closure properly for redirecting to a controller in a post_login hook

[GitHubUser4234]

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):

PHP Fatal error:  
Uncaught exception 'Exception' with message 'Session has been closed - no further changes to the session are allowed' in /server/lib/private/Session/Internal.php:154
Stack trace:
#0 /server/lib/private/Session/Internal.php(64): OC\\Session\\Internal->validateSession()
#1 /server/lib/private/Session/CryptoSessionData.php(164): OC\\Session\\Internal->set('encrypted_sessi...', 'e08a3041c452d86...')
#2 /server/lib/private/Session/CryptoSessionData.php(67): OC\\Session\\CryptoSessionData->close()
#3 [internal function]: OC\\Session\\CryptoSessionData->__destruct()
#4 {main}
  thrown in /server/lib/private/Session/Internal.php on line 154

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 :smiley:

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?

[GitHubUser4234]

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 :yum:

[nickvergessen]

@GitHubUser4234 I ran into a similar issue latly, so please retry on master, whether https://github.com/nextcloud/server/pull/1943/commits/2cd92d0abbeffd1817c87522f9b633b14e60181a fixes the issue

[GitHubUser4234]

@nickvergessen : Thanks for the hint, I just retried, but unfortunately the error is still there. Line numbers of the stacktrace remain unchanged.

[GitHubUser4234]

As discussed with @nickvergessen in IRC, this can quickly be reproduced by adding the following lines to https://github.com/nextcloud/server/blob/ce964f0a10dc2d160a67e8b4e86c5f0c18195d57/apps/dav/lib/HookManager.php#L143-L143 :

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.

[tcitworld]

Ran into the same issue while trying to have https://github.com/nextcloud/server/pull/1893 in a separate app.

[tcitworld]

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#115

[GitHubUser4234]

Ran 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)?

[MorrisJobke]

@LukasReschke and @nickvergessen want to look into this again for Nextcloud 11

[tcitworld]

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.

[GitHubUser4234]

@LukasReschke and @nickvergessen want to look into this again for Nextcloud 11

Very happy, thanks guys :)

[GitHubUser4234]

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...

[LukasReschke]

Minimal example is in the branch minimal-example-for-1303. See https://github.com/nextcloud/server/commit/01919951b191088af0578a82c99619ff88c4e5b6

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 154

cc @rullzer

[MorrisJobke]

@GitHubUser4234 🙌

[GitHubUser4234]

Thanks a lot @MorrisJobke @nickvergessen @LukasReschke @rullzer for the fix :))

The fix solves the major part of the problem, however a flaw has been found which I'm currently discussing with @LukasReschke :

Remove @NoCSRFRequired from thetryLogin() method in the LoginController and then run the minimal-example-for-1303 (see above): The first time when clicking the login button AFTER the post_login hook was called, CSRF fails. However when clicking the browser's back button and trying it again, the error doesn't occur again.

[GitHubUser4234]

A reminder for everyone still running into the same problem even after applying the fix: In case the methods involved work with sessions, you also need add the "@UseSession" annotation for them.

[rullzer]

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.

[GitHubUser4234]

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 :))

[rullzer]

As discussed today on IRC. Lets try to solve this somewhat safe early in the 12 cycle.

[jospoortvliet]

'early' would be now, I suppose :D

[GitHubUser4234]

'early' would be now, I suppose :D

Hehe, yeah would be really great if someone could have a look at it :)

[GitHubUser4234]

@rullzer Hem, hem :)

[rullzer]

Ah 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

[GitHubUser4234]

Cool, it has been merged, thanks a lot!!!