Log the rejected value and the caller on a rejected request - #4562
Merged
Conversation
A rejected request is logged with its reason but with nothing about who sent it. On an endpoint that runs without authentication there is then no way to tell a partner integration, one of our own apps and a third-party script apart, which leaves a recurring rejection without an owner who could fix it. The WARN line now carries the X-Client value, the requesting site (Origin, or the origin of Referer - never its path or query, which can hold personal data or tokens) and the user agent. All three are client-supplied and unauthenticated, so they are a diagnostic hint, never an identity, and nothing is gated on them. Each part is masked to the same standard as the rest of the logs, capped per header, and stripped of anything that could break the line, so a crafted header cannot forge a log entry of its own.
A validation message names the field and the values it accepts, not the value that arrived. A client sending one wrong constant is therefore visible as a steady rejection count and stays unidentifiable: the same line is produced whether the field was missing, misspelled or set to a value from a neighbouring enum. The global ValidationPipe now raises a ValidationFailedException that carries the raw ValidationError[] alongside the response, and the exception filter renders the rejected values into its WARN line. The response is unchanged - the exception is built by the base factory and only re-raised, which a test pins field by field against the stock pipe. The rendering treats every value as untrusted input: redacted by field name, masked by value pattern, bounded in count, depth and length, and reduced to a summary for structured or oversized values, so a request body cannot be turned into a log dump through a validation failure.
The first pass rendered any scalar that failed validation and relied on a field-name denylist to hold back the sensitive ones. Review found three fields it does not hold back: `apiKey` and `masterKey` are not matched by it, `accountNumber` is not either because the list anchors `number` exactly, and a rejected `webhookUrl` or `redirectUri` would have carried its query string - the place a webhook credential lives - into the log verbatim. Widening the list would have been the wrong repair. It has to grow with every DTO that ever carries a credential, and the field it has not heard of yet is the one that leaks. The value is now rendered only where the constraint that failed declares a closed set of literals (`isEnum`, `isIn`). That is the case the log line cannot be read without, because one client sending one wrong constant looks exactly like another sending a different one, and it is bounded by what the field declares rather than by what happened to arrive. Every other field keeps its shape and loses its content: `<string(43)>`, `<number>`, `<array(2)>`. Missing, null and empty stay visible for every field - there is nothing to disclose, and it is what separates a client that never sent the field from one that sent it wrong. The name-based redaction stays as a second layer over the fields it does cover. Also moves the oversize rule into `maskLogValue`, so a caller cannot pay for masking a string it is about to cut away; types the exception body as `Record<string, unknown>` rather than `any`; and points the neighbouring payment-info spec at the pipe `main.ts` now installs, whose comment this change had made inaccurate.
The gate's advisory step named them on this branch and not on the base: the new DTO spec is what carries `get-buy-quote.dto.ts` and `xor.validator.ts` to 100% on all four metrics. Unpinned they would stay unguarded, so a later change could erode the coverage this pull request created without turning the gate red.
The comment read as if declaring a closed set of values also bounded the value that arrives there. It does not: the declaration decides which fields may show their content at all, and what is then shown is still untrusted input, held only by the masking and the length cap.
…d not The comment claimed that what gets rendered "stays masked and capped". That is true of a string, and only of a string: a number or a boolean is written out as it is - which is harmless, because being one is already the bound, but the sentence did not say so. The gap was possible because no test covered a non-string under a closed set of values, although the repository has such a field: `noExecutionVerified` is `@IsBoolean() @isin([true])`. Adds one.
…o it That commit put the field name through the same rendering as the value - a precaution, since no DTO today validates through a client-keyed object - but said only what it did to the value. Names it, and closes the paragraph it had left mid-line.
Only the referring URL was cut down to its origin. `Origin` was passed through as it arrived - on the reasoning that it carries nothing else - and that is the reasoning this whole line is built to distrust: the header comes from the client, and a value that is not what it is supposed to be is exactly the one that must not reach the log with a query string on it. A crafted `Origin: https://example.com/x?token=…` went into the WARN line as sent, which is what the comment above it says cannot happen. Both headers now go through the same reduction, and an unparsable value is dropped either way. Two comments were left behind by the previous commit and are corrected with it: the summary over `describeRejectedValues` and the one in the exception filter both still claimed that everything rendered is masked and capped, which holds for a string and not for a number or a boolean. And the field name goes through `maskLogValue`, not through the whole of `renderValue` - "the same rendering as the value" overstated it.
…s there Reducing `Origin` to its origin cost two things that were not meant to go: `Origin: null` - what a browser sends for an opaque origin, a sandboxed frame or a redirect across sites - is not a URL, so it fell into the catch and vanished, although having no origin to name is itself worth the line. And an `Origin` the client filled with something unparsable now suppressed the `Referer` too, because the choice was made on which header was present rather than on which one produced something: a caller that could have been named ended up as no caller at all. The headers are now tried in order and the first one that yields an origin wins, with the opaque literal kept as it is. Both cases are pinned by a test. Also drops a completeness claim from the neighbouring DTO spec: it demonstrates two rejections, it does not enumerate the ones that DTO can produce.
The rule is that the first header to yield an origin wins, and `null` is one - so a request that carries both an opaque `Origin` and a usable `Referer` is logged as opaque. That is intended and now written down in the comment, but nothing held it: the test covered the opaque header alone.
The oversized origin it sent was not a URL, so `callerOrigin` dropped it before the cap could apply: the assertion that nothing floods the line held for a reason the test did not intend, and the origin cap itself was never exercised. It now sends a parsable URL that is too long and checks where it gets cut.
`slice` counts UTF-16 units, so a value whose character straddles the cap lost half of a surrogate pair: the stray half went into the log right before the ellipsis and reaches a UTF-8 transport as a replacement character. Every caller inherits it - both caller headers and every rendered field value - since none of them filter what a client can send. The cut now walks characters. Pinned by a test that puts an emoji on the boundary.
`maskLogValue` reports an oversized value as `<N chars>`, but N is `String.length` - UTF-16 code units, not characters. 257 astral characters are reported as 514. That is the very distinction the previous commit drew for the cut, so the label is renamed rather than the count converted: the number is the one `MAX_STRING` is compared against, and counting characters would mean walking the oversized string this branch exists to avoid. The same inaccuracy exists in `redact` and `format` (`<... N chars ...>`, `...(N chars)`), which are untouched here: those are shipped log formats and outside what this branch changes. `DetailedValidationPipe.createExceptionFactory` gets the explicit return type CONTRIBUTING.md asks for, matching the base signature.
Two gaps the caller markers and the rejected values were already closed against,
but the line they join was not:
The reason is masked, but not collapsed. Ninety-nine of the exceptions that
produce it interpolate a value into their message, and some of those values come
from the request (`Invalid address for ${field}: ${address}`), so a line break in
one of them ends the log line and starts a second one that looks like a log entry
of its own. It now goes through the same collapse and the same character-safe cut
as everything else on the line - `slice` would have halved a surrogate pair at
the cap the same way it did before the previous commit.
Neither the name-based nor the value-based redaction covered an IBAN that is not
under a field named for one. The rejected value of a field with a closed set of
literals is rendered as it arrived, so a client putting an account number into
such a field put it in the log; in the request trace the same value under any key
the name list does not know reached it too. `maskValue` masks it by shape now, in
one run or in the groups of four it is printed in, bounded so a transaction hash
is still left intact.
`singleLine` and `capCharacters` come out of `maskLogValue` for this, which
leaves one definition of "cannot break a log line" in the file. `format` gets it
as well: `JSON.stringify` escapes the control characters but leaves U+2028 and
U+2029, which is the one way the request trace could still be split.
The IBAN pattern is withdrawn. Matching an account number by shape needs the country to know where it ends: without it the grouped form either stops short of a 32-character IBAN and leaves the last group readable, or runs on and swallows the words behind it - both were measured, and the way out of both is a country-length table inside a log formatter. A value-shape list is also open by construction: an account number is one shape, a document number and a card are others, and the one that is not in the list yet is the one that leaks. What is left is the rule the branch already had - the value is only rendered where the field declares a closed set of literals, and it is masked by field name there. `capCharacters` walks to the cap instead of materializing the value first. It is reached with an exception message now, and one of those can be as large as the body it interpolated a value from; spreading that to render 500 characters cost a multiple of the message in heap. The reason is cut to a scan length before it is masked for the same reason, wide enough past the cap that a pattern starting inside it is still seen whole. `format` cuts on a character boundary too - it was the one section left that could halve a surrogate pair - and reports the section length in the unit it counts, as the per-string cap already does. Two comments claimed more than the code does: not every string on a trace line goes through the collapse, only the free-form values do.
The client header was the one value on a trace line that was interpolated as it arrived. A header can carry U+0085, which `LINE_BREAKING` covers and no other step did, so it is rendered like every other value from the caller now, capped to a name rather than a payload. The reason's scan cut could expose what it split. Masking only shortens, so the part of a message that survives to the log can come from well past the visible cap - and a pattern that straddled the cut arrives halved, is no longer recognized, and its head is then among the characters that survive. A pattern length is read past what is kept and dropped again, which leaves only patterns that ended before the cut, and those were seen whole. The length comes from the patterns themselves, next to where they are declared. Reading the message can throw: the response body is whatever the thrower put there, and an array element that cannot be turned into a string takes `join` with it - before the response is sent. The line loses its reason instead. `format` cuts to its own budget again. That budget is in code units and `capCharacters` counts characters, so an astral section came out at twice it; the cut moves off a surrogate pair rather than counting past it.
Masking ran after the collapse, so a control character sitting inside a pattern took the pattern with it: the collapse turned it into a space, the pattern no longer matched, and an address was logged in full. It was measured on both the reason and the client header. Masking runs first now, on the value as it arrived. The scan margin is withdrawn. It cut the message before masking so the work was bounded, and every version of it cut somewhere a pattern could be open - a pattern crossing the cut arrives halved, is no longer recognized, and masking what precedes it shortens the text enough to pull its head into view. Two attempts at a margin produced two ways for that to happen. The message is masked whole again, as it was before this branch; what is left is the cap, which is what this branch actually needed to bound. The request target was the last free-form value that reached a line as it arrived. `maskUrl` collapses it too, which is one line where the query is already being dropped, and makes the sentence about this file true. The response now goes out before the line is written. Everything the line renders comes from the request or from the thrower, and reading either can throw - which left the caller with no response rather than with a line missing a detail. An unreadable exception body gets the generic one instead of none. Two comments claimed more than they had to: a message *can* interpolate a request value, and what the field-name masking covers is stated without a claim about every DTO in the repository.
Rendering the value wherever the constraint declares a closed set of literals was the wrong rule, and it is the one thing this branch does that `develop` does not: `develop` logs no rejected values at all. A constraint bounds what is accepted, not what a client sends, and a rejected value is by definition outside it - so `paymentMethod` rendered an account number, a card number, a passport number and an API key just as readily as it rendered a wrong constant. Every attempt to catch those by shape has failed in a new way, because that list is open. `@LogRejectedValue()` closes it from the other side. The field declares that its wrong values are constants of the program, and only a field that says so has its value rendered; everything else keeps its shape and loses its content, including every field that exists today. The two payment-method fields and the personal IBAN provider carry the marker, which is what the endpoint this started from needs. An error without the object it came from renders nothing, so a value cannot arrive through a `ValidationError` that never passed a DTO. `maskLogValue` masks a value whole when removing the control characters is what reveals a pattern in it. A control character splits the pattern so it no longer matches, and the collapse then puts the halves next to each other in the line; a single value is not a sentence, so masking more of it than the pattern costs nothing. Two comments still said more than they had to: the response is already sent by the time the reason is read, and what is masked by value are the three patterns declared above, not personal data in general.
The marker said a field's value may be shown; it did not say which values, so a client could still put an account number, a card number or an API key into a field that carries it and have it logged in full. The marker now carries the set those values may come from, and only a value in that set is rendered - matched without regard to case, and written out of the set rather than out of the request, so what reaches the line is a constant of this program either way. For a field taking the fiat payment methods that set is the full payment-method union: its crypto member is exactly what a client sends there by mistake, which is the case these lines exist for. The personal IBAN provider loses the marker again - there is no wider set its wrong values come from, so it would never render anything. With that, nothing client-composed reaches the line and the masking is no longer what protects it, which is what every attempt so far had rested on. `singleLine` removes what could break a line instead of replacing it, and runs before the masking everywhere: a character placed inside a pattern used to leave the pattern split around whatever replaced it, so the masking no longer saw it - in the reason, in the request target and in the trace bodies, not only where the per-value guard reached. Removing it puts the pattern back together first. That guard is gone with it.
The personal IBAN provider was dropped from the declarations on the grounds that no wider set exists for it. That was wrong: the matching ignores case, so the field's own values are exactly what makes `frick` readable as `Frick` - the mistake this line is for. It declares them again. A numeric enum object carries its reverse mapping, so `Object.values` on one returns the member names alongside the values and a request sending a name would have matched. Only the values are taken now. A declared constant is written by this code rather than by the request, but it goes through the same rendering as everything else on the line - there is no reason for the one value on it that is not checked to be the one a hand wrote. The status is resolved before anything else is read and falls back to a server error when the exception cannot answer or answers with something Express will not send; the request is read after the response has gone out, since the response never needed it. Two comments described the replaced behaviour rather than the removal that took its place.
…he removal The provider declaration was inert. `personalIbanProvider` carries `iban` in its name, so the name-based redaction answered first and the value never reached the declaration - the fix landed and changed nothing. A declared match now comes first: what it renders is a constant of this program, and the field's name says nothing about a value that was never the client's. Removing what breaks a line breaks a pattern in the other direction. It joins what stood on either side, so an address followed by a control character and one more digit comes out as one run, where it no longer ends on a word boundary and the masking no longer sees it - the mirror image of the case the removal was introduced for. Both passes run now, around the removal rather than on one side of it, in the one place that renders free-form text for a line. A second pass cannot invent a match: what the first leaves behind carries no alphanumerics. The response body is the generic one whenever the status being sent is not the one the exception names, so a replaced status no longer ships a body that contradicts it, and a message that cannot be read falls back to the status rather than out of the method. The line is written inside its own guard. The response is already out by then, so a failure to describe it - the logger included, which is the one thing that could not report it - ends there instead of travelling back to the caller. 1xx leaves the accepted range: it is not a final response, so it is not one this can send.
Collaborator
Author
|
Ready after 18 review passes. Each pass took the full diff through a conformance review and a logic The passes changed what this does more than once, and the short version is worth having here:
Two things are deliberately not in this branch and are better decided on their own: masking account |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Why
A request body the server rejects with a 400 or a 422 produces one WARN line with its reason. Two things that line does not contain
are what make a recurring rejection impossible to act on:
the one that arrived. A client sending a single wrong constant produces the same line as one
sending nothing at all, so the fix - usually one constant in one client - cannot be named from
the logs.
integration, one of our own apps and a third-party script are the same anonymous request.
What
DetailedValidationPipe(new, replaces the globalValidationPipeinmain.ts) raises aValidationFailedExceptionthat carries the rawValidationError[]alongside the response.describeRejectedValuesrenders those for the log line, bounded in count, depth and length.describeCallerrenders what a request says about its caller:X-Client, the requesting site,and the user agent.
OriginandRefererare both reduced to their origin - never a path or aquery - the header that is supposed to carry nothing else included, since it arrives from the
client like everything else here.
maskLogValueis the shared primitive both use: report by length (in UTF-16 code units, themeasure the guard compares) if oversized, then
maskLogText- mask, remove anything that couldbreak the line, mask again - and cap. The cut lands between characters rather than between code
units, and runs after the masking so a truncated email cannot slip through.
An example of the resulting line (illustrative):
What is rendered, and what is not
The value appears only where the field declared the set it may come from -
@LogRejectedValue(...),carried today by the two payment-method fields, which declare the full payment-method union, and by
the personal IBAN provider, which declares its own. A value
is matched against that set without regard to case, and what is written is the constant out of the
set rather than the string out of the request, so nothing the client composed reaches the line.
Everything else keeps its shape and loses its content:
<string(43)>,<number>,<array(2)>.(missing),(null)and''stay visible for every field; there is nothing to disclose there, andit is what separates a client that never sent the field from one that sent it wrong.
That declaration replaces three earlier rules, each of which review showed does not hold. A
field-name denylist let
apiKey,masterKeyandaccountNumberthrough. Reading the constraintinstead - render wherever the field declares a closed set of literals - reads the wrong side of the
rejection: a constraint bounds what is accepted, not what a client sends, and a rejected value is by
definition outside it, so
paymentMethodrendered an account number, a card number, a passportnumber and an API key as readily as a wrong constant. Marking the field without naming the values
left that unchanged.
Catching those by value shape does not close it either: masking an account number by shape needs the
country to know where it ends, and the list is open in any case - an account number is one shape, a
document number and a card are others. So the field names the values, and what it did not name is
never written. The name-based redaction and the value-pattern masking stay as they were, for
everything else on the line.
The response does not change
The exception is built by the base factory and only re-raised with the errors attached, so status,
message array and body shape stay what the stock pipe produced. Tests assert that against a stock
ValidationPipefor the same body, including nested errors and withdisableErrorMessages.Untrusted input
Everything added to the line comes from the request. The three headers are client-supplied and
unauthenticated - a diagnostic hint, never an identity, and nothing is gated on them. Values are
masked to the same standard as the rest of the logs, capped per field, and stripped of control
characters and the Unicode line separators, so a crafted header or body value cannot forge a
second log line or repaint a terminal tailing the log.
The reason the line already carried gets the same treatment. It was masked but not collapsed, and
an exception message can interpolate a value the request supplied, so a line break in one of those
ended the line and started what looked like a second entry.
singleLineandcapCharacterscomeout of
maskLogValuefor that, which leaves one definition of "cannot break a log line" in thefile; the request target and the request trace use it too, the latter because
JSON.stringifyescapes the control characters but leaves U+2028 and U+2029.
A character that breaks a line breaks a pattern in either direction, which is why the masking runs on
both sides of the removal. Put inside a pattern, it hides the pattern from a pass before the removal;
removing it joins what stood on either side, which can hide a pattern that was whole from a pass
after it - an address followed by one more digit no longer ends on a word boundary. Neither order
sees both, and a second pass cannot invent a match, since what the first leaves behind carries no
alphanumerics. The request target and the traced body strings go through the same step.
The response is sent before the line is written. Everything the line renders comes from the request
or from the thrower, and reading either can throw; that used to leave the caller with no response
rather than with a line missing a detail.
The value-shape masking is unchanged: a wallet address, an email and an IP are masked wherever they
appear, an account number is not. Masking one by shape needs the country to know where it ends -
without that the grouped form either stops short of a long IBAN and leaves its last group readable
or runs on and swallows the words behind it, and the way out of both is a country-length table
inside a log formatter. It is also open by construction: an account number is one shape, a document
number and a card are others. What stands instead is the rule above - the value is rendered only
where the field declares a closed set of literals, and is masked by field name there.
Tests
Seven spec files carry it: the declaration and what it reads back, the pipe (response identity
against the stock pipe, wrapping boundaries), the rendering (what is and is not disclosed, missing
vs. empty vs. null, nesting, redaction, caps, control characters), the caller markers, and the two
buy DTOs end to end for the rejections their specs cover.
Three files are pinned in the coverage ratchet -
log-rejected-value.decorator.ts,get-buy-quote.dto.tsandxor.validator.ts: the gate's advisory step names them on this branchand not on the base, because the new specs are what carry them to 100%.