Skip to content

Commit 1cffae6

Browse files
maaarghkmaaarghk
committed
php-fpm: tester: Add and use access log checking function
1 parent 76af65c commit 1cffae6

File tree

3 files changed

+121
-91
lines changed

3 files changed

+121
-91
lines changed

‎sapi/fpm/tests/log-suppress-output-request-body.phpt

Lines changed: 10 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -11,8 +11,6 @@ $testScript = <<<EOT
1111
<?php
1212
echo strlen(file_get_contents('php://input'));
1313
EOT;
14-
$s = __DIR__ . '/health_check.php';
15-
file_put_contents($s, $testScript);
1614

1715
$body = str_repeat('a', 100);
1816

@@ -24,7 +22,7 @@ pid = {{FILE:PID}}
2422
[unconfined]
2523
listen = {{ADDR}}
2624
access.log = {{FILE:LOG:ACC}}
27-
access.format = "%R \"%m %r%Q%q\" %s"
25+
access.format = "'%m %r%Q%q' %s"
2826
access.suppress_path[] = /ping
2927
access.suppress_path[] = /request-1
3028
access.suppress_path[] = /request-2
@@ -43,71 +41,67 @@ pm.min_spare_servers = 1
4341
pm.max_spare_servers = 3
4442
EOT;
4543

46-
$tester = new FPM\Tester($cfg);
44+
$tester = new FPM\Tester($cfg, $testScript);
4745
$tester->start();
4846
$tester->expectLogStartNotices();
47+
$tester->expectSuppressableAccessLogEntries(false);
4948
$tester->ping();
5049

5150
// Should not suppress POST with no body
5251
$tester->request(
53-
scriptFilename: $s,
5452
uri: '/request-1',
5553
headers: ['REQUEST_METHOD' => 'POST']
5654
)->expectBody('0');
55+
$tester->expectAccessLog("'POST /request-1' 200", suppressable: false);
5756

5857
// Should not suppress POST with body
5958
$tester->request(
60-
scriptFilename: $s,
6159
uri: '/request-2',
6260
stdin: $body
6361
)->expectBody('100');
62+
$tester->expectAccessLog("'POST /request-2' 200", suppressable: false);
6463

6564
// Should not suppress GET with body
6665
$tester->request(
67-
scriptFilename: $s,
6866
uri: '/request-3',
6967
headers: ['REQUEST_METHOD' => 'GET'],
7068
stdin: $body
7169
)->expectBody('100');
70+
$tester->expectAccessLog("'GET /request-3' 200", suppressable: false);
7271

7372
// Should suppress GET with no body
7473
$tester->request(
75-
scriptFilename: $s,
7674
uri: '/request-4'
7775
)->expectBody('0');
76+
$tester->expectAccessLog("'GET /request-4' 200", suppressable: true);
7877

7978
// Should not suppress GET with no body but incorrect content length
8079
$tester->request(
81-
scriptFilename: $s,
8280
uri: '/request-5',
8381
headers: ['REQUEST_METHOD' => 'GET', 'CONTENT_LENGTH' => 100]
8482
)->expectBody('0');
83+
$tester->expectAccessLog("'GET /request-5' 200", suppressable: false);
8584

8685
// Should suppress GET with body but 0 content length (no stdin readable)
8786
$tester->request(
88-
scriptFilename: $s,
8987
uri: '/request-6',
9088
headers: ['REQUEST_METHOD' => 'GET', 'CONTENT_LENGTH' => 0],
9189
stdin: $body
9290
)->expectBody('0');
91+
$tester->expectAccessLog("'GET /request-6' 200", suppressable: true);
9392

9493
$tester->terminate();
9594
$tester->expectLogTerminatingNotices();
9695
$tester->close();
9796
$tester->expectNoFile(FPM\Tester::FILE_EXT_PID);
98-
$tester->printAccessLog();
97+
$tester->checkAccessLog();
9998

10099
?>
101100
Done
102101
--EXPECT--
103-
127.0.0.1 "POST /request-1" 200
104-
127.0.0.1 "POST /request-2" 200
105-
127.0.0.1 "GET /request-3" 200
106-
127.0.0.1 "GET /request-5" 200
107102
Done
108103
--CLEAN--
109104
<?php
110105
require_once "tester.inc";
111106
FPM\Tester::clean();
112-
unlink(__DIR__ . '/health_check.php');
113107
?>

