bug64539-status-json-encoding.phpt fail on 32-bits

[andypost]

Description

The following test fails on 32-bit arches building 8.4.2 for Alpinelinux https://gitlab.alpinelinux.org/alpine/aports/-/pipelines/283003

TEST 18384/18580 [sapi/fpm/tests/bug64539-status-json-encoding.phpt]
========DIFF========
001+ >>> Response
002+ ----------------- OUT -----------------
003+ X-Powered-By: PHP/8.4.2
004+ Expires: Thu, 01 Jan 1970 00:00:00 GMT
005+ Cache-Control: no-cache, no-store, must-revalidate, max-age=0
006+ Content-Type: application/json
007+ 
008+ {"pool":"unconfined","process manager":"static","start time":1734469914,"start since":0,"accepted conn":2,"listen queue":0,"max listen queue":0,"listen queue len":4096,"idle processes":0,"active processes":2,"total processes":2,"max active processes":2,"max children reached":0,"slow requests":0,"memory peak":0, "processes":[{"pid":18046,"state":"Running","start time":1734469914,"start since":0,"requests":1,"request duration":100588,"request method":"(null)","request uri":"GET/bug64539-status-json-encoding.src.php?","content length":4154871857,"user":"(null)","script":"-","last request cpu":0.00,"last request memory":0},{"pid":18047,"state":"Running","start time":1734469914,"start since":0,"requests":1,"request duration":361,"request method":"(null)","request uri":"GET/status?","content length":4154871857,"user":"(null)","script":"-","last request cpu":0.00,"last request memory":0}]}
009+ ----------------- ERR -----------------
010+ 
011+ ---------------------------------------
012+ 
013+ ERROR: No field request uri matched pattern \?a=b"c$ for any process in status data '{"pool":"unconfined","process manager":"static","start time":1734469914,"start since":0,"accepted conn":2,"listen queue":0,"max listen queue":0,"listen queue len":4096,"idle processes":0,"active processes":2,"total processes":2,"max active processes":2,"max children reached":0,"slow requests":0,"memory peak":0, "processes":[{"pid":18046,"state":"Running","start time":1734469914,"start since":0,"requests":1,"request duration":100588,"request method":"(null)","request uri":"GET/bug64539-status-json-encoding.src.php?","content length":4154871857,"user":"(null)","script":"-","last request cpu":0.00,"last request memory":0},{"pid":18047,"state":"Running","start time":1734469914,"start since":0,"requests":1,"request duration":361,"request method":"(null)","request uri":"GET/status?","content length":4154871857,"user":"(null)","script":"-","last request cpu":0.00,"last request memory":0}]}'
014+ 
015+ LOGS:
016+ --------------------------------------------------------------------
017+ [17-Dec-2024 21:11:54] NOTICE: fpm is running, pid 18045
018+ [17-Dec-2024 21:11:54] NOTICE: ready to handle connections
019+ --------------------------------------------------------------------
020+ 
     Done
========DONE========
FAIL FPM: bug64539 - status json format escaping [sapi/fpm/tests/bug64539-status-json-encoding.phpt] 

PHP Version

PHP 8.4.2

Operating System

Alpinelinux

[bukka]

Hmm, this part is really strange:

"request uri":"GET/bug64539-status-json-encoding.src.php?"

For some reason it's not getting query string. It will need some debugging. I just created #17239 which will allow printing a bit more info for this with setting TEST_FPM_DEBUG_FILTER=bug64539 env var .

[andypost]

Here's debug build and logs

