Possible bug: future_promise() reports each error twice, onRejected only handles one

[chris31415926535]

Thanks for this awesome package! I'm trying to get promise error handling to work with future_promise(), but it reports each error twice. With onReject only one error is printed to console and the error catching seems to work okay, but it's confusing for the user (and there may be other issues I'm not seeing). Here's a minimal example showing the behaviour on my machine:

library(magrittr)
library(future)
library(promises)

future::plan(future::multisession)

test <- promises::future_promise( stop("An intentional error.") ) 

Which gives this output showing two identical unhandled errors:

Unhandled promise error: An intentional error.
Unhandled promise error: An intentional error.

Here's an example with error handling following the code this vignette, along with the results on my machine. Note that it still throws one error to the console:

test_handled <- future_promise( stop("An intentional error.") ) %>%
  then(onRejected = function(err) {
    warning("An error occurred: ", err)
    warning("Using default value of 0 instead")
    0
  }
  )

Which gives this output still showing one unhandled error:

Unhandled promise error: An intentional error.

And if I print test_handled to the console, I get what I think is the expected result of the warning output and the fulfilled promise:

test_handled

Output:

<Promise [fulfilled: numeric]>
Warning messages:
1: In onRejected(reason) :
  An error occurred: Error in withCallingHandlers({: An intentional error.

2: In onRejected(reason) : Using default value of 0 instead

Am I making an obvious user mistake, or missing some setup? Naively, I'd think the expected behaviour is to not report a handled error, or at least not to report it as an unhandled error.

Session Info:

> sessionInfo()
R version 4.1.2 (2021-11-01)
Platform: x86_64-pc-linux-gnu (64-bit)
Running under: Ubuntu 20.04.3 LTS

Matrix products: default
BLAS:   /usr/lib/x86_64-linux-gnu/blas/libblas.so.3.9.0
LAPACK: /usr/lib/x86_64-linux-gnu/lapack/liblapack.so.3.9.0

locale:
 [1] LC_CTYPE=C.UTF-8       LC_NUMERIC=C           LC_TIME=C.UTF-8        LC_COLLATE=C.UTF-8     LC_MONETARY=C.UTF-8    LC_MESSAGES=C.UTF-8   
 [7] LC_PAPER=C.UTF-8       LC_NAME=C              LC_ADDRESS=C           LC_TELEPHONE=C         LC_MEASUREMENT=C.UTF-8 LC_IDENTIFICATION=C   

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base     

other attached packages:
[1] promises_1.2.0.1 future_1.28.0    magrittr_2.0.3  

loaded via a namespace (and not attached):
 [1] Rcpp_1.0.9        codetools_0.2-18  listenv_0.8.0     digest_0.6.29     later_1.3.0       parallelly_1.32.1 R6_2.5.1         
 [8] rlang_1.0.5       cli_3.4.0         logdriver_0.1.0   rstudioapi_0.14   tools_4.1.2       parallel_4.1.2    fastmap_1.1.0    
[15] compiler_4.1.2    globals_0.16.1 

[jcheng5]

Hmmm, weird. And it gets weirder:

library(magrittr)
library(promises)

p1 <- promise(~{ reject("boom1") }) %...!% {}
p2 <- promise(~{ reject("boom2") }) %>% then(onRejected = ~{})
p3 <- promise(~{ reject("boom3") })$then(onRejected = ~{})

library(future)
plan(multisession)

p4 <- future_promise(stop("boom4")) %...!% {}
p5 <- future_promise(stop("boom5")) %>% then(onRejected = ~{})
p6 <- future_promise(stop("boom6"))$then(onRejected = ~{})

I wouldn't expect any of these to report an unhandled promise error, but p3, p4, and p5 do, while p6 does twice.

Update 2023-02-07: p3 reports because the then method does not convert formulas to functions, but instead, silently ignores anything that's not a function. (I copied that from JavaScript but probably better to warn or error if not a function or NULL.) So it's only future_promise that has the problem.

[jcheng5]

And if I print test_handled to the console, I get what I think is the expected result of the warning output and the fulfilled promise:

That is sort of expected, consider using message() instead.

warning() doesn't work very well from within promise handlers; by default, R wants to batch up all the warning() calls and report them all after the current console command is done executing. The problem is, promise handlers run during the random in-between times, when the console isn't executing a command, so warnings() get batched up but not reported until the next console command is done executing. (See the warn option under ?options)

[chris31415926535]

That is weird! And duly noted about using message() instead.

Importantly, future_promise() does seem to handle the error with onRejected, even if it prints a message to the contrary. This very silly Shiny example has three buttons: one for an unhandled synchronous error, one for an unhandled future_promise() error, and one for a handled future_promise() error. The first two buttons halt the app, but the third doesn't: the app keeps working, prints the expected message to the console, and then also gives the output about an unhandled promise error.

library(shiny)
library(future)
library(promises)

ui <- fluidPage(
  actionButton(inputId = "sync_unhandled_error", label = "Synchronous Unhandled Error"),
  actionButton(inputId = "async_unhandled_error", label = "Asynchronous Unhandled Error (future_promise)"),
  actionButton(inputId = "async_handled_error", label = "Asynchronous Handled Error (future_promise)"),
)

server <- function(input, output, session) {

  observeEvent(input$sync_unhandled_error, {
    stop( "A synchronous unhandled error." )
  })  

  observeEvent(input$async_unhandled_error, {
    promises::future_promise( stop( "An asynchronous unhandled error." ) )
  })  

  observeEvent(input$async_handled_error, {
    promises::future_promise( stop( "An asynchronous handled error." ) ) %>%
      then(onRejected = function(err) {
        message("An error occurred, but we handled it: ", err)
      }) 
  }) 

}

shinyApp(ui, server)

[chris31415926535]

Update: I've taken a look at the promises code and done some basic print debugging. When I trigger a future_promise() error the internal function private$doRejectFinalReason is called three times, although it seems (both from the name and the code) like it should only be called once. In addition, the first two times it's called the internal value private$rejectionHandled starts with value FALSE, even if I manually set it to TRUE at the end of the function. This is mysterious because there's no command setting it back to FALSE, which makes me wonder if it's related to part of the function wrapped in then::then() .

I'm very new to this codebase, but I wonder if this could be a combination of two things:

1. private$doReject can be called in a few different places, and if it is then it may call private$doRejectFinalReason more than once; and,
2. The use of then::then() inside of private$doRejectFinalReason, which means that if private$doRejectFinalReason is being called more than once, the previous iteration hasn't updated private$rejectionHandled before the new iteration is called.

Just a guess though. Hope this is useful for someone more knowledgeable :)

[r2evans]

@chris31415926535 any progress or resolution with this?

[r2evans]

@jcheng5 this bug is more than cosmetic, I believe it is causing "worker-leakage" requiring manual intervention.

library(future)
library(promises)
plan(multicore, workers = 3)

Sys.getpid()
# [1] 1270066
nbrOfFreeWorkers()
# [1] 3

thisproc <- promises::future_promise({
  setTimeLimit(elapsed = 2, transient = TRUE)
  Sys.sleep(3)
  1L
}, seed = TRUE) %>%
  promises::then(
    function(val) {
      message("survived: ", val)
      val
    }) %>%
  catch(
    function(error) {
      message("terminated: ", substring(conditionMessage(error), 1, 16))
      NULL
    })
# terminated: Unexpected resul
# Unhandled promise error: Unexpected result (of class ‘NULL’ != ‘FutureResult’) retrieved for MulticoreFuture future (label = ‘<none>’, expression = ‘{; setTimeLimit(elapsed = 2, transient \
# = TRUE); Sys.sleep(3); 1L; }’):

nbrOfFreeWorkers()
# [1] 2
resetWorkers(plan())
# NULL
nbrOfFreeWorkers()
# [1] 3

See https://stackoverflow.com/questions/75354879/why-future-promise-error-is-unhandled-with-onrejected.

Linux, R-4.2.2, future-1.30.0, promises-1.2.0.1, later-1.3.0.

[jcheng5]

@schloerke Maybe one for us to look at together next week?

[r2evans]

This is related to a bug in future that I've been discussing, https://github.com/HenrikBengtsson/future/discussions/676. I have been testing his develop branch and it still occasionally runs out of workers, but I'm not certain that is due to a bug or just a long long queue in promises that I somehow over-filled. I'm working on that component ...