Note where a session was already started #10736

NattyNarwhal · 2023-02-28T21:42:05Z

Duplicated session starts can be annoying to debug. The error that occurs when a session is already active doesn't tell you where it was initialized, so figuring out the callsite involves manual debugging to find it out.

This keeps track of the call site of session_start as a request global, and frees at the end of the request. It should make it easier to find these instances for PHP users.

The resulting message can look like:

Notice: session_start(): Ignoring session_start() because a session is already active (started from /home/calvin/src/php-src/inc.php on line 4) in /home/calvin/src/php-src/index.php on line 9

Fixes GH-10721

Duplicated session starts can be annoying to debug. The error that occurs when a session is already active doesn't tell you where it was initialized, so figuring out the callsite involves manual debugging to find it out. This keeps track of the call site of session_start as a request global, and frees at the end of the request. It should make it easier to find these instances for PHP users. The resulting message can look like: Notice: session_start(): Ignoring session_start() because a session is already active (started from /home/calvin/src/php-src/inc.php on line 4) in /home/calvin/src/php-src/index.php on line 9 Fixes phpGH-10721

NattyNarwhal · 2023-02-28T21:43:32Z

Major caveat: the Zend allocator thinks this leaks:

[Tue Feb 28 17:31:52 2023]  Script:  '/home/calvin/src/php-src/ext/session/tests/006.php'
/home/calvin/src/php-src/ext/session/session.c(1617) :  Freeing 0x00007fb672e04a20 (51 bytes), script=/home/calvin/src/php-src/ext/session/tests/006.php
=== Total 1 memory leaks detected ===

...but shouldn't the RSHUTDOWN for the module take care of this if I free there?

Oddly, Valgrind has no complaints for the tests that do fail (when I do make test TESTS="-m ext/session/tests")?

nielsdos · 2023-02-28T21:49:24Z

Oddly, Valgrind has no complaints for the tests that do fail

This is because Zend's leak detector frees it for you (check the line "Freeing 0x...").
It only does the leak detection in debug mode though, so you could try configuring without --enable-debug, making, and running valgrind then.

NattyNarwhal · 2023-02-28T21:50:58Z

I thought run-tests disabled the Zend allocator (USE_ZEND_ALLOC=0 ZEND_DONT_UNLOAD_MODULES=1), with -m/-M set, so that shouldn't happen?

nielsdos · 2023-02-28T22:04:32Z

Sorry, my mistake.

A minimal reproducer for your leak is:

<?php
session_start();
session_write_close();
session_start(); // creates leak because it overwrites the old filename, without freeing the old one

That's because session_write_close() calls php_session_flush() which will set the session status to none. Then the session initialisation code assumes that no filename has been set yet, but it actually has one still set.

nielsdos · 2023-02-28T22:08:07Z

In fact there are a couple of places where the session status may be set to none.
One way to fix it would be to first check if the old string needs to be freed in the session starting code where you currently estrdup the filename.
A slightly nicer imo (*), but more intrusive fix, is to create a static cleanup function which will clean up the filename & linenumber. Then you can call that function in all places where the session gets reset to state none, and also call that in the session initialisation code.

(*) nicer imo, because PS() will have a more consistent state.

If this was already initialized, we'd forget it. Have shared free between session_start and RSHUTDOWN.

NattyNarwhal · 2023-02-28T22:10:55Z

Ah, I forgot that if it was already initialized earlier, it would be overwritten because of that.

I don't think putting it flush is appropriate; cleaning it RSHUTDOWN and when initializing seems to be adequate.

nielsdos · 2023-02-28T22:15:19Z

I think this PR is a nice improvement. I remember in the past having issues debugging duplicate session starts. So thanks for working on this.

mvorisek · 2023-02-28T22:28:36Z

"header already sent" is not only a session problem, but also when sending a header() and http_response_code() and this PR should fix the messages for these functions as well

nielsdos · 2023-02-28T22:31:30Z

"header already sent" is not only a session problem, but also when sending a header() and http_response_code() and this PR should fix the messages for these functions as well

This one is slightly different, this one is about sessions already being active, not about header themself.

mvorisek · 2023-02-28T22:37:10Z

