Add bunyan JSON formatter

[HCastano]

This PR changes the output of our JSON logs to follow the bunyan format.

Bunyan provides a bit of a standardized approach to what fields we log, and also adds more context to our JSON logs than what we currently have.

The libray we're using does also mention that events will have access to the parent span's context. I've been trying to manually trace this through our logs and I'm not entirely sure how to properly make use of this - but could be handy as well.

Couple of downsides here:

• Logging is a more verbose, e.g it prints out info about Spans (e.g entering and exiting).
• Custom logging levels (integers instead of INFO, DEBUG, etc.)
  • We can still filter properly using RUST_LOG, this is more about interpreting the output after the fact

Since I expect that these logs are going to go into some sort of aggregator for later analysis it doesn't seem like a huge deal that they're more verbose. However, it could also come back to bite us if we have too many logs and can't understand what they're trying to tell us while debugging issues.

If this turns out to be overkill we can always change the formatting. I'm not tied to bunyan - it's just something I saw come up a few times during the last couple of weeks.

Here is an example of what the output looks like:

$ RUST_LOG=server,tower_http cargo test -p server -- test_sync_kvdb

{"v":0,"name":"server@0.1.0-release/v0.0.8-28-g425b87c","msg":"Starting process with account ID: `5D2SVCUkK5FgFiBwPTJuTN65J6fACSEoZrL41thZBAycwnQV`","level":20,"hostname":"hcastano","pid":27425,"time":"2023-11-23T20:44:59.765668Z","target":"server::helpers::launch","line":200,"file":"crypto/server/src/helpers/launch.rs"}
{"v":0,"name":"server@0.1.0-release/v0.0.8-28-g425b87c","msg":"Server started in unsafe mode - do not use in production!","level":40,"hostname":"hcastano","pid":27425,"time":"2023-11-23T20:44:59.766691Z","target":"server","line":160,"file":"crypto/server/src/lib.rs"}
{"v":0,"name":"server@0.1.0-release/v0.0.8-28-g425b87c","msg":"[HTTP-REQUEST - START]","level":30,"hostname":"hcastano","pid":27425,"time":"2023-11-23T20:44:59.768961Z","target":"server","line":173,"file":"crypto/server/src/lib.rs","uri":"/validator/sync_kvdb","method":"POST","uuid":"8317b39c-5450-4928-aef6-c8ad84b7c14d"}
{"v":0,"name":"server@0.1.0-release/v0.0.8-28-g425b87c","msg":"[HTTP-REQUEST - EVENT] started processing request","level":30,"hostname":"hcastano","pid":27425,"time":"2023-11-23T20:44:59.769005Z","target":"tower_http::trace::on_request","line":88,"file":"/Users/hcastano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.3.5/src/trace/on_request.rs","uri":"/validator/sync_kvdb","method":"POST","uuid":"8317b39c-5450-4928-aef6-c8ad84b7c14d"}
{"v":0,"name":"server@0.1.0-release/v0.0.8-28-g425b87c","msg":"[SYNC_KVDB - START]","level":30,"hostname":"hcastano","pid":27425,"time":"2023-11-23T20:44:59.769195Z","target":"server::validator::api","line":110,"file":"crypto/server/src/validator/api.rs","method":"POST","signing_address":"5D2SVCUkK5FgFiBwPTJuTN65J6fACSEoZrL41thZBAycwnQV","uri":"/validator/sync_kvdb","uuid":"8317b39c-5450-4928-aef6-c8ad84b7c14d"}
{"v":0,"name":"server@0.1.0-release/v0.0.8-28-g425b87c","msg":"[SYNC_KVDB - END]","level":30,"hostname":"hcastano","pid":27425,"time":"2023-11-23T20:44:59.832279Z","target":"server::validator::api","line":110,"file":"crypto/server/src/validator/api.rs","method":"POST","elapsed_milliseconds":63,"signing_address":"5D2SVCUkK5FgFiBwPTJuTN65J6fACSEoZrL41thZBAycwnQV","uri":"/validator/sync_kvdb","uuid":"8317b39c-5450-4928-aef6-c8ad84b7c14d"}
{"v":0,"name":"server@0.1.0-release/v0.0.8-28-g425b87c","msg":"[HTTP-REQUEST - EVENT] finished processing request","level":30,"hostname":"hcastano","pid":27425,"time":"2023-11-23T20:44:59.832471Z","target":"tower_http::trace::on_response","line":254,"file":"/Users/hcastano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.3.5/src/trace/on_response.rs","latency":"63 ms","status":200,"uri":"/validator/sync_kvdb","method":"POST","uuid":"8317b39c-5450-4928-aef6-c8ad84b7c14d"}
{"v":0,"name":"server@0.1.0-release/v0.0.8-28-g425b87c","msg":"[HTTP-REQUEST - END]","level":30,"hostname":"hcastano","pid":27425,"time":"2023-11-23T20:44:59.83254Z","target":"server","line":173,"file":"crypto/server/src/lib.rs","method":"POST","elapsed_milliseconds":63,"uri":"/validator/sync_kvdb","uuid":"8317b39c-5450-4928-aef6-c8ad84b7c14d"}

