Curious bug with transaction and `dbSendQuery()` #424

mgirlich · 2023-03-09T11:42:01Z

I'm not sure if this is expected behaviour, a bug in RPostgres, or a bug in Postgres itself. But it took quite some time to figure out the issue...

con <- DBI::dbConnect(RPostgres::Postgres())

write_table <- function(n) {
  DBI::dbWriteTable(
    con,
    "df_x",
    tibble::tibble(x = 1:n),
    temporary = TRUE,
    overwrite = TRUE
  )
}


DBI::dbWithTransaction(
  con, {
    write_table(2e3)
    res <- DBI::dbSendQuery(con, "SELECT * FROM df_x")
    DBI::dbFetch(res, n = 0)
    DBI::dbClearResult(res)
    DBI::dbGetQuery(con, "SELECT * FROM df_x LIMIT 1")
  }
)
#> Error: Failed to prepare query: ERROR:  current transaction is aborted, commands ignored until end of transaction block

# Interestingly, this works if the table is small
DBI::dbWithTransaction(
  con, {
    write_table(200)
    res <- DBI::dbSendQuery(con, "SELECT * FROM df_x")
    DBI::dbFetch(res, n = 0)
    DBI::dbClearResult(res)
    DBI::dbGetQuery(con, "SELECT * FROM df_x LIMIT 1")
  }
)
#>   x
#> 1 1

^{Created on 2023-03-09 with reprex v2.0.2}

krlmlr · 2023-03-09T13:19:56Z

Thanks, interesting. I can repro locally on Linux with Postgres 12 and write_table(1e5) .

krlmlr · 2023-03-16T04:43:45Z

Confirmed with Postgres 14 and 15 on macOS aarch64, built with client 14.5.

Reprex that uses simpler libpq calls under the hood, with variants:

con <- DBI::dbConnect(RPostgres::Postgres())

write_table <- function(n) {
  DBI::dbWriteTable(
    con,
    "df_x",
    tibble::tibble(x = 1:n),
    temporary = TRUE,
    overwrite = TRUE
  )
}

# Install with `R_PLOGR_ENABLE=1 R CMD INSTALL .` to enable the code below
# init_logging("VERB")

DBI::dbBegin(con)

# Setup
write_table(2e3)

res <- DBI::dbSendQuery(con, "SELECT * FROM df_x", immediate = TRUE)
# Also causes failure with:
# res <- DBI::dbSendQuery(con, "SELECT * FROM df_x")

invisible(DBI::dbFetch(res, n = 500))
# Also causes failure with:
# invisible(DBI::dbFetch(res, n = 0))
# invisible(DBI::dbFetch(res, n = 1))
# Successful with:
# invisible(DBI::dbFetch(res, n = 800))
DBI::dbClearResult(res)

# This is the failing call:
DBI::dbGetQuery(con, "SELECT * FROM df_x LIMIT 1", immediate = TRUE)
#> Error: Failed to fetch row : ERROR:  current transaction is aborted, commands ignored until end of transaction block

# Also failing with:
# DBI::dbGetQuery(con, "SELECT * FROM df_x LIMIT 1")
# DBI::dbGetQuery(con, "SELECT * FROM df_x LIMIT 10", immediate = TRUE)
# DBI::dbGetQuery(con, "SELECT * FROM df_x", immediate = TRUE)

# Not reached in case of failure
DBI::dbCommit(con)

^{Created on 2023-03-16 with reprex v2.0.2}

@Antonov548: can you reproduce this with the most recent development (bleeding edge) version of Postgres and libpq? (Is there a Docker image that we can use? Otherwise, we'll need to build from source I'm afraid.)

mgirlich · 2023-03-16T05:45:42Z

How curious that it is successful for n = 800. A quick loop shows that:

it is always the same error
the error vanishes starting from DBI::dbFetch(res, n = 590)

library(tidyverse)

con <- DBI::dbConnect(RPostgres::Postgres())

write_table <- function(n) {
  DBI::dbWriteTable(
    con,
    "df_x",
    tibble::tibble(x = 1:n),
    temporary = TRUE,
    overwrite = TRUE
  )
}

f <- function(n) {
  DBI::dbWithTransaction(
    con, {
      write_table(2e3)
      res <- DBI::dbSendQuery(con, "SELECT * FROM df_x", immediate = TRUE)
      invisible(DBI::dbFetch(res, n = n))
      DBI::dbClearResult(res)
      DBI::dbGetQuery(con, "SELECT * FROM df_x LIMIT 1", immediate = TRUE)
    }
  )
  
  TRUE
}

