DE-178815 Log OpenSearch requests with large responses - #40
Conversation
|
Downstream consumer: BrandEmbassy/platform-backend#23444 (adds the |
There was a problem hiding this comment.
🟡 Changes recommended
src/Response.php introduces PHP-version-sensitive syntax and also needs a small robustness fix around json_encode() failures when computing size from array bodies.
Once you've addressed the issues Copilot identified, you can request another Copilot review.
Pull request overview
This PR extends the existing “slow request” logging path so OpenSearch/Elastica requests are also logged when the response body exceeds a configurable size threshold (default 10 MB), enabling easier replay/debug of large-payload queries while reusing the existing LOG_SLOW_REQUESTS toggle.
Changes:
- Capture and expose response body size via
Response::getResponseSizeInBytes()(captured at construction time). - Add large-response threshold configuration to
Clientand log when a request is slow or produces a large response (including response size in the log message/context). - Plumb the new threshold through
ClientFactoryand add unit tests + a transport double to exercise the behavior.
File summaries
| File | Description |
|---|---|
| tests/Transport/LargeResponseTransport.php | Adds a transport double that returns a deterministic response to trigger large-response logging tests. |
| tests/ResponseTest.php | Adds unit coverage for response-size capture and persistence after decoding. |
| tests/ClientTest.php | Adds unit coverage verifying warning logging for large responses under LOG_SLOW_REQUESTS. |
| src/Response.php | Captures raw response size at construction and exposes it via a new getter. |
| src/ClientFactory.php | Adds and forwards a configurable large-response threshold when constructing clients. |
| src/Client.php | Implements large-response detection and extends the slow-request logging branch to also log large responses. |
Review details
- Files reviewed: 6/6 changed files
- Comments generated: 2
- Review effort level: Lite
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
chrudos-vorlicek
left a comment
There was a problem hiding this comment.
Code review — NEEDS_REVISION (1 blocking, 6 should-fix)
Reviewed at d491b570 (both commits), diffed against origin/opensearch (merge base eb074464). I read the surrounding code and every caller of the changed constructor, not just the diff. Detail is in the inline comments; this is the overview.
🔴 Blocking
The new json_encode() in Response::__construct() runs on every bulk and msearch response, unconditionally, to compute a size nothing ever reads — see the inline comment on src/Response.php. A bulk of N documents now performs N+1 full json_encode() calls per request, one of them over the entire response array, and none of the resulting sizes is consumed anywhere. On the ~290 MB bulk responses this PR is written to diagnose, that is a fresh ~290 MB allocation on the hottest write path.
🟡 Should fix
| # | Where | Issue |
|---|---|---|
| S1 | src/Client.php:185 |
The size trigger logs an unbounded response body — by definition every record it produces is ≥ the threshold |
| S2 | src/Client.php:191, :182 |
Changed log message and synthetic exception text silently break anything keyed on the old strings |
| S3 | src/Client.php:180 |
No discrete reason field, so "large but fast" can't be filtered; MB-as-float aggregates poorly |
| S4 | tests/*, src/Client.php:162 |
The slow path has no test at all; the json_encode() === false branch has none either |
| S5 | src/Client.php:165 |
logSlowRequest / shouldLogSlowRequests / LOG_SLOW_REQUESTS no longer describe what they do |
| S6 | src/Response.php:31 |
Docblock is inaccurate for the array branch |
✅ Checked and clean — not findings
configuration.md—DEFAULT_LARGE_RESPONSE_THRESHOLD_IN_BYTES = 10 MBis a universal behavioural limit, which that document's "Accept — do not flag" list names explicitly ("timeouts, limits, retry counts, batch sizes"). No environment-scoped value is committed and the same value is correct in every region, cell and estate.elasticsearch.md— its single rule (avoidExistsquery) is untouched.git.md— branch and PR title both match the required patterns.php.mdPR scope — 172 added lines against ~200 guidance, one idea, no drive-by refactoring.- Backward compatibility — both new constructor parameters are optional and appended last, on
ClientandClientFactoryalike. - Title and description match the change, and the rationale holds up.
getData()really does clear_responseString(src/Response.php:250), and Guzzle and HttpAdapter really do populate transfer info with onlyrequest_header+http_code(src/Transport/Guzzle.php:89,src/Transport/HttpAdapter.php:72) — so curl'ssize_downloadis genuinely unavailable there and capturing at construction is the right call. S6 is the one inaccuracy. - No double-read or re-buffering of the body.
Httpalready buffers the whole response viaob_start()/ob_get_clean()(src/Transport/Http.php:161-163), sostrlen()on the string branch is O(1). There is no streaming or truncation path in this client. - The three new
ClientTestcases should pass. Passing an FQCN as'transport'resolves through the second candidate class name inAbstractTransport::create()(src/Transport/AbstractTransport.php:137) — a pattern already covered bytests/Transport/AbstractTransportTest.php:48.DummyTransportnever sets a query time, soround(null * 1000)is 0, andRequestnever emitswarning, soexpects($this->once())is safe. Reasoned, not executed — see below.
Context worth knowing (not findings against this PR)
- The PHP 7.2/7.3 floor is already broken on
opensearch, so this is not a regression.protected int $_responseSizeInBytesneeds 7.4+ and the trailing commas intests/ClientTest.phpfunction calls need 7.3+, whilecomposer.jsondeclaresphp: ^7.2 || ^8.0and CI still matrixes 7.2 and 7.3. Butsrc/Client.phpalready carries typed properties on the base branch (private int $loggingMode,protected LoggerInterface $logger), so Copilot's "PHP-version-sensitive syntax" note does not describe something this PR introduced. Worth a separate PR to aligncomposer.jsonwith the matrix; not a reason to hold this one. - CI cannot confirm any of this, and the new tests have never run anywhere. Every check on #39 — the last merge into
opensearch— reportsfailat 24h0m0s, i.e. the runs expired without a runner rather than genuinely failing; this branch's own runs are allcancelled; and this PR is currently 14 pending / 1 pass (Aikido only). The Test Plan above says onlyphp -land a standalone assert check were run. Please runvendor/bin/phpunit --group unitbefore merge, and make sure Aikido is green with the PR marked ready. - Behaviour change worth knowing: a fast-but-large request now takes the early
returnatsrc/Client.php:701, so underLOG_BASIC | LOG_SLOW_REQUESTSit emits the warning instead of the previous debugElastica Request …line. Pre-existing control flow, new consequence. - Org standards vs. vendor-fork conventions — flagged, but I would not block on it. This repo has no
.claude/org-standards.yml, sophp.md§ Testing applies by its own terms, and the new tests break several of its MUSTs: mocks MUST use Mockery (there is nomockerydev dependency and 10+ test files usecreateMock); assertions MUST go throughPHPUnit\Framework\Assertstatically; TestCase classes MUST be final (ClientTestis not, pre-existing); every test-dedicated class MUST carry aTestToolsuffix (LargeResponseTransportdoes not, matching its siblingDummyTransport). Every one of these matches the upstream ruflin/Elastica convention this repo forks, and under the repo-convention-wins precedence rule the new code is the consistent choice. The durable fix is to commit.claude/org-standards.ymlonopensearchin its own PR —AGENTS.mdmakes an opt-out added in the PR it exempts a finding in itself, so not here.
🤖 Review generated with Claude Code against BrandEmbassy/developers-manifest (AGENTS.md → README.md, git.md, php.md, configuration.md, elasticsearch.md; all fetched successfully).
Re-review at
|
State at f92731ab |
|
|---|---|
M1 json_encode() in Response::__construct() on every bulk/msearch response |
Fixed. ?int $_responseSizeInBytes = null; the array branch stores only _response; the string branch keeps the eager O(1) strlen it must have because getData() clears _responseString; getResponseSizeInBytes() encodes lazily and memoises. I grepped the readers — src/Client.php:189, :216, :733, all on the string-bodied transport response — so Bulk\ResponseSet, Bulk\Response and Multi\MultiBuilder now pay nothing. |
| S2 changed log message / exception text | Fixed, better than proposed. 'Slow Elastica Request %s %s %s took %d ms' and RuntimeException('slow query') restored verbatim, so saved searches and fingerprints keep matching, and the new case gets its own message and reason. |
| S1 unbounded response body on the size trigger | Half fixed — see R1 below. |
| S3 no way to filter by trigger reason | Fixed. Two distinct messages, two distinct reasons, plus responseSizeInBytes as an int. |
| S4 coverage gaps | Largely fixed. SlowResponseTransport + a slow-path test, the unencodable-body test, and the large-response test now asserts the log context. Two gaps left — R2, R3. |
S5 stale logSlowRequest naming · S6 inaccurate docblock · minor isLargeResponse(int) |
Fixed. |
Three things I'd still change.
R1 (blocking) — both warnings carry the full request payload, so an incident-scale bulk writes its NDJSON body into two records
src/Client.php:224, in the new shared helper, reached from logSlowRequest() (:165) and logLargeResponse() (:180):
$context = [
...
'request' => $request->toArray(), // unconditional, both paths
'exception' => new \RuntimeException($reason),
];
if ($includeResponseBody) { // large path passes false ✔
$context['response'] = $response->getData();
}Omitting the response body on the large path was the right call. But the request side is still unbounded and unconditional, and Bulk::send() passes the whole payload as $data:
// src/Bulk.php:299
$response = $this->_client->request($this->getPath(), Request::POST, (string) $this, …);(string) $this is the entire bulk NDJSON document set, so Request::toArray() (src/Request.php:204-212) returns it verbatim under data, and the log handler has to JSON-encode that array to write the record — a full copy of the payload, plus escaping.
Failure scenario — the exact request this PR exists to diagnose. The ~260–290 MB bulk response you cite was also slow (a response that size cannot come back inside 500 ms), so both branches at src/Client.php:731-745 fire:
isSlow→ record DE-40276: add request counter support #1 withrequest.data= the full bulk payload;isLargeResponse→ record DE-48156 Improve ES requests logging #2 withrequest.data= the same payload again.
Before this PR that request produced one such record. It now produces two, on a memory-capped worker, at the moment the cluster is already degraded — M1's failure mode relocated from Response::__construct() into the log handler, and paid twice.
Reproduced with your own test double (SlowResponseTransport, threshold at 10 bytes so both trigger), one POST /_bulk:
# f92731ab # opensearch (eb074464)
warning records emitted: 2 records: 1
#1 Slow Elastica Request POST /_bulk … Slow Elastica Request POST /_bulk …
request.data = <full NDJSON payload> request.data present
#2 Large Elastica Response POST /_bulk …
request.data = <full NDJSON payload> ← same payload, second record
Any of these fixes it without losing the diagnostic value — you still know which query to replay:
- give
logLargeResponse()a metadata-only context (path, method, query, status, size, elapsed) and leave the payload to the slow record; - when both fire, emit a single record whose reason is
'slow query, large response'; - cap
request.datainbuildRequestLogContext()(first N KB + original length).
R2 — the one untested combination is the one that double-logs
tests/ClientTest.php:27-95 covers large+fast, slow+small, small+fast and logging-off. Nothing covers slow and large, which is the new interaction and the case R1 is about. With the doubles you already added it is six lines — SlowResponseTransport's body is 13 bytes, so a 10-byte threshold makes it both:
public function testSlowAndLargeResponseIsLoggedTwice(): void
{
$logger = $this->createMock(LoggerInterface::class);
$logger->expects($this->exactly(2))->method('warning');
$client = $this->createClientWithTransportAndLogger(SlowResponseTransport::class, $logger, 10);
$client->setLoggingMode(Client::LOG_SLOW_REQUESTS);
$client->request('/_search');
}R3 — boundary test is still missing, and the reason for skipping it doesn't hold
The reply on the isLargeResponse thread says an exact-boundary test "would need a transport emitting a precise byte count". LargeResponseTransport already emits one: json_encode(['hits' => str_repeat('x', 1024)]) is deterministically 1035 bytes. So the > vs >= boundary at src/Client.php:162 pins with two calls to the helper you already wrote — threshold 1035 logs nothing, 1034 logs once. I confirmed the mechanism with SlowResponseTransport's 13-byte body: threshold 10 emits the large-response record, threshold 13 does not. It's the only assertion that would catch someone later "fixing" isLargeResponse to >=.
Nits
responseSizeInMbis computed twice —src/Client.php:189for the message,:223for the context, same/ 1024 / 1024. Read it from the context (or a tiny private helper) so they can't diverge.- Context keys mix conventions:
execution_time(snake, pre-existing) besideresponseSizeInBytes/responseSizeInMb(camel). sprintfis unqualified in both new log calls (:175,:191) while.php-cs-fixer.dist.phpsetsnative_function_invocation => ['include' => ['@all']], which wants\sprintf. Cosmetic only, because that check is already red onopensearch(five unqualifiedsprintfin this file at the merge base) and matching local style is defensible — flagging it so it's a conscious choice. Same reason the suggestion to drop the\from\json_encodewould point the wrong way against this config.RuntimeException('slow query')is now constructed one frame deeper, insidebuildRequestLogContext(). The message is restored verbatim, so message-keyed searches are safe; only a sink that groups by stack trace would still split. Cheap to keep the construction at the call site if that matters to you.
Verification — I ran what CI hasn't
Checks here are 14 pending / 1 pass (Aikido) and the matrix has no runner, so the new tests had never executed anywhere. Locally, PHP 8.2, composer install, vendor/bin/phpunit --group unit:
| Tests | Assertions | Errors | Failures | |
|---|---|---|---|---|
opensearch (eb074464) |
565 | 2552 | 11 | 3 |
f92731ab |
573 | 2568 | 11 | 3 |
Your eight new cases pass and add no regressions (OK (8 tests, 16 assertions) when filtered to them alone). PHPStan: 36 errors on both branches, identical src/Client.php message set — the PR adds none.
Two things worth knowing before anyone reads those numbers as a problem with this PR:
- The pre-existing red is the base branch's. All 11 errors / 3 failures are fork signature drift —
ArgumentCountErrorinConnectionTest,MultiBuilderTest,ResultSet\*Test,Bulk\Action\*Test. NotablyClientTest::testConstructWithDsn()dies with aTypeError, becauseClient::__construct()declaresarray $config = []while the docblock still says@param array|stringand the body still branches on\is_string($config). Same file you extended, not your doing. - PHP floor.
?int $_responseSizeInBytesneeds 7.4+ and the new trailing commas in call sites need 7.3+, whilecomposer.jsonstill saysphp: ^7.2 || ^8.0and the matrix still runs 7.2/7.3. Pre-existing (src/Client.phpalready had typed properties at the merge base), so not a regression here — but those two columns can't ever go green.
Verdict: NEEDS_REVISION on R1; R2/R3 and the nits are non-blocking. Deliberately a comment rather than REQUEST_CHANGES — it's your PR, so the call is yours.
|
Thanks — implemented at R1 (blocking) — fixed. The large-response record is now metadata-only ( R2 — added. R3 — added. Boundary pinned with Nits. On CI / the pre-existing red: agreed it's all the base branch — the missing runner, the PHP 7.2/7.3 floor vs typed properties, and the |
0af52ab to
eaf34e1
Compare
Extend the slow-request logging path to also log requests whose response body exceeds a configurable threshold (default 10 MB), reusing the LOG_SLOW_REQUESTS toggle. Slow and large fire as two independent warnings; the large-response record is metadata-only (no request/response body) so a slow+large bulk logs its payload once. Response sizes array bodies lazily so bulk/msearch pay nothing unless the size is read. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
53cb016 to
c072f52
Compare
Description: Log OpenSearch requests whose response exceeds a configurable size threshold
Possible impact: OpenSearch/Elastica request logging, Client & ClientFactory construction
Summary
LOG_SLOW_REQUESTStoggle — no new logging mode.Changes
Response: exposesgetResponseSizeInBytes(). A string body is sized eagerly at construction (beforegetData()clears the raw string); an array body is sized lazily on first read from the re-encoded JSON, so bulk/msearch paths that build array-bodied responses pay nothing unless the size is read. An unencodable body reports size 0.Client: addsDEFAULT_LARGE_RESPONSE_THRESHOLD_IN_BYTES(10 MB), alargeResponseThresholdBytesconstructor param,isLargeResponse(int)(mirrorsisSlow(int)), and logs a slow warning and/or a large-response warning. The slow message/exception are unchanged from before this PR. The large-response log omits the (huge) response body — the feature replays via the request. Context carriesresponseSizeInBytes(int) andresponseSizeInMb.ClientFactory: plumbs the new threshold toClient.Test Plan
ResponseTest— size for string/array bodies, survival aftergetData(), and unencodable-body → 0.ClientTest— large response logs "Large …" with size in context; slow response logs "Slow …"; toggle off / small+fast log nothing (viaLargeResponseTransportandSlowResponseTransportdoubles).php -lclean; core logic verified with a standalone assert check (full PHPUnit is docker/Makefile-based).🤖 Generated with Claude Code