Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix header warnings from log flushing #1176

Closed

Conversation

@totpet
Copy link

commented Jul 31, 2019

See #1168
There are warnings about headers being sent by the Logger::flush function when the loglevel is set to DEBUG, for example on the IDP metadata page.

@totpet

This comment has been minimized.

Copy link
Author

commented Aug 14, 2019

An easy way to verify the patch:

docker run --rm -d -p 9080:80 --name ssp tothp/test-saml-idp:7.2
curl -v "http://127.0.0.1:9080/simplesaml/saml2/idp/metadata.php?output=xhtml"

and then:

curl https://raw.githubusercontent.com/totpet/simplesamlphp/bug/session-warning-on-log-flush/lib/SimpleSAML/Logger.php > /tmp/Logger.php
docker cp /tmp/Logger.php ssp:/var/www/simplesamlphp/lib/SimpleSAML/Logger.php
curl -v "http://127.0.0.1:9080/simplesaml/saml2/idp/metadata.php?output=xhtml"

This line should be present at the bottom of only the first response:

<b>Warning</b>:  session_name(): Cannot change session name when headers already sent in <b>/var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php</b> on line <b>72</b><br />
@totpet

This comment has been minimized.

Copy link
Author

commented Aug 22, 2019

Hi @jaimeperez!
Can you please check my changes? Let me now if I can improve the patch or should give further description!

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Aug 23, 2019

Hi @totpet!

I'm looking into it. I managed to reproduce it partially, although didn't get all those error messages that you are getting (just the first one). In any case, this PR in particular wouldn't be complete, since if we are moving session initialization to the defer() method, we should remove the code in the flush() method fetching the session.

Furthermore, I'm not sure that would suffice, as in theory it could still be possible that we call defer() after starting output, and the error would happen again. I'll try to review it next week and find the best solution to get rid of these errors for good.

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Sep 2, 2019

Hi again!

After looking a bit closer into it, I think this is actually an issue with PHP, which is causing session_name() to try to send cookies. This is a change in behaviour since PHP 7.2, described in the changelog of the function in PHP's documentation:

session_name() checks session status, previously it only checked cookie status. Therefore, older session_name() allows to call session_name() after session_start() which may crash PHP and may result in misbehaviors.

There is nothing wrong actually with the way we proceed, it's just an unfortunate situation that attempting to load a session (when flushing logs at the end of the processing) will try to set cookies. Note also that this happens only when using the PHP session handler. I think the proper solution is to just silence warnings generated by session_name(), like this:

diff --git a/lib/SimpleSAML/SessionHandlerPHP.php b/lib/SimpleSAML/SessionHandlerPHP.php
index 7d320a275..88afbfb1c 100644
--- a/lib/SimpleSAML/SessionHandlerPHP.php
+++ b/lib/SimpleSAML/SessionHandlerPHP.php
@@ -68,7 +68,7 @@ class SessionHandlerPHP extends SessionHandler
         }

         if (!empty($this->cookie_name)) {
-            session_name($this->cookie_name);
+            @session_name($this->cookie_name);
         } else {
             $this->cookie_name = session_name();
         }

Would you mind applying this patch and telling us if you still see warnings or they are completely gone? I've tested it with the docker image you created, and it seems to work, but I would like your confirmation.

Fix header warnings from log flushing
Fixes #1168

Co-authored-by: Jaime Pérez Crespo <jaime.perez@uninett.no>

@totpet totpet force-pushed the totpet:bug/session-warning-on-log-flush branch from adc33dd to 55c9ba7 Sep 2, 2019

@totpet

This comment has been minimized.

Copy link
Author

commented Sep 2, 2019

Yes, thank you! Your fix removed the warnings in all cases where I've seen them.

Some other warning can still persist in a browser that has previously visited the IDP, but I'm not sure if this is a problem, since they disappear after clearing the browser cookies:

Warning: session_id(): Cannot change session id when headers already sent in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 193

Warning: ini_set(): Headers already sent. You cannot change the session module's ini settings at this time in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 246

Warning: session_id(): Cannot change session id when headers already sent in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 193

I can consistently reproduce this in 1.17.6 (I have updated tothp/test-saml-idp:7.3), using the commands from my previous comment, but navigating to the page in a browser instead of using curl.

After docker cp-ing the patched SessionHandlerPHP.php, this line disappears:

 Warning: session_name(): Cannot change session name when headers already sent in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 72

but the three above remain. They are all gone after clearing the cookies.

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Sep 2, 2019

Thanks a lot for testing it @totpet! Are you able to reproduce those additional warnings in any way? I'm basically wondering whether we should apply the same approach to the rest of session_*() calls in the PHP session handler, or just stick to this specific one that we know works with the patch.

