Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Try to write the panic message with a single write_all call #122565

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

Zoxc
Copy link
Contributor

@Zoxc Zoxc commented Mar 15, 2024

This writes the panic message to a buffer before writing to stderr. This allows it to be printed with a single write_all call, preventing it from being interleaved with other outputs. It also adds newlines before and after the message ensuring that only the panic message will have its own lines.

Before:

thread 'thread 'thread 'thread 'thread '<unnamed>thread 'thread 'thread 'thread '<unnamed><unnamed>thread '<unnamed>' panicked at ' panicked at <unnamed><unnamed><unnamed><unnamed><unnamed>' panicked at <unnamed>' panicked at src\heap.rssrc\heap.rs' 
panicked at ' panicked at ' panicked at ' panicked at ' panicked at src\heap.rs' panicked at src\heap.rs::src\heap.rssrc\heap.rssrc\heap.rssrc\heap.rssrc\heap.rs:src\heap.rs:455455:::::455:455::455455455455455:455:99:::::9:9:
:
999:
999:
assertion failed: size <= (*queue).block_size:
:
assertion failed: size <= (*queue).block_size:
assertion failed: size <= (*queue).block_size:
:
:
assertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_size

assertion failed: size <= (*queue).block_size
assertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_sizeerror: process didn't exit successfully: `target\debug\direct_test.exe` (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)

After:


thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size


thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size


thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size

error: process didn't exit successfully: `target\debug\direct_test.exe` (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)

@rustbot rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. T-libs Relevant to the library team, which will review and decide on the PR/issue. labels Mar 15, 2024
@rust-log-analyzer

This comment has been minimized.

@rust-log-analyzer

This comment has been minimized.

@rust-log-analyzer

This comment has been minimized.

@rustbot
Copy link
Collaborator

rustbot commented Mar 16, 2024

The Miri subtree was changed

cc @rust-lang/miri

@rust-log-analyzer

This comment has been minimized.

@rust-log-analyzer

This comment has been minimized.

let mut cursor = crate::io::Cursor::new(&mut buffer[..]);

