elastic / elastic/elastic-transport-php

logHeaders() materializes complete message bodies when using NullLogger

Open
#46 0 comments 0 reactions 0 assignees View on GitHub
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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.