Wrong starttime when multiple process of the same program

[Yunuuuu]

    old1 <- processx::process$new("ping", "localhost")
    old2 <- processx::process$new("ping", "localhost")
    old3 <- processx::process$new("ping", "localhost")
    old4 <- processx::process$new("ping", "localhost")
# run following command multiple times, sometimes it will stop quickly (less than 4 seconds)
# I checked the starttime (by defining a new `process` R6 object, and define `private$starttime2 <- Sys.time()`) and 
# found it may be much smaller than the actual `starttime2`. 
# The elapsed time calculated by `system.time` is much smaller than the defined `timeout`.
    system.time(processx::run("ping", "localhost",
        echo_cmd = TRUE, echo = TRUE,
        timeout = 4,
        error_on_status = FALSE
    ))
    old1$kill_tree()
    old1$kill()
    old2$kill_tree()
    old2$kill()
    old3$kill_tree()
    old3$kill()
    old4$kill_tree()
    old4$kill()

Sometimes, it will stop immediately:

sessioninfo::session_info()
#> ─ Session info ───────────────────────────────────────────────────────────────
#>  setting  value
#>  version  R version 4.4.2 (2024-10-31)
#>  os       Ubuntu 24.04.1 LTS
#>  system   x86_64, linux-gnu
#>  ui       X11
#>  language en
#>  collate  C.UTF-8
#>  ctype    C.UTF-8
#>  tz       Asia/Shanghai
#>  date     2025-03-29
#>  pandoc   3.1.3 @ /usr/bin/ (via rmarkdown)
#> 
#> ─ Packages ───────────────────────────────────────────────────────────────────
#>  package     * version date (UTC) lib source
#>  cli           3.6.3   2024-06-21 [1] CRAN (R 4.4.0)
#>  digest        0.6.37  2024-08-19 [1] CRAN (R 4.4.2)
#>  evaluate      1.0.1   2024-10-10 [1] CRAN (R 4.4.2)
#>  fastmap       1.2.0   2024-05-15 [1] CRAN (R 4.4.0)
#>  fs            1.6.5   2024-10-30 [1] CRAN (R 4.4.2)
#>  glue          1.8.0   2024-09-30 [1] CRAN (R 4.4.2)
#>  htmltools     0.5.8.1 2024-04-04 [1] CRAN (R 4.4.0)
#>  knitr         1.49    2024-11-08 [1] CRAN (R 4.4.2)
#>  lifecycle     1.0.4   2023-11-07 [1] CRAN (R 4.4.0)
#>  magrittr      2.0.3   2022-03-30 [1] CRAN (R 4.4.0)
#>  processx      3.8.6   2025-02-21 [1] CRAN (R 4.4.2)
#>  ps            1.8.1   2024-10-28 [1] CRAN (R 4.4.2)
#>  purrr         1.0.2   2023-08-10 [1] CRAN (R 4.4.0)
#>  R.cache       0.16.0  2022-07-21 [1] CRAN (R 4.4.0)
#>  R.methodsS3   1.8.2   2022-06-13 [1] CRAN (R 4.4.0)
#>  R.oo          1.26.0  2024-01-24 [1] CRAN (R 4.4.0)
#>  R.utils       2.12.3  2023-11-18 [1] CRAN (R 4.4.0)
#>  R6            2.5.1   2021-08-19 [1] CRAN (R 4.4.0)
#>  reprex        2.1.0   2024-01-11 [1] CRAN (R 4.4.0)
#>  rlang         1.1.4   2024-06-04 [1] CRAN (R 4.4.0)
#>  rmarkdown     2.29    2024-11-04 [1] CRAN (R 4.4.2)
#>  sessioninfo   1.2.2   2021-12-06 [1] CRAN (R 4.4.0)
#>  styler        1.10.3  2024-04-07 [1] CRAN (R 4.4.0)
#>  vctrs         0.6.5   2023-12-01 [1] CRAN (R 4.4.0)
#>  withr         3.0.2   2024-10-28 [1] CRAN (R 4.4.2)
#>  xfun          0.49    2024-10-31 [1] CRAN (R 4.4.2)
#>  yaml          2.3.10  2024-07-26 [1] CRAN (R 4.4.2)
#> 
#>  [1] /home/yun/Rlibrary/4.4
#>  [2] /usr/local/lib/R/site-library
#>  [3] /usr/lib/R/site-library
#>  [4] /usr/lib/R/library
#> 
#> ──────────────────────────────────────────────────────────────────────────────

[Yunuuuu]

After several times of test, I can make following reprex (the last two process is much smaller than the timeout):

