Skip to content

Commit ffcf57f

Browse files
sadapon2008bukka
sadapon2008
authored and
bukka
committed
Fix bug #78334 (fpm log prefix message includes wrong stdout/stderr notation)
1 parent 461db52 commit ffcf57f

File tree

8 files changed

+95
-9
lines changed

8 files changed

+95
-9
lines changed

‎NEWS‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,10 @@ PHP NEWS
1111
. Fixed bug #77812 (Interactive mode does not support PHP 7.3-style heredoc).
1212
(cmb, Nikita)
1313

14+
- FPM:
15+
. Fixed bug #78334 (fpm log prefix message includes wrong stdout/stderr
16+
notation). (Tsuyoshi Sadakata)
17+
1418
- Intl:
1519
. Ensure IDNA2003 rules are used with idn_to_ascii() and idn_to_utf8()
1620
when requested. (Sara)

‎sapi/fpm/fpm/fpm_stdio.c‎

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -144,11 +144,22 @@ static void fpm_stdio_child_said(struct fpm_event_s *ev, short which, void *arg)
144144
zlog_stream_init_ex(log_stream, ZLOG_WARNING, STDERR_FILENO);
145145
zlog_stream_set_decorating(log_stream, child->wp->config->decorate_workers_output);
146146
zlog_stream_set_wrapping(log_stream, ZLOG_TRUE);
147-
zlog_stream_set_msg_prefix(log_stream, "[pool %s] child %d said into %s: ",
147+
zlog_stream_set_msg_prefix(log_stream, STREAM_SET_MSG_PREFIX_FMT,
148148
child->wp->config->name, (int) child->pid, is_stdout ? "stdout" : "stderr");
149149
zlog_stream_set_msg_quoting(log_stream, ZLOG_TRUE);
150+
zlog_stream_set_is_stdout(log_stream, is_stdout);
151+
zlog_stream_set_child_pid(log_stream, (int)child->pid);
150152
} else {
151153
log_stream = child->log_stream;
154+
// if fd type (stdout/stderr) or child's pid is changed,
155+
// then the stream will be finished and msg's prefix will be reinitialized
156+
if (log_stream->is_stdout != (unsigned int)is_stdout || log_stream->child_pid != (int)child->pid) {
157+
zlog_stream_finish(log_stream);
158+
zlog_stream_set_msg_prefix(log_stream, STREAM_SET_MSG_PREFIX_FMT,
159+
child->wp->config->name, (int) child->pid, is_stdout ? "stdout" : "stderr");
160+
zlog_stream_set_is_stdout(log_stream, is_stdout);
161+
zlog_stream_set_child_pid(log_stream, (int)child->pid);
162+
}
152163
}
153164

154165
while (fifo_in || fifo_out) {

‎sapi/fpm/fpm/fpm_stdio.h‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,8 @@
55

66
#include "fpm_worker_pool.h"
77

8+
#define STREAM_SET_MSG_PREFIX_FMT "[pool %s] child %d said into %s: "
9+
810
int fpm_stdio_init_main();
911
int fpm_stdio_init_final();
1012
int fpm_stdio_init_child(struct fpm_worker_pool_s *wp);

‎sapi/fpm/fpm/zlog.c‎

Lines changed: 17 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -563,6 +563,18 @@ void zlog_stream_set_wrapping(struct zlog_stream *stream, zlog_bool wrap) /* {{{
563563
}
564564
/* }}} */
565565

566+
void zlog_stream_set_is_stdout(struct zlog_stream *stream, zlog_bool is_stdout) /* {{{ */
567+
{
568+
stream->is_stdout = is_stdout ? 1 : 0;
569+
}
570+
/* }}} */
571+
572+
void zlog_stream_set_child_pid(struct zlog_stream *stream, int child_pid) /* {{{ */
573+
{
574+
stream->child_pid = child_pid;
575+
}
576+
/* }}} */
577+
566578
void zlog_stream_set_msg_quoting(struct zlog_stream *stream, zlog_bool quote) /* {{{ */
567579
{
568580
stream->msg_quote = quote && stream->decorate ? 1 : 0;
@@ -583,9 +595,11 @@ zlog_bool zlog_stream_set_msg_prefix(struct zlog_stream *stream, const char *fmt
583595
len = vsnprintf(buf, MAX_WRAPPING_PREFIX_LENGTH - 1, fmt, args);
584596
va_end(args);
585597

586-
stream->msg_prefix = malloc(len + 1);
587-
if (stream->msg_prefix == NULL) {
588-
return ZLOG_FALSE;
598+
if (stream->msg_prefix_len < len) {
599+
stream->msg_prefix = stream->msg_prefix_len ? realloc(stream->msg_prefix, len + 1) : malloc(len + 1);
600+
if (stream->msg_prefix == NULL) {
601+
return ZLOG_FALSE;
602+
}
589603
}
590604
memcpy(stream->msg_prefix, buf, len);
591605
stream->msg_prefix[len] = 0;

‎sapi/fpm/fpm/zlog.h‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -73,8 +73,10 @@ struct zlog_stream {
7373
unsigned int wrap:1;
7474
unsigned int msg_quote:1;
7575
unsigned int decorate:1;
76+
unsigned int is_stdout:1;
7677
int fd;
7778
int line;
79+
int child_pid;
7880
const char *function;
7981
struct zlog_stream_buffer buf;
8082
size_t len;
@@ -92,6 +94,8 @@ void zlog_stream_init(struct zlog_stream *stream, int flags);
9294
void zlog_stream_init_ex(struct zlog_stream *stream, int flags, int fd);
9395
void zlog_stream_set_decorating(struct zlog_stream *stream, zlog_bool decorate);
9496
void zlog_stream_set_wrapping(struct zlog_stream *stream, zlog_bool wrap);
97+
void zlog_stream_set_is_stdout(struct zlog_stream *stream, zlog_bool is_stdout);
98+
void zlog_stream_set_child_pid(struct zlog_stream *stream, int child_pid);
9599
void zlog_stream_set_msg_quoting(struct zlog_stream *stream, zlog_bool quote);
96100
zlog_bool zlog_stream_set_msg_prefix(struct zlog_stream *stream, const char *fmt, ...)
97101
__attribute__ ((format(printf,2,3)));

‎sapi/fpm/tests/log-bwd-multiple-msgs-stdout-stderr.phpt‎

Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,50 @@
1+
--TEST--
2+
FPM: Buffered worker output decorated log with multiple continuous messages (stdout/stderr mixed)
3+
--SKIPIF--
4+
<?php include "skipif.inc"; ?>
5+
--FILE--
6+
<?php
7+
8+
require_once "tester.inc";
9+
10+
$cfg = <<<EOT
11+
[global]
12+
error_log = {{FILE:LOG}}
13+
[unconfined]
14+
listen = {{ADDR}}
15+
pm = dynamic
16+
pm.max_children = 5
17+
pm.start_servers = 1
18+
pm.min_spare_servers = 1
19+
pm.max_spare_servers = 3
20+
catch_workers_output = yes
21+
EOT;
22+
23+
$code = <<<EOT
24+
<?php
25+
file_put_contents('php://stdout', "msg 1 - ");
26+
usleep(1);
27+
file_put_contents('php://stderr', "msg 2 - ");
28+
usleep(1);
29+
file_put_contents('php://stderr', "msg 3");
30+
EOT;
31+
32+
$tester = new FPM\Tester($cfg, $code);
33+
$tester->start();
34+
$tester->expectLogStartNotices();
35+
$tester->request()->expectEmptyBody();
36+
$tester->request()->expectEmptyBody();
37+
$tester->terminate();
38+
$tester->expectLogLine('msg 1 - ', false);
39+
$tester->expectLogLine('msg 2 - msg 3', true);
40+
$tester->close();
41+
42+
?>
43+
Done
44+
--EXPECT--
45+
Done
46+
--CLEAN--
47+
<?php
48+
require_once "tester.inc";
49+
FPM\Tester::clean();
50+
?>

‎sapi/fpm/tests/logtool.inc‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ class LogTool
66
{
77
const P_TIME = '\[\d\d-\w\w\w-\d{4} \d\d:\d\d:\d\d\]';
88
const P_PREFIX = '\[pool unconfined\] child \d+ said into stderr: ';
9+
const P_PREFIX_STDOUT = '\[pool unconfined\] child \d+ said into stdout: ';
910
const FINAL_SUFFIX = ', pipe is closed';
1011

1112
/**
@@ -130,7 +131,7 @@ class LogTool
130131
* @param bool $decorated
131132
* @return bool
132133
*/
133-
public function checkWrappedMessage(array $lines, bool $terminated = true, bool $decorated = true)
134+
public function checkWrappedMessage(array $lines, bool $terminated = true, bool $decorated = true, bool $is_stderr = true)
134135
{
135136
if ($this->message === null) {
136137
throw new \LogicException('The message has not been set');
@@ -140,7 +141,7 @@ class LogTool
140141
'/^(%s %s: %s)"([^"]*)"(.*)?$/',
141142
self::P_TIME,
142143
$this->getExpectedLevel(),
143-
self::P_PREFIX
144+
$is_stderr ? self::P_PREFIX : self::P_PREFIX_STDOUT
144145
);
145146
} else {
146147
$this->pattern = null;
@@ -157,7 +158,7 @@ class LogTool
157158
$suffixPattern = sprintf(
158159
'/^%s %s: %s(.*)$/',
159160
self::P_TIME, $this->getExpectedLevel(),
160-
self::P_PREFIX
161+
$is_stderr ? self::P_PREFIX : self::P_PREFIX_STDOUT
161162
);
162163
$line = $lines[++$idx];
163164
if (preg_match($suffixPattern, $line, $matches) === 0) {

‎sapi/fpm/tests/tester.inc‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1080,7 +1080,7 @@ class Tester
10801080
* @param string $message
10811081
* @return bool
10821082
*/
1083-
public function expectLogLine(string $message)
1083+
public function expectLogLine(string $message, bool $is_stderr = true)
10841084
{
10851085
$messageLen = strlen($message);
10861086
$limit = $messageLen > 1024 ? $messageLen + 16 : 1024;
@@ -1090,7 +1090,7 @@ class Tester
10901090
$this->message("LOG LINE: " . ($logLines[0] ?? ''));
10911091
}
10921092

1093-
return $this->logTool->checkWrappedMessage($logLines, false);
1093+
return $this->logTool->checkWrappedMessage($logLines, false, true, $is_stderr);
10941094
}
10951095

10961096
/**

0 commit comments

Comments
 (0)