results <- map(
  1:2e3,
  \(n) safely(f, otherwise = FALSE)(n = n)
)

results_df <- tibble(
  n = seq_along(results),
  success = map_lgl(results, "result")
)

purrr::map(results, "error") |> unique()
#> [[1]]
#> <Rcpp::exception: Failed to fetch row: ERROR:  current transaction is aborted, commands ignored until end of transaction block
#> >
#> 
#> [[2]]
#> NULL

results_df |>
  ggplot(aes(n, success)) +
  geom_line()

^{Created on 2023-03-16 with reprex v2.0.2}

krlmlr · 2024-04-01T14:35:00Z

This no longer fails for me with libpq 14.11 run against Postgres 15. Are you still seeing this behavior?

mgirlich · 2024-04-03T09:46:08Z

Running with Postgres 15.2 and the dev version of RPostgres I still get the error.

Not sure which libpq version this is. Does this help?

otool -L /usr/local/opt/postgresql@15/lib/libpq.5.dylib
/usr/local/opt/postgresql@15/lib/libpq.5.dylib:
	/usr/local/opt/postgresql@15/lib/libpq.5.dylib (compatibility version 5.0.0, current version 5.15.0)
	/usr/local/opt/gettext/lib/libintl.8.dylib (compatibility version 13.0.0, current version 13.0.0)
	/usr/local/opt/openssl@3/lib/libssl.3.dylib (compatibility version 3.0.0, current version 3.0.0)
	/usr/local/opt/openssl@3/lib/libcrypto.3.dylib (compatibility version 3.0.0, current version 3.0.0)
	/usr/local/opt/krb5/lib/libgssapi_krb5.2.2.dylib (compatibility version 2.0.0, current version 2.2.0)
	/usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1336.61.1)
	/System/Library/Frameworks/LDAP.framework/Versions/A/LDAP (compatibility version 1.0.0, current version 2.4.0)

DBI::dbGetInfo(RPostgres::Postgres())
#> $driver.version
#> [1] '1.4.6.9006'
#> 
#> $client.version
#> [1] '15.2'


con <- DBI::dbConnect(RPostgres::Postgres())

write_table <- function(n) {
  DBI::dbWriteTable(
    con,
    "df_x",
    tibble::tibble(x = 1:n),
    temporary = TRUE,
    overwrite = TRUE
  )
}

DBI::dbBegin(con)

write_table(2e3)

res <- DBI::dbSendQuery(con, "SELECT * FROM df_x")

invisible(DBI::dbFetch(res, n = 500))
DBI::dbClearResult(res)

# This is the failing call:
DBI::dbGetQuery(con, "SELECT * FROM df_x LIMIT 1", immediate = TRUE)
#> Error: Failed to fetch row : ERROR:  current transaction is aborted, commands ignored until end of transaction block

^{Created on 2024-04-03 with reprex v2.1.0}

Session info