The same logs can be pretty printed in your terminal using a Bunyan CLI tool (here's one written in Rust).

Below is a sample of what that looks like.

$ RUST_LOG=server,tower_http cargo test -p server -- test_sync_kvdb | bunyan

[2023-11-23T20:45:31.443Z] DEBUG: server@0.1.0-release/v0.0.8-28-g425b87c/27460 on hcastano: Starting process with account ID: `5D2SVCUkK5FgFiBwPTJuTN65J6fACSEoZrL41thZBAycwnQV` (file=crypto/server/src/helpers/launch.rs,line=200,target=server::helpers::launch)
[2023-11-23T20:45:31.444Z]  WARN: server@0.1.0-release/v0.0.8-28-g425b87c/27460 on hcastano: Server started in unsafe mode - do not use in production! (file=crypto/server/src/lib.rs,line=160,target=server)
[2023-11-23T20:45:31.446Z]  INFO: server@0.1.0-release/v0.0.8-28-g425b87c/27460 on hcastano: [HTTP-REQUEST - START] (file=crypto/server/src/lib.rs,line=173,method=POST,target=server,uri=/validator/sync_kvdb,uuid=11517cac-b536-4f32-8c8b-a105465997b9)
[2023-11-23T20:45:31.446Z]  INFO: server@0.1.0-release/v0.0.8-28-g425b87c/27460 on hcastano: [HTTP-REQUEST - EVENT] started processing request (line=88,method=POST,target=tower_http::trace::on_request,uri=/validator/sync_kvdb,uuid=11517cac-b536-4f32-8c8b-a105465997b9)
    file: /Users/hcastano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.3.5/src/trace/on_request.rs
[2023-11-23T20:45:31.446Z]  INFO: server@0.1.0-release/v0.0.8-28-g425b87c/27460 on hcastano: [SYNC_KVDB - START] (file=crypto/server/src/validator/api.rs,line=110,method=POST,signing_address=5D2SVCUkK5FgFiBwPTJuTN65J6fACSEoZrL41thZBAycwnQV,target=server::validator::api,uri=/validator/sync_kvdb,uuid=11517cac-b536-4f32-8c8b-a105465997b9)
[2023-11-23T20:45:31.510Z]  INFO: server@0.1.0-release/v0.0.8-28-g425b87c/27460 on hcastano: [SYNC_KVDB - END] (elapsed_milliseconds=63,file=crypto/server/src/validator/api.rs,line=110,method=POST,signing_address=5D2SVCUkK5FgFiBwPTJuTN65J6fACSEoZrL41thZBAycwnQV,target=server::validator::api,uri=/validator/sync_kvdb,uuid=11517cac-b536-4f32-8c8b-a105465997b9)
[2023-11-23T20:45:31.510Z]  INFO: server@0.1.0-release/v0.0.8-28-g425b87c/27460 on hcastano: [HTTP-REQUEST - EVENT] finished processing request (latency="64 ms",line=254,method=POST,status=200,target=tower_http::trace::on_response,uri=/validator/sync_kvdb,uuid=11517cac-b536-4f32-8c8b-a105465997b9)
    file: /Users/hcastano/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tower-http-0.3.5/src/trace/on_response.rs
[2023-11-23T20:45:31.510Z]  INFO: server@0.1.0-release/v0.0.8-28-g425b87c/27460 on hcastano: [HTTP-REQUEST - END] (elapsed_milliseconds=64,file=crypto/server/src/lib.rs,line=173,method=POST,target=server,uri=/validator/sync_kvdb,uuid=11517cac-b536-4f32-8c8b-a105465997b9)

Part of #498.

[vercel]

The latest updates on your projects. Learn more about Vercel for Git ↗︎

Name	Status	Preview	Comments	Updated (UTC)
entropy-core	✅ Ready (Inspect)	Visit Preview	💬 Add feedback	Nov 23, 2023 10:06pm

[ameba23]

I'm totally willing to give this a try, although the advantages are not 100% clear to me. If i've understood right, it only effects how JSON logs will be displayed - 'Full' and 'Pretty' aren't effected.

So this is mostly significant for when we are piping the logs into some other tool. Until i start doing that, i don't have strong opinions about how that JSON looks.

[HCastano]

I'm totally willing to give this a try, although the advantages are not 100% clear to me. If i've understood right, it only effects how JSON logs will be displayed - 'Full' and 'Pretty' aren't effected.

Yeah exactly, it's only the JSON codepath that's affected.

tl;dr of benefits

• Span event information lets us trace execution in a more fine-grained way
• Inheritance of context for parent spans
• Standardized fields across logging events
  • Additional default fields like PID and hostname
• Still JSON, so we can extend it as needed

So this is mostly significant for when we are piping the logs into some other tool. Until i start doing that, i don't have strong opinions about how that JSON looks.

Haha sure. Again I'm not tied to this so happy to change the format in a way that best suits us.