Skip to content

Commit 1c5844a

Browse files
bukkabukka
committed
Fix GH-9754: SaltStack hangs when running php-fpm 8.1.11
SaltStack uses Python subprocess and redirects stderr to stdout which is then piped to the returned output. If php-fpm starts in daemonized mode, it should close stderr. However a fix introduced in GH-8913 keeps stderr around so it can be later restored. That causes the issue reported in GH-9754. The solution is to keep stderr around only when php-fpm runs in foreground as the issue is most likely visible only there. Basically there is no need to restore stderr when php-fpm is daemonized.
1 parent 9604986 commit 1c5844a

File tree

6 files changed

+146
-25
lines changed

6 files changed

+146
-25
lines changed

‎NEWS‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,10 @@ PHP NEWS
1515
. Fixed bug GH-9763 (DateTimeZone ctr mishandles input and adds null byte if
1616
the argument is an offset larger than 100*60 minutes). (Derick)
1717

18+
- FPM:
19+
. Fixed bug GH-9754 (SaltStack (using Python subprocess) hangs when running
20+
php-fpm 8.1.11). (Jakub Zelenka)
21+
1822
- mysqli:
1923
. Fixed bug GH-9841 (mysqli_query throws warning despite using
2024
silenced error mode). (Kamil Tekiela)

‎sapi/fpm/fpm/fpm_conf.c‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1282,7 +1282,7 @@ static int fpm_conf_post_process(int force_daemon) /* {{{ */
12821282
fpm_evaluate_full_path(&fpm_global_config.error_log, NULL, PHP_LOCALSTATEDIR, 0);
12831283
}
12841284