old1 <- processx::process$new("ping", "localhost")
system.time(processx::run("ping", "localhost",
    echo_cmd = TRUE, echo = TRUE,
    timeout = 4,
    error_on_status = FALSE
))
#> Running ping localhost
#> PING localhost (127.0.0.1) 56(84) bytes of data.
#> 64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.014 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=2 ttl=64 time=0.030 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=3 ttl=64 time=0.037 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=4 ttl=64 time=0.014 ms
#>    user  system elapsed 
#>   0.015   0.000   3.925
old2 <- processx::process$new("ping", "localhost")
system.time(processx::run("ping", "localhost",
    echo_cmd = TRUE, echo = TRUE,
    timeout = 4,
    error_on_status = FALSE
))
#> Running ping localhost
#> PING localhost (127.0.0.1) 56(84) bytes of data.
#> 64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.013 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=2 ttl=64 time=0.034 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=3 ttl=64 time=0.031 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=4 ttl=64 time=0.017 ms
#>    user  system elapsed 
#>   0.011   0.001   5.953
old3 <- processx::process$new("ping", "localhost")
system.time(processx::run("ping", "localhost",
    echo_cmd = TRUE, echo = TRUE,
    timeout = 4,
    error_on_status = FALSE
))
#> Running ping localhost
#> PING localhost (127.0.0.1) 56(84) bytes of data.
#> 64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.014 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=2 ttl=64 time=0.040 ms
#>    user  system elapsed 
#>   0.011   0.000   1.890
old4 <- processx::process$new("ping", "localhost")
system.time(processx::run("ping", "localhost",
    echo_cmd = TRUE, echo = TRUE,
    timeout = 4,
    error_on_status = FALSE
))
#> Running ping localhost
#> PING localhost (127.0.0.1) 56(84) bytes of data.
#> 64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.014 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=2 ttl=64 time=0.032 ms
#>    user  system elapsed 
#>   0.002   0.007   1.894
old1$kill_tree()
#> named integer(0)
old1$kill()
#> [1] TRUE
old2$kill_tree()
#> named integer(0)
old2$kill()
#> [1] TRUE
old3$kill_tree()
#> named integer(0)
old3$kill()
#> [1] TRUE
old4$kill_tree()
#> named integer(0)
old4$kill()
#> [1] TRUE

^{Created on 2025-03-29 with reprex v2.1.0}

Session info

sessioninfo::session_info()
#> ─ Session info ───────────────────────────────────────────────────────────────
#>  setting  value
#>  version  R version 4.4.2 (2024-10-31)
#>  os       Ubuntu 24.04.1 LTS
#>  system   x86_64, linux-gnu
#>  ui       X11
#>  language en
#>  collate  C.UTF-8
#>  ctype    C.UTF-8
#>  tz       Asia/Shanghai
#>  date     2025-03-29
#>  pandoc   3.1.3 @ /usr/bin/ (via rmarkdown)
#> 
#> ─ Packages ───────────────────────────────────────────────────────────────────
#>  package     * version date (UTC) lib source
#>  cli           3.6.3   2024-06-21 [1] CRAN (R 4.4.0)
#>  digest        0.6.37  2024-08-19 [1] CRAN (R 4.4.2)
#>  evaluate      1.0.1   2024-10-10 [1] CRAN (R 4.4.2)
#>  fastmap       1.2.0   2024-05-15 [1] CRAN (R 4.4.0)
#>  fs            1.6.5   2024-10-30 [1] CRAN (R 4.4.2)
#>  glue          1.8.0   2024-09-30 [1] CRAN (R 4.4.2)
#>  htmltools     0.5.8.1 2024-04-04 [1] CRAN (R 4.4.0)
#>  knitr         1.49    2024-11-08 [1] CRAN (R 4.4.2)
#>  lifecycle     1.0.4   2023-11-07 [1] CRAN (R 4.4.0)
#>  magrittr      2.0.3   2022-03-30 [1] CRAN (R 4.4.0)
#>  processx      3.8.6   2025-02-21 [1] CRAN (R 4.4.2)
#>  ps            1.8.1   2024-10-28 [1] CRAN (R 4.4.2)
#>  purrr         1.0.2   2023-08-10 [1] CRAN (R 4.4.0)
#>  R.cache       0.16.0  2022-07-21 [1] CRAN (R 4.4.0)
#>  R.methodsS3   1.8.2   2022-06-13 [1] CRAN (R 4.4.0)
#>  R.oo          1.26.0  2024-01-24 [1] CRAN (R 4.4.0)
#>  R.utils       2.12.3  2023-11-18 [1] CRAN (R 4.4.0)
#>  R6            2.5.1   2021-08-19 [1] CRAN (R 4.4.0)
#>  reprex        2.1.0   2024-01-11 [1] CRAN (R 4.4.0)
#>  rlang         1.1.4   2024-06-04 [1] CRAN (R 4.4.0)
#>  rmarkdown     2.29    2024-11-04 [1] CRAN (R 4.4.2)
#>  sessioninfo   1.2.2   2021-12-06 [1] CRAN (R 4.4.0)
#>  styler        1.10.3  2024-04-07 [1] CRAN (R 4.4.0)
#>  vctrs         0.6.5   2023-12-01 [1] CRAN (R 4.4.0)
#>  withr         3.0.2   2024-10-28 [1] CRAN (R 4.4.2)
#>  xfun          0.49    2024-10-31 [1] CRAN (R 4.4.2)
#>  yaml          2.3.10  2024-07-26 [1] CRAN (R 4.4.2)
#> 
#>  [1] /home/yun/Rlibrary/4.4
#>  [2] /usr/local/lib/R/site-library
#>  [3] /usr/lib/R/site-library
#>  [4] /usr/lib/R/library
#> 
#> ──────────────────────────────────────────────────────────────────────────────

