php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #81275 status page, contain bugus value in request duration sometimes
Submitted: 2021-07-19 18:23 UTC Modified: 2021-09-05 19:23 UTC
Votes:1
Avg. Score:3.0 ± 0.0
Reproduced:0 of 0 (0.0%)
From: tsmtgdi at gmail dot com Assigned: bukka (profile)
Status: Assigned Package: FPM related
PHP Version: 8.1Git-2021-07-19 (Git) OS: Suse
Private report: No CVE-ID: None
View Add Comment Developer Edit
Anyone can comment on a bug. Have a simpler test case? Does it work for you on a different platform? Let us know!
Just going to say 'Me too!'? Don't clutter the database with that please — but make sure to vote on the bug!
Your email address:
MUST BE VALID
Solve the problem:
23 + 39 = ?
Subscribe to this entry?

 
 [2021-07-19 18:23 UTC] tsmtgdi at gmail dot com
Description:
------------
When accessing the php-fpm status page (pm.status_path), when the process is in status "Reading headers", "Finishing" and "Starting", we have several cases in which the value request duration is bogus, we suspect is just reading an uninitialized memory location, we can even have value of 18446744073709551592 (almost all bit set)...

Test script:
---------------
Is quite easy, you have to poll with very high frequency the status page while doing many small request to increase the chance to find this bug.

you can use siege or ab2 so simulate traffic on a dummy page (even empty is fine)
and something like 

It should take 4/5 second at most on a free running loop...

<?php

while(true){
    $json = file_get_contents("http://127.0.0.1/status.php?json&full");
    $result = json_decode($json);
    $processes = $result->processes;
    foreach ($processes as $proc){
        //a dummy page should take low time to be gen no ?
        if($proc->{"request duration"} > 1000000){
            echo "impossible value found!";
            print_r($proc);
            echo "\n";
            die();
        }
    }
}


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2021-07-19 18:24 UTC] tsmtgdi at gmail dot com
I forget to add, I just compiled the php code (very easy! bravo!), and I will now try with the help of two coworker to do a patch.
 [2021-07-19 20:06 UTC] tsmtgdi at gmail dot com
After reviewing the code, I think the logic is correct, the problem is in some missing mutex or sync problem, for example I discovered having a single fpm process will never trigger the error.
Also I had case of

    [pid] => 0
    [state] => (null)
    [start time] => 0
    [start since] => 1626722020
    [requests] => 0
    [request duration] => 51276947114

Which is... in theory impossible 

What I discovered is that, the proc = *scoreboard_p->procs[i];
Is not doing a correct copy, I have stack trace in which the proc is different from the scoreboard_p->procs[0]

https://pastebin.com/Hxgwq1c1

I can say that "maybe" the operation is done outside of the mutex (in fact around line 196 you have a 
		/* copy the scoreboard not to bother other processes */
		scoreboard = *scoreboard_p;
		fpm_unlock(scoreboard_p->lock);)

I will later try to use this copy.
 [2021-07-20 01:20 UTC] tsmtgdi at gmail dot com
I tried doing

		int   scoreboard_size        = sizeof(struct fpm_scoreboard_s) + (scoreboard_p->nprocs) * sizeof(struct fpm_scoreboard_proc_s*);
		int   scoreboard_nprocs_size = sizeof(struct fpm_scoreboard_proc_s) * scoreboard_p->nprocs;
		scoreboardCopy                = (struct fpm_scoreboard_s*)emalloc(scoreboard_size + scoreboard_nprocs_size);
		
		memcpy(scoreboardCopy, scoreboard_p, scoreboard_size + scoreboard_nprocs_size);

To have a full copy, both of the fpm_scoreboard_s and the array of fpm_scoreboard_proc_s, but the problem is still present.
 [2021-08-03 13:05 UTC] ramsey@php.net
-Assigned To: +Assigned To: bukka
 [2021-08-03 13:05 UTC] ramsey@php.net
bukka, can you take a look? nikic thinks there might already be a PR for this, but I can't find it.
 [2021-08-03 13:10 UTC] nikic@php.net
This is the PR I had in mind: https://github.com/php/php-src/pull/3188
 [2021-09-05 19:23 UTC] bukka@php.net
Ah so it's not maybe such a theoretical issue that I thought initially. That PR looks like a potential fix indeed. I will need to test it to confirm though. Will also think about creating some test for this (most likely the slow one if possible).
 
PHP Copyright © 2001-2021 The PHP Group
All rights reserved.
Last updated: Thu Oct 28 09:03:35 2021 UTC