"header already sent" is not only a session problem, but also when sending a header() and http_response_code() and this PR should fix the messages for these functions as well

This one is slightly different, this one is about sessions already being active, not about header themself.

The title of #10721 mention "header already sent" which this PR does not fix (but it claims so in the description).

NattyNarwhal · 2023-02-28T22:49:36Z

The referenced issue is unfortunately a little inconsistent. The title mentions headers but the body mentions sessions.

I think another PR to handle headers and the status could could be useful, though more care would have to be taken because I think there’s a lot more places where the HTTP header can be sent AFAIK.

NattyNarwhal · 2023-03-01T04:51:39Z

I quickly checked and php_output_get_start_filename does exist and things already use it - it just seems inconsistent in usage:

[calvin@salient php-src]$ git grep php_output_get_start_filename
ext/session/session.c:          const char *output_start_filename = php_output_get_start_filename();
ext/session/session.c:          const char *output_start_filename = php_output_get_start_filename();
ext/standard/head.c:            file = php_output_get_start_filename();
main/SAPI.c:            const char *output_start_filename = php_output_get_start_filename();
main/output.c:/* {{{ char *php_output_get_start_filename(void)
main/output.c:PHPAPI const char *php_output_get_start_filename(void)
main/php_output.h:PHPAPI const char *php_output_get_start_filename(void);
[calvin@salient php-src]$ git grep "already sent"
Zend/tests/output_started_at_eval.phpt:Warning: Cannot modify header information - headers already sent by (output started at %s(2) : eval()'d code:1) in %s on line %d
ext/bcmath/libbcmath/LICENSE:    materials or that you have already sent this user a copy.
ext/mbstring/libmbfl/LICENSE:    materials or that you have already sent this user a copy.
ext/session/session.c: * Remove already sent session ID cookie.
ext/session/session.c:  php_session_remove_cookie(); /* remove already sent session ID cookie */
ext/session/tests/bug74514.phpt:'headers already sent' errors if they try to set new values.
ext/spl/spl_iterators.c:                                /* pcre_get_compiled_regex_cache has already sent error */
ext/standard/head.c:/* {{{ Return list of headers to be sent / already sent */
ext/standard/tests/general_functions/head.phpt:Warning: Cannot modify header information - headers already sent by (output started at %s:%d) in %s on line %d
ext/standard/tests/general_functions/head.phpt:Warning: Cannot modify header information - headers already sent by (output started at %s:%d) in %s on line %d
ext/standard/tests/general_functions/head.phpt:Warning: Cannot modify header information - headers already sent by (output started at %s:%d) in %s on line %d
ext/standard/tests/general_functions/head.phpt:Warning: Cannot modify header information - headers already sent by (output started at %s:%d) in %s on line %d
ext/tidy/tidy.c:                        php_error_docref(NULL, E_WARNING, "Cannot change tidy.clean_output - headers already sent");
ext/zlib/tests/bug61820.phpt:bug #61820 using ob_gzhandler will complain about headers already sent when no compression
ext/zlib/zlib.c:                        php_error_docref("ref.outcontrol", E_WARNING, "Cannot change zlib.output_compression - headers already sent");
ext/zlib/zlib.c:                php_error_docref("ref.outcontrol", E_WARNING, "Cannot change zlib.output_handler - headers already sent");
main/SAPI.c:                    sapi_module.sapi_error(E_WARNING, "Cannot modify header information - headers already sent by (output started at %s:%d)",
main/SAPI.c:                    sapi_module.sapi_error(E_WARNING, "Cannot modify header information - headers already sent");
php.ini-development:; You may be able to send headers and cookies after you've already sent output
php.ini-production:; You may be able to send headers and cookies after you've already sent output
sapi/cgi/tests/011.phpt:Warning: Cannot modify header information - headers already sent by (output started at %s:3) in %s on line 5
sapi/fpm/tests/bug77780-header-sent-error.phpt:FPM: bug77780 - Headers already sent error incorrectly emitted

NattyNarwhal · 2023-03-01T14:47:32Z

I guess further questions for the session stuff specifically:

Would a function to get the location be useful? It might be useful to expose to userland (or extensions like Xdebug?).
Is the location of where it's set ideal? This seems to work as expected for tests, but I don't know if this should be moved somewhere better.

NattyNarwhal · 2023-03-01T14:54:16Z

I quickly checked and php_output_get_start_filename does exist and things already use it - it just seems inconsistent in usage

Reading around, I think things core PHP use this properly (i.e. header() or SAPI APIs), but extensions that can also touch headers/output (tidy/zlib) don't use that API. Of course, I could have missed some stuff; this was a skim focused on "already sent" as the keywords.

mvorisek · 2023-03-01T15:25:06Z

"header already sent" is not only a session problem, but also when sending a header and http_response_code and this PR should fix the messages for these functions as well

https://3v4l.org/LrUEr for header the message is already mentioning the origin, for http_response_code I have opened #10742

iluuu1994 · 2023-03-22T22:26:22Z

ext/session/session.c

+
+	/* Should these be set here, or in session_initialize? */
+	php_session_cleanup_filename();
+	PS(session_started_filename) = estrdup(zend_get_executed_filename());


Can't we just use zend_get_executed_filename_ex to avoid the string duplication?

This diff would work:

diff --git a/ext/session/php_session.h b/ext/session/php_session.h index 2f26cd16b5..341aac5716 100644 --- a/ext/session/php_session.h +++ b/ext/session/php_session.h @@ -154,7 +154,7 @@ typedef struct _php_ps_globals { const ps_module *default_mod; void *mod_data; php_session_status session_status; - char *session_started_filename; + zend_string *session_started_filename; uint32_t session_started_lineno; zend_long gc_probability; zend_long gc_divisor; diff --git a/ext/session/session.c b/ext/session/session.c index f853da4b65..aaaaf98b38 100644 --- a/ext/session/session.c +++ b/ext/session/session.c @@ -126,7 +126,7 @@ static inline void php_rinit_session_globals(void) /* {{{ */ static inline void php_session_cleanup_filename(void) /* {{{ */ { if (PS(session_started_filename)) { - efree(PS(session_started_filename)); + zend_string_release_ex(PS(session_started_filename), 0); PS(session_started_filename) = NULL; PS(session_started_lineno) = 0; } @@ -1505,7 +1505,7 @@ PHPAPI zend_result php_session_start(void) /* {{{ */ switch (PS(session_status)) { case php_session_active: if (PS(session_started_filename)) { - php_error(E_NOTICE, "Ignoring session_start() because a session has already been started (started from %s on line %u)", PS(session_started_filename), PS(session_started_lineno)); + php_error(E_NOTICE, "Ignoring session_start() because a session has already been started (started from %s on line %u)", ZSTR_VAL(PS(session_started_filename)), PS(session_started_lineno)); } else { php_error(E_NOTICE, "Ignoring session_start() because a session has already been started"); } @@ -1621,8 +1621,11 @@ PHPAPI zend_result php_session_start(void) /* {{{ */ /* Should these be set here, or in session_initialize? */ php_session_cleanup_filename(); - PS(session_started_filename) = estrdup(zend_get_executed_filename()); - PS(session_started_lineno) = zend_get_executed_lineno(); + zend_string *session_started_filename = zend_get_executed_filename_ex(); + if (session_started_filename != NULL) { + PS(session_started_filename) = zend_string_copy(session_started_filename); + PS(session_started_lineno) = zend_get_executed_lineno(); + } return SUCCESS; } @@ -2538,7 +2541,7 @@ PHP_FUNCTION(session_start) if (PS(session_status) == php_session_active) { if (PS(session_started_filename)) { - php_error_docref(NULL, E_NOTICE, "Ignoring session_start() because a session is already active (started from %s on line %d)", PS(session_started_filename), PS(session_started_lineno)); + php_error_docref(NULL, E_NOTICE, "Ignoring session_start() because a session is already active (started from %s on line %d)", ZSTR_VAL(PS(session_started_filename)), PS(session_started_lineno)); } else { php_error_docref(NULL, E_NOTICE, "Ignoring session_start() because a session is already active"); }

...but it breaks ext/session/tests/session_start_variation9.diff:

*** Testing session_start() : variation *** string(%d) "%s" 004+ Notice: session_start(): Ignoring session_start() because a session is already active in /home/calvin/src/php-src/ext/session/tests/session_start_variation9.php on line 8 004- Notice: session_start(): Ignoring session_start() because a session is already active (started from %s on line %d) in %s on line %d bool(true) string(%d) "%s" bool(true) --

iluuu1994 · 2023-03-23T14:14:49Z

I think zend_string_release_ex should be zend_string_release, as it might or might not be a persistent string.

NattyNarwhal · 2023-03-23T14:21:56Z

I did realize that and fixed it after I had posted the diff. I'm still curious why the zend_get_executed_filename case works for that test, but not zend_get_executed_filename_ex.

iluuu1994 · 2023-03-23T14:29:18Z

@NattyNarwhal I missed that part. I don't know, the two functions zend_get_executed_filename and zend_get_executed_filename_ex look exactly the same except that the former returns a char* and has a different default value.

iluuu1994 · 2023-03-23T14:30:18Z

@NattyNarwhal Oh, are you sure the result isn't actually Ignoring session_start() because a session is already active (started from [no active file] on line 0)?

NattyNarwhal · 2023-03-23T14:34:01Z

Nope, it's null and thus uses the old message:

*** Testing session_start() : variation ***
string(32) "97d9f2918efb3c125ba43e7b8540044b"

Notice: session_start(): Ignoring session_start() because a session is already active in /home/calvin/src/php-src/ext/session/tests/session_start_variation9.php on line 8
bool(true)
string(32) "97d9f2918efb3c125ba43e7b8540044b"
bool(true)
string(0) ""
Done

iluuu1994 · 2023-03-23T14:35:46Z

@NattyNarwhal I was referring to the old variation with zend_get_executed_filename.

NattyNarwhal · 2023-03-23T18:33:32Z

Ugh, you're right. I guess I should probably revert the change to that test then, or is the current output actually desirable?

iluuu1994 · 2023-03-23T19:42:11Z

@NattyNarwhal started from [no active file] doesn't make much sense, so we should drop the started from when the file isn't available.

Also fix the improper test case.

Girgias

This looks like a nice improvement!

Mainly nits. :)

ext/session/session.c

NattyNarwhal · 2023-03-24T13:37:51Z

started from [no active file] doesn't make much sense, so we should drop the started from when the file isn't available.

WRT this, I do realize the test that caused this was setting auto_start. Perhaps it might be worth communicating that to the user (instead of relying on the implication if there is no file blamed, it's likely that INI option).

iluuu1994 · 2023-03-24T14:33:59Z

Perhaps it might be worth communicating that to the user

Would it be possible to record the file/position that caused the auto-start of the session?

NattyNarwhal · 2023-03-24T14:52:02Z

Would it be possible to record the file/position that caused the auto-start of the session?

auto_start can't be set at runtime (it's PHP_INI_PERDIR), and works during request init. So, I think this would actually work:

diff --git a/ext/session/session.c b/ext/session/session.c
index 95485cba67..e79656691a 100644
--- a/ext/session/session.c
+++ b/ext/session/session.c
@@ -1513,6 +1513,9 @@ PHPAPI zend_result php_session_start(void) /* {{{ */
 		case php_session_active:
 			if (PS(session_started_filename)) {
 				php_error(E_NOTICE, "Ignoring session_start() because a session has already been started (started from %s on line %"PRIu32")", ZSTR_VAL(PS(session_started_filename)), PS(session_started_lineno));
+			} else if (PS(auto_start)) {
+				/* This option can't be changed at runtime, so we can assume it's because of this */
+				php_error(E_NOTICE, "Ignoring session_start() because a session has already been started automatically");
 			} else {
 				php_error(E_NOTICE, "Ignoring session_start() because a session has already been started");
 			}
@@ -2541,6 +2544,9 @@ PHP_FUNCTION(session_start)
 	if (PS(session_status) == php_session_active) {
 		if (PS(session_started_filename)) {
 			php_error_docref(NULL, E_NOTICE, "Ignoring session_start() because a session is already active (started from %s on line %"PRIu32")", ZSTR_VAL(PS(session_started_filename)), PS(session_started_lineno));
+		} else if (PS(auto_start)) {
+			/* This option can't be changed at runtime, so we can assume it's because of this */
+			php_error_docref(NULL, E_NOTICE, "Ignoring session_start() because a session is already automatically active");
 		} else {
 			php_error_docref(NULL, E_NOTICE, "Ignoring session_start() because a session is already active");
 		}
diff --git a/ext/session/tests/session_start_variation9.phpt b/ext/session/tests/session_start_variation9.phpt
index e4c6e57381..3fdcdcffbb 100644
--- a/ext/session/tests/session_start_variation9.phpt
+++ b/ext/session/tests/session_start_variation9.phpt
@@ -26,7 +26,7 @@
 *** Testing session_start() : variation ***
 string(%d) "%s"
 
-Notice: session_start(): Ignoring session_start() because a session is already active in %s on line %d
+Notice: session_start(): Ignoring session_start() because a session is already automatically active in %s on line %d
 bool(true)
 string(%d) "%s"
 bool(true)

Seems to pass tests, at least.

iluuu1994 · 2023-03-24T14:54:52Z

What I meant was, can we record the location of the statement (like $_SESSION['foo'] = 'foo';) that triggered the session start. These are probably harder to track down than a session_start() and so would actually be more useful.

NattyNarwhal · 2023-03-24T15:08:30Z

What I meant was, can we record the location of the statement (like $_SESSION['foo'] = 'foo';) that triggered the session start. These are probably harder to track down than a session_start() and so would actually be more useful.

Based on my reading of the source and trying to experiment with it, I don't think it can get initialized when I set $_SESSION. Without auto_start, session_start clobbers $_SESSION, and with it, the session gets initialized at RINIT, not at first set in user code.

iluuu1994 · 2023-03-24T15:11:19Z

@NattyNarwhal Ah right, I've never used this setting and assumed the behavior would be different.

Easy to forget that you have this set, in which case, session start is done at RINIT outside of user code. Because this config option can't change at runtime, we can check for it and make the error more specific if that's the case.

Girgias · 2023-03-26T13:22:02Z

ASAN Failure is legit

NattyNarwhal · 2023-03-26T14:38:35Z

I can't reproduce it; clang ASan seems to pass just fine, and gcc ASan does give me an error, but it's incredibly useless (no stack trace, wrong thread ID, just sits paused until I ^C it):

==112264==ERROR: AddressSanitizer: stack-buffer-overflow on address 0x7f084b1feac8 at pc 0x7f085be61b61 bp 0x7f084b1fea90 sp 0x7f084b1fe240
WRITE of size 24 at 0x7f084b1feac8 thread T-1

Girgias · 2023-03-26T22:04:08Z

Well the failure is legit as the Release ZTS build segfaults on that regression bug, I'll have a look during the week to see if I can reproduce it.

NattyNarwhal · 2023-03-27T02:20:09Z

I don't doubt it either; I just never have good luck with ASan. I'll try rebuilding with the right arguments tomorrow; hopefully it reproduces fine under Valgrind instead.

iluuu1994 · 2023-03-27T10:29:31Z

@NattyNarwhal The failing test seems to call php_session_cleanup_filename() before RINIT. It's better to move the initializing code to MINIT.

diff --git a/ext/session/session.c b/ext/session/session.c
index 919b16b158..7aa80a1997 100644
--- a/ext/session/session.c
+++ b/ext/session/session.c
@@ -110,8 +110,6 @@ static inline void php_rinit_session_globals(void) /* {{{ */
 	/* TODO: These could be moved to MINIT and removed. These should be initialized by php_rshutdown_session_globals() always when execution is finished. */
 	PS(id) = NULL;
 	PS(session_status) = php_session_none;
-	PS(session_started_filename) = NULL;
-	PS(session_started_lineno) = 0;
 	PS(in_save_handler) = 0;
 	PS(set_handler) = 0;
 	PS(mod_data) = NULL;
@@ -2880,6 +2878,8 @@ static PHP_MINIT_FUNCTION(session) /* {{{ */
 
 	my_module_number = module_number;
 	PS(module_number) = module_number;
+	PS(session_started_filename) = NULL;
+	PS(session_started_lineno) = 0;
 
 	PS(session_status) = php_session_none;
 	REGISTER_INI_ENTRIES();

NattyNarwhal · 2023-03-27T15:25:30Z

I did manage to reproduce that failure with release ZTS; that patch fixed it.

Girgias · 2023-03-28T14:14:29Z

Thank you!

github-actions bot added the Extension: session label Feb 28, 2023

Fix leak with session start callsite filename

74a017c

If this was already initialized, we'd forget it. Have shared free between session_start and RSHUTDOWN.

iluuu1994 reviewed Mar 22, 2023

View reviewed changes

Convert to using zend_string for session start location

df5bd1f

Also fix the improper test case.

NattyNarwhal requested a review from Girgias as a code owner March 23, 2023 20:14

Girgias reviewed Mar 24, 2023

View reviewed changes

ext/session/session.c Outdated Show resolved Hide resolved

ext/session/session.c Outdated Show resolved Hide resolved

ext/session/session.c Outdated Show resolved Hide resolved

NattyNarwhal added 2 commits March 24, 2023 10:28

Update format string

b7c8429

Move session started filename into php_session_initialize

a34f6e6

For sessions that are automatically started, note that

d057210

Easy to forget that you have this set, in which case, session start is done at RINIT outside of user code. Because this config option can't change at runtime, we can check for it and make the error more specific if that's the case.

Move variable init from RINIT to MINIT

4eaa191

Girgias approved these changes Mar 28, 2023

View reviewed changes

Girgias merged commit 180f785 into php:master Mar 28, 2023

NattyNarwhal mentioned this pull request Apr 16, 2023

http_response_code should warn if headers already sent #10744

Closed

Note where a session was already started #10736

Note where a session was already started #10736

Uh oh!

Conversation

NattyNarwhal commented Feb 28, 2023

Uh oh!

NattyNarwhal commented Feb 28, 2023

Uh oh!

nielsdos commented Feb 28, 2023

Uh oh!

NattyNarwhal commented Feb 28, 2023

Uh oh!

nielsdos commented Feb 28, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nielsdos commented Feb 28, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

NattyNarwhal commented Feb 28, 2023

Uh oh!

nielsdos commented Feb 28, 2023

Uh oh!

mvorisek commented Feb 28, 2023

Uh oh!

nielsdos commented Feb 28, 2023

Uh oh!

mvorisek commented Feb 28, 2023

Uh oh!

NattyNarwhal commented Feb 28, 2023

Uh oh!

NattyNarwhal commented Mar 1, 2023

Uh oh!

NattyNarwhal commented Mar 1, 2023

Uh oh!

NattyNarwhal commented Mar 1, 2023

Uh oh!

mvorisek commented Mar 1, 2023

Uh oh!

iluuu1994 Mar 22, 2023

Choose a reason for hiding this comment

Uh oh!

NattyNarwhal Mar 23, 2023

Choose a reason for hiding this comment

Uh oh!

iluuu1994 commented Mar 23, 2023

Uh oh!

NattyNarwhal commented Mar 23, 2023

Uh oh!

iluuu1994 commented Mar 23, 2023

Uh oh!

iluuu1994 commented Mar 23, 2023

Uh oh!

NattyNarwhal commented Mar 23, 2023

Uh oh!

iluuu1994 commented Mar 23, 2023

Uh oh!

NattyNarwhal commented Mar 23, 2023

Uh oh!

iluuu1994 commented Mar 23, 2023

Uh oh!

Girgias left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

NattyNarwhal commented Mar 24, 2023

Uh oh!

iluuu1994 commented Mar 24, 2023

Uh oh!

NattyNarwhal commented Mar 24, 2023

Uh oh!

iluuu1994 commented Mar 24, 2023

Uh oh!

NattyNarwhal commented Mar 24, 2023

Uh oh!

iluuu1994 commented Mar 24, 2023

Uh oh!

Girgias commented Mar 26, 2023

Uh oh!

nielsdos commented Feb 28, 2023 •

edited

Loading

nielsdos commented Feb 28, 2023 •

edited

Loading