@tvdijen

This comment has been minimized.

Copy link
Member

commented Sep 2, 2019

I'm not thrilled with prepending calls with an @ because that not only suppresses warnings, but also errors and even criticals...

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Sep 3, 2019

Neither am I, but I find this a legitimate use of the @ operator. It's not reasonable to degrade functionality (in this case, use a transient session which makes it impossible to track the logs corresponding a certain user) in order to get rid of warnings, and I'm afraid warnings are inevitable in this case. If we're going to load the session, we have to tell PHP its name. If PHP decides it needs to set cookies at that point, I don't see a way around that.

I'd be happy to stand corrected though 😉

@tvdijen

This comment has been minimized.

Copy link
Member

commented Sep 3, 2019

I don’t have a proper solution either, but we cannot be the only one that is experiencing this issue..

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Sep 3, 2019

Well, I don't think it's very common that you load/initialize a session in the __destruct() methods or in the shutdown callback, so it doesn't surprise me that this is not a common problem. Also, remember that this specific issue appeared in PHP 7.2, because session_name() now tries to set the session cookies. So I think it's really a corner case that we are hitting, and we were just unfortunate.

@totpet

This comment has been minimized.

Copy link
Author

commented Sep 3, 2019

Thanks a lot for testing it @totpet! Are you able to reproduce those additional warnings in any way?

Yes, I tried describing that above, or are you referring to other warnings? I don't know of other warning beyond the 4 I pasted there.

You visit /saml2/idp/metadata.php?output=xhtml in an unpatched (1.17.6) version to get the cookies, apply the patch, then visit again.

I'm basically wondering whether we should apply the same approach to the rest of session_*() calls in the PHP session handler, or just stick to this specific one that we know works with the patch.

I feel that the discussion is above my expertise, but wouldn't creating a session earlier solve the problem without hiding other errors, like my first commit, adc33ddf? Can checking for a session be done when the Logger class is imported (since it doesn't have a constuctor)?

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Sep 4, 2019

Creating (or loading) a session earlier is not a viable solution, unfortunately. There are pages that legitimately don't need a session for anything. Think precisely of the page you are using as example here. There's no point at all for that page to load a session, as it doesn't have a use for it. Loading it would have an impact in many deployments, as the session needs to be fetched from the backend, usually meaning network access. That network delay would transpire directly into the response time for the page: the result is that it takes longer to get the metadata.

The need in such pages is therefore to log what's going on, but not to use the session at all. Session is needed for logging though, as if there is a session, it's associated track ID can be used to relate all requests made by the same client. Being able to see that a certain client requested a page might have value, regardless of whether that page needs a session or not.

So we want to avoid loading a session upfront for every request, but at the same time we want the perks of tracking in logs, which involves loading the session if there is one. The only way to achieve that is by lazy-loading sessions once we are shutting down, because at that point it no longer has an impact on the response time. But of course, by definition, at that point output has already been generated, so it's not possible to set a new session if there's none in place. That used to work just fine until PHP 7.2, because session_name() was only setting the session name, not sending session cookies. Since PHP 7.2 the behaviour of the function changed, and hence the warnings here. The warnings don't provide anything useful (we don't care if we cannot set cookies, we are detecting that case and a transient session will be created if necessary), but the use case is still legitimate, which is why I'm in favour of just silencing those warnings.

I'll have a look at the rest of the warnings you are mentioning, and see if I can reproduce them.

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Sep 6, 2019

I've been investigating this further, and unfortunately it looks like it's impossible to load a session once output has been generated, starting with PHP 7.2. This used to work before, but I don't see a way to make it work optimally now. I think we'll need to pay more attention to return values from the session_*() functions, and abort in case of error, combined with manual session loading before output in those pages where this is a problem. We'll need to evaluate in those cases if being able to keep tracking the user in the logs is worth the trouble of loading a session we don't really need.

@totpet

This comment has been minimized.

Copy link
Author

commented Sep 9, 2019

Maybe I'm mistaken, but I think this could work: we could check session_status, and only call session_name if it returns PHP_SESSION_ACTIVE in the Session constructor or Logger::shutdown. Additionally an optional parameter could be added to getSessionFromRequest or Session::_contructor, to make it only check for existing sessions, not create new ones.

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Sep 10, 2019

Session::__construct() already has the concept of transient sessions, which aren't meant to be saved to storage in any way (they are used precisely when we cannot create a session). The issue there is that the PHP session handler creates a session when it tries to load one, and in this particular case, it doesn't know we're using a transient session and then it tries to create one.

