R: newlines have gone missing in messages

[jennybc]

I'm noticing a lack of newlines in messages in R. I haven't done a thorough study, but it's definitely affecting cli-emitted messages, e.g.:

> devtools::document()
ℹ Updating reprex documentationℹ Loading reprex

which should instead be like this:

> devtools::document()
ℹ Updating reprex documentation
ℹ Loading reprex

Presumably related to some loose ends in posit-dev/ark@fc13102. The output above corresponds to:

> .ps.ark.version()
                                      branch 
                                      "main" 
                                      commit 
                                   "51f0b51" 
                                        date 
                   "2023-11-22 13:48:25 PST" 
                                      flavor 
                                     "debug" 
                                        path 
"/Users/jenny/rrr/amalthea/target/debug/ark" 
                                     version 
                                    "0.1.25" 

[lionel-]

The appendLF argument of message() is TRUE by default so you get:

conditionMessage(rlang::catch_cnd(message("foo")))
#> [1] "foo\n"

Compare to warnings:

conditionMessage(rlang::catch_cnd(warning("foo")))
#> [1] "foo"

That said it all happens within base::message() and is only visible if you capture the message condition. Other message emitters need not necessarily reproduce this behaviour, but then when we capture arbitrary messages we have an ambiguity as to whether a message has an implicit trailing newline (as in warnings and errors) or not (because message() has explicit control of trailing newlines).

But that's not a big deal, I'll just add a newline if there isn't one already. We'll lose support for constructing messages piece by piece, i.e. like:

message("Hello", appendLF = FALSE)
message("there", appendLF = TRUE)

But that's a rather esoteric feature.

[lionel-]

Addressed by posit-dev/ark@da5fe14

[jennybc]

Yes, ark 0.1.27, which includes the commit linked above, fixes this behaviour for me. Should we close this or wait to experience the fix in a release build? Seems possibly unnecessary because I'm not sure the problem ever made it into a release build (of Positron) either, i.e. Positron just skipped over ark 0.1.26 entirely.

721d40d

[lionel-]

In the meantime a new build was released, so we can close this.

[softwarenerd]

I've reopened this issue because the fix for it, posit-dev/ark@da5fe14, caused a significant regression, #1919, in the Console.

Basically, the regression is this:

If you try to execute pak::pak("tidymodels/tune") in R, instead of seeing:

> pak::pak("tidymodels/tune")

→ Will install 1 package.
→ Will download 1 package with unknown size.
+ tune   1.1.2.9004 👷🏾🔧 ⬇ (GitHub: 3aa7075)
ℹ Getting 1 pkg with unknown size
✔ Cached copy of tune 1.1.2.9004 (source) is the latest build
✔ No downloads needed, all packages are cached ??s  | Connecting...
✔ Installed tune 1.1.2.9004 (github::tidymodels/tune@3aa7075) (18ms)
✔ 1 pkg + 81 deps: kept 71, added 1 [1.1s]2 ⠴ 1 | installing tune

You will see something like:

> pak::pak("tidymodels/tune")

 Found  1  deps for  0/1  pkgs [⠋] Resolving tidymodels/tune
 Found  1  deps for  0/1  pkgs [⠙] Resolving tidymodels/tune
 Found  23  deps for  1/1  pkgs [⠹] Resolving tidymodels/yardstick
 Found  171  deps for  1/1  pkgs [⠸] Resolving tidymodels/yardstick
 Found  172  deps for  1/1  pkgs [⠼] Checking installed packages   
                                                                
 
→ Will install 1 package.
→ Will download 1 package with unknown size.
+ tune   1.1.2.9004 👷🏼‍♀️🔧 ⬇ (GitHub: 3aa7075)
ℹ Getting 1 pkg with unknown size


✔ Cached copy of tune 1.1.2.9004 (source) is the latest build


✔ No downloads needed, all packages are cached
Installing...
⸨████████████▒⸩ | 📦  82/82     | ✅  81/82     | 
⸨████████████▒⸩ | 📦  82/82     | ✅  81/82 ⠸ 1 | installing tune
                                                                 
✔ Installed tune 1.1.2.9004 (github::tidymodels/tune@3aa7075) (18ms)
⸨████████████▒⸩ | 📦  82/82     | ✅  81/82 ⠸ 1 | installing tune
⸨████████████▒⸩ | 📦  82/82     | ✅  81/82 ⠴ 1 | installing tune
                                                                 
✔ 1 pkg + 81 deps: kept 71, added 1 [1.2s]

Which is all kinds of messed up.

This is being caused by the fact that progress output like this is done using a CR (and / or ANSI escape sequences) to set the cursor position back to 0 so that the next line of progress output overwrites the previous line. For example, a progress output stream might look something like:

Downloading package 1         [CR]
Downloading package 2         [CR]
Downloading package 3         [CR]
Downloading package 4         [CR]
...
Downloading package 64        [CR]
                                                                                              [CR]
All packages downloaded[CR][LF]

Which results in a final output of one line in the Console:

All packages downloaded

So, the fix in posit-dev/ark@da5fe14 causes these line erasures to fail resulting in output that shouldn't be visible once the progress output is compete because it is inserting LFs where there should just be CRs.

[lionel-]

See r-lib/rlang#1677 which I've just opened for context. Base and rlang messages behave differently regarding the inclusion of an explicit trailing line feed, which causes an ambiguity when handling both kinds of messages externally (in this case with our global handler that captures messages and redirect them to stdout).

[lionel-]

posit-dev/ark@50d3cf5

[juliasilge]

In Positron 2023.12.0 (Universal) build 1623 we see the correct behavior again:

pak.mov

Just to reiterate once more, we have identified this kind of interaction (user types something in Console, we go all the way back to a real runtime to get output, then Console displays output) as important to get under automated testing at some level so we know when there is a regression, at the least with a nightly test run (if it's not possible to run every smoke test on every PR).