elastic / elastic/elastic-transport-php
logHeaders() materializes complete message bodies when using NullLogger
- Dominant language
- PHP
- Stars
- 21
- Forks
- 20
- PR merge metrics
- No merged PRs in 30d
Description
### Description
`Transport::logHeaders()` converts the complete PSR-7 message body to a string while constructing the argument passed to `LoggerInterface::debug()`:
```php
$this->logger->debug(sprintf(
"Headers: %s\nBody: %s",
json_encode($message->getHeaders()),
(string) $message->getBody()
));
```
The conversion and `sprintf()` formatting happen before the logger receives the message. Consequently, the complete body is materialized even when the logger discards debug messages, including when the transport uses `Psr\Log\NullLogger`.
Both `logRequest()` and `logResponse()` call this method, so this applies to request and response bodies.
### Expected behavior
When debug output is discarded, processing a message should not require body-proportional transient allocations solely for logging.
### Actual behavior
The following results were reproduced with `elastic/transport` v9.0.1 and `NullLogger`:
| Body size | PHP 8.3.32 | PHP 8.4.23 | PHP 8.5.9 |
|----------:|-----------:|-----------:|----------:|
| 0.40 MB | 0.90 MB | 0.80 MB | 0.80 MB |
| 1.70 MB | 3.67 MB | 3.41 MB | 3.41 MB |
| 5.00 MB | 12.88 MB | 10.01 MB | 10.01 MB |
| 15.00 MB | 30.75 MB | 30.02 MB | 30.02 MB |
Each run was repeated with identical results. Each payload size runs in a fresh PHP process. The stream is populated incrementally before peak-memory accounting is reset, preventing payload construction and allocator reuse from being included in the measurement.
### Reproduction
Create an empty directory and install the dependencies:
```console
composer require elastic/transport:9.0.1 nyholm/psr7:^1.8
```
Save the following as `benchmark.php`:
```php
0) {
$written = fwrite(
$resource,
substr($chunk, 0, min($remaining, strlen($chunk)))
);
if ($written === false) {
throw new RuntimeException('Unable to populate temporary stream');
}
$remaining -= $written;
}
rewind($resource);
$request = new Request(
'POST',
'http://localhost:9200/_bulk',
[],
Stream::create($resource)
);
// Isolate the actual method responsible for preparing the debug message.
$reflection = new ReflectionClass(Transport::class);
$transport = $reflection->newInstanceWithoutConstructor();
$reflection->getProperty('logger')->setValue($transport, new NullLogger());
$logHeaders = $reflection->getMethod('logHeaders');
gc_collect_cycles();
memory_reset_peak_usage();
$before = memory_get_usage(false);
$logHeaders->invoke($transport, $request);
echo memory_get_peak_usage(false) - $before;
}
function installedVersion(string $package): string
{
return Composer\InstalledVersions::getPrettyVersion($package) ?? 'unknown';
}
```
Run it:
```console
php benchmark.php
```
Output under PHP 8.5.9:
```text
PHP 8.5.9
elastic/transport v9.0.1
nyholm/psr7 1.8.2
psr/log 3.0.2
Body size Transient allocation
0.40 MB 0.80 MB
1.70 MB 3.41 MB
5.00 MB 10.01 MB
15.00 MB 30.02 MB
```
### Environment
- `elastic/transport`: v9.0.1, commit `3488b9d070e220f2a1ebdb500e6c588069f1897f`
- PHP: 8.5.9 CLI, NTS, x86-64
- `nyholm/psr7`: 1.8.2
- `psr/log`: 3.0.2
- Logger: `Psr\Log\NullLogger`
- OS: Linux x86-64
### Possible direction
One option would be to prepare only a bounded body preview and mark it as truncated. Any implementation should account for seekable and non-seekable streams and avoid unexpectedly changing the stream cursor.
This is only a suggested direction; lazy formatting or another approach may fit the transport's logging API better.
Contributor guide
No contributing guide indexed for this repository
Research direction
Start by reading Transport::logHeaders() and the calls from logRequest() and logResponse(), then run benchmark.php with NullLogger to reproduce the allocation. Evaluate an approach that avoids body-proportional work when debug output is discarded while accounting for seekable and non-seekable streams and preserving the stream cursor; done means the reported transient allocation no longer scales with the body solely because of logging.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- php
- Domain
- backend, performance
- Issue type
- Bug
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Quiet
- Clarity
- Mostly clear
- Newbie friendliness
- 45/100