feat(booster-http): --log-file, defaulting to stdout, for standardised http log output

[rvagg]

On top of #1736 which is on top of #1676, separate to make it a bit easier to review but they can be merged in reverse order.

The meat of this is in the first commit. There's noise because in the second commit I did a minor reorg and moved all of the /piece/ handling code into piecehandler.go with minimal change to the substance. So consider reviewing just the first commit if you want to see the diff.

This uses some exposed stuff in ipld/frisbii#59 to do logging nicely. I've removed the custom logging stuff in here and replaced it with a unified HTTP logging middleware with a consistent format that prints to stdout by default, but with --log-file=/path/to/file.log you can put it where you want it and get an nginx-like log output that should be parseable by http log parsing tools for metrics and whatnot.

Log format is described here: https://github.com/ipld/frisbii#log-format, we could put that in the boost docs too as it may be helpful.

One nice feature that we get from this and #1736 is the compression ratio - we now collect both bytes written by the respective handlers, and bytes sent to the client, so we get compression ratio in the logs; see the tests where there's high-compression data being sent so we have high compression ratios.

---

Old /piece/ handler log output looked something like this, two lines per log output (there's a \n in there):

2023-10-09T20:00:37.003+1100    DONE    GET /piece/bafybeigdyrzt5sfp7udm7hu76uh7y26nf3efuylqabf3oclgtqy55fbzdi
2023-10-09T20:00:37.003+1100 - 2023-10-09T20:00:36.965+1100: 37.389716ms / 10,000,000 bytes transferred (gzipped)

New log output is:

2023-10-09T20:00:36+11:00 127.0.0.1 GET "/piece/bafybeigdyrzt5sfp7udm7hu76uh7y26nf3efuylqabf3oclgtqy55fbzdi" 200 37 19458 513.93 "Go-http-client/1.1" ""

So we get a single log line, same information and a bit more, and we see the bytes sent to user (19458) and compression ratio (513.93, i.e. 19458 x 513.93 ~ 10,000,000 as on the original).

[rvagg]

Depends on a tag from ipld/frisbii#59

[rvagg]

Updated to tagged [email protected]

[rvagg]

example http log output from the e2e test, first using just a go request, then via bifrost-gateway, then lastly directly with lassie:

2023-10-09T21:55:48+11:00 127.0.0.1 GET "/" 200 0 358 - "Go-http-client/1.1" ""
2023-10-09T21:56:21+11:00 127.0.0.1 GET "/ipfs/bafybeibvadlfuxzhziq6zgnvd5pbwgku3yxlkhzrjxbslrgoyf7rgakasi/foo/bar/baz.txt?format=car&dag-scope=entity" 200 524 6294732 1.00 "bifrost-gateway/dev-build" ""
2023-10-09T21:56:22+11:00 127.0.0.1 GET "/ipfs/bafybeibvadlfuxzhziq6zgnvd5pbwgku3yxlkhzrjxbslrgoyf7rgakasi/foo/bar/boom.png?format=car&dag-scope=entity" 200 5 1586 0.98 "bifrost-gateway/dev-build" ""
2023-10-09T21:56:22+11:00 127.0.0.1 GET "/ipfs/bafybeibvadlfuxzhziq6zgnvd5pbwgku3yxlkhzrjxbslrgoyf7rgakasi/foo/bar/fizz.mov?format=car&dag-scope=entity" 200 5 534 - "bifrost-gateway/dev-build" ""
2023-10-09T21:56:22+11:00 127.0.0.1 GET "/ipfs/bafybeibvadlfuxzhziq6zgnvd5pbwgku3yxlkhzrjxbslrgoyf7rgakasi/qux.html?format=car&dag-scope=entity" 200 2 1266 - "bifrost-gateway/dev-build" ""
2023-10-09T21:56:22+11:00 127.0.0.1 GET "/ipfs/bafybeibvadlfuxzhziq6zgnvd5pbwgku3yxlkhzrjxbslrgoyf7rgakasi/nope?format=car&dag-scope=entity" 200 1 204 - "bifrost-gateway/dev-build" ""
2023-10-09T21:56:22+11:00 127.0.0.1 GET "/ipfs/bafybeigdyrzt5sfp7udm7hu76uh7y26nf3efuylqabf3oclgtqy55fbzdi?format=car&dag-scope=entity" 500 0 76 - "bifrost-gateway/dev-build" ""
2023-10-09T21:56:22+11:00 127.0.0.1 GET "/ipfs/bafybeibvadlfuxzhziq6zgnvd5pbwgku3yxlkhzrjxbslrgoyf7rgakasi/foo/bar/baz.txt?dag-scope=all" 200 202 6294732 1.00 "lassie/v0.0.0-unknown" ""

Compression ratios don't look very happy, because (a) it's pure random content and (b) most of these are tiny, one's 1 byte long; so not representative of typical unixfs content!

[rvagg]

I've simplified this to 2 commits - the main feature addition and the refactor of the piece handler to a separate file and pulled it in to #1676 so it can be reviewed as part of that.