Stdout and stderr are not in chronological order when redirected to the same file.
wlandau opened this issue · 3 comments
wlandau commented
When I start an R process and set stdout and stderr to the same file path, the ordering of text in the output is counterintuitive. The stderr stream appears first, then part of the R startup message (with part of the first line missing), and then stdout. There's also something happening in the last couple lines that I do not understand. All this happens even if writing to stderr is the last thing the task does. Is this expected under normal circumstances?
log <- tempfile()
handle <- processx::process$new(
command = file.path(R.home("bin"), "R"),
args = c("-e", "print(\"this-print\"); message(\"this-message\")"),
cleanup = TRUE,
stdout = log,
stderr = log
)
while (is.null(handle$get_exit_status())) {
Sys.sleep(0.1)
}
writeLines(readLines(log))
#> this-message
#> 3.2 (2023-10-31) -- "Eye Holes"
#> Copyright (C) 2023 The R Foundation for Statistical Computing
#> Platform: aarch64-apple-darwin20 (64-bit)
#>
#> R is free software and comes with ABSOLUTELY NO WARRANTY.
#> You are welcome to redistribute it under certain conditions.
#> Type 'license()' or 'licence()' for distribution details.
#>
#> Natural language support but running in an English locale
#>
#> R is a collaborative project with many contributors.
#> Type 'contributors()' for more information and
#> 'citation()' on how to cite R or R packages in publications.
#>
#> Type 'demo()' for some demos, 'help()' for on-line help, or
#> 'help.start()' for an HTML browser interface to help.
#> Type 'q()' to quit R.
#>
#> > print("this-print"); message("this-message")
#> [1] "this-print"
#> >
#> >Created on 2024-01-04 with reprex v2.0.2
I would prefer to see:
#> R version 4.3.2 (2023-10-31) -- "Eye Holes"
#> Copyright (C) 2023 The R Foundation for Statistical Computing
#> Platform: aarch64-apple-darwin20 (64-bit)
#>
#> R is free software and comes with ABSOLUTELY NO WARRANTY.
#> You are welcome to redistribute it under certain conditions.
#> Type 'license()' or 'licence()' for distribution details.
#>
#> Natural language support but running in an English locale
#>
#> R is a collaborative project with many contributors.
#> Type 'contributors()' for more information and
#> 'citation()' on how to cite R or R packages in publications.
#>
#> Type 'demo()' for some demos, 'help()' for on-line help, or
#> 'help.start()' for an HTML browser interface to help.
#> Type 'q()' to quit R.
#>
#> > print("this-print"); message("this-message")
#> [1] "this-print"
#> this-messageIs there a way to make the output lines respect chronological order when redirecting to the same log file in processx?
wlandau commented
Oddly enough, callr prints the streams in the order I would expect. However, I would still prefer to use processx without callr for my purposes.
log <- tempfile()
callr::r(
\() {
print("this-print")
message("this-message")
},
cmdargs = character(0L),
cleanup = TRUE,
stdout = log,
stderr = log
)
#> NULL
writeLines(readLines(log))
#>
#> R version 4.3.2 (2023-10-31) -- "Eye Holes"
#> Copyright (C) 2023 The R Foundation for Statistical Computing
#> Platform: aarch64-apple-darwin20 (64-bit)
#>
#> R is free software and comes with ABSOLUTELY NO WARRANTY.
#> You are welcome to redistribute it under certain conditions.
#> Type 'license()' or 'licence()' for distribution details.
#>
#> Natural language support but running in an English locale
#>
#> R is a collaborative project with many contributors.
#> Type 'contributors()' for more information and
#> 'citation()' on how to cite R or R packages in publications.
#>
#> Type 'demo()' for some demos, 'help()' for on-line help, or
#> 'help.start()' for an HTML browser interface to help.
#> Type 'q()' to quit R.
#>
#> > {
#> + tryCatch(withCallingHandlers({
#> + NULL
#> + saveRDS(do.call(do.call, c(readRDS("/var/folders/4v/vh7xp8553lsbl49svl48g7p00000gp/T//Rtmp8fEOYH/callr-fun-da9e9c611aa"),
#> + list(envir = .GlobalEnv, quote = TRUE)), envir = .GlobalEnv,
#> + quote = TRUE), file = "/var/folders/4v/vh7xp8553lsbl49svl48g7p00000gp/T//Rtmp8fEOYH/callr-res-da9e2ab1b4e9",
#> + compress = FALSE)
#> + flush(stdout())
#> + flush(stderr())
#> + NULL
#> + invisible()
#> + }, error = function(e) {
#> + {
#> + callr_data <- as.environment("tools:callr")$`__callr_data__`
#> + err <- callr_data$err
#> + if (FALSE) {
#> + assign(".Traceback", .traceback(4), envir = callr_data)
#> + dump.frames("__callr_dump__")
#> + assign(".Last.dump", .GlobalEnv$`__callr_dump__`,
#> + envir = callr_data)
#> + rm("__callr_dump__", envir = .GlobalEnv)
#> + }
#> + e <- err$process_call(e)
#> + e2 <- err$new_error("error in callr subprocess")
#> + class(e2) <- c("callr_remote_error", class(e2))
#> + e2 <- err$add_trace_back(e2)
#> + cut <- which(e2$trace$scope == "global")[1]
#> + if (!is.na(cut)) {
#> + e2$trace <- e2$trace[-(1:cut), ]
#> + }
#> + saveRDS(list("error", e2, e), file = paste0("/var/folders/4v/vh7xp8553lsbl49svl48g7p00000gp/T//Rtmp8fEOYH/callr-res-da9e2ab1b4e9",
#> + ".error"))
#> + }
#> + }, interrupt = function(e) {
#> + {
#> + callr_data <- as.environment("tools:callr")$`__callr_data__`
#> + err <- callr_data$err
#> + if (FALSE) {
#> + assign(".Traceback", .traceback(4), envir = callr_data)
#> + dump.frames("__callr_dump__")
#> + assign(".Last.dump", .GlobalEnv$`__callr_dump__`,
#> + envir = callr_data)
#> + rm("__callr_dump__", envir = .GlobalEnv)
#> + }
#> + e <- err$process_call(e)
#> + e2 <- err$new_error("error in callr subprocess")
#> + class(e2) <- c("callr_remote_error", class(e2))
#> + e2 <- err$add_trace_back(e2)
#> + cut <- which(e2$trace$scope == "global")[1]
#> + if (!is.na(cut)) {
#> + e2$trace <- e2$trace[-(1:cut), ]
#> + }
#> + saveRDS(list("error", e2, e), file = paste0("/var/folders/4v/vh7xp8553lsbl49svl48g7p00000gp/T//Rtmp8fEOYH/callr-res-da9e2ab1b4e9",
#> + ".error"))
#> + }
#> + }, callr_message = function(e) {
#> + try(signalCondition(e))
#> + }), error = function(e) {
#> + NULL
#> + if (TRUE) {
#> + try(stop(e))
#> + }
#> + else {
#> + invisible()
#> + }
#> + }, interrupt = function(e) {
#> + NULL
#> + if (TRUE) {
#> + e
#> + }
#> + else {
#> + invisible()
#> + }
#> + })
#> + }
#> [1] "this-print"
#> this-message
#> >Created on 2024-01-04 with reprex v2.0.2
gaborcsardi commented
This seems like a bug to me, but a better way to collect stdout and stderr together is stderr = "2>&1", see the docs.
log <- tempfile()
handle <- processx::process$new(
command = file.path(R.home("bin"), "R"),
args = c("-q", "-e", "print(\"this-print\"); message(\"this-message\")"),
cleanup = TRUE,
stdout = log,
stderr = "2>&1"
)
handle$wait()
writeLines(readLines(log))> print("this-print"); message("this-message")
[1] "this-print"
this-message
wlandau commented
Awesome, works for me. Thanks!