init default logger

[yoshuawuyts]

Relies on lrlna/femme#9. Adds a default logger that supports log's key-value API. A base "hello world" example now looks like this:

#[async_std::main]
async fn main() -> Result<(), std::io::Error> {
    tide::log::start();
    let mut app = tide::new();
    app.at("/").get(|_| async move { Ok("Hello, world!") });
    app.listen("127.0.0.1:8080").await?;
    Ok(())
}

---

There's a bit of a design question whether we should expose this as a separate function, or integrate it directly into the framework. I think logging is kind of on the fringe here since it not only captures things going on inside the framework; it captures things going on outside of it as well.

I feel that making it a single line to enable logging strikes a good balance between the two -- we make it easy to get a good setup going with minimal work, but we don't enable things that have global implications for the program without consulting the user.

Screenshots

[dignifiedquire]

Can this be filtered by an env variable? I think that is really a requirement to enabling this by default, especially having a way to make it only log things inside my app or just tide, not all dependencies.

[yoshuawuyts]

@dignifiedquire still working on adding filtering on the femme through femme::with_filter, but it should then be a one-liner to hook up env vars to apply filtering.

[jbr]

In reply to the question of whether logging should be integrated: For a production logger, I think there'll be a lot more API surface area, possibly justifying splitting this out into an independent crate (even if it's included by a default logging feature in tide).

Other features people might reasonably eventually expect from a feature-complete local logger: Log rotation, configurable formats, splitting into different files depending on a predicate like status code (similar to nginx's approach to logging), parameter filtering.

It would be really nice if the default logger were able to support stuff like that, so that the path from development to production wouldn't be "replace the tide logger" but instead "configure the tide logger."

[yoshuawuyts]

It would be really nice if the default logger were able to support stuff like that, so that the path from development to production wouldn't be "replace the tide logger" but instead "configure the tide logger."

@jbr I love this phrasing and agree that is indeed the way we should be thinking of driving this feature. As such I probably should add some more context for this logger specifically, explaining the ideas behind it, the direction it's going, and shortcomings it has.

The idea behind femme is to create a logger in the tradition of winston, bole, and pino: using ndjson for logs so that each line can be unambiguously parsed, overcoming much of the problems around common-log formatting. In particular femme acts as a hybrid of pino and the pino-colada pretty printer. When in development it will pretty-print messages. But in production the output is ndjson-formatted [1]. This allows for easy piping into e.g. logstash.

Because femme's format is based on pino, we can use many of the same utilities. For example log rotation exists as a tool already. And so does splitting logs on log level. The pino docs feature many tools and techniques that would likely get us most of the way, right away.

However some things we indeed do not support yet; in particular redaction seems important. Maybe the right approach here is to have femme::with_filter act as some kind of filter_map operation that can both modify and edit values. Though a more elaborate override mechanism might be useful as well. We'll need to think this one over probably.

Hopefully this sheds some light on what femme is, what some of the ideas behind it are, and what it would enable for Tide today. None of this is to say that implementing femme in its current state would be the final word on logging for Tide. But I think it would get us really far out of the box. As we get feedback from users we could look to expend our logging facilities. But hopefully this can help us get off to a good start!

[1]: We probably should do tty detection here as well.

edit: something I forgot to mention is just how fast ndjson is -- as of 2020 it can be parsed at a rate that's nearing disk read speeds (~2-4 x 2.5gb/s). The chances overall of this ever being a performance bottleneck seem fairly slim.

[jbr]

I should have looked more into femme before commenting, that's really cool! I saw the pretty-printed output in the screenshot and assumed that it was just logging unstructured text, but the ability to repurpose pino's utilities (and transporters!) makes this approach way more feature-complete and production ready than I understood.

[yoshuawuyts]

@jbr no worries; I understand the confusion and felt it was on me to share more details here heh 😅

[isgj]

I'd like to try it out. Can you post which version of femme is used?

[yoshuawuyts]

@isgj lrlna/femme#9

[isgj]

When I build the app with the release flag the logs look like

{"level":30,"time":1589717147052,"msg":"--> Response sent","method":"\"GET\"","status":"200","duration":"\"157ms\"","path":"\"/api/v1/users\""}

the string (of key: value, not the message) have also the double quotes escaped. Is that intended?

[yoshuawuyts]

@isgj that's definitely not expected and we should fix that. Filed lrlna/femme#12 on femme. Thanks for reporting!

[yoshuawuyts]

Okay, this will require patching the log crate. I don't think we should block adding this feature on that, even if it might be worth fixing in either femme or tide for the time being.

[yoshuawuyts]

Filed an issue on log as well. Merging this so folks get access to logging, and once log is patched we'll receive a new version as well thanks to semver.