1285-
if (0 > fpm_stdio_save_original_stderr()) {
1285+
if (!fpm_global_config.daemonize && 0 > fpm_stdio_save_original_stderr()) {
12861286
return -1;
12871287
}
12881288

‎sapi/fpm/fpm/fpm_stdio.c‎

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -74,7 +74,9 @@ int fpm_stdio_init_final(void)
7474

7575
int fpm_stdio_save_original_stderr(void)
7676
{
77-
/* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */
77+
/* STDERR fd gets lost after calling fpm_stdio_init_final() (check GH-8555) so it can be saved.
78+
* It should be used only when PHP-FPM is not daemonized otherwise it might break some
79+
* applications (e.g. GH-9754). */
7880
zlog(ZLOG_DEBUG, "saving original STDERR fd: dup()");
7981
fd_stderr_original = dup(STDERR_FILENO);
8082
if (0 > fd_stderr_original) {
@@ -87,7 +89,7 @@ int fpm_stdio_save_original_stderr(void)
8789

8890
int fpm_stdio_restore_original_stderr(int close_after_restore)
8991
{
90-
/* php-fpm loses STDERR fd after call of the fpm_stdio_init_final(). Check #8555. */
92+
/* Restore original STDERR fd if it was previously saved. */
9193
if (-1 != fd_stderr_original) {
9294
zlog(ZLOG_DEBUG, "restoring original STDERR fd: dup2()");
9395
if (0 > dup2(fd_stderr_original, STDERR_FILENO)) {
@@ -98,9 +100,6 @@ int fpm_stdio_restore_original_stderr(int close_after_restore)
98100
close(fd_stderr_original);
99101
}
100102
}
101-
} else {
102-
zlog(ZLOG_DEBUG, "original STDERR fd is not restored, maybe function is called from a child: dup2()");
103-
return -1;
104103
}
105104

106105
return 0;

‎sapi/fpm/tests/gh9754-daemonized-stderr-close.phpt‎

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
--TEST--
2+
FPM: GH-9754 - stderr is not closed in daemonized run
3+
--SKIPIF--
4+
<?php
5+
include "skipif.inc";
6+
FPM\Tester::skipIfRoot();
7+
?>
8+
--FILE--
9+
<?php
10+
11+
require_once "tester.inc";
12+
13+
$cfg = <<<EOT
14+
[global]
15+
error_log = {{FILE:LOG}}
16+
pid = {{FILE:PID}}
17+
[unconfined]
18+
listen = {{ADDR}}
19+
pm = dynamic
20+
pm.max_children = 5
21+
pm.start_servers = 1
22+
pm.min_spare_servers = 1
23+
pm.max_spare_servers = 3
24+
EOT;
25+
26+
$tester = new FPM\Tester($cfg);
27+
$tester->start(daemonize: true);
28+
$tester->expectLogStartNotices();
29+
$tester->switchLogSource('{{MASTER:OUT}}');
30+
$tester->expectLogEmpty();
31+
$tester->switchLogSource('{{FILE:LOG}}');
32+
$tester->terminate();
33+
$tester->expectLogTerminatingNotices();
34+
$tester->close();
35+
36+
?>
37+
Done
38+
--EXPECT--
39+
Done
40+
--CLEAN--
41+
<?php
42+
require_once "tester.inc";
43+
FPM\Tester::clean();
44+
?>

‎sapi/fpm/tests/logreader.inc‎

Lines changed: 52 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -81,15 +81,23 @@ class LogReader
8181
/**
8282
* Get a single log line.
8383
*
84-
* @param int $timeoutSeconds
85-
* @param int $timeoutMicroseconds
84+
* @param int $timeoutSeconds Read timeout in seconds
85+
* @param int $timeoutMicroseconds Read timeout in microseconds
86+
* @param bool $throwOnTimeout Whether to throw an exception on timeout
8687
*
8788
* @return null|string
8889
* @throws \Exception
8990
*/
90-
public function getLine(int $timeoutSeconds = 3, int $timeoutMicroseconds = 0): ?string
91-
{
92-
$line = $this->getSource()->getLine($timeoutSeconds, $timeoutMicroseconds);
91+
public function getLine(
92+
int $timeoutSeconds = 3,
93+
int $timeoutMicroseconds = 0,
94+
bool $throwOnTimeout = false
95+
): ?string {
96+
$line = $this->getSource()->getLine(
97+
$timeoutSeconds,
98+
$timeoutMicroseconds,
99+
$throwOnTimeout
100+
);
93101
$this->trace(is_null($line) ? "LINE - null" : "LINE: $line");
94102

95103
return $line;
@@ -196,17 +204,27 @@ class LogReader
196204
}
197205
}
198206

207+
class LogTimoutException extends \Exception
208+
{
209+
}
210+
199211
abstract class LogSource
200212
{
201213
/**
202214
* Get single line from the source.
203215
*
204-
* @param int $timeoutSeconds Read timeout in seconds
205-
* @param int $timeoutMicroseconds Read timeout in microseconds
216+
* @param int $timeoutSeconds Read timeout in seconds
217+
* @param int $timeoutMicroseconds Read timeout in microseconds
218+
* @param bool $throwOnTimeout Whether to throw an exception on timeout
206219
*
207220
* @return string|null
221+
* @throws LogTimoutException
208222
*/
209-
public abstract function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string;
223+
public abstract function getLine(
224+
int $timeoutSeconds,
225+
int $timeoutMicroseconds,
226+
bool $throwOnTimeout = false
227+
): ?string;
210228

211229
/**
212230
* Get all lines that has been returned by getLine() method.
@@ -236,13 +254,18 @@ class LogStreamSource extends LogSource
236254
/**
237255
* Get single line from the stream.
238256
*
239-
* @param int $timeoutSeconds Read timeout in seconds
240-
* @param int $timeoutMicroseconds Read timeout in microseconds
257+
* @param int $timeoutSeconds Read timeout in seconds
258+
* @param int $timeoutMicroseconds Read timeout in microseconds
259+
* @param bool $throwOnTimeout Whether to throw an exception on timeout
241260
*
242261
* @return string|null
262+
* @throws LogTimoutException
243263
*/
244-
public function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string
245-
{
264+
public function getLine(
265+
int $timeoutSeconds,
266+
int $timeoutMicroseconds,
267+
bool $throwOnTimeout = false
268+
): ?string {
246269
if (feof($this->stream)) {
247270
return null;
248271
}
@@ -255,6 +278,10 @@ class LogStreamSource extends LogSource
255278

256279
return $line;
257280
} else {
281+
if ($throwOnTimeout) {
282+
throw new LogTimoutException('Timout exceeded when reading line');
283+
}
284+
258285
return null;
259286
}
260287
}
@@ -296,13 +323,18 @@ class LogFileSource extends LogSource
296323
/**
297324
* Get single line from the file.
298325
*
299-
* @param int $timeoutSeconds Read timeout in seconds
300-
* @param int $timeoutMicroseconds Read timeout in microseconds
326+
* @param int $timeoutSeconds Read timeout in seconds
327+
* @param int $timeoutMicroseconds Read timeout in microseconds
328+
* @param bool $throwOnTimeout Whether to throw an exception on timeout
301329
*
302330
* @return string|null
331+
* @throws LogTimoutException
303332
*/
304-
public function getLine(int $timeoutSeconds, int $timeoutMicroseconds): ?string
305-
{
333+
public function getLine(
334+
int $timeoutSeconds,
335+
int $timeoutMicroseconds,
336+
bool $throwOnTimeout = false
337+
): ?string {
306338
$endTime = microtime(true) + $timeoutSeconds + ($timeoutMicroseconds / 1_000_000);
307339
while ($this->position >= count($this->lines)) {
308340
if (is_file($this->filePath)) {
@@ -317,6 +349,10 @@ class LogFileSource extends LogSource
317349
}
318350
usleep(50_000);
319351
if (microtime(true) > $endTime) {
352+
if ($throwOnTimeout) {
353+
throw new LogTimoutException('Timout exceeded when reading line');
354+
}
355+
320356
return null;
321357
}
322358
}

‎sapi/fpm/tests/tester.inc‎

Lines changed: 41 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -104,6 +104,11 @@ class Tester
104104
*/
105105
private $masterProcess;
106106

107+
/**
108+
* @var bool
109+
*/
110+
private bool $daemonized;
111+
107112
/**
108113
* @var resource
109114
*/
@@ -373,21 +378,27 @@ class Tester
373378
*
374379
* @param array $extraArgs Command extra arguments.
375380
* @param bool $forceStderr Whether to output to stderr so error log is used.
381+
* @param bool $daemonize Whether to start FPM daemonized
376382
*
377383
* @return bool
378384
* @throws \Exception
379385
*/
380-
public function start(array $extraArgs = [], bool $forceStderr = true)
386+
public function start(array $extraArgs = [], bool $forceStderr = true, bool $daemonize = false)
381387
{
382388
$configFile = $this->createConfig();
383389
$desc = $this->outDesc ? [] : [1 => array('pipe', 'w'), 2 => array('redirect', 1)];
384390

385-
$cmd = [self::findExecutable(), '-F', '-y', $configFile];
391+
$cmd = [self::findExecutable(), '-y', $configFile];
386392

387393
if ($forceStderr) {
388394
$cmd[] = '-O';
389395
}
390396

397+
$this->daemonized = $daemonize;
398+
if ( ! $daemonize) {
399+
$cmd[] = '-F';
400+
}
401+
391402
if (getenv('TEST_FPM_RUN_AS_ROOT')) {
392403
$cmd[] = '--allow-to-run-as-root';
393404
}
@@ -410,6 +421,9 @@ class Tester
410421
if ( ! $this->outDesc !== false) {
411422
$this->outDesc = $pipes[1];
412423
$this->logReader->setStreamSource('{{MASTER:OUT}}', $this->outDesc);
424+
if ($daemonize) {
425+
$this->switchLogSource('{{FILE:LOG}}');
426+
}
413427
}
414428

415429
return true;
@@ -833,7 +847,11 @@ class Tester
833847
*/
834848
public function terminate()
835849
{
836-
proc_terminate($this->masterProcess);
850+
if ($this->daemonized) {
851+
$this->signal('TERM');
852+
} else {
853+
proc_terminate($this->masterProcess);
854+
}
837855
}
838856

839857
/**
@@ -1272,6 +1290,26 @@ class Tester
12721290
$this->logTool->checkTruncatedMessage($this->response->getErrorData());
12731291
}
12741292

1293+
/**
1294+
* Expect log to be empty.
1295+
*
1296+
* @throws \Exception
1297+
*/
1298+
public function expectLogEmpty()
1299+
{
1300+
try {
1301+
$line = $this->logReader->getLine(1, 0, true);
1302+
if ($line === '') {
1303+
$line = $this->logReader->getLine(1, 0, true);
1304+
}
1305+
if ($line !== null) {
1306+
$this->error('Log is not closed and returned line: ' . $line);
1307+
}
1308+
} catch (LogTimoutException $exception) {
1309+
$this->error('Log is not closed and timed out', $exception);
1310+
}
1311+
}
1312+
12751313
/**
12761314
* Expect reloading lines to be logged.
12771315
*

0 commit comments

Comments
 (0)