Stop one unformattable number from destroying the whole message - #37
Merged
Merged
Conversation
Every parse failure recorded on the live install turned out to be the same
thing, byte for byte: the device writes utcunixtime as 1.#INF00, which is what
a C printf("%f") produces for a value that isn't finite. That isn't JSON, so
the decoder abandons the entire body rather than the one bad field, and every
reading beside it goes too. For a /pings message that's the signal strength,
which is the only thing in there we read at all.
There were 892 of them sitting in the log buffer, each with a full traceback,
all reporting the same column. The constant column is what gave it away. A
truncated body, which is what this looked like, would fail somewhere different
every time.
parse_request now retries once with those renderings replaced by null, and only
for a body that has already failed. The healthy path is untouched, so the
repair can't mangle good data. A message that comes back clean is logged at
debug; one that's still unreadable keeps the warning and the traceback it
always had.
The substitution runs over the raw bytes, so it also reaches the second JSON
document /bbs_json hides inside a string. None of these characters need
escaping there, so they appear verbatim.
A run whose current came through as null no longer counts as evidence that the
primary pump is healthy.
Verified by replaying the bytes at a real listener rather than only in tests:
the reading is recorded and the warning is gone, including when the forward
upstream fails, which is when this happens most.
Refs #27.
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
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.
Fixes the parse failures in #27, which turned out not to be truncation.
Every one of the 892 failures in the log buffer was identical, down to the
column:
Expecting ',' delimiter: line 1 column 47 (char 46). That offset isthe first byte of the
utcunixtimevalue in a/pingsbody, and substituting1.#INF00for the timestamp reproduces the error exactly. So do1.#QNAN0and-1.#IND00. Those are what a Cprintf("%f")writes for a value that isn'tfinite, so the device appears to format its clock out even when it doesn't have
one.
A constant offset is the part that settles it. A body cut short mid-flight,
which is what this looked like, would fail somewhere different every time.
The message itself is fine apart from that one field, but
json.loadsgives upon all of it, so the readings alongside are thrown away too. For
/pingsthat'sthe signal strength, and it's the only field in there we read. The same thing in
a
/bbs_jsonmessage would take the battery voltage and any pump run with it.There's no recorded instance of that yet, which is luck.
What changed
parse_requestretries once with those renderings replaced bynull, and onlyon a body that has already failed to parse. The healthy path never sees the
substitution, so there's no way for it to damage a message that was fine. A
repaired message logs at debug. One that's still unreadable keeps the warning
and the traceback it always had, which is now rare enough to deserve one.
Running it over the raw bytes also reaches the second JSON document
/bbs_jsonkeeps inside a string, because none of these characters need escaping there.
_device_timealready tolerated an unreadable timestamp; it just never got thechance, because the decode failed first. Now it does. One related fix came with
it: a run whose current came through as
nullno longer counts as evidence theprimary pump is working.
Verification
Six new tests, including the exact byte sequence from production, which
reproduces the live error string character for character.
Then replayed at a real listener on the dev instance rather than trusted to the
tests, since this sits in the request path:
No warning, and the reading was recorded even though the forward upstream
failed, which is the condition these arrive under most.
229 tests pass.