[gaborcsardi]

I cannot reproduce this. What is the actual output from the ping process that quits early? What's its exit status?

[Yunuuuu]

The actual output from the ping process terminates prematurely, showing significantly fewer lines than usual (expected duration: 4 seconds). The exit status is -9 which indicates a timeout:

#> PING localhost (127.0.0.1) 56(84) bytes of data.
#> 64 bytes from localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.014 ms
#> 64 bytes from localhost (127.0.0.1): icmp_seq=2 ttl=64 time=0.032 ms

The following code helps clarify the issue:

• The recorded start time (proc$get_start_time()) from processx is expected to be later than mystart, meaning proc$get_start_time() > mystart.
• However, the observed behavior shows the opposite inequality (proc$get_start_time() < mystart), and the discrepancy can be significant.

I use lubridate to make sure the display of the time is in the same timezone.

process_list <- vector("list")
while (TRUE) {
    # this time should be early than the `$get_start_time()`
    mystart <- lubridate::with_tz(Sys.time())
    proc <- processx::process$new("ping", "localhost")
    process_list <- c(process_list, list(proc))
    recorded <- lubridate::with_tz(proc$get_start_time())
    if (recorded < mystart &&
        (mystart - recorded) > as.difftime(2, units = "secs")) {
        cli::cli_inform("My recorded starttime @ [{mystart}]")
        cli::cli_inform("`processx` Recorded starttime @ [{recorded}]")
        print(mystart - recorded)
        break
    }
    if (length(process_list) > 100L) break
}
invisible(lapply(process_list, function(proc) {
    proc$kill_tree()
    proc$kill()
}))

I can't consistently reproduce a large difference (≥2 seconds) using reprex. However, I can reproduce the incorrect inequality (proc$get_start_time() < mystart) without enforcing a difference greater than 2 seconds in reprex.

process_list <- vector("list")
while (TRUE) {
    mystart <- lubridate::with_tz(Sys.time())
    proc <- processx::process$new("ping", "localhost")
    process_list <- c(process_list, list(proc))
    recorded <- lubridate::with_tz(proc$get_start_time())
    if (recorded < mystart) {
        cli::cli_inform("My recorded starttime @ [{mystart}]")
        cli::cli_inform("`processx` Recorded starttime @ [{recorded}]")
        print(mystart - recorded)
        break
    }
    if (length(process_list) > 100L) break
}
#> My recorded starttime @ [2025-03-29 08:07:50.749146]
#> `processx` Recorded starttime @ [2025-03-29 08:07:50.39]
#> Time difference of 0.3591464 secs
invisible(lapply(process_list, function(proc) {
    proc$kill_tree()
    proc$kill()
}))

^{Created on 2025-03-29 with reprex v2.1.0}

The probability of this issue occurring is low, so it may require multiple runs to observe the behavior

[gaborcsardi]

I ran this 300 times in a loop, and could not reproduce it. This was on aarch64 Linux, though. I'll try x86_64 Linux later.

Possibly the start time query is just buggy.

[Yunuuuu]

Thanks for testing it! It does seem tricky to reproduce consistently. For now, I’m using a temporary fix by creating a new child class of process:

Process <- R6Class(
    "Process",
    inherit = processx::process,
    public = list(
        initialize = function(...) {
            super$initialize(...)

            # workaround for https://github.com/r-lib/processx/issues/394
            private$starttime <- Sys.time()
        }
    )
)