Let's figure out logging

[sgrif]

As I'm adding SQLite support, I'm finding it annoying to track down cases like called `Result::unwrap()` on an `Err` value: DatabaseError("SQL logic error or missing database").

This should definitely be injectable, and I'd prefer that it be decoupled from the individual connection classes, but I'm not sure that's actually possible.

I'd originally imagined something like LoggingConnection being a struct, which wrapped another T: Connection, and ran everything through the DebugQueryBuilder (and eventually cached it through the same mechanisms that we add for prepared statement caching). This should also log the values for the bind params. I am fine with adding the constraint ToSql<ST, DB>: Debug to accommodate this, as basically everything should implement it.

However, given that DebugQueryBuilder can have output which potentially differs from the actual SQL executed (for example, we're currently figuring out how to deal with SQLite's lack of a DEFAULT keyword, and I don't see how what we end up doing can actually be reflected in DebugQueryBuilder). So perhaps the correct answer is to have a set_logger method added to Connection.

Ultimately I'm undecided on this, and am open to either solution, if presented as a working PR. Discussion about how to go about this, or use cases that we think we need to support is certainly welcomed.

[sgrif]

I'm going to pull this off the 1.0 milestone. I don't see any way for this to happen in the immediate future. The ecosystem isn't there yet. From my point of view there are two main requirements here:

• Doesn't require the use of a global logger.
  • Doing something as simple as "log crate1 to stdout, crate2 to a file" or "temporarily disable logging for a single crate" should not be difficult.
  • It would be impossible to test our implementation of logging if a global logger is required.
• Has a reasonably simple "getting started" story. e.g. "I just want to log to STDOUT or a file and don't care about anything else" shouldn't require much more than connection.set_logger(Logger::new(stdout()))
  • Happy to see more complex configuration available, but this is a thing that people will see pretty early on. It needs to be possible without stalling getting started.

The two options today seem to be log and slog. log fails the first requirement (the Log trait is present, but impossible to interact with from outside the crate). slog fails the second (Printing to stdout requires 4 lines and 3 different crates. Most of the examples in their docs that I encountered don't compile, a lot of bit-rot over there it seems). Arguably log fails the second requirement as well.

I'll be interested to see what happens with SergioBenitez/Rocket#21, as I assume they have similar concerns to mine.

[dpc]

slog is like LEGO for Rust logging, so exposes all the important details. That's why eg. creating logger might feel verbose. I've changed strategy a bit, and to smooth the learning curve I explicitly advise newcomers to use https://docs.rs/sloggers

Also, if diesel wants to shield users from the complexity of building a Drain and root Logger in slog, the following can be done:

impl Connection {
   fn set_stderr_logger(level: Level) { ... }
   fn set_stdout_logger(level: Level) { ... }
   fn set_file_logger(level: Level, path: &Path) { ... }
   fn set_custom_logger(log : slog::Logger) { ... }
}

• so, as many common methods, that do the hard part for the user and set up the right logging configuration, and one "advanced" method for brave souls who need something custom, and want to get more dirty with slog.

[theduke]

@sgrif would it be possible to leave logging up to the user by providing hooks on the connection?

I'm thinking something like this:

trait Connection {
  ...
  /// Register a function that will be called before each executed statement. 
  fn pre_execute<F>(&mut self, hook: F)
    where F: Fn(query: &str, args: &[?]) -> bool;

  fn on_success<F>(&mut self, hook: F) where ..;
  fn on_error<F>(&mut self, hook: F) where ..;
}

This would allow customized logging, only logging errors, profiling by measuring execution time, ...

[sgrif]

Profiling execution time is definitely an interesting case that I haven't considered much. I need to give that one some thought. (The general answer to your question is, yes having us provide our own ad-hoc logging system with shims for log and slog is probably the most likely path forward at this point)

[weiznich]

I've played a bit with making a custom Connection outside of diesel which does the logging on each command. I came up with the following interface/implementation:
(I mainly write this because this won't make it into 1.0. So this don't get lost till one implement this feature)

#[derive(Debug, Clone, Copy)]
pub enum TransactionState {
    Start,
    Commit,
    Abort,
}

pub trait Logger<DB: Backend>: Send + Default {
    fn on_establish(&self, url: &str);
    fn on_transaction(&self, state: TransactionState);
    fn on_execute(&self, query: &str);
    fn on_query<T>(&self, source: &T)
        where T: QueryFragment<DB>,
              DB::QueryBuilder: Default;
}

#[derive(Debug)]
pub struct LogConnection<C, L> {
    inner: C,
    logger: L,
}

impl<C, L> SimpleConnection for LogConnection<C, L>
    where C: Connection,
          L: Logger<C::Backend>
{
    fn batch_execute(&self, query: &str) -> QueryResult<()> {
        self.logger.on_execute(query);
        self.inner.batch_execute(query)
    }
}

impl<C, L> Connection for LogConnection<C, L>
    where C: Connection,
          L: Logger<C::Backend>,
          <C::Backend as Backend>::QueryBuilder: Default
{
    type Backend = C::Backend;
    type TransactionManager = LogTransactionManager<C::TransactionManager>;

    fn establish(database_url: &str) -> ConnectionResult<Self> {
        let logger = L::default();
        logger.on_establish(database_url);
        C::establish(database_url).map(|inner| LogConnection { inner, logger })
    }

    fn execute(&self, query: &str) -> QueryResult<usize> {
        self.logger.on_execute(query);
        self.inner.execute(query)
    }

    fn query_by_index<T, U>(&self, source: T) -> QueryResult<Vec<U>>
        where T: AsQuery,
              T::Query: QueryFragment<Self::Backend> + QueryId,
              Self::Backend: HasSqlType<T::SqlType>,
              U: Queryable<T::SqlType, Self::Backend>
    {
        self.logger.on_query(&source.clone().as_query());
        self.inner.query_by_index(source)
    }

    fn query_by_name<T, U>(&self, source: &T) -> QueryResult<Vec<U>>
        where T: QueryFragment<Self::Backend> + QueryId,
              U: QueryableByName<Self::Backend>
    {
        self.logger.on_query(source);
        self.inner.query_by_name(source)
    }

    fn execute_returning_count<T>(&self, source: &T) -> QueryResult<usize>
        where T: QueryFragment<Self::Backend> + QueryId
    {
        self.logger.on_query(source);
        self.inner.execute_returning_count(source)
    }

    fn transaction_manager(&self) -> &Self::TransactionManager {
        // See the implementation of `std::path::Path::new`
        unsafe {
            &*(self.inner.transaction_manager() as *const C::TransactionManager as
               *const LogTransactionManager<C::TransactionManager>)
        }
    }
}

#[derive(Debug)]
pub struct LogTransactionManager<T> {
    inner: T,
}

impl<C, L> TransactionManager<LogConnection<C, L>> for LogTransactionManager<C::TransactionManager>
    where C: Connection,
          L: Logger<C::Backend>,
          <C::Backend as Backend>::QueryBuilder: Default
{
    fn begin_transaction(&self, conn: &LogConnection<C, L>) -> QueryResult<()> {
        conn.logger.on_transaction(TransactionState::Start);
        self.inner.begin_transaction(&conn.inner)
    }

    fn rollback_transaction(&self, conn: &LogConnection<C, L>) -> QueryResult<()> {
        conn.logger.on_transaction(TransactionState::Abort);
        self.inner.rollback_transaction(&conn.inner)
    }

    fn commit_transaction(&self, conn: &LogConnection<C, L>) -> QueryResult<()> {
        conn.logger.on_transaction(TransactionState::Commit);
        self.inner.commit_transaction(&conn.inner)
    }

    fn get_transaction_depth(&self) -> u32 {
        self.inner.get_transaction_depth()
    }
}

This could nearly be implemented outside of diesel.
The following changes must by applied inside of diesel to make this fully working:

• Add a Clone-trait bound for AsQuery and fix all errors rustc is throwing at you
• Generalize this ExecuteDsl impl for all Connections with Connection::Backend = Sqlite (Not sure if this is possible outside of diesel, or how I must change that code)

[sgrif]

The main problem with that implementation is that I made the mistake of encouraging code written as &PgConnection, not C: Connection<Backend = Pg>, meaning this will likely need to be part of Connection itself.

[sgrif]

I also doubt this could ever be (efficiently) implemented outside of Diesel, since any outside implementation would have to force the query builder to run when we would normally skip it because it's in the prepared statement cache and looked up by QueryId.

[weiznich]

The main problem with that implementation is that I made the mistake of encouraging code written as &PgConnection, not C: Connection<Backend = Pg>, meaning this will likely need to be part of Connection itself.

That's a bit unfortunate, but is it really required that logging works out of box for existing implementation?

I also doubt this could ever be (efficiently) implemented outside of Diesel, since any outside implementation would have to force the query builder to run when we would normally skip it because it's in the prepared statement cache and looked up by QueryId.

In the interface that I've proposed above there is a Default bound on QueryBuilder. This means it is possible to construct a QueryBuilder and use it from there. (::diesel::debug_sql works from outside of diesel, so one could simply use this method there or call QueryFragment::to_sql() with a constructed QueryBuilder)

[lolgesten]

@sgrif enabling log_statement 'all' isn't a good workaround. I'm trying to figure out why an insert is throwing off my constraints, so I tried to log all and found this:

2018-03-08 09:12:58.527 GMT [70] STATEMENT:  INSERT INTO "live" ("recording_id", "time_stamp", "time_offset", "user_id", "role", "kind", "reason", "ice_conn_state", "state", "moderator", "screen", "camera", "mic", "actual_enc_br", "available_send_bw", "retransmit_br", "available_recv_bw", "target_enc_br", "bucket_delay", "transmit_br", "origin", "track", "bit_rate", "packet_rate", "packet_loss", "jitter", "rtt", "nack_count", "peak_level", "fir_count", "pli_count", "framerate", "avg_encode_time", "avg_qp") VALUES ($1, $2, $3, $4, $5, $6, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT), ($7, $8, $9, $10, $11, $12, $13, DEFAULT, $14, $15, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT, DEFAULT)

I.e. the postgres logs do not actually show you the values, so it's not a good replacement for hunting down bugs.

[weiznich]

@diesel-rs/core I would like to propose that we discuss this issue again in the context of diesel 2.0.

The main problem with that implementation is that I made the mistake of encouraging code written as &PgConnection, not C: Connection<Backend = Pg>, meaning this will likely need to be part of Connection itself.

Couldn't this be simply "solved" by doing type PgConnection = LogConnection<diesel::PgConnection, MyLogger>; in your crate root and then fixing the includes?

[sgrif]

@weiznich If your crate doesn't ever pass a connection to a dependency... Maybe? I don't think it's a viable option at this point even beyond the "People take PgConnection and not T: Connection<Backend = Pg>" piece these days. Until associated types are considered for disjointness, this would break a lot of generic code (e.g. the recent issue with batch insert not working for pooled SQLite connections)