001+ >>> Created file: /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/tests/bug64539-status-json-encoding.ini
002+ --------------------------------------------------------------------
003+ [global]
004+ error_log = /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/tests/bug64539-status-json-encoding.err.log
005+ [unconfined]
006+ listen = 127.0.0.1:9004
007+ pm = static
008+ pm.max_children = 2
009+ pm.status_path = /status
010+ catch_workers_output = yes
011+ --------------------------------------------------------------------
012+ 
013+ >>> Starting FPM using command:
014+ /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/php-fpm -n -y /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/tests/bug64539-status-json-encoding.ini -O -F -dextension_dir=modules
015+ LogTool - Matching EXPECTED: fpm is running, pid \d+
016+ LogTool - PATTERN: /^(?:\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d(?:\.\d+)?\] )?NOTICE: (?:pid \d+, (?:\w+|\(null\))\(\), line \d+: )?(fpm is running, pid \d+)$/
017+ LogReader - LINE: [22-Dec-2024 14:59:56] NOTICE: fpm is running, pid 25911
018+ LogTool - Matched ACTUAL: fpm is running, pid 25911
019+ LogTool - Matching EXPECTED: ready to handle connections
020+ LogTool - PATTERN: /^(?:\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d(?:\.\d+)?\] )?NOTICE: (?:pid \d+, (?:\w+|\(null\))\(\), line \d+: )?(ready to handle connections)$/
021+ LogReader - LINE: [22-Dec-2024 14:59:56] NOTICE: ready to handle connections
022+ LogTool - Matched ACTUAL: ready to handle connections
023+ 
024+ >>> Created file: /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/tests/bug64539-status-json-encoding.src.php
025+ --------------------------------------------------------------------
026+ <?php
027+ usleep(200000);
028+ --------------------------------------------------------------------
029+ 
030+ >>> Request params
031+ Array
032+ (
033+     [GATEWAY_INTERFACE] => FastCGI/1.0
034+     [REQUEST_METHOD] => GET
035+     [SCRIPT_FILENAME] => /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/tests/bug64539-status-json-encoding.src.php
036+     [SCRIPT_NAME] => /bug64539-status-json-encoding.src.php
037+     [QUERY_STRING] => a=b"c
038+     [REQUEST_URI] => /bug64539-status-json-encoding.src.php?a=b"c
039+     [DOCUMENT_URI] => /bug64539-status-json-encoding.src.php
040+     [SERVER_SOFTWARE] => php/fcgiclient
041+     [REMOTE_ADDR] => 127.0.0.1
042+     [REMOTE_PORT] => 7777
043+     [SERVER_ADDR] => 127.0.0.1
044+     [SERVER_PORT] => 80
045+     [SERVER_NAME] => runner-79ekzzfe-project-1-concurrent-1
046+     [SERVER_PROTOCOL] => HTTP/1.1
047+     [DOCUMENT_ROOT] => /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/tests
048+     [CONTENT_TYPE] => 
049+     [CONTENT_LENGTH] => 0
050+ )
051+ 
052+ >>> Request params
053+ Array
054+ (
055+     [GATEWAY_INTERFACE] => FastCGI/1.0
056+     [REQUEST_METHOD] => GET
057+     [SCRIPT_FILENAME] => /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/tests/bug64539-status-json-encoding.src.php
058+     [SCRIPT_NAME] => /status
059+     [QUERY_STRING] => full&json
060+     [REQUEST_URI] => /status?full&json
061+     [DOCUMENT_URI] => /status
062+     [SERVER_SOFTWARE] => php/fcgiclient
063+     [REMOTE_ADDR] => 127.0.0.1
064+     [REMOTE_PORT] => 7777
065+     [SERVER_ADDR] => 127.0.0.1
066+     [SERVER_PORT] => 80
067+     [SERVER_NAME] => runner-79ekzzfe-project-1-concurrent-1
068+     [SERVER_PROTOCOL] => HTTP/1.1
069+     [DOCUMENT_ROOT] => /builds/alpine/aports/community/php84/src/php-8.4.2/sapi/fpm/tests
070+     [CONTENT_TYPE] => 
071+     [CONTENT_LENGTH] => 0
072+ )
073+ >>> Response
074+ ----------------- OUT -----------------
075+ X-Powered-By: PHP/8.4.2
076+ Content-type: text/html; charset=UTF-8
077+ 
078+ 
079+ ----------------- ERR -----------------
080+ 
081+ ---------------------------------------
082+ 
083+ >>> Response
084+ ----------------- OUT -----------------
085+ X-Powered-By: PHP/8.4.2
086+ Expires: Thu, 01 Jan 1970 00:00:00 GMT
087+ Cache-Control: no-cache, no-store, must-revalidate, max-age=0
088+ Content-Type: application/json
089+ 
090+ {"pool":"unconfined","process manager":"static","start time":1734879596,"start since":0,"accepted conn":2,"listen queue":0,"max listen queue":0,"listen queue len":4096,"idle processes":0,"active processes":2,"total processes":2,"max active processes":2,"max children reached":0,"slow requests":0,"memory peak":0, "processes":[{"pid":25912,"state":"Running","start time":1734879596,"start since":0,"requests":1,"request duration":100693,"request method":"(null)","request uri":"GET/bug64539-status-json-encoding.src.php?","content length":4150677553,"user":"(null)","script":"-","last request cpu":0.00,"last request memory":0},{"pid":25913,"state":"Running","start time":1734879596,"start since":0,"requests":1,"request duration":368,"request method":"(null)","request uri":"GET/status?","content length":4150677553,"user":"(null)","script":"-","last request cpu":0.00,"last request memory":0}]}
091+ ----------------- ERR -----------------
092+ 
093+ ---------------------------------------
094+ 
095+ ERROR: No field request uri matched pattern \?a=b"c$ for any process in status data '{"pool":"unconfined","process manager":"static","start time":1734879596,"start since":0,"accepted conn":2,"listen queue":0,"max listen queue":0,"listen queue len":4096,"idle processes":0,"active processes":2,"total processes":2,"max active processes":2,"max children reached":0,"slow requests":0,"memory peak":0, "processes":[{"pid":25912,"state":"Running","start time":1734879596,"start since":0,"requests":1,"request duration":100693,"request method":"(null)","request uri":"GET/bug64539-status-json-encoding.src.php?","content length":4150677553,"user":"(null)","script":"-","last request cpu":0.00,"last request memory":0},{"pid":25913,"state":"Running","start time":1734879596,"start since":0,"requests":1,"request duration":368,"request method":"(null)","request uri":"GET/status?","content length":4150677553,"user":"(null)","script":"-","last request cpu":0.00,"last request memory":0}]}'
096+ 
097+ LOGS:
098+ --------------------------------------------------------------------
099+ [22-Dec-2024 14:59:56] NOTICE: fpm is running, pid 25911
100+ [22-Dec-2024 14:59:56] NOTICE: ready to handle connections
101+ --------------------------------------------------------------------
102+ 
103+ LogTool - Matching EXPECTED: Terminating ...
104+ LogTool - PATTERN: /^(?:\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d(?:\.\d+)?\] )?NOTICE: (?:pid \d+, (?:\w+|\(null\))\(\), line \d+: )?(Terminating ...)$/
105+ LogReader - LINE: [22-Dec-2024 14:59:56] NOTICE: Terminating ...
106+ LogTool - Matched ACTUAL: Terminating ...
107+ LogTool - Matching EXPECTED: exiting, bye-bye!
108+ LogTool - PATTERN: /^(?:\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d(?:\.\d+)?\] )?NOTICE: (?:pid \d+, (?:\w+|\(null\))\(\), line \d+: )?(exiting, bye-bye!)$/
109+ LogReader - LINE: [22-Dec-2024 14:59:56] NOTICE: exiting, bye-bye!
110+ LogTool - Matched ACTUAL: exiting, bye-bye!
     Done