let write_msg = |dst: &mut dyn crate::io::Write| {
writeln!(dst, "\nthread '{name}' panicked at {location}:\n{msg}")
Copy link
Member

Choose a reason for hiding this comment

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

I'd suggest to separate the functional change (more newlines) from the implementation change. Makes it easier to discuss and decide on these separately.

A leading newline is not very common in Rust output, so if it stays it definitely needs a comment explaining the purpose.

Copy link
Member

Choose a reason for hiding this comment

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

Panic output isn't stable. There's some work to add thread IDs to the panic message for example.

Yeah the extra newline is unusual, but this is an unsynchronized write to a shared output so we don't have many options to clean up the formatting in cases where a panic is emitted in the middle of something else that's printing.

proc_macro_generated_packed.stderr is a good example of this. It start printing the panic message in the middle of reporting another error.

Do you think it's disruptive enough that it warrants separate discussion?

@rustbot
Copy link
Collaborator

rustbot commented Mar 17, 2024

Some changes occurred in run-make tests.

cc @jieyouxu

@bors
Copy link
Contributor

bors commented Apr 2, 2024

☔ The latest upstream changes (presumably #122267) made this pull request unmergeable. Please resolve the merge conflicts.

@correabuscar
Copy link

Would it be possible(or too overkill?) to check how much stack is left(but without using external crate) and if enough only then write to the on-stack buffer, else write to err directly to avoid a stack overflow ?

I sort of tried to look into it, preliminarily, and it seems that (perhaps due to println!? unsure) it needs >=816 bytes left on reported stack or it will stack overflow in this example:
https://github.com/correabuscar/sandbox/blob/9aecdfa0aead32bc37377a07e57030f623aaad7b/rust/05_sandbox/stack/how_much_stack_is_left/src/main.rs#L9

output is like this on linux/gentoo:

     Running `target/debug/how_much_stack_is_left`
Hello, main world! Some(8371024)
Hello, thread world! Some(19664)
Depth: 1, stack left: Some(19344)
Depth: 2, stack left: Some(19024)
...
Depth: 57, stack left: Some(1424)
Depth: 58, stack left: Some(1104)
End=58
From cloj, stack left: Some(816)

@workingjubilee
Copy link
Member

If we reserve a 512 byte buffer on the stack, then we don't have a guarantee that the compiler doesn't emit code that forces using 512 bytes deeper into the stack even on the codepath that does not write to that (as it may do something like, for instance, sub rsp, 512; push rax;).

@the8472 the8472 added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels May 12, 2024
@correabuscar
Copy link

If we reserve a 512 byte buffer on the stack, then we don't have a guarantee that the compiler doesn't emit code that forces using 512 bytes deeper into the stack even on the codepath that does not write to that (as it may do something like, for instance, sub rsp, 512; push rax;).

I'm not sure I understand that ^, which leads me to say this: but isn't the buffer only allocated on the stack if the specific closure gets to execute? assuming the buffer is inside that closure which we wouldn't execute in the case when we'd know there's not enough stack left for it.

@workingjubilee
Copy link
Member

workingjubilee commented May 17, 2024

I'm not sure I understand that ^, which leads me to say this: but isn't the buffer only allocated on the stack if the specific closure gets to execute? assuming the buffer is inside that closure which we wouldn't execute in the case when we'd know there's not enough stack left for it.

Speaking very broadly... please do not take this as a gospel fact in all cases, but rather as more "Jubilee's understanding of the underlying principles at work, as she has derived from experience (and sometimes talking to LLVM devs)"... LLVM does not view itself as beholden to concerns like "have we run out of stack?" when performing optimizations. That means it is basically always valid to hoist constant byte arrays like that to earlier.

That in itself wouldn't mean we allocate a bunch of extra stack always... but by and large, our closures tend to optimize well because they are inlined into the function that calls them, which means that the enclosing function and the closure are optimized together into a single call. We have to apply many annotations to discourage this behavior.

This doesn't mean LLVM loves optimizing byte arrays on the stack so much it will always do this, it's just that when it's about, like... 512 bytes? I don't think checking if we have 512 bytes available is worth the other costs.

@workingjubilee
Copy link
Member

on a less "what are legal program optimizations?" level: in general the stack is chunked into pages of 4KB or more, so using stacker to check for less than 4kb left of stack is... a little silly.

weihanglo added a commit to weihanglo/cargo that referenced this pull request Sep 26, 2024
rust-lang/rust#122565 adds a new line to thread panic output.
To make the current test suites works on stable, beta, and nightly,
this relaxes the assertion around that by globbing everything.
weihanglo added a commit to weihanglo/cargo that referenced this pull request Sep 26, 2024
rust-lang/rust#122565 adds a new line to thread panic output.
To make the current test suites works on stable, beta, and nightly,
this relaxes the assertion around that by globbing everything.
@weihanglo
Copy link
Member

Thought somebody will post a PR instead 😆.

Anyhow, I have just opened one: rust-lang/cargo#14602.

bors added a commit to rust-lang/cargo that referenced this pull request Sep 26, 2024
test: relax panic output assertion

### What does this PR try to resolve?

rust-lang/rust#122565 adds a new line to thread panic output. To make the current test suites works on stable, beta, and nightly, this relaxes the assertion around that by globbing everything.

### How should we test and review this PR?

Switch to rust-lang/rust#122565 and build a stage0 std, then use it to run these Cargo tests.

Linking to stage0 toolchain should work: https://rustc-dev-guide.rust-lang.org/building/how-to-build-and-run.html#creating-a-rustup-toolchain
@Zoxc
Copy link
Contributor Author

Zoxc commented Sep 28, 2024

This could use another try run now.

@the8472
Copy link
Member

the8472 commented Sep 28, 2024

@bors try

@bors
Copy link
Contributor

bors commented Sep 28, 2024

⌛ Trying commit 86fc657 with merge 09d4459...

bors added a commit to rust-lang-ci/rust that referenced this pull request Sep 28, 2024
Try to write the panic message with a single `write_all` call

This writes the panic message to a buffer before writing to stderr. This allows it to be printed with a single `write_all` call, preventing it from being interleaved with other outputs. It also adds newlines before and after the message ensuring that only the panic message will have its own lines.

Before:
```
thread 'thread 'thread 'thread 'thread '<unnamed>thread 'thread 'thread 'thread '<unnamed><unnamed>thread '<unnamed>' panicked at ' panicked at <unnamed><unnamed><unnamed><unnamed><unnamed>' panicked at <unnamed>' panicked at src\heap.rssrc\heap.rs'
panicked at ' panicked at ' panicked at ' panicked at ' panicked at src\heap.rs' panicked at src\heap.rs::src\heap.rssrc\heap.rssrc\heap.rssrc\heap.rssrc\heap.rs:src\heap.rs:455455:::::455:455::455455455455455:455:99:::::9:9:
:
999:
999:
assertion failed: size <= (*queue).block_size:
:
assertion failed: size <= (*queue).block_size:
assertion failed: size <= (*queue).block_size:
:
:
assertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_size

assertion failed: size <= (*queue).block_size
assertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_sizeerror: process didn't exit successfully: `target\debug\direct_test.exe` (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)
```
After:
```

thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size

thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size

thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size

error: process didn't exit successfully: `target\debug\direct_test.exe` (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)
```

r? `@the8472`

try-job: x86_64-gnu-aux
@bors
Copy link
Contributor

bors commented Sep 29, 2024

☀️ Try build successful - checks-actions
Build commit: 09d4459 (09d4459cbf2d34ce7fe65d6c3d49f89354b26fe0)

@Zoxc
Copy link
Contributor Author

Zoxc commented Oct 7, 2024

@rustbot ready

@rustbot rustbot added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Oct 7, 2024
@the8472
Copy link
Member

the8472 commented Oct 15, 2024

Rebased and reblessed.

@bors r+

@bors
Copy link
Contributor

bors commented Oct 15, 2024

📌 Commit a59ae4c has been approved by the8472

It is now in the queue for this repository.

@bors bors added S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Oct 15, 2024
@bors
Copy link
Contributor

bors commented Oct 16, 2024

⌛ Testing commit a59ae4c with merge 6601467...

bors added a commit to rust-lang-ci/rust that referenced this pull request Oct 16, 2024
Try to write the panic message with a single `write_all` call

This writes the panic message to a buffer before writing to stderr. This allows it to be printed with a single `write_all` call, preventing it from being interleaved with other outputs. It also adds newlines before and after the message ensuring that only the panic message will have its own lines.

Before:
```
thread 'thread 'thread 'thread 'thread '<unnamed>thread 'thread 'thread 'thread '<unnamed><unnamed>thread '<unnamed>' panicked at ' panicked at <unnamed><unnamed><unnamed><unnamed><unnamed>' panicked at <unnamed>' panicked at src\heap.rssrc\heap.rs'
panicked at ' panicked at ' panicked at ' panicked at ' panicked at src\heap.rs' panicked at src\heap.rs::src\heap.rssrc\heap.rssrc\heap.rssrc\heap.rssrc\heap.rs:src\heap.rs:455455:::::455:455::455455455455455:455:99:::::9:9:
:
999:
999:
assertion failed: size <= (*queue).block_size:
:
assertion failed: size <= (*queue).block_size:
assertion failed: size <= (*queue).block_size:
:
:
assertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_size

assertion failed: size <= (*queue).block_size
assertion failed: size <= (*queue).block_sizeassertion failed: size <= (*queue).block_sizeerror: process didn't exit successfully: `target\debug\direct_test.exe` (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)
```
After:
```

thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size

thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size

thread '<unnamed>' panicked at src\heap.rs:455:9:
assertion failed: size <= (*queue).block_size

error: process didn't exit successfully: `target\debug\direct_test.exe` (exit code: 0xc0000409, STATUS_STACK_BUFFER_OVERRUN)
```
@rust-log-analyzer
Copy link
Collaborator

The job x86_64-msvc failed! Check out the build log: (web) (plain)

Click to see the possible cause of the failure (guessed by this bot)
To only update this specific test, also pass `--test-args doctest\failed-doctest-output-windows.rs`

error: 1 errors occurred comparing output.
status: exit code: 101
command: PATH="C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage2\bin;C:\Program Files (x86)\Windows Kits\10\bin\x64;C:\Program Files (x86)\Windows Kits\10\bin\10.0.22621.0\x64;C:\Program Files\Microsoft Visual Studio\2022\Enterprise\VC\Tools\MSVC\14.41.34120\bin\HostX64\x64;C:\Program Files\Microsoft Visual Studio\2022\Enterprise\VC\Tools\MSVC\14.41.34120\bin\HostX64\x64;C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage0-bootstrap-tools\x86_64-pc-windows-msvc\release\deps;C:\a\rust\rust\build\x86_64-pc-windows-msvc\stage0\bin;C:\Program Files\PowerShell\7;C:\a\_temp\msys64\mingw64\bin;C:\a\_temp\msys64\usr\local\bin;C:\a\_temp\msys64\usr\bin;C:\a\_temp\msys64\usr\bin;C:\a\rust\rust\ninja;C:\a\rust\rust\sccache;C:\a\_temp\setup-msys2;C:\Program Files\MongoDB\Server\5.0\bin;C:\aliyun-cli;C:\vcpkg;C:\Program Files (x86)\NSIS;C:\tools\zstd;C:\Program Files\Mercurial;C:\hostedtoolcache\windows\stack\3.1.1\x64;C:\cabal\bin;C:\ghcup\bin;C:\mingw64\bin;C:\Program Files\dotnet;C:\Program Files\MySQL\MySQL Server 8.0\bin;C:\Program Files\R\R-4.4.1\bin\x64;C:\SeleniumWebDrivers\GeckoDriver;C:\SeleniumWebDrivers\EdgeDriver;C:\SeleniumWebDrivers\ChromeDriver;C:\Program Files (x86)\sbt\bin;C:\Program Files (x86)\GitHub CLI;C:\Program Files\Git\bin;C:\Program Files (x86)\pipx_bin;C:\npm\prefix;C:\hostedtoolcache\windows\go\1.21.13\x64\bin;C:\hostedtoolcache\windows\Python\3.9.13\x64\Scripts;C:\hostedtoolcache\windows\Python\3.9.13\x64;C:\hostedtoolcache\windows\Ruby\3.0.7\x64\bin;C:\Program Files\OpenSSL\bin;C:\tools\kotlinc\bin;C:\hostedtoolcache\windows\Java_Temurin-Hotspot_jdk\8.0.422-5\x64\bin;C:\Program Files\ImageMagick-7.1.1-Q16-HDRI;C:\Program Files\Microsoft SDKs\Azure\CLI2\wbin;C:\ProgramData\kind;C:\ProgramData\Chocolatey\bin;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0;C:\Windows\System32\OpenSSH;C:\Program Files\dotnet;C:\Program Files\PowerShell\7;C:\Program Files\Microsoft\Web Platform Installer;C:\Program Files\TortoiseSVN\bin;C:\Program Files\Microsoft SQL Server\Client SDK\ODBC\170\Tools\Binn;C:\Program Files\Microsoft SQL Server\150\Tools\Binn;C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit;C:\Program Files (x86)\WiX Toolset v3.14\bin;C:\Program Files\Microsoft SQL Server\130\DTS\Binn;C:\Program Files\Microsoft SQL Server\140\DTS\Binn;C:\Program Files\Microsoft SQL Server\150\DTS\Binn;C:\Program Files\Microsoft SQL Server\160\DTS\Binn;C:\Strawberry\c\bin;C:\Strawberry\perl\site\bin;C:\Strawberry\perl\bin;C:\ProgramData\chocolatey\lib\pulumi\tools\Pulumi\bin;C:\Program Files\CMake\bin;C:\ProgramData\chocolatey\lib\maven\apache-maven-3.8.7\bin;C:\Program Files\Microsoft Service Fabric\bin\Fabric\Fabric.Code;C:\Program Files\Microsoft SDKs\Service Fabric\Tools\ServiceFabricLocalClusterManager;C:\Program Files\nodejs;C:\Program Files\Git\cmd;C:\Program Files\Git\mingw64\bin;C:\Program Files\Git\usr\bin;C:\Program Files\GitHub CLI;C:\tools\php;C:\Program Files (x86)\sbt\bin;C:\Program Files\Amazon\AWSCLIV2;C:\Program Files\Amazon\SessionManagerPlugin\bin;C:\Program Files\Amazon\AWSSAMCLI\bin;C:\Program Files\Microsoft SQL Server\130\Tools\Binn;C:\Program Files\LLVM\bin;C:\Users\runneradmin\.dotnet\tools;C:\Users\runneradmin\.cargo\bin;C:\Users\runneradmin\AppData\Local\Microsoft\WindowsApps;C:\a\_temp\msys64\usr\bin\site_perl;C:\a\_temp\msys64\usr\bin\vendor_perl;C:\a\_temp\msys64\usr\bin\core_perl" "C:\\a\\rust\\rust\\build\\x86_64-pc-windows-msvc\\stage2\\bin\\rustdoc.exe" "C:\\a\\rust\\rust\\tests\\rustdoc-ui\\doctest\\failed-doctest-output-windows.rs" "-Zthreads=1" "-Zsimulate-remapped-rust-src-base=/rustc/FAKE_PREFIX" "-Ztranslate-remapped-path-to-local-path=no" "-Z" "ignore-directory-in-diagnostics-source-blocks=C:\\Users\\runneradmin\\.cargo" "-Z" "ignore-directory-in-diagnostics-source-blocks=C:\\a\\rust\\rust\\vendor" "--sysroot" "C:\\a\\rust\\rust\\build\\x86_64-pc-windows-msvc\\stage2" "--target=x86_64-pc-windows-msvc" "--check-cfg" "cfg(FALSE)" "--error-format" "json" "--json" "future-incompat" "-Ccodegen-units=1" "-Zui-testing" "-Zdeduplicate-diagnostics=no" "-Zwrite-long-types-to-disk=no" "-Cstrip=debuginfo" "-o" "C:\\a\\rust\\rust\\build\\x86_64-pc-windows-msvc\\test\\rustdoc-ui\\doctest\\failed-doctest-output-windows" "-A" "internal_features" "-Cdebuginfo=0" "-Lnative=C:\\a\\rust\\rust\\build\\x86_64-pc-windows-msvc\\native\\rust-test-helpers" "-L" "C:\\a\\rust\\rust\\build\\x86_64-pc-windows-msvc\\test\\rustdoc-ui\\doctest\\failed-doctest-output-windows\\auxiliary" "--test" "--test-args" "--test-threads=1"

running 2 tests
test tests\rustdoc-ui\doctest\failed-doctest-output-windows.rs - OtherStruct (line 25) ... FAILED
test tests\rustdoc-ui\doctest\failed-doctest-output-windows.rs - SomeStruct (line 15) ... FAILED
---
test result: FAILED. 281 passed; 1 failed; 7 ignored; 0 measured; 0 filtered out; finished in 25.83s

Some tests failed in compiletest suite=rustdoc-ui mode=ui host=x86_64-pc-windows-msvc target=x86_64-pc-windows-msvc
Build completed unsuccessfully in 1:29:58
make: *** [Makefile:106: ci-msvc-ps1] Error 1
  network time: Wed, 16 Oct 2024 04:04:14 GMT
##[error]Process completed with exit code 2.
Post job cleanup.
[command]"C:\Program Files\Git\bin\git.exe" version

@bors
Copy link
Contributor

bors commented Oct 16, 2024

💔 Test failed - checks-actions

@bors bors added S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. and removed S-waiting-on-bors Status: Waiting on bors to run and complete tests. Bors will change the label on completion. labels Oct 16, 2024
@bors
Copy link
Contributor

bors commented Oct 17, 2024

☔ The latest upstream changes (presumably #129582) made this pull request unmergeable. Please resolve the merge conflicts.

@jieyouxu
Copy link
Member

@bors r- (bors sync)

@bors bors added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. labels Oct 18, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-run-make Area: port run-make Makefiles to rmake.rs S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. T-compiler Relevant to the compiler team, which will review and decide on the PR/issue. T-libs Relevant to the library team, which will review and decide on the PR/issue.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Scoped thread panic messages unexpectedly interleaving in stderr output