‎sapi/fpm/tests/log-suppress-output.phpt

Lines changed: 52 additions & 72 deletions
Original file line numberDiff line numberDiff line change
@@ -7,34 +7,68 @@ FPM: Test excluding URIs from access log
77

88
require_once "tester.inc";
99

10-
$normalCode = <<<EOT
11-
<?php
12-
echo \$_REQUEST['test'] ?? "Hello world";
13-
EOT;
10+
function doTestCalls(FPM\Tester &$tester, bool $expectSuppressableEntries)
11+
{
12+
$tester->expectSuppressableAccessLogEntries($expectSuppressableEntries);
13+
14+
$tester->ping();
15+
$tester->expectAccessLog("'GET /ping' 200", suppressable: true);
16+
17+
$tester->request()->expectBody('OK');
18+
$tester->expectAccessLog("'GET /log-suppress-output.src.php' 200", suppressable: true);
19+
20+
$tester->ping();
21+
$tester->expectAccessLog("'GET /ping' 200", suppressable: true);
22+
23+
$tester->request()->expectBody('OK');
24+
$tester->expectAccessLog("'GET /log-suppress-output.src.php' 200", suppressable: true);
25+
26+
$tester->ping();
27+
$tester->expectAccessLog("'GET /ping' 200", suppressable: true);
28+
29+
$tester->request(query: 'test=output')->expectBody('output');
30+
$tester->expectAccessLog("'GET /log-suppress-output.src.php?test=output' 200", suppressable: false);
31+
32+
$tester->ping();
33+
$tester->expectAccessLog("'GET /ping' 200", suppressable: true);
1434

15-
file_put_contents(__DIR__ . '/log_exclude_paths_normal.php', $normalCode);
35+
$tester->request()->expectBody('OK');
36+
$tester->expectAccessLog("'GET /log-suppress-output.src.php' 200", suppressable: true);
1637

17-
$statusCode = <<<EOT
38+
$tester->request(query: 'test=output', uri: '/ping')->expectBody('pong', 'text/plain');
39+
$tester->expectAccessLog("'GET /ping?test=output' 200", suppressable: false);
40+
41+
$tester->request(headers: ['X_ERROR' => 1])->expectBody('Not OK');
42+
$tester->expectAccessLog("'GET /log-suppress-output.src.php' 500", suppressable: false);
43+
44+
$tester->request()->expectBody('OK');
45+
$tester->expectAccessLog("'GET /log-suppress-output.src.php' 200", suppressable: true);
46+
47+
$tester->request(query: 'test=output', uri: '/ping')->expectBody('pong', 'text/plain');
48+
$tester->expectAccessLog("'GET /ping?test=output' 200", suppressable: false);
49+
50+
$tester->ping();
51+
$tester->expectAccessLog("'GET /ping' 200", suppressable: true);
52+
}
53+
54+
$src = <<<EOT
1855
<?php
1956
if (isset(\$_SERVER['X_ERROR'])) {
2057
echo "Not OK";
2158
http_response_code(500);
2259
exit;
2360
}
24-
echo "OK";
61+
echo \$_REQUEST['test'] ?? "OK";
2562
EOT;
2663

27-
file_put_contents(__DIR__ . '/log_exclude_paths_status.php', $statusCode);
28-
29-
3064
$cfg = <<<EOT
3165
[global]
3266
error_log = {{RFILE:LOG:ERR}}
3367
pid = {{RFILE:PID}}
3468
[unconfined]
3569
listen = {{ADDR}}
3670
access.log = {{RFILE:LOG:ACC}}
37-
access.format = "%R \"%m %r%Q%q\" %s Output"
71+
access.format = "'%m %r%Q%q' %s"
3872
slowlog = {{RFILE:LOG:SLOW}}
3973
request_slowlog_timeout = 1
4074
ping.path = /ping
@@ -47,36 +81,21 @@ pm.max_spare_servers = 3
4781
EOT;
4882