[andypost]

pipeline is https://gitlab.alpinelinux.org/alpine/aports/-/jobs/1661498

[nielsdos]

Was able to reproduce this in an i386/alpine container.

[nielsdos]

The reason this breaks is because of a type mismatch.
The following line uses fields of the timeval struct which are both 8 bytes on Alpine 32-bit, which results in a computed value of also 8 bytes:

php-src/sapi/fpm/fpm/fpm_status.c

Line 611 in b09ed9a

duration.tv_sec * 1000000UL + duration.tv_usec,

However, it is passed to a format string which expects 4 bytes (unsigned long and thus the %lu format specifier is 4 bytes on Alpine 32-bit), resulting in argument corruption.
Since the value is generally small, truncating to 4 bytes is sufficient to fix this.

@andypost Please try the following patch:

diff --git a/sapi/fpm/fpm/fpm_status.c b/sapi/fpm/fpm/fpm_status.c
index cc3412149c7..96bdb96e408 100644
--- a/sapi/fpm/fpm/fpm_status.c
+++ b/sapi/fpm/fpm/fpm_status.c
@@ -608,7 +608,7 @@ int fpm_status_handle_request(void) /* {{{ */
 					time_buffer,
 					(unsigned long) (now_epoch - proc->start_epoch),
 					proc->requests,
-					duration.tv_sec * 1000000UL + duration.tv_usec,
+					(unsigned long) (duration.tv_sec * 1000000UL + duration.tv_usec),
 					proc->request_method[0] != '\0' ? proc->request_method : "-",
 					proc->request_uri[0] != '\0' ? proc->request_uri : "-",
 					query_string ? "?" : "",

[andypost]

@nielsdos checked your patch and the test pass, thank you!