False error in statement logs

Bug Description

When I enable logging for statements with log level Error I get some errors for queries that do not fail:

This is the way I enable logging:

let mut connection_options =
    SqliteConnectOptions::from_str(database_url).expect("Unable to create connection options.");

connection_options
    .log_statements(log::LevelFilter::Error)
    .log_slow_statements(log::LevelFilter::Warn, Duration::from_secs(1));

If I run the queries manually, they do not fail.

Minimal Reproduction

I've created a repo to reproduce the problem:

https://github.com/josecelano/sqlx-false-database-query-error

Info

SQLx version: 0.6.3
SQLx features enabled: ["runtime-tokio-native-tls","sqlite","mysql","migrate","time",]
Database server and version: 3.40.1 2022-12-28 14:03:47 df5c253c0b3dd24916e4ec7cf77d3db5294cc9fd45ae7b9c5e82ad8197f3alt1
Operating system: Ubuntu 23.04
rustc --version: rustc 1.71.0-nightly (18bfe5d8a 2023-05-14)

The sample repo output:

$ cargo run
    Finished dev [unoptimized + debuginfo] target(s) in 0.03s
     Running `target/debug/sqlx-false-database-query-error`
summary: PRAGMA foreign_keys = ON;
2023-06-20T16:44:07.467203835+01:00 [sqlx::query][ERROR] PRAGMA foreign_keys = ON; …; rows affected: 0, rows returned: 0, elapsed: 28.229µs

PRAGMA foreign_keys = ON;

summary: CREATE TABLE IF NOT
2023-06-20T16:44:07.469929893+01:00 [sqlx::query][ERROR] CREATE TABLE IF NOT …; rows affected: 0, rows returned: 0, elapsed: 1.331ms

CREATE TABLE IF NOT EXISTS _sqlx_migrations (
  version BIGINT PRIMARY KEY,
  description TEXT NOT NULL,
  installed_on TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP,
  success BOOLEAN NOT NULL,
  checksum BLOB NOT NULL,
  execution_time BIGINT NOT NULL
);

summary: SELECT version FROM _sqlx_migrations
2023-06-20T16:44:07.470428657+01:00 [sqlx::query][ERROR] SELECT version FROM _sqlx_migrations …; rows affected: 0, rows returned: 0, elapsed: 49.910µs

SELECT
  version
FROM
  _sqlx_migrations
WHERE
  success = false
ORDER BY
  version
LIMIT
  1

summary: SELECT version, checksum FROM
2023-06-20T16:44:07.470781713+01:00 [sqlx::query][ERROR] SELECT version, checksum FROM …; rows affected: 0, rows returned: 0, elapsed: 34.790µs

SELECT
  version,
  checksum
FROM
  _sqlx_migrations
ORDER BY
  version

summary: CREATE TABLE IF NOT
2023-06-20T16:44:07.471650412+01:00 [sqlx::query][ERROR] CREATE TABLE IF NOT …; rows affected: 0, rows returned: 0, elapsed: 126.358µs

CREATE TABLE IF NOT EXISTS users (
  user_id INTEGER NOT NULL PRIMARY KEY AUTOINCREMENT,
  date_registered TEXT NOT NULL
)

summary: INSERT INTO _sqlx_migrations (
2023-06-20T16:44:07.472489522+01:00 [sqlx::query][ERROR] INSERT INTO _sqlx_migrations ( …; rows affected: 1, rows returned: 0, elapsed: 59.099µs

INSERT INTO
  _sqlx_migrations (
    version,
    description,
    success,
    checksum,
    execution_time
  )
VALUES
  (?1, ?2, TRUE, ?3, -1)

summary: UPDATE _sqlx_migrations SET execution_time
2023-06-20T16:44:07.474829055+01:00 [sqlx::query][ERROR] UPDATE _sqlx_migrations SET execution_time …; rows affected: 1, rows returned: 0, elapsed: 929.029µs

UPDATE
  _sqlx_migrations
SET
  execution_time = ?1
WHERE
  version = ?2

I've just realized that the log level ERROR in the log record does not mean there was an error in the SQL query. It means the query was logged because the global logging level wis ERROR and the configuration says statements should be logged when glogal loging level is ERROR

2023-12-20T14:05:36.189980850+00:00 [sqlx::query][ERROR] SELECT version, checksum FROM …; rows affected: 0, rows returned: 1, elapsed: 35.472µs

SELECT
  version,
  checksum
FROM
  _sqlx_migrations
ORDER BY
  version

The functions log_statements and log_slow_statements only specified when you want to log the queries regardless of the query failing or not.

The following configuration:

connection_options
  .log_statements(log::LevelFilter::Debug)
  .log_slow_statements(log::LevelFilter::Warn, Duration::from_secs(1));

means you want to log all statements when the global logging level is Debug and you want to log slow statements when the global logging level is Warn.

connection_options.log_statements(log::LevelFilter::Error) does not mean you want to log failing statements as I was supposing.

This is the code:

pub trait ConnectOptions: 'static + Send + Sync + FromStr<Err = Error> + Debug + Clone {
    type Connection: Connection + ?Sized;

    /// Establish a new database connection with the options specified by `self`.
    fn connect(&self) -> BoxFuture<'_, Result<Self::Connection, Error>>
    where
        Self::Connection: Sized;

    /// Log executed statements with the specified `level`
    fn log_statements(&mut self, level: LevelFilter) -> &mut Self;

    /// Log executed statements with a duration above the specified `duration`
    /// at the specified `level`.
    fn log_slow_statements(&mut self, level: LevelFilter, duration: Duration) -> &mut Self;

    /// Entirely disables statement logging (both slow and regular).
    fn disable_statement_logging(&mut self) -> &mut Self {
        self.log_statements(LevelFilter::Off)
            .log_slow_statements(LevelFilter::Off, Duration::default())
    }
}

launchbadge / sqlx