fix: relocate log() so parse/validation failures are captured (#35)

[jwadhams]

Summary

Fixes #35 — a response that looks fine over the wire (e.g. HTTP 200) but later
fails json_decode or JSON Schema validation was being logged as a plain
success, hiding the real failure.

• log() is now called once, at the same point as writeResponseToCache() —
  after parseResponseBody() and postProcess() have both had a chance to
  run/throw. A single log() call now sees the real outcome (postprocessed
  response, or whatever exception was thrown along the way), and still
  includes the raw Response it has on hand, so schema failures show both
  the response and the exception (with ->getExtendedData()/->errors()).
• The "don't log cache hits" decision moves from the call site into log()
  itself (log() now returns early when $this->responseIsFromCache is
  true), instead of being an implicit side effect of nobody calling log()
  on a cache hit.
• log() is split into a guard (log()) and the actual write (writeLog()).
  Children that want different behavior on a cache hit — e.g. writing a short
  log that points back at the original request — can override log() and
  call writeLog() directly to bypass the guard, without also having to
  override responseFromCache() just to get a chance to log.

Tests

• testParseFailureIsLogged / testSchemaValidationFailureIsLoggedWithExtendedExceptionData:
  reproduce the exact scenario from the ticket. The schema-validation test does
  a full-content match (assertStringMatchesFormat) of the log, pinning down
  that the response body, the exception, and its ->getExtendedData()
  (->errors()) are all present in the expected shape.
• testPostProcessFailureIsLogged: for a cache miss, a log entry was already
  written before this change, immediately after the Guzzle transfer completed
  — before postProcess() ever ran. So a postProcess() failure wasn't
  unlogged, it was logged as a false success (the entry was already sealed
  before the real outcome was known). This test confirms that same entry now
  reflects the real outcome instead.
• testLogCanBeOverriddenToHandleCacheHits: demonstrates overriding log() to
  write a distinct, differentiable log on a cache hit that references the
  original.

All 78 tests pass.

Upgrading: what to audit in your own request classes before adopting this

This changes when log() is called and what it's called with. For plain
consumers that only override getLogFolder(), nothing changes. If you override
log(), responseFromCache(), or writeResponseToCache(), check the following:

1. Any log($outcome) override that doesn't check responseIsFromCache will now also fire on cache hits

Previously, log() was never invoked at all on a cache hit — that was an
implicit side effect of the call site, not a guard inside log() itself. Now
log() is called on every outcome, cache hit or miss, and the default
implementation returns early when $this->responseIsFromCache is true. But if
you have an override that fully replaces the base logic (i.e. doesn't call
parent::log()), it won't inherit that guard, and will start running on cache
hits too.

Audit: grep for every function log( override. Any that don't call
parent::log() need an explicit if ($this->responseIsFromCache) { return; }
(or equivalent) added, unless firing on cache hits is actually desired.

2. File count for cache-miss requests is unchanged; entry content is not

For a cache miss, exactly one log entry was already being written both before
and after this change, success or failure — this PR doesn't create new log
entries where none existed. What changes is timing and content: previously
log() ran immediately after the Guzzle transfer, before parseResponseBody()/
postProcess() had a chance to run, so a downstream failure never appeared in
that entry — it just looked like an unremarkable success (the exact bug in
#35). Now that same entry is deferred until parsing and postprocessing have
both had their turn, so it reflects the real outcome, including the exception
and its getExtendedData()/->errors() where applicable.

Audit: review what your parseResponseString()/postProcess() exceptions'
messages and getExtendedData() contain. That content now lands in the same
log entry the response body was already going into — check nothing sensitive
is exposed there that wasn't being logged before.

3. postProcess() should reject with Throwable, not arbitrary values

To be clear about the shape of the change: the log entry still contains the
Request and Response data exactly like before -- writeLog() builds
[$this->toGuzzle(), $this->response, $outcome, $this->requestStats], so a
postProcess() rejection doesn't replace or alter the familiar Request/Response
section, it just appends as a new, final section ahead of the transfer stats.

That appended section is the part to watch: LogFile::put()'s
array_map(stringify_body, $contents) runs outside its own try/catch, and
until now was only ever exercised with Guzzle's own Response/Throwable
types. Since postProcess() can return new RejectedPromise($anything), that
value now flows into log() → writeLog() → stringify_body() for the first
time -- as that new appended section. If it's not a Throwable and not
cleanly JSON-serializable (a resource, a closure, a circular structure),
stringify_body() will throw on that section -- and because array_map
aborts entirely on the first exception, nothing gets written, not even the
Request/Response section that would otherwise have succeeded. The exception
from the failed logging attempt, not your real failure, becomes the promise's
rejection reason, masking the actual error.

Audit: confirm postProcess() implementations only reject with Throwable
instances (best practice regardless of this change).

4. Log entries for transfer-level exceptions may show the response body twice

log() now includes the raw $this->response and $outcome whenever they
differ. For BadResponseException/RequestException-style failures, the
response body was already embedded inside the exception's own stringified
form — so it'll now appear twice in that entry (once standalone, once nested
in the exception). Cosmetic, but:

Audit: any tooling or tests that parse log files structurally (e.g.
asserting an exact number of blank-line-delimited sections) should be
rechecked.

5. responseFromCache()-based cache-hit logging (the PreQualifyStrangerRequest pattern) keeps working unchanged

If you have a class that overrides responseFromCache() purely to call
$this->log(...) manually for cache-hit visibility, no change is required:
responseIsFromCache isn't flipped to true until after responseFromCache()
returns, so the manual call still runs normally, and the later, automatic
log() call is a no-op (guard is active by then) — no double-write. That said,
this is a good opportunity to simplify by overriding log() directly instead
(see the docblock on AbstractRequest::log() for the pattern), rather than a
requirement.

6. Tests asserting "nothing gets logged on parse/postProcess failure" will need updating

If you have tests asserting an empty log directory (or unchanged file count)
after a deliberately-broken response, the entry's content will now differ
from what it was — worth a look even though the file count itself won't
change for cache-miss traffic.

🤖 Generated with Claude Code