4983
$prefix = __DIR__;
50-
$tester = new FPM\Tester($cfg);
84+
$tester = new FPM\Tester($cfg, $src);
5185
$tester->start(['--prefix', $prefix]);
5286
$tester->expectLogStartNotices();
53-
$tester->ping();
54-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_normal.php')->expectBody('Hello world');
55-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('OK');
56-
$tester->ping();
57-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('OK');
58-
$tester->request(query: 'test=output', scriptFilename: __DIR__ . '/log_exclude_paths_normal.php')->expectBody('output');
59-
$tester->ping();
60-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('OK');
61-
$tester->request(query: 'test=output', scriptFilename: __DIR__ . '/ping')->expectBody('pong', 'text/plain');
62-
$tester->request(headers: ['X_ERROR' => 1], scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('Not OK');
63-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_normal.php')->expectBody('Hello world');
64-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('OK');
65-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_normal.php')->expectBody('Hello world');
66-
$tester->request(query: 'test=output', scriptFilename: __DIR__ . '/ping')->expectBody('pong', 'text/plain');
67-
$tester->ping();
68-
69-
// Add health checks to ignore list
87+
doTestCalls($tester, expectSuppressableEntries: true);
88+
// Add source file and ping to ignore list
7089
$cfg = <<<EOT
7190
[global]
7291
error_log = {{RFILE:LOG:ERR}}
7392
pid = {{RFILE:PID}}
7493
[unconfined]
7594
listen = {{ADDR}}
7695
access.log = {{RFILE:LOG:ACC}}
77-
access.format = "%R \"%m %r%Q%q\" %s Ignore"
96+
access.format = "'%m %r%Q%q' %s"
7897
access.suppress_path[] = /ping
79-
access.suppress_path[] = /log_exclude_paths_status.php
98+
access.suppress_path[] = /log-suppress-output.src.php
8099
slowlog = {{RFILE:LOG:SLOW}}
81100
request_slowlog_timeout = 1
82101
ping.path = /ping
@@ -89,55 +108,16 @@ pm.max_spare_servers = 3
89108
EOT;
90109
$tester->reload($cfg);
91110
$tester->expectLogReloadingNotices();
92-
$tester->ping();
93-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_normal.php')->expectBody('Hello world');
94-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('OK');
95-
$tester->ping();
96-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('OK');
97-
$tester->request(query: 'test=output', scriptFilename: __DIR__ . '/log_exclude_paths_normal.php')->expectBody('output');
98-
$tester->ping();
99-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('OK');
100-
$tester->request(query: 'test=output', scriptFilename: __DIR__ . '/ping')->expectBody('pong', 'text/plain');
101-
$tester->request(headers: ['X_ERROR' => 1], scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('Not OK');
102-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_normal.php')->expectBody('Hello world');
103-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_status.php')->expectBody('OK');
104-
$tester->request(scriptFilename: __DIR__ . '/log_exclude_paths_normal.php')->expectBody('Hello world');
105-
$tester->request(query: 'test=output', scriptFilename: __DIR__ . '/ping')->expectBody('pong', 'text/plain');
106-
$tester->ping();
111+
doTestCalls($tester, expectSuppressableEntries: false);
107112
$tester->terminate();
108113
$tester->expectLogTerminatingNotices();
109114
$tester->close();
110115
$tester->expectNoFile(FPM\Tester::FILE_EXT_PID, $prefix);
111-
$tester->printAccessLog();
112-
113-
unlink(__DIR__ . '/log_exclude_paths_normal.php');
114-
unlink(__DIR__ . '/log_exclude_paths_status.php');
116+
$tester->checkAccessLog();
115117

116118
?>
117119
Done
118120
--EXPECT--
119-
127.0.0.1 "GET /ping" 200 Output
120-
127.0.0.1 "GET /log_exclude_paths_normal.php" 200 Output
121-
127.0.0.1 "GET /log_exclude_paths_status.php" 200 Output
122-
127.0.0.1 "GET /ping" 200 Output
123-
127.0.0.1 "GET /log_exclude_paths_status.php" 200 Output
124-
127.0.0.1 "GET /log_exclude_paths_normal.php?test=output" 200 Output
125-
127.0.0.1 "GET /ping" 200 Output
126-
127.0.0.1 "GET /log_exclude_paths_status.php" 200 Output
127-
127.0.0.1 "GET /ping?test=output" 200 Output
128-
127.0.0.1 "GET /log_exclude_paths_status.php" 500 Output
129-
127.0.0.1 "GET /log_exclude_paths_normal.php" 200 Output
130-
127.0.0.1 "GET /log_exclude_paths_status.php" 200 Output
131-
127.0.0.1 "GET /log_exclude_paths_normal.php" 200 Output
132-
127.0.0.1 "GET /ping?test=output" 200 Output
133-
127.0.0.1 "GET /ping" 200 Output
134-
127.0.0.1 "GET /log_exclude_paths_normal.php" 200 Ignore
135-
127.0.0.1 "GET /log_exclude_paths_normal.php?test=output" 200 Ignore
136-
127.0.0.1 "GET /ping?test=output" 200 Ignore
137-
127.0.0.1 "GET /log_exclude_paths_status.php" 500 Ignore
138-
127.0.0.1 "GET /log_exclude_paths_normal.php" 200 Ignore
139-
127.0.0.1 "GET /log_exclude_paths_normal.php" 200 Ignore
140-
127.0.0.1 "GET /ping?test=output" 200 Ignore
141121
Done
142122
--CLEAN--
143123
<?php

‎sapi/fpm/tests/tester.inc

Lines changed: 59 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -120,6 +120,16 @@ class Tester
120120
*/
121121
private $response;
122122

123+
/**
124+
* @var string[]
125+
*/
126+
private $expectedAccessLogs;
127+
128+
/**
129+
* @var bool
130+
*/
131+
private $expectSuppressableAccessLogEntries;
132+
123133
/**
124134
* Clean all the created files up
125135
*
@@ -537,9 +547,9 @@ class Tester
537547
string $scriptFilename = null,
538548
?string $stdin = null
539549
) {
540-
if (is_null($scriptFilename)) {
541-
$scriptFilename = $this->makeSourceFile();
542-
}
550+
if (is_null($scriptFilename)) {
551+
$scriptFilename = $this->makeSourceFile();
552+
}
543553
if (is_null($uri)) {
544554
$uri = "/" . basename($scriptFilename);
545555
}
@@ -1496,4 +1506,50 @@ class Tester
14961506
print file_get_contents($accessLog);
14971507
}
14981508
}
1509+
1510+
/**
1511+
* Return content of access log.
1512+
*/
1513+
public function getAccessLog()
1514+
{
1515+
$accessLog = $this->getFile('acc.log');
1516+
if (is_file($accessLog)) {
1517+
return file_get_contents($accessLog);
1518+
}
1519+
return false;
1520+
}
1521+
1522+
public function expectAccessLog(
1523+
string $logLine,
1524+
bool $suppressable = false
1525+
) {
1526+
if (!$suppressable || $this->expectSuppressableAccessLogEntries) {
1527+
$this->expectedAccessLogs[] = $logLine;
1528+
}
1529+
}
1530+
1531+
public function checkAccessLog()
1532+
{
1533+
if (isset($this->expectedAccessLogs)) {
1534+
$expectedAccessLog = implode("\n", $this->expectedAccessLogs) . "\n";
1535+
} else {
1536+
$this->error("Called checkAccessLog but did not previous call expectAccessLog");
1537+
}
1538+
if ($accessLog = $this->getAccessLog()) {
1539+
if ($expectedAccessLog !== $accessLog) {
1540+
$this->error(sprintf(
1541+
"Access log was not as expected.\nEXPECTED:\n%s\n\nACTUAL:\n%s",
1542+
$expectedAccessLog,
1543+
$accessLog
1544+
));
1545+
}
1546+
} else {
1547+
$this->error("Called checkAccessLog but access log does not exist");
1548+
}
1549+
}
1550+
1551+
public function expectSuppressableAccessLogEntries($expectSuppressableAccessLogEntries)
1552+
{
1553+
$this->expectSuppressableAccessLogEntries = $expectSuppressableAccessLogEntries;
1554+
}
14991555
}

0 commit comments

Comments
 (0)