Incorrect output order with cat and message in Debug Console

[bersbersbers]

Describe the bug Output from cat and message is shown out of order. Here's an extreme example:

To Reproduce Steps to reproduce the behavior:

1. Debug the code below.

Your R code

while (TRUE) {
    cat("> ")
    message("Something")
    # Sys.sleep(0.1) # play around with this to separate lines from each other
}

Note that the code works fine here:

Rscript bug.R | grep -v "> Something"

Flushing does not help:

while (TRUE) {
    cat("> ")
    flush.console()
    message("Something")
    flush.console()
}

The same does not happen when replacing cat(...) by message(..., appendLF = FALSE), which I am now doing. So this is mostly an fyi.

[ManuelHentschel]

Thanks for the info! Does this happen on your local machine or over a network connection?

Either way, this would be rather hard to fix, since stdin and stderr are transmitted through different connections, which cannot (easily) be forced to be in sync.

Does this also happen if you replace cat("> ") with cat("> ", file=stderr())?

[bersbersbers]

That's over a network connection - I haven't tried locally.

It does not seem to happen with cat("> ", file=stderr()).

Although, now that you remind me, my .Rprofile has this:

.stderr_message <- message
message <- function(...) {
    sink(stdout(), type = "message")
    .stderr_message(...)
    sink(NULL, type = "message")
}

and the problem reproduces only with this code in .Rprofile - not even when it's in the code, in which case it is ineffective.

[ManuelHentschel]

This is a bit of a complicated topic, so here's a small summary of how the R session and the vscode extension communicate:

• The extension launches an R process in the background and reads its stdout
• and stderr.
• The R package calls sink(SOME_SOCKET_CONNECTION) to redirect all "normal" output to stdout through a different pipe. This does not include the input prompt, which makes it easier to identify when the prompt shows up.
• The R package establishes a socket connection with the extension through which it sends DAP-messages.

These different connections are not guaranteed to be sent/received in the correct order, but usually are on a local machine.

By default, the R package overwrites cat, print, and message with custom functions that do not print to stdout/stderr but instead send a DAP-message containing the content, info about the line of code that produced it, and how to display it (stdout vs stderr). So these should be in sync, even when working over a network.

If you remove your message function, the overwrites should keep everything that is produced by these three functions in the correct order. Other methods of printing output (e.g. by direcctly calling base::print) are not affected by this and might still be out of order.

You can also disable these overwrites by setting overwritePrint, overwriteMessage, and overwriteCat to false in your debug config.

[bersbersbers]

Thanks for that explanation! Once I had found my message function, I also found that you mention explicitly that sink() is not fully supported (https://manuelhentschel.github.io/vscDebugger/articles/troubleshooting.html). So I can easily live with that.

But I will at least try calling .vsc.message in my custom message function and see if that works ;)

[bersbersbers]

Also, I will try replacing my message function (the idea of which is simply to redirect message to stdout) by this:

message <- function(...) invisible(lapply(list(..., "\n"), cat))

Many, many solutions are possible :)

[ManuelHentschel]

If you are just bothered by the red color you could consider adding sth. like this to your settings.json:

  "workbench.colorCustomizations": {
    "[Default Dark+]": {
      "debugConsole.errorForeground": "#75beff"
    }
  }

This will color all errors blue though, so it's probably a bit too general.

To overwrite only the message function, you could also try copying the body of base::message to your .Rprofile and only replace the line that contains the call to cat. That's what I did in .vsc.message, and replacing the stderr() with stdout() should work as intended.