Better logging

[Sytten]

Just wanted to restart the discussion on logging for development.
This is linked to issue #150

I think a few key points are:

• Zero cost for the release build
• Allows plugging any crate we want (so people using tracing and people using log will both be happy)
• Allow to log the query and optionally the values
• Works with all connections types and pools supported by diesel

[weiznich]

First of all I want to clearly state that while I'm interested in having such a discussion that won't be something that will be implemented in the near future (so at least not before the 2.0 release). As an intermediate solution: There are existing, crates that provide wrapping connection implementation for various logging solutions.

That out of the way: I would be interested in hearing use cases. What exactly would you like to achieve with logging? What information would you like to see in your log? And how would you like to be able to configure that?

Another important point while talking about potential designs is how this should interact with prepared statement caching and query building? For example logging the query itself every time it's executed would require us to rerun the query builder every time the query is logged. Currently we sometimes skip the query builder completely for cases where we already have a prepared statement and the mapping between query and statement could be known at compile time.

[Sytten]

For my use case, it is purely for debugging the executed queries easily when developing. So my goal is to have a simple switch I can toggle to get an output of some or all the queries (with or without values) even if it is not efficient because it is needs to rerun the builder.

[weiznich]

The diesel_logger crate already "solves" that use case.

[Sytten]

Unsure if it still works with the master branch I will have to check.
To me it's not a zero runtime cost nor easy to enable with a feature flag kinda thing so I feel it's not the perfect solution.
It could be a good first step to bring into diesel core directly though (I am happy to do the work for it).

[ensc]

That out of the way: I would be interested in hearing use cases. What exactly would you like to achieve with logging?

For me, it is purely for debugging (see whether queries are so as expected, inspect parameters).

It would be nice when the output can be copied & pasted, so that the query plan can be inspected (e.g. EXPLAIN <middle mouse click>). Unfortunately, this does not work atm because existing loggers print the prepared statements and bound values separately.

Performance loss due to logging does not matter.

What information would you like to see in your log?

The query itself with values substituted. Perhaps plus some statistics (time).

And how would you like to be able to configure that?

For me, customization at compile time suffices (e.g. https://gitlab-ext.sigma-chemnitz.de/ensc/sstate-server/-/blob/789f4b4948d63c8b4188e18abb4ee45385074f7b/modules/db/src/lib/postgres.rs#L8-12).

[musjj]

That out of the way: I would be interested in hearing use cases.

If you're using GraphQL, you want to be able to quickly check if there's any problematic N+1 queries and logging would make this easy to do. I'm sure even with REST, a sufficiently complex application would benefit from logging for debugging any problematic queries.

[weiznich]

Unsure if it still works with the master branch I will have to check.

It likely won't work with the master branch as it is, as the master branch is a moving target and breaks stuff from time to time. If you need that kind of integration with other crates you should not use the master branch.

It could be a good first step to bring into diesel core directly though (I am happy to do the work for it).

As at least I have currently quite limited maintenance capacity I do not want to upstream whole crates into diesel. I'm fine with adding stuff that cannot be done outside of diesel, but everything else needs to stay outside so that's maintained by someone else. Sorry for being that hard here, but I cannot maintain everything for everyone for free.

[ensc]

It likely won't work with the master branch as it is, as the master branch is a moving target and breaks stuff from time to time. If you need that kind of integration with other crates you should not use the master branch.

fwiw, https://gitlab-ext.sigma-chemnitz.de/ensc/sstate-server/-/blob/develop/modules/db/src/lib/logger.rs provides an implementation which works on master (but requires i-implement-a-third-party-backend-and-opt-into-breaking-changes recently to have access to ConnectionGatWorkaround).

[weiznich]

I had thoughts on how to provide a better solution for this problem, than having extern crates wrapping existing connection implementations. This post is a call for feedback. A potential implementation will not start before the finial 2.0 release, which means I mostly write this down now to remember it later on.

First of all let me write down some basic assumptions of my idea:

• There is no on fit's all logging solution (tracing vs log vs …)
• Different people may be interested in logging different stuff (query times, tracing spans, …, sql, only sometimes, …)
• Not just logging might be interesting, but more general speaking instrumentation (so doing stuff on some action, for example incrementing a metrics counter, …)

Requiring to implement all of this as custom connection implementation, has a few potential problems:

• Requires to implement the complete connection interface, which we might not want to allow outside of the "unstable"/i-implement-a-third-party-backend-and-opt-into-breaking-changes feature flag
• Requires users to use the other logging/instrumentation connection instead of the default diesel one. This makes it hard to just quickly switch something like that on to try debug things.
• These solutions do not have access to low level information like: Is this prepared statement cached, …)

Because of this it might be useful to expose a general interface from Connection itself. This interface should be as minimal as possible, so that we could provide it as part of the stable API. Additionally it should not implement a specific down stream "consumer" (so no tracing/log/…). This can then be provided by third party crates.

I believe something like the following interface might work:

trait Connection {
    fn instrument(&mut self, i: Box<dyn ConnectionInstrumentation<Self::Backend>>);
}

trait ConnectionInstrumentation<DB: Backend> {
    fn on_action(&mut self, action: Action<'_>);
}

#[non_exhaustive] 
enum Action<'a, DB: Backend> {
    #[non_exhaustive]
    QueryStart{
        query: &'a dyn QueryFragment<DB>,
        // other relevant information
    },
    #[non_exhaustive]
    FetchedRow {
        row: &'a dyn Row<DB>, // This might require some work on row to expose this information
        // other relevant information
    },
    #[non_exhaustive]
    QueryEnd {
        query: &'a dyn QueryFragment<DB>,
        result: Result<(), &Error>,
        // other relevant information
    },
    #[non_exhaustive]
    TransactionStart{},
    #[non_exhaustive]
    RollbackTransaction{reason: Result<&(), &Error>},
    #[non_exhaustive]
    CommitTransaction{}, 
}

(Names up for discussion)

Such an interface would allow us to add more information later on, while users could use the already exposed information. In additional I'm quite confident that such a interface could be implemented without imposing additional overhead on use cases that don't use this interface at all.

[onx2]

@weiznich Now that v2 has been released, will this be on your radar? Logging just the executed queries would be helpful for development 😄

Something along these lines would even be great to have without any additional logging features:

let results = posts
        .filter(published.eq(true))
        .limit(5)
        .output_raw_sql::<Post>(connection);
// select * from posts where published = 'true' limit 5;

[weiznich]

I'm happy to accept contributions here, but otherwise I will likely not work on that on my own.

[onx2]

Do you think this additional function to output the generated sql would be a good first issue?

[weiznich]

To be clear: The statement above refereed to the implementation of the logging API proposed above

The API you've proposed in not possible in that way, as diesel uses prepared statements + binds internally. This means we don't build one query string with inline parameters at all. These representation is just not available in diesel, so it cannot be returned to the user at all. diesel::debug_query is what's already there today and what can be used to get the generated SQL.

[onx2]

Got it -- thank you for the explanation