The proper solution for the warnings is indeed to fix that by making the handler aware of transient sessions. However, that doesn't resolve the issue of not being able to load an existing session once headers have been sent 😞

@jaimeperez jaimeperez added this to the 1.18 milestone Sep 11, 2019

@jaimeperez jaimeperez added the bug label Sep 11, 2019

@jaimeperez jaimeperez self-assigned this Sep 11, 2019

@jaimeperez

This comment has been minimized.

Copy link
Member

commented Sep 13, 2019

Hi again @totpet!

I've finally been able to debug this properly, and I think I managed to get it fixed without silencing warnings with the @ operator. It's unfortunate because it implies a downgrade in functionality, but there's not much more that we can do. In any case, I created a patch for master that seems to work. Would you mind applying it and telling me if all the errors and warnings are gone?

Index: lib/SimpleSAML/SessionHandlerPHP.php
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- lib/SimpleSAML/SessionHandlerPHP.php        (revision 3c52b289c253a8c5395908d0d3493a879f869d53)
+++ lib/SimpleSAML/SessionHandlerPHP.php        (date 1568380614815)
@@ -189,6 +189,11 @@
             return null; // there's no session cookie, can't return ID
         }
 
+        if (version_compare(PHP_VERSION, '7.2', 'ge') && headers_sent()) {
+            // latest versions of PHP don't allow loading a session when output sent, get the ID from the cookie
+            return $_COOKIE[$this->cookie_name];
+        }
+
         // do not rely on session_id() as it can return the ID of a previous session. Get it from the cookie instead.
         session_id($_COOKIE[$this->cookie_name]);
 
@@ -241,7 +246,7 @@
         assert(is_string($sessionId) || $sessionId === null);
 
         if ($sessionId !== null) {
-            if (session_id() === '') {
+            if (session_id() === '' && !(version_compare(PHP_VERSION, '7.2', 'ge') && headers_sent())) {
                 // session not initiated with getCookieSessionId(), start session without setting cookie
                 $ret = ini_set('session.use_cookies', '0');
                 if ($ret === false) {

Thanks in advance!

@totpet

This comment has been minimized.

Copy link
Author

commented Sep 19, 2019

I had some issues building docker images from the repo, if I build it from your commit fixing this (b278b2b) or current master (1a6c8f3), I get this output on every page:

Warning: require(/var/www/simplesamlphp/vendor/composer/../../tests/_autoload_modules.php): failed to open stream: No such file or directory in /var/www/simplesamlphp/vendor/composer/autoload_real.php on line 66

Fatal error: require(): Failed opening required '/var/www/simplesamlphp/vendor/composer/../../tests/_autoload_modules.php' (include_path='.:/usr/local/lib/php') in /var/www/simplesamlphp/vendor/composer/autoload_real.php on line 66

I modified the dockerfile to install dependencies as described in docs/simplesamlphp-install-repo.md

Building from the simplesamlphp-1.17 branch (1.17.6 tag) works, but if I copy your changed SessionHandlerPHP.php into it, one warning still remains, even with no previous cookies:

 Warning: session_name(): Cannot change session name when headers already sent in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 71

I built and pushed new tags for tothp/test-saml-idp:
7.3-repo-b278b2b, 7.3-master, 7.3-repo1.17.6

Reproduction:

docker run --rm -d -p 9080:80 --name ssp tothp/test-saml-idp:7.3-repo1.17.6
curl -v "http://127.0.0.1:9080/simplesaml/saml2/idp/metadata.php?output=xhtml"
curl https://raw.githubusercontent.com/simplesamlphp/simplesamlphp/b278b2b41b6400b48ed0fc44ce41f3f0fa846e31/lib/SimpleSAML/SessionHandlerPHP.php > /tmp/SessionHandlerPHP.php
docker cp /tmp/SessionHandlerPHP.php ssp:/var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php
curl -v "http://127.0.0.1:9080/simplesaml/saml2/idp/metadata.php?output=xhtml"

This only changes the line number of the warning from 72 to 71

When visiting with a browser, your commit removes the last 3 warnings:

Warning: session_name(): Cannot change session name when headers already sent in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 72

Warning: session_id(): Cannot change session id when headers already sent in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 192

Warning: ini_set(): Headers already sent. You cannot change the session module's ini settings at this time in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 244

Warning: session_id(): Cannot change session id when headers already sent in /var/www/simplesamlphp/lib/SimpleSAML/SessionHandlerPHP.php on line 192
@totpet

This comment has been minimized.

Copy link
Author

commented Sep 20, 2019

About the _autoload error:
I used git bisect to find the source of the error, and found commit 48a4bcf , which is not the history of the simplesamlphp-1.17

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
3 participants
You can’t perform that action at this time.