Incomplete logging to file when using log_query_path option

[joostas]

DuckDB provides local configuration option that lets log all executed queries to file:

Name	Description
log_query_path	Specifies the path to which queries should be logged (default: NULL, queries are not logged)

When this setting is enabled and queries are executed through DuckDB.NET, the log file records only successful queries - failed queries are not logged. In contrast, when using the DuckDB CLI, both successful and failed queries are logged.

CLI behavior:

DuckDB v1.3.2 (Ossivalis) 0b83e5d2f6
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.
D SET log_query_path = log_cli.txt;
D SELECT 1;
┌───────┐
│   1   │
│ int32 │
├───────┤
│   1   │
└───────┘
D SELECT 1 FROM;
Parser Error:
syntax error at or near ";"

LINE 1: SELECT 1 FROM;
                     ^
D SELECT 1 FROM B;
Catalog Error:
Table with name B does not exist!

LINE 1: SELECT 1 FROM B;
                      ^
D RESET log_query_path;
D .exit

cat .\log_cli.txt

SELECT 1;
SELECT 1 FROM B;

Successful query and failed to execute query are logged. Didn't log failed to parse query.

DuckDB.NET behavior (DuckDBCommand):

   // in public class DuckDBDataReaderTests(DuckDBDatabaseFixture db) : DuckDBTestBase(db)
    [Fact]
    public void LogSqlStatements()
    {
        var suffix = "origin";
        var fileName = $"log_{suffix}.txt";
        if (File.Exists(fileName))
        {
            File.Delete(fileName);
        }

        Command.CommandText = $"SET log_query_path = {fileName}";
        _ = Command.ExecuteNonQuery();
        Command.CommandText = "SELECT 1";
        Command.ExecuteReader();
        Command.CommandText = "SELECT 1 FROM";
        try
        {
            Command.ExecuteReader();
        }
        catch { }

        Command.CommandText = "SELECT 1 FROM B";
        try
        {
            Command.ExecuteReader();
        }
        catch { }

        File.Exists(fileName);
        Command.CommandText = "RESET log_query_path";
        Command.ExecuteReader();
        var logs = File.ReadAllText(fileName);
        logs.Contains("SELECT 1 FROM").Should().BeTrue();
    }

Logs

cat .\DuckDB.NET.Test\bin\Debug\net8.0\log_origin.txt

SELECT 1
RESET log_query_path

Only successful queries were logged.

[joostas]

After some investigation I found that root cause of such behavior is that DuckDBCommand always execute queries using method PreparedStatement.PrepareMultiple. Which uses these C API methods:

• duckdb_extract_statements
• duckdb_prepare_extracted_statement
• group of API calls related to parameters binding (e.g. duckdb_nparams, duckdb_bind_parameter_index, ...)
• duckdb_execute_prepared or duckdb_execute_prepared_streaming

But if DuckDBCommand does not have any parameters defined it is possible to execute query using this C API call duckdb_query.

I applied this logic (pseudo code below):

if (parameters.Count > 0 || UseStreamingMode ) // duckdb_query does not support streaming mode
{
  //current execution path using prepared statements
}
else
{
    var statementCount = // call duckdb_extract_statements;
    if (statementCount == 1)
    {
       //execute `duckdb_query` directly
    }
    else
    {
       //use current code flow with prepared statements.
    }
}

Using this logic DuckDB.NET logs failed queries as well.

If you are interested in that change I could try to polish it up and create PR.

[Giorgi]

@joostas I think duckdb_execute_prepared should be updated to log failed queries. In that case, it would also work with DuckDB.NET.

[joostas]

In given case even if duckdb_execute_prepared would log failed queries I don't think DuckDB.NET would work "out of the box", because code fails fast earlier:

                var status = NativeMethods.ExtractStatements.DuckDBPrepareExtractedStatement(connection, extractedStatements, index, out var statement);

                if (status.IsSuccess())
                {
                    using var preparedStatement = new PreparedStatement(statement);
                    yield return preparedStatement.Execute(parameters, useStreamingMode);
                }
                else
                {
                    var errorMessage = NativeMethods.PreparedStatements.DuckDBPrepareError(statement).ToManagedString(false);
                    throw new DuckDBException(string.IsNullOrEmpty(errorMessage) ? "DuckDBQuery failed" : errorMessage);
                }

But when DuckDBCommand has no parameters, I don’t see any reason to execute the query indirectly through duckdb_prepare_extracted_statement and duckdb_execute_prepared instead of directly using duckdb_query.

Executing directly should be more efficient and will give functionality to improve query logging as well. What do you think @Giorgi?

[Giorgi]

That code can be changed 🙂

If log_query_path is intended to log failed parameterized queries too, the better fix is the one I suggested. If it is not designed for that, I can consider making that changed. I think you should open an issue/discussion in the duckdb repo

[joostas]

IMHO from the perspective of the C API, the behavior appears to be correct. When using a Prepared Statement, if the preparation phase fails, the query itself is not executed - hence, it is not logged. This seems consistent with expected behavior.

However, when using DuckDBCommand without any parameters, such as in the following example:

using var command = connection.CreateCommand();
command.CommandText = "SELECT 1 FROM B";
using var reader = command.ExecuteReader();
//...

I would anticipate that the query is executed directly, as there is no preparation involved. In such a case, if the query fails, I would expect it to be logged accordingly.

Therefore, it seems that the issue may lie more in how the C API calls are wrapped within DuckDBCommand, rather than in the C API itself.

[Giorgi]

With your suggested workaround, the following will still not log an error:

cmd.CommandText = "CREATE TABLE person (name VARCHAR, age BIGINT); INSERT INTO person VALUES ('Alice', ?); SELECT * FROM test";
cmd.Parameters.Add(new DuckDBParameter(5));
cmd.ExecuteNonQuery();

[joostas]

True. The given solution won’t cover all cases, but it will handle the scenario where CommandText is a single SQL statement without any parameters. I think this is quite a common case.