Skip to content

Restore output capture of R tasks correctly#1065

Merged
lionel- merged 4 commits intomainfrom
bugfix/capture-output
Mar 3, 2026
Merged

Restore output capture of R tasks correctly#1065
lionel- merged 4 commits intomainfrom
bugfix/capture-output

Conversation

@lionel-
Copy link
Contributor

@lionel- lionel- commented Feb 27, 2026

Previously we were only restoring the output capture on Drop, when the idle task was completely finished. If the task yielded with .await and went pending, giving control back to R, the output capture would remain in place! This PR fixes that by restoring the output capture at yield points.

Fixes some test failures I observed in the quiet debugger branch.

And we can now test the R task infra!

     Summary [ 162.183s] 925 tests run: 924 passed, 1 failed, 0 skipped
     FAIL [  11.481s] (702/925) ark::kernel-captured-output
     test_pending_idle_task_does_not_swallow_stdout
     stdout ───

    running 1 test
    test test_pending_idle_task_does_not_swallow_stdout ... FAILED
@lionel- lionel- force-pushed the bugfix/capture-output branch from a8b1a37 to a29838f Compare February 28, 2026 10:25
@lionel-
Copy link
Contributor Author

lionel- commented Feb 28, 2026

This is causing the debugonce failure that tripped up @juliasilge's PR in posit-dev/positron@52dc638

I could only inconsistently reproduce the failure manually, but very consistently when running the test. In the harness, I saw these messages:

r-3580cd08 [R]   2026-02-28T10:44:20.867349Z TRACE  Populated virtual namespace for base: 17294 lines, 1131 ok, 13 bad, 265 skipped
r-3580cd08 [R]     at crates/ark/src/srcref.rs:108
r-3580cd08 [R]     in R task with thread: "main", interrupt: false
r-3580cd08 [R]     in resource_namespaces
r-3580cd08 [R]
r-3580cd08 [R]   2026-02-28T10:44:20.869092Z TRACE  Inserting vdoc for `ark:ark-63428/namespace/base.R`
r-3580cd08 [R]     at crates/ark/src/console.rs:2629
r-3580cd08 [R]     in R task with thread: "main", interrupt: false
r-3580cd08 [R]     in resource_namespaces
r-3580cd08 [R]
r-3580cd08 [R]   2026-02-28T10:44:20.869143Z TRACE  Sending LSP notification: DidOpenVirtualDocument {
r-3580cd08 [R]     uri: "ark-63428/namespace/base.R",
r-3580cd08 [R]     contents: "<snip>",
r-3580cd08 [R] }
r-3580cd08 [R]     at crates/ark/src/console.rs:2572
r-3580cd08 [R]     in R task with thread: "main", interrupt: false
r-3580cd08 [R]     in resource_namespaces
r-3580cd08 [R]
r-44c5140f [R]   2026-02-28T06:45:36.388594Z  INFO  [Captured idle output]
r-44c5140f [R] debugging in: fruit_avg(dat, "berry")
r-44c5140f [R] debug at /var/folders/7y/4vj0crtj06x8gzcv5mv5vxj80000gp/T/vscsmoke/qa-example-content/workspaces/r-debugging/fruit_avg.r#1: {
r-44c5140f [R]     cols <- grep(pattern, names(dat))
r-44c5140f [R]     mini_dat <- dat[, cols]
r-44c5140f [R]     message("Found ", ncol(mini_dat), " fruits!")
r-44c5140f [R]     rowMeans(mini_dat)
r-44c5140f [R] }
r-44c5140f [R] Found 2 fruits!
r-44c5140f [R] exiting from: fruit_avg(dat, "berry")
r-44c5140f [R]  calories    weight yumminess
r-44c5140f [R]       2.5       5.5       7.0
r-44c5140f [R]     at crates/ark/src/console.rs:601
r-44c5140f [R]     in R task with thread: "main", interrupt: false
r-44c5140f [R]     in resource_namespaces
r-44c5140f [R]

Notice the last "INFO [Captured idle output]" message, confirming the namespace population task is swallowing user output.

I've confirmed that with the fix in this PR, the test now passes as expected.

The output capture seen in this log is from
the changes in https://github.com/posit-dev/ark/pull/1037/changes#diff-cf381546ed9955620ca2fea4d03124df0227315437b51858f6c587e83264550d where I've added support for capturing output in idle tasks, such as the ones that evaluate expressions for the Watch Pane.

Why do we only see the E2E test fail only with dev Ark? I'm not entirely sure, but it might have to do with the environment refresh implemented in https://github.com/posit-dev/ark/pull/1052/changes, which triggers a new non-idle task that might shift the event loop just in the right way that the execute request gets picked up while a pending idle task's capture is active.

In any case, the test failure is very consistently reproducible without the fix, and I can't reproduce with it.

Now onto the risks created by this bug. The risk mostly depends on whether the tasks yield or not. If they don't yield, they will complete in one go. If they do, they will become pending while capturing output and if an execute request is picked up at that time the output is swallowed.

Idle tasks are involved in:

  1. Namespace srcref generation when debug() and debugonce() are called. These tasks are long and broken down with regular yields to R.

  2. Data explorer requests to get column profiles. These yield.

  3. Initial Variables pane scan. Happens once and doesn't yield.

  4. Evaluation requests for the Watch Pane. These don't yield.

So I'd say the risk is limited overal. (3) and (4) are fine since the tasks don't yield. For (1), there's a brief window of time after calling debug() where namespace srcrefs are generated and where output can be swallowed. For (2), triggering the bug would require users to evaluate code directly after interacting with the data explorer, which is unlikely.

So I think I'm comfortable with letting the bug slip in the release, although I'd also be happy to get a fix in.

@juliasilge
Copy link
Contributor

We chatted over the weekend and I agree it's OK for the release to go out as is, without this fix.

Thanks for working on this, @lionel-! 🙌

}

#[macro_export]
macro_rules! soft_assert {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why not debug_assert!, like debug_panic!?

they both have the same implication:

  • panic, but only die during debug
  • assert, but only die during debug

Copy link
Contributor Author

@lionel- lionel- Mar 3, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's the name I initially picked, but it conflicts with a macro in the standard library. I thought it's fine to have stdext::debug_assert! as a disambiguator but then ran into complications due to scoping of macro exports at top-level that I don't fully understand.

@lionel- lionel- merged commit ef79b7a into main Mar 3, 2026
8 checks passed
@lionel- lionel- deleted the bugfix/capture-output branch March 3, 2026 11:25
@github-actions github-actions bot locked and limited conversation to collaborators Mar 3, 2026
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants