Skip to content

DE-178815 Log OpenSearch requests with large responses - #40

Open
jzajac-nice wants to merge 1 commit into
DE-178815-ci-php82from
DE-178815-log-large-opensearch-responses
Open

DE-178815 Log OpenSearch requests with large responses#40
jzajac-nice wants to merge 1 commit into
DE-178815-ci-php82from
DE-178815-log-large-opensearch-responses

Conversation

@jzajac-nice

@jzajac-nice jzajac-nice commented Sep 10, 2026

Copy link
Copy Markdown

Description: Log OpenSearch requests whose response exceeds a configurable size threshold
Possible impact: OpenSearch/Elastica request logging, Client & ClientFactory construction


Summary

  • Extends the existing slow-request logging so a request is also logged when its response body exceeds a configurable threshold (default 10 MB), reusing the same LOG_SLOW_REQUESTS toggle — no new logging mode.
  • Slow and large are logged as two separate warnings (a request that is both emits both).
  • Goal: allow re-running a logged query to inspect large response payloads (e.g. the ~260–290 MB bulk responses seen during the Sept 10 2026 EU1 OpenSearch incident).

Changes

  • Response: exposes getResponseSizeInBytes(). A string body is sized eagerly at construction (before getData() 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: adds DEFAULT_LARGE_RESPONSE_THRESHOLD_IN_BYTES (10 MB), a largeResponseThresholdBytes constructor param, isLargeResponse(int) (mirrors isSlow(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 carries responseSizeInBytes (int) and responseSizeInMb.
  • ClientFactory: plumbs the new threshold to Client.

Test Plan

  • ResponseTest — size for string/array bodies, survival after getData(), and unencodable-body → 0.
  • ClientTest — large response logs "Large …" with size in context; slow response logs "Slow …"; toggle off / small+fast log nothing (via LargeResponseTransport and SlowResponseTransport doubles).
  • php -l clean; core logic verified with a standalone assert check (full PHPUnit is docker/Makefile-based).

Consumed by platform-backend via brandembassy/elastica: dev-opensearch. Merge this first, then platform-backend's config PR (BrandEmbassy/platform-backend#23444) can resolve the new constant after a composer update brandembassy/elastica --lock.

🤖 Generated with Claude Code

@jzajac-nice

Copy link
Copy Markdown
Author

Downstream consumer: BrandEmbassy/platform-backend#23444 (adds the elasticSearchLargeResponseThresholdBytes config + feature-toggle wording). This Elastica PR must merge into opensearch first.

@jzajac-nice
jzajac-nice marked this pull request as ready for review September 10, 2026 12:50
Copilot AI lite review requested due to automatic review settings September 10, 2026 12:50

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 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 Client and log when a request is slow or produces a large response (including response size in the log message/context).
  • Plumb the new threshold through ClientFactory and 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.

Comment thread src/Response.php Outdated
Comment thread src/Response.php

@chrudos-vorlicek chrudos-vorlicek left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.mdDEFAULT_LARGE_RESPONSE_THRESHOLD_IN_BYTES = 10 MB is 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 (avoid Exists query) is untouched. git.md — branch and PR title both match the required patterns. php.md PR 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 Client and ClientFactory alike.
  • 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 only request_header + http_code (src/Transport/Guzzle.php:89, src/Transport/HttpAdapter.php:72) — so curl's size_download is 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. Http already buffers the whole response via ob_start() / ob_get_clean() (src/Transport/Http.php:161-163), so strlen() on the string branch is O(1). There is no streaming or truncation path in this client.
  • The three new ClientTest cases should pass. Passing an FQCN as 'transport' resolves through the second candidate class name in AbstractTransport::create() (src/Transport/AbstractTransport.php:137) — a pattern already covered by tests/Transport/AbstractTransportTest.php:48. DummyTransport never sets a query time, so round(null * 1000) is 0, and Request never emits warning, so expects($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 $_responseSizeInBytes needs 7.4+ and the trailing commas in tests/ClientTest.php function calls need 7.3+, while composer.json declares php: ^7.2 || ^8.0 and CI still matrixes 7.2 and 7.3. But src/Client.php already 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 align composer.json with 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 — reports fail at 24h0m0s, i.e. the runs expired without a runner rather than genuinely failing; this branch's own runs are all cancelled; and this PR is currently 14 pending / 1 pass (Aikido only). The Test Plan above says only php -l and a standalone assert check were run. Please run vendor/bin/phpunit --group unit before 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 return at src/Client.php:701, so under LOG_BASIC | LOG_SLOW_REQUESTS it emits the warning instead of the previous debug Elastica 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, so php.md § Testing applies by its own terms, and the new tests break several of its MUSTs: mocks MUST use Mockery (there is no mockery dev dependency and 10+ test files use createMock); assertions MUST go through PHPUnit\Framework\Assert statically; TestCase classes MUST be final (ClientTest is not, pre-existing); every test-dedicated class MUST carry a TestTool suffix (LargeResponseTransport does not, matching its sibling DummyTransport). 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.yml on opensearch in its own PR — AGENTS.md makes 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.mdREADME.md, git.md, php.md, configuration.md, elasticsearch.md; all fetched successfully).

Comment thread src/Response.php Outdated
Comment thread src/Response.php Outdated
Comment thread src/Client.php Outdated
Comment thread src/Client.php
Comment thread src/Client.php Outdated
Comment thread src/Client.php
Comment thread src/Client.php Outdated
Comment thread src/Client.php Outdated
Comment thread tests/ClientTest.php
Comment thread tests/ResponseTest.php
Comment thread src/Client.php Outdated
Comment thread src/Response.php
@chrudos-vorlicek

Copy link
Copy Markdown

Re-review at f92731ab — follow-up to my review at d491b570

Thanks for the fast turnaround. I re-read the whole changed surface at the new head rather than just diffing the replies, and this time I also ran the suite locally, since CI on this PR has never executed (more on that at the end).

All seven findings from the previous round are fixed, a couple better than I proposed:

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:

  1. isSlow → record DE-40276: add request counter support #1 with request.data = the full bulk payload;
  2. isLargeResponse → record DE-48156 Improve ES requests logging #2 with request.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.data in buildRequestLogContext() (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

  • responseSizeInMb is computed twice — src/Client.php:189 for the message, :223 for 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) beside responseSizeInBytes / responseSizeInMb (camel).
  • sprintf is unqualified in both new log calls (:175, :191) while .php-cs-fixer.dist.php sets native_function_invocation => ['include' => ['@all']], which wants \sprintf. Cosmetic only, because that check is already red on opensearch (five unqualified sprintf in 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_encode would point the wrong way against this config.
  • RuntimeException('slow query') is now constructed one frame deeper, inside buildRequestLogContext(). 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 — ArgumentCountError in ConnectionTest, MultiBuilderTest, ResultSet\*Test, Bulk\Action\*Test. Notably ClientTest::testConstructWithDsn() dies with a TypeError, because Client::__construct() declares array $config = [] while the docblock still says @param array|string and the body still branches on \is_string($config). Same file you extended, not your doing.
  • PHP floor. ?int $_responseSizeInBytes needs 7.4+ and the new trailing commas in call sites need 7.3+, while composer.json still says php: ^7.2 || ^8.0 and the matrix still runs 7.2/7.3. Pre-existing (src/Client.php already 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.

@jzajac-nice

Copy link
Copy Markdown
Author

Thanks — implemented at d9df696c.

R1 (blocking) — fixed. The large-response record is now metadata-only (requestMethod / requestPath / requestQuery, plus status/size/elapsed); it no longer calls $request->toArray(), and it never logs the response body. The request payload lives only in the slow-request record. So the incident-scale slow+large bulk logs its NDJSON body once, not twice, and the size-only trigger for a fast+large search still carries enough to identify the query. Kept two separate warnings (per your R2 expectation) — I did not collapse to one record.

R2 — added. testSlowAndLargeResponseAreLoggedAsTwoWarnings (SlowResponseTransport, 13-byte body, threshold 10) asserts warning is called exactly(2). Also added testLargeResponseLogOmitsRequestAndResponseBody, which pins that the large record has requestPath but no request/response key even under LOG_RESPONSE_BODY.

R3 — added. Boundary pinned with LargeResponseTransport's deterministic 1035-byte body: threshold 1035 logs nothing, 1034 logs once — locks > against a future >=.

Nits. responseSizeInMb is now computed once in the context and read back for the message. Left sprintf unqualified (matches the neighbouring logRequest and, as you note, the base branch) and the pre-existing execution_time snake/camel mix, to keep the diff to the change's purpose. The synthetic RuntimeException is still built in the shared helper; the slow message/reason are verbatim so message-keyed grouping is unaffected.

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 Client::__construct() array $config signature drift. That's being handled separately on DE-178815-fix-ci-runner-label (CI → PHP 8.2/8.4, php-cs-fixer 3.84, signature/deprecation fixes), so this PR stays scoped to the logging change and picks the green matrix up once that lands.

@jzajac-nice
jzajac-nice force-pushed the DE-178815-log-large-opensearch-responses branch from 0af52ab to eaf34e1 Compare September 11, 2026 11:41
@jzajac-nice
jzajac-nice changed the base branch from opensearch to DE-178815-ci-php82 September 11, 2026 11:41
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>
@jzajac-nice
jzajac-nice force-pushed the DE-178815-log-large-opensearch-responses branch 3 times, most recently from 53cb016 to c072f52 Compare September 11, 2026 13:04
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants