Logging is truncated

[Joe-Heffer-Shef]

If an error occurs while running a query with a long SQL script, the logging cuts off the error message.

For example, we get an error message like this, but the SQL code is shown so the error message is truncated so the error message from DuckDB can't be seen.

Error: rapi_prepare: Failed to prepare query <SQL_GOES_HERE>
Execution halted

This might be a separate probelm, but when I choose to log to a file, it truncates the query to SELECT 1.

[krlmlr]

Thanks, this slipped through the cracks.

Is this a deployment that uses the pool package?

A reproducible example would be great.

[Joe-Heffer-Shef]

Here is some example code:

Create virtual environment

conda create --yes --quiet --name duckdb-r-example -c conda-forge r-duckdb=1 r-base
conda activate duckdb-r-example
Rscript -e 'packageVersion("duckdb")'

[1] ‘1.0.0.1’

Run R

R

Execute a query with lots of text:

query <- "/*
This is a multiline query designed to exceed R package logging limit
*/
CREATE TABLE weather (
    city    VARCHAR,
    temp_lo INTEGER, -- minimum temperature on a day
    temp_hi INTEGER, -- maximum temperature on a day
    prcp    FLOAT,
    date    DATE
);

/*
Lorem ipsum dolor sit amet, consectetur adipiscing elit.
Quisque quam eros, dictum non mi sed, porta pellentesque enim.
Proin ut imperdiet dolor. Proin id rutrum dui. Phasellus consequat est mauris,
ut congue elit pulvinar in. Donec eu consequat enim. Nullam dictum malesuada pharetra.
 Aenean vel ipsum id ipsum pretium cursus in in arcu. Duis viverra mi sit amet lorem mollis faucibus.
 Nunc vestibulum ac lorem at tempus. Quisque pretium, libero eu tincidunt tincidunt, dui felis aliquet sem, eget viverra nisl nibh a metus.
 Mauris euismod luctus porttitor.
Morbi varius ante nec tristique hendrerit. Nam ullamcorper laoreet lobortis.
*/

INSERT INTO weather
VALUES  ('San Francisco', 46, 50, 0.25, '1994-11-27'),
        ('San Diego', 45, 51, 0.25, '1994-11-27'),
        ('San Francisco', 43, 49, 0.25, '1994-11-28');

WITH weather_two AS (
  SELECT
     city AS city_name
    ,temp_lo AS low_temperature
    ,temp_hi AS high_temperature
    ,prcp AS precipitation
    ,date AS the_day
  FROM weather
)
SELECT
  city_name,
  low_temperature,
  high_temperature,
  precipitation,
  the_day23
FROM weather_two;
"
con <- DBI::dbConnect(duckdb::duckdb())
DBI::dbGetQuery(con, query)

The error message is truncated at the bottom, hiding the actual error message from DuckDB:

Error: rapi_prepare: Failed to prepare query /*
This is a multiline query designed to exceed R package logging limit
*/
CREATE TABLE weather (
    city    VARCHAR,
    temp_lo INTEGER, -- minimum temperature on a day
    temp_hi INTEGER, -- maximum temperature on a day
    prcp    FLOAT,
    date    DATE
);

/*
Lorem ipsum dolor sit amet, consectetur adipiscing elit.
Quisque quam eros, dictum non mi sed, porta pellentesque enim.
Proin ut imperdiet dolor. Proin id rutrum dui. Phasellus consequat est mauris,
ut congue elit pulvinar in. Donec eu consequat enim. Nullam dictum malesuada pharetra.
 Aenean vel ipsum id ipsum pretium cursus in in arcu. Duis viverra mi sit amet lorem mollis faucibus.
 Nunc vestibulum ac lorem at tempus. Quisque pretium, libero eu tincidunt tincidunt, dui felis aliquet sem, eget viverra nisl nibh a metus.
 Mauris euismod luctus porttitor.
Morbi varius ante nec tristique hendrerit. Nam ullamcorper laoreet lobortis.
*/

INSERT INTO weather
VALUES  ('San Francisco'
>

[krlmlr]

Thanks. Can you please try the brand-new 1.1.2? I see different results, could be a side effect from #522.

(Can't use the reprex package with this query.)

> DBI::dbGetQuery(con, query)
Error in `dbSendQuery()` at DBI/R/dbGetQuery_DBIConnection_character.R:5:3:
! rapi_prepare: Failed to prepare query /*
This is a multiline query designed to exceed R package logging limit
*/
CREATE TABLE weather (
    city    VARCHAR,
    temp_lo INTEGER, -- minimum temperature on a day
    temp_hi INTEGER, -- maximum temperature on a day
    prcp    FLOAT,
    date    DATE
);

/*
Lorem ipsum dolor sit amet, consectetur adipiscing elit.
Quisque quam eros, dictum non mi sed, porta pellentesque enim.
Proin ut imperdiet dolor. Proin id rutrum dui. Phasellus consequat est mauris,
ut congue elit pulvinar in. Donec eu consequat enim. Nullam dictum malesuada pharetra.
 Aenean vel ipsum id ipsum pretium cursus in in arcu. Duis viverra mi sit amet lorem mollis faucibus.
 Nunc vestibulum ac lorem at tempus. Quisque pretium, libero eu tincidunt tincidunt, dui felis aliquet sem, eget viverra nisl nibh a metus.
 Mauris euismod luctus porttitor.
Morbi varius ante nec tristique hendrerit. Nam ullamcorper laoreet lobortis.
*/

INSERT INTO weather
VALUES  ('San Francisco', 46, 50, 0.25, '1994-11-27'),
        ('San Diego', 45, 51, 0.25, '1994-11-27'),
        ('San Francisco', 43, 49, 0.25, '1994-11-28');

WITH weather_two AS (
  SELECT
     city AS city_name
    ,temp_lo AS low_temperature
    ,temp_hi AS high_temperature
    ,prcp AS precipitation
    ,date AS the_day
  FROM weather
)
SELECT
  city_name,
  low_temperature,
  high_temperature,
  precipitation,
  the_day23
FROM weather_two;

Error: Binder Error: Referenced column "the_day23" not found in FROM clause!
Candidate bindings: "weather_two.the_day", "weather_two.city_name"
LINE 43:   the_day23
           ^
Backtrace:
 1. DBI::dbGetQuery(con, query)
 2. DBI::dbGetQuery(con, query)
      at DBI/R/dbGetQuery.R:64:9
 3. DBI (local) .local(conn, statement, ...)
 5. duckdb::dbSendQuery(conn, statement, ...)