Feature Idea: Flag that only retrieves the last 10KB of logs?

[mhaamann]

Currently the health checks fail when logs gets bigger than 10KB even though everything ran successfully.

Would it be possible to add a flag that only includes the last 10KB of the logs so the healthchecks.io would access the payload.

The project is written in Go, which sadly rules me out. I'm hoping someone is willing to look at this feature request and make a PR.

See section: Handling More Than 10KB of Logs (https://healthchecks.io/docs/attaching_logs/)

[bdd]

Thanks for the report. This is actually an unhandled case, so it's more of a bug than feature.
This is a poorly handled case right now, relying on the server side implementation of healthchecks.io. See comment below.

Current implementation is just a simple tee mechanism. I'll need to replace it with a tailing buffer limited to 10KB minus a string indicating log is truncated. Not quite decided if this should be the default behavior or not but regardless both options should be available with a flag.

I expect to work on this before Nov 21.

[bdd]

Currently the health checks fail when logs gets bigger than 10KB even though everything ran successfully.

Only if the output is larger than 1 MiB. Currently healthchecks.io API does the truncation (not the behavior you're asking) on the service side.

% runitor -quiet bash -c "dd if=/dev/zero count=1 bs=$((2**20+1)) 2>/dev/null | tr '\0' 0"
2020/11/16 14:14:30 PingSuccess: nonretriable error response: 413 Request Entity Too Large
% runitor -quiet bash -c "dd if=/dev/zero count=1 bs=$((2**20)) 2>/dev/null | tr '\0' 0"
% echo $?
0

[bdd]

Hey @mhaamann, would you like to give this implementation a try?

If you have Go toolchain on your machine you can quickly compile this preview version with

git clone https://github.com/bdd/runitor && cd runitor
git checkout pingbody-ring-buffer
./scripts/build dist-all

This will compile for all currently supported OS-platform pairs and resulting binaries will be under build directory. Pick the one matching your test environment.

Edit: I tagged a beta release so GitHub action could build release binaries. If you don't want to deal with compiling on your own machine, you can find the binaries at https://github.com/bdd/runitor/releases/tag/v0.7.0-beta.1

[bdd]

@cuu508, would you happen to have some time to test (or maybe code review) client side ping body truncation feature?

This adds the feature to tail truncate ping body instead of POSTing large body pings (seems like current settings on healthchecks.io for request body limit is 1MB), saving bandwidth to both parties but also retaining possibly more relevant last 10K of the log output.

[cuu508]

@bdd just gave it a quick test. There seems to be an issue with bytes/kibibytes conversion somewhere:

./runitor-v0.7.0-beta.1-linux-amd64 -uuid my-uuid-here --ping-body-limit 50 -- python /tmp/generate_text.py

Here's what gets logged to the server:

sdkjlh

(runitor) Output truncated to last 50 KiB.

It logged precisely 50 bytes, but the output says 50 KiB.

If I increase ping-body-limit to 1'000'000 (my intention being 1MB), it crashes:

./runitor-v0.7.0-beta.1-linux-amd64 -uuid my-uuid-here --ping-body-limit 1000000 -- python /tmp/generate_text.py

[ ... lots of output from generate_text.py ... ]
panic: runtime error: slice bounds out of range [901702:887236]

goroutine 10 [running]:
bdd.fi/x/runitor/internal.(*RingBuffer).read(0xc00009ac30, 0xc0007ca000, 0x3fff, 0x4000, 0xc000001f70)
	bdd.fi/x/runitor/internal/ringbuffer.go:107 +0x16f
bdd.fi/x/runitor/internal.(*RingBuffer).Read(0xc00009ac30, 0xc0007ca000, 0x3fff, 0x4000, 0xc000053d08, 0x53673b, 0xc000242c20)
	bdd.fi/x/runitor/internal/ringbuffer.go:95 +0xb3
net/http.(*readTrackingBody).Read(0xc000242d40, 0xc0007ca000, 0x3fff, 0x4000, 0x35, 0x0, 0x0)
	net/http/transport.go:621 +0x55
net/http.(*http2clientStream).writeRequestBody(0xc0002449a0, 0x72d780, 0xc000242d40, 0x7f0b08352988, 0xc000242d40, 0x0, 0x0)
	net/http/h2_bundle.go:7771 +0x682
net/http.(*http2Transport).getBodyWriterState.func1()
	net/http/h2_bundle.go:9038 +0xd0
created by net/http.http2bodyWriterState.scheduleBodyWrite
	net/http/h2_bundle.go:9085 +0xa6

[cuu508]

seems like current settings on healthchecks.io for request body limit is 1MB

Correct – to be honest, I did not specifically pick the limit, it's a default nginx configuration value.

Self-hosted instances may disable or change both the 10KB and the 1MB limit, so it's good to have the ping-body-limit parameter.

[bdd]

@bdd just gave it a quick test. There seems to be an issue with bytes/kibibytes conversion somewhere:

Ah, yes. Initially I wanted this parameter to take kilobyte values but then I noticed your default was KB and which is the SI one but not the KiB one, and thought this would cause confusion, so went back to just bytes. Forgot to update the format string. It's fixed now.

panic: runtime error: slice bounds out of range [901702:887236]

Ah, this is a legit bug that should have been caught by unit tests easily but while trying to make Write tests easier to write, I mistakenly removed the Read test and committed it as is. Recovered it from my monorepo, also found a test determinism issue, which got fixed here.

Beta 3 (https://github.com/bdd/runitor/releases/tag/v0.7.0-beta.3) should address the issues above.

Thanks for assisting @cuu508. I really appreciate it.

[cuu508]

No problem at all!

I tested the beta.3 some more, and it looks good to me. In each test, the response was chopped off exactly where I expected it to be.

One thing I did notice, but not sure if it's an issue or not: I made a script that alternates writing to stdout and stderr:

import sys

for i in range(0, 100000):
    sys.stdout.write("Line %d: this is stdout\n" % i)
    sys.stderr.write("Line %d: this is stderr\n" % i)

If I run it in console, the output alternates: one line of stdout, one line of stderr etc.:

[...]
Line 99996: this is stderr
Line 99997: this is stdout
Line 99997: this is stderr
Line 99998: this is stdout
Line 99998: this is stderr
Line 99999: this is stdout
Line 99999: this is stderr

Runitor shows entries only from stdout, as if it processed all of stderr first, and only then stdout:

I don't know if that's easy to fix, or possible to fix (is it maybe caused by OS deciding what to buffer, by how much, in what order), but thought I'd point it out.

[bdd]

I don't know if that's easy to fix, or possible to fix (is it maybe caused by OS deciding what to buffer, by how much, in what order), but thought I'd point it out.

Hmm. That's annoying. I'll read the implementation of Go's io.MultiWriter (like a tee) and see how exec.Command's Run handles stderr and stdout. Looks like they're buffered.

I'll probably attempt to fix this in 0.7.1.

[bdd]

I finally had some time to look into stdout and stderr ordering issue.

I think 292b4d6 addresses it.

Cut a 0.7.0-beta.4 for testing convenience. https://github.com/bdd/runitor/releases/tag/v0.7.0-beta.4

[cuu508]

I tested with the same script as before:

import sys

for i in range(0, 100000):
    sys.stdout.write("Line %d: this is stdout\n" % i)
    sys.stderr.write("Line %d: this is stderr\n" % i)

I ran it like so:

runitor -uuid my-uuid-here python script.py

The ping body had batches of stdout output mixed with batches of stderr output:

[...]
Line 99925: this is stdout
Line 99926: this is stdout
Line 99927: this is stdout
Line 99928: this is stdout
LinLine 99929: this is stderr
Line 99930: this is stderr
Line 99931: this is stderr
Line 99932: this is stderr
Line 99933: this is stderr
Line 99934: this is stderr
Line 99935: this is stderr
Line 99936: this is stderr
Line 99937: this is stderr
Line 99938: this is stderr
Line 99939: this is stderr
Line 99940: this is stderr
Line 99941: this is stderr
Line 99942: this is stderr
Line 99943: this is stderr
Line 99944: this is stderr
Line 99945: this is stderr
Line 99946: this is stderr
Line 99947: this is stderr
Line 99948: this is stderr
Line 99949: this is stderr
Line 99950: this is stderr
Line 99951: this is stderr
Line 99952: this is stderr
Line 99953: this is stderr
Line 99954: this is stderr
Line 99955: this is stderr
Line 99956: this is stderr
Line 99957: this is stderr
Line 99958: this is stderr
Line 99959: this is stderr
Line 99960: this is stderr
Line 99961: this is stderr
Line 99962: this is stderr
Line 99963: this is stderr
Line 99964: this is stderr
Line 99965: this is stderr
Line 99966: this is stderr
Line 99967: this is stderr
Line 99968: this is stderr
Line 99969: this is stderr
Line 99970: this is stderr
Line 99971: this is stderr
Line 99972: this is stderr
Line 99973: this is stderr
Line 99974: this is stderr
Line 99975: this is stderr
Line 99976: this is stderr
Line 99977: this is stderr
Line 99978: this is stderr
Line 99979: this is stderr
Line 99980: this is stderr
Line 99981: this is stderr
Line 99982: this is stderr
Line 99983: this is stderr
Line 99984: this is stderr
Line 99985: this is stderr
Line 99986: this is stderr
Line 99987: this is stderr
Line 99988: this is stderr
Line 99989: this is stderr
Line 99990: this is stderr
Line 99991: this is stderr
Line 99992: this is stderr
Line 99993: this is stderr
Line 99994: this is stderr
Line 99995: this is stderr
Line 99996: this is stderr
Line 99997: this is stderr
Line 99998: this is stderr
Line 99999: this is stderr
e 99929: this is stdout
Line 99930: this is stdout
Line 99931: this is stdout
Line 99932: this is stdout
[...]

I think this happens because python uses output buffering by default. If I run the same thing with a -u (unbuffered) flag:

runitor -uuid my-uuid-here python -u script.py

Then it produces perfect output:

[...]
Line 99997: this is stdout
Line 99997: this is stderr
Line 99998: this is stdout
Line 99998: this is stderr
Line 99999: this is stdout
Line 99999: this is stderr

[runitor] Output truncated to last 10000 bytes.

An interesting thing is, if I run the python script from console, then

python script.py

and

python -u script.py

produce identical, correct results. I don't know how or why it works under the hood. I'm guessing Python is using a single buffer internally when stdout and stderr are the same. And the results end up looking correct because, even with buffering, the script is sequentially writing to the same single buffer.

[bdd]

Implemented in 6bb0a8a.
Released in v0.7.0.