sessioninfo::session_info()
#> ─ Session info ───────────────────────────────────────────────────────────────
#>  setting  value
#>  version  R version 4.3.0 (2023-04-21)
#>  os       macOS 14.4.1
#>  system   x86_64, darwin20
#>  ui       X11
#>  language (EN)
#>  collate  en_US.UTF-8
#>  ctype    en_US.UTF-8
#>  tz       UTC
#>  date     2024-04-03
#>  pandoc   3.1.1 @ /Applications/RStudio.app/Contents/Resources/app/quarto/bin/tools/ (via rmarkdown)
#> 
#> ─ Packages ───────────────────────────────────────────────────────────────────
#>  package     * version    date (UTC) lib source
#>  bit           4.0.5      2022-11-15 [1] CRAN (R 4.3.0)
#>  bit64         4.0.5      2020-08-30 [1] CRAN (R 4.3.0)
#>  blob          1.2.4      2023-03-17 [1] CRAN (R 4.3.0)
#>  cli           3.6.2      2023-12-11 [1] CRAN (R 4.3.0)
#>  DBI           1.2.2      2024-02-16 [1] CRAN (R 4.3.2)
#>  digest        0.6.35     2024-03-11 [1] CRAN (R 4.3.2)
#>  evaluate      0.23       2023-11-01 [1] CRAN (R 4.3.0)
#>  fansi         1.0.6      2023-12-08 [1] CRAN (R 4.3.0)
#>  fastmap       1.1.1      2023-02-24 [1] CRAN (R 4.3.0)
#>  fs            1.6.3      2023-07-20 [1] CRAN (R 4.3.0)
#>  generics      0.1.3      2022-07-05 [1] CRAN (R 4.3.0)
#>  glue          1.7.0      2024-01-09 [1] CRAN (R 4.3.0)
#>  hms           1.1.3      2023-03-21 [1] CRAN (R 4.3.0)
#>  htmltools     0.5.8      2024-03-25 [1] CRAN (R 4.3.2)
#>  knitr         1.45       2023-10-30 [1] CRAN (R 4.3.0)
#>  lifecycle     1.0.4      2023-11-07 [1] CRAN (R 4.3.0)
#>  lubridate     1.9.3      2023-09-27 [1] CRAN (R 4.3.0)
#>  magrittr      2.0.3      2022-03-30 [1] CRAN (R 4.3.0)
#>  pillar        1.9.0      2023-03-22 [1] CRAN (R 4.3.0)
#>  pkgconfig     2.0.3      2019-09-22 [1] CRAN (R 4.3.0)
#>  purrr         1.0.2      2023-08-10 [1] CRAN (R 4.3.0)
#>  R.cache       0.16.0     2022-07-21 [1] CRAN (R 4.3.0)
#>  R.methodsS3   1.8.2      2022-06-13 [1] CRAN (R 4.3.0)
#>  R.oo          1.26.0     2024-01-24 [1] CRAN (R 4.3.2)
#>  R.utils       2.12.3     2023-11-18 [1] CRAN (R 4.3.0)
#>  reprex        2.1.0      2024-01-11 [1] CRAN (R 4.3.0)
#>  rlang         1.1.3      2024-01-10 [1] CRAN (R 4.3.0)
#>  rmarkdown     2.26       2024-03-05 [1] CRAN (R 4.3.2)
#>  RPostgres     1.4.6.9006 2024-04-02 [1] Github (r-dbi/RPostgres@a69fce0)
#>  rstudioapi    0.16.0     2024-03-24 [1] CRAN (R 4.3.2)
#>  sessioninfo   1.2.2      2021-12-06 [1] CRAN (R 4.3.0)
#>  styler        1.10.2     2023-08-29 [1] CRAN (R 4.3.0)
#>  tibble        3.2.1      2023-03-20 [1] CRAN (R 4.3.0)
#>  timechange    0.3.0      2024-01-18 [1] CRAN (R 4.3.0)
#>  utf8          1.2.4      2023-10-22 [1] CRAN (R 4.3.0)
#>  vctrs         0.6.5      2023-12-01 [1] CRAN (R 4.3.0)
#>  withr         3.0.0      2024-01-16 [1] CRAN (R 4.3.0)
#>  xfun          0.43       2024-03-25 [1] CRAN (R 4.3.2)
#>  yaml          2.3.8      2023-12-11 [1] CRAN (R 4.3.0)
#> 
#>  [1] /Library/Frameworks/R.framework/Versions/4.3-x86_64/Resources/library
#> 
#> ──────────────────────────────────────────────────────────────────────────────

krlmlr · 2024-04-13T09:31:17Z

This seems to be libpq 15.2 . I need to work on my setup (https://github.com/r-dbi/docker) to test with different libpq versions.

krlmlr added the bug label Mar 9, 2023

krlmlr added the reprex label Apr 1, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Curious bug with transaction and `dbSendQuery()` #424

Curious bug with transaction and `dbSendQuery()` #424

mgirlich commented Mar 9, 2023

krlmlr commented Mar 9, 2023

krlmlr commented Mar 16, 2023 •

edited

mgirlich commented Mar 16, 2023

krlmlr commented Apr 1, 2024

mgirlich commented Apr 3, 2024

krlmlr commented Apr 13, 2024

Curious bug with transaction and dbSendQuery() #424

Curious bug with transaction and dbSendQuery() #424

Comments

mgirlich commented Mar 9, 2023

krlmlr commented Mar 9, 2023

krlmlr commented Mar 16, 2023 • edited

mgirlich commented Mar 16, 2023

krlmlr commented Apr 1, 2024

mgirlich commented Apr 3, 2024

krlmlr commented Apr 13, 2024

Curious bug with transaction and `dbSendQuery()` #424

Curious bug with transaction and `dbSendQuery()` #424

krlmlr commented Mar 16, 2023 •

edited