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

libstd: use block buffering when stdout is not a TTY #60904

Closed
wants to merge 3 commits into from

Conversation

Arcterus
Copy link
Contributor

@Arcterus Arcterus commented May 17, 2019

This PR is meant to resolve #60673.

At the moment, there are a couple issues. I am unfamiliar with several of the platforms in libstd::io::sys, so I don't actually know if they have methods to determine if stdout is a TTY (or some equivalent).

Additionally, the original issue mentioned buffering for stderr in addition to stdout, which I have not implemented at the moment (although doing so is pretty straightforward). I also have not added methods to manually switch between block buffering and line buffering. If either of these are desired, let me know and I'll try to add them.

I noticed that run-pass/command-pre-exec.rs seems to fail with this change because (AFAICT) the println!() in Command::pre_exec() doesn't get flushed, so the contents of stdout are missing a hello. I haven't modified the test yet because I am unsure if we should just tell users to flush stdout (in which case I'll change the test), or if we should special case functions that can exit in libstd, or something else.

run-pass/issues/issue-30490.rs fails for a similar reason (doesn't flush before exec).

@rust-highfive
Copy link
Collaborator

r? @sfackler

(rust_highfive has picked a reviewer for you, use r? to override)

@rust-highfive rust-highfive added the S-waiting-on-review Status: Awaiting review from the assignee but also interested parties. label May 17, 2019
@rust-highfive
Copy link
Collaborator

The job x86_64-gnu-llvm-6.0 of your PR failed on Travis (raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.
travis_time:end:04ab31c7:start=1558073747108693651,finish=1558073749178045994,duration=2069352343
$ git checkout -qf FETCH_HEAD
travis_fold:end:git.checkout

Encrypted environment variables have been removed for security reasons.
See https://docs.travis-ci.com/user/pull-requests/#pull-requests-and-security-restrictions
$ export SCCACHE_BUCKET=rust-lang-ci-sccache2
$ export SCCACHE_REGION=us-west-1
$ export GCP_CACHE_BUCKET=rust-lang-ci-cache
$ export AWS_ACCESS_KEY_ID=AKIA46X5W6CZEJZ6XT55
---
[01:16:46] .................................................................................................... 100/2960
[01:16:59] .................................................................................i.................. 200/2960
[01:17:07] .................................................................................................... 300/2960
[01:17:18] .................................................................................................... 400/2960
[01:17:27] ...........................................F........................................................ 500/2960
[01:17:53] .................................................................................................... 700/2960
[01:18:04] .................................................................................................... 800/2960
[01:18:13] .................................................................................................... 900/2960
[01:18:26] .................................................................................................... 1000/2960
[01:18:26] .................................................................................................... 1000/2960
[01:18:40] .................................................................................................... 1100/2960
[01:18:49] .................................................................................................... 1200/2960
[01:18:59] .................................................................................................... 1300/2960
[01:19:10] ...........................ii....................................................................... 1400/2960
[01:19:22] ....F............................................................................................... 1500/2960
[01:19:44] .................................................................................................... 1700/2960
[01:19:57] .................................................................................................... 1800/2960
[01:20:07] .................................................................................................... 1900/2960
[01:20:21] ..........i.......................................................................i................. 2000/2960
---
[01:22:59] ------------------------------------------
[01:22:59] stderr:
[01:22:59] ------------------------------------------
[01:22:59] thread 'main' panicked at 'assertion failed: `(left == right)`
[01:22:59]   left: `[104, 101, 108, 108, 111, 50, 10]`,
[01:22:59]  right: `[104, 101, 108, 108, 111, 10, 104, 101, 108, 108, 111, 50, 10]`', /checkout/src/test/run-pass/command-pre-exec.rs:42:5
[01:22:59] 
[01:22:59] ------------------------------------------
[01:22:59] 
[01:22:59] 
---
[01:22:59] ------------------------------------------
[01:22:59] stderr:
[01:22:59] ------------------------------------------
[01:22:59] thread 'main' panicked at 'assertion failed: `(left == right)`
[01:22:59]   left: `"child stderr\n"`,
[01:22:59]  right: `"parent stdout\nchild stderr\n"`', /checkout/src/test/run-pass/issues/issue-30490.rs:78:5
[01:22:59] 
[01:22:59] ------------------------------------------
[01:22:59] 
[01:22:59] 
---
[01:22:59] thread 'main' panicked at 'Some tests failed', src/tools/compiletest/src/main.rs:512:22
[01:22:59] note: Run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
[01:22:59] 
[01:22:59] 
[01:22:59] command did not execute successfully: "/checkout/obj/build/x86_64-unknown-linux-gnu/stage0-tools-bin/compiletest" "--compile-lib-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/lib" "--run-lib-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/lib/rustlib/x86_64-unknown-linux-gnu/lib" "--rustc-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/bin/rustc" "--src-base" "/checkout/src/test/run-pass" "--build-base" "/checkout/obj/build/x86_64-unknown-linux-gnu/test/run-pass" "--stage-id" "stage2-x86_64-unknown-linux-gnu" "--mode" "run-pass" "--target" "x86_64-unknown-linux-gnu" "--host" "x86_64-unknown-linux-gnu" "--llvm-filecheck" "/usr/lib/llvm-6.0/bin/FileCheck" "--host-rustcflags" "-Crpath -O -Zunstable-options  -Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "--target-rustcflags" "-Crpath -O -Zunstable-options  -Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "--docck-python" "/usr/bin/python2.7" "--lldb-python" "/usr/bin/python2.7" "--gdb" "/usr/bin/gdb" "--quiet" "--llvm-version" "6.0.0\n" "--system-llvm" "--cc" "" "--cxx" "" "--cflags" "" "--llvm-components" "" "--llvm-cxxflags" "" "--adb-path" "adb" "--adb-test-dir" "/data/tmp/work" "--android-cross-path" "" "--color" "always"
[01:22:59] 
[01:22:59] 
[01:22:59] failed to run: /checkout/obj/build/bootstrap/debug/bootstrap test
[01:22:59] Build completed unsuccessfully in 0:11:00
[01:22:59] Build completed unsuccessfully in 0:11:00
[01:22:59] Makefile:48: recipe for target 'check' failed
[01:22:59] make: *** [check] Error 1
The command "stamp sh -x -c "$RUN_SCRIPT"" exited with 2.
travis_time:start:06263529
$ date && (curl -fs --head https://google.com | grep ^Date: | sed 's/Date: //g' || true)
Fri May 17 07:38:58 UTC 2019
---
travis_time:end:29a6b02e:start=1558078740022301581,finish=1558078740026978087,duration=4676506
travis_fold:end:after_failure.3
travis_fold:start:after_failure.4
travis_time:start:35127651
$ ln -s . checkout && for CORE in obj/cores/core.*; do EXE=$(echo $CORE | sed 's|obj/cores/core\.[0-9]*\.!checkout!\(.*\)|\1|;y|!|/|'); if [ -f "$EXE" ]; then printf travis_fold":start:crashlog\n\033[31;1m%s\033[0m\n" "$CORE"; gdb --batch -q -c "$CORE" "$EXE" -iex 'set auto-load off' -iex 'dir src/' -iex 'set sysroot .' -ex bt -ex q; echo travis_fold":"end:crashlog; fi; done || true
travis_fold:end:after_failure.4
travis_fold:start:after_failure.5
travis_time:start:05e48497
travis_time:start:05e48497
$ cat ./obj/build/x86_64-unknown-linux-gnu/native/asan/build/lib/asan/clang_rt.asan-dynamic-i386.vers || true
cat: ./obj/build/x86_64-unknown-linux-gnu/native/asan/build/lib/asan/clang_rt.asan-dynamic-i386.vers: No such file or directory
travis_fold:end:after_failure.5
travis_fold:start:after_failure.6
travis_time:start:069260fd
$ dmesg | grep -i kill

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @TimNN. (Feature Requests)

@rust-highfive
Copy link
Collaborator

The job x86_64-gnu-llvm-6.0 of your PR failed on Travis (raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.
travis_time:end:062f5d9f:start=1558117023535016117,finish=1558117127525297136,duration=103990281019
$ git checkout -qf FETCH_HEAD
travis_fold:end:git.checkout

Encrypted environment variables have been removed for security reasons.
See https://docs.travis-ci.com/user/pull-requests/#pull-requests-and-security-restrictions
$ export SCCACHE_BUCKET=rust-lang-ci-sccache2
$ export SCCACHE_REGION=us-west-1
$ export GCP_CACHE_BUCKET=rust-lang-ci-cache
$ export AWS_ACCESS_KEY_ID=AKIA46X5W6CZEJZ6XT55
---
[01:13:24] .................................................................................................... 100/2959
[01:13:36] .................................................................................i.................. 200/2959
[01:13:45] .................................................................................................... 300/2959
[01:13:56] .................................................................................................... 400/2959
[01:14:06] .........................................F.......................................................... 500/2959
[01:14:32] .................................................................................................... 700/2959
[01:14:44] .................................................................................................... 800/2959
[01:14:53] .................................................................................................... 900/2959
[01:15:07] .................................................................................................... 1000/2959
[01:15:07] .................................................................................................... 1000/2959
[01:15:21] .................................................................................................... 1100/2959
[01:15:30] .................................................................................................... 1200/2959
[01:15:40] .................................................................................................... 1300/2959
[01:15:52] ..........................ii........................................................................ 1400/2959
[01:16:03] ...F................................................................................................ 1500/2959
[01:16:26] .................................................................................................... 1700/2959
[01:16:40] .................................................................................................... 1800/2959
[01:16:50] .................................................................................................... 1900/2959
[01:17:04] .........i.......................................................................i.................. 2000/2959
---
[01:19:46] ------------------------------------------
[01:19:46] stderr:
[01:19:46] ------------------------------------------
[01:19:46] thread 'main' panicked at 'assertion failed: `(left == right)`
[01:19:46]   left: `[104, 101, 108, 108, 111, 50, 10]`,
[01:19:46]  right: `[104, 101, 108, 108, 111, 10, 104, 101, 108, 108, 111, 50, 10]`', /checkout/src/test/run-pass/command-pre-exec.rs:42:5
[01:19:46] 
[01:19:46] ------------------------------------------
[01:19:46] 
[01:19:46] 
---
[01:19:46] ------------------------------------------
[01:19:46] stderr:
[01:19:46] ------------------------------------------
[01:19:46] thread 'main' panicked at 'assertion failed: `(left == right)`
[01:19:46]   left: `"child stderr\n"`,
[01:19:46]  right: `"parent stdout\nchild stderr\n"`', /checkout/src/test/run-pass/issues/issue-30490.rs:78:5
[01:19:46] 
[01:19:46] ------------------------------------------
[01:19:46] 
[01:19:46] 
---
[01:19:46] thread 'main' panicked at 'Some tests failed', src/tools/compiletest/src/main.rs:512:22
[01:19:46] note: Run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
[01:19:46] 
[01:19:46] 
[01:19:46] command did not execute successfully: "/checkout/obj/build/x86_64-unknown-linux-gnu/stage0-tools-bin/compiletest" "--compile-lib-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/lib" "--run-lib-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/lib/rustlib/x86_64-unknown-linux-gnu/lib" "--rustc-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/bin/rustc" "--src-base" "/checkout/src/test/run-pass" "--build-base" "/checkout/obj/build/x86_64-unknown-linux-gnu/test/run-pass" "--stage-id" "stage2-x86_64-unknown-linux-gnu" "--mode" "run-pass" "--target" "x86_64-unknown-linux-gnu" "--host" "x86_64-unknown-linux-gnu" "--llvm-filecheck" "/usr/lib/llvm-6.0/bin/FileCheck" "--host-rustcflags" "-Crpath -O -Zunstable-options  -Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "--target-rustcflags" "-Crpath -O -Zunstable-options  -Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "--docck-python" "/usr/bin/python2.7" "--lldb-python" "/usr/bin/python2.7" "--gdb" "/usr/bin/gdb" "--quiet" "--llvm-version" "6.0.0\n" "--system-llvm" "--cc" "" "--cxx" "" "--cflags" "" "--llvm-components" "" "--llvm-cxxflags" "" "--adb-path" "adb" "--adb-test-dir" "/data/tmp/work" "--android-cross-path" "" "--color" "always"
[01:19:46] 
[01:19:46] 
[01:19:46] failed to run: /checkout/obj/build/bootstrap/debug/bootstrap test
[01:19:46] Build completed unsuccessfully in 0:11:18
[01:19:46] Build completed unsuccessfully in 0:11:18
[01:19:46] make: *** [check] Error 1
[01:19:46] Makefile:48: recipe for target 'check' failed
The command "stamp sh -x -c "$RUN_SCRIPT"" exited with 2.
travis_time:start:159479f0
$ date && (curl -fs --head https://google.com | grep ^Date: | sed 's/Date: //g' || true)
Fri May 17 19:38:43 UTC 2019
---
travis_time:end:35e59e50:start=1558121924747896241,finish=1558121924752881577,duration=4985336
travis_fold:end:after_failure.3
travis_fold:start:after_failure.4
travis_time:start:13fd6512
$ ln -s . checkout && for CORE in obj/cores/core.*; do EXE=$(echo $CORE | sed 's|obj/cores/core\.[0-9]*\.!checkout!\(.*\)|\1|;y|!|/|'); if [ -f "$EXE" ]; then printf travis_fold":start:crashlog\n\033[31;1m%s\033[0m\n" "$CORE"; gdb --batch -q -c "$CORE" "$EXE" -iex 'set auto-load off' -iex 'dir src/' -iex 'set sysroot .' -ex bt -ex q; echo travis_fold":"end:crashlog; fi; done || true
travis_fold:end:after_failure.4
travis_fold:start:after_failure.5
travis_time:start:08f85a24
travis_time:start:08f85a24
$ cat ./obj/build/x86_64-unknown-linux-gnu/native/asan/build/lib/asan/clang_rt.asan-dynamic-i386.vers || true
cat: ./obj/build/x86_64-unknown-linux-gnu/native/asan/build/lib/asan/clang_rt.asan-dynamic-i386.vers: No such file or directory
travis_fold:end:after_failure.5
travis_fold:start:after_failure.6
travis_time:start:11710b00
$ dmesg | grep -i kill

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @TimNN. (Feature Requests)

@rust-highfive
Copy link
Collaborator

The job x86_64-gnu-llvm-6.0 of your PR failed on Travis (raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.
travis_time:end:0db7b98a:start=1558140643943904230,finish=1558140733431993876,duration=89488089646
$ git checkout -qf FETCH_HEAD
travis_fold:end:git.checkout

Encrypted environment variables have been removed for security reasons.
See https://docs.travis-ci.com/user/pull-requests/#pull-requests-and-security-restrictions
$ export SCCACHE_BUCKET=rust-lang-ci-sccache2
$ export SCCACHE_REGION=us-west-1
$ export GCP_CACHE_BUCKET=rust-lang-ci-cache
$ export AWS_ACCESS_KEY_ID=AKIA46X5W6CZEJZ6XT55
---
[01:24:45] .................................................................................................... 100/2959
[01:25:00] .................................................................................i.................. 200/2959
[01:25:10] .................................................................................................... 300/2959
[01:25:23] .................................................................................................... 400/2959
[01:25:34] .........................................F.......................................................... 500/2959
[01:26:05] .................................................................................................... 700/2959
[01:26:18] .................................................................................................... 800/2959
[01:26:29] .................................................................................................... 900/2959
[01:26:45] .................................................................................................... 1000/2959
[01:26:45] .................................................................................................... 1000/2959
[01:27:01] .................................................................................................... 1100/2959
[01:27:12] .................................................................................................... 1200/2959
[01:27:24] .................................................................................................... 1300/2959
[01:27:38] ..........................ii........................................................................ 1400/2959
[01:27:51] ...F................................................................................................ 1500/2959
[01:28:18] .................................................................................................... 1700/2959
[01:28:35] .................................................................................................... 1800/2959
[01:28:47] .................................................................................................... 1900/2959
[01:29:03] .........i.......................................................................i.................. 2000/2959
---
[01:32:06] ------------------------------------------
[01:32:06] stderr:
[01:32:06] ------------------------------------------
[01:32:06] thread 'main' panicked at 'assertion failed: `(left == right)`
[01:32:06]   left: `[104, 101, 108, 108, 111, 50, 10]`,
[01:32:06]  right: `[104, 101, 108, 108, 111, 10, 104, 101, 108, 108, 111, 50, 10]`', /checkout/src/test/run-pass/command-pre-exec.rs:42:5
[01:32:06] 
[01:32:06] ------------------------------------------
[01:32:06] 
[01:32:06] 
---
[01:32:06] ------------------------------------------
[01:32:06] stderr:
[01:32:06] ------------------------------------------
[01:32:06] thread 'main' panicked at 'assertion failed: `(left == right)`
[01:32:06]   left: `"child stderr\n"`,
[01:32:06]  right: `"parent stdout\nchild stderr\n"`', /checkout/src/test/run-pass/issues/issue-30490.rs:78:5
[01:32:06] 
[01:32:06] ------------------------------------------
[01:32:06] 
[01:32:06] 
---
[01:32:06] test result: FAILED. 2948 passed; 2 failed; 9 ignored; 0 measured; 0 filtered out
[01:32:06] 
[01:32:06] 
[01:32:06] 
[01:32:06] command did not execute successfully: "/checkout/obj/build/x86_64-unknown-linux-gnu/stage0-tools-bin/compiletest" "--compile-lib-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/lib" "--run-lib-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/lib/rustlib/x86_64-unknown-linux-gnu/lib" "--rustc-path" "/checkout/obj/build/x86_64-unknown-linux-gnu/stage2/bin/rustc" "--src-base" "/checkout/src/test/run-pass" "--build-base" "/checkout/obj/build/x86_64-unknown-linux-gnu/test/run-pass" "--stage-id" "stage2-x86_64-unknown-linux-gnu" "--mode" "run-pass" "--target" "x86_64-unknown-linux-gnu" "--host" "x86_64-unknown-linux-gnu" "--llvm-filecheck" "/usr/lib/llvm-6.0/bin/FileCheck" "--host-rustcflags" "-Crpath -O -Zunstable-options  -Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "--target-rustcflags" "-Crpath -O -Zunstable-options  -Lnative=/checkout/obj/build/x86_64-unknown-linux-gnu/native/rust-test-helpers" "--docck-python" "/usr/bin/python2.7" "--lldb-python" "/usr/bin/python2.7" "--gdb" "/usr/bin/gdb" "--quiet" "--llvm-version" "6.0.0\n" "--system-llvm" "--cc" "" "--cxx" "" "--cflags" "" "--llvm-components" "" "--llvm-cxxflags" "" "--adb-path" "adb" "--adb-test-dir" "/data/tmp/work" "--android-cross-path" "" "--color" "always"
[01:32:06] 
[01:32:06] 
[01:32:06] failed to run: /checkout/obj/build/bootstrap/debug/bootstrap test
[01:32:06] Build completed unsuccessfully in 0:13:02
[01:32:06] Build completed unsuccessfully in 0:13:02
[01:32:06] Makefile:48: recipe for target 'check' failed
[01:32:06] make: *** [check] Error 1
The command "stamp sh -x -c "$RUN_SCRIPT"" exited with 2.
travis_time:start:0687a334
$ date && (curl -fs --head https://google.com | grep ^Date: | sed 's/Date: //g' || true)
Sat May 18 02:24:30 UTC 2019

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @TimNN. (Feature Requests)

@Arcterus
Copy link
Contributor Author

Arcterus commented May 18, 2019

I'm not really sure how to fix the test cases other than adding explicit flushes as we can't lock stdout in Command::spawn() (or whatever) in case the user is holding the lock on another thread.

@sfackler
Copy link
Member

It seems like adding explicit flushes is the expected necessary change after this PR.

@Dylan-DPC-zz Dylan-DPC-zz 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 Jun 3, 2019
@Dylan-DPC-zz
Copy link

ping from triage @Arcterus any updates on this?

@Arcterus
Copy link
Contributor Author

Arcterus commented Jun 3, 2019

Sorry, I’ve been dealing with some other stuff for the past couple weeks. I was trying to add the ability to switch buffering strategies the last time I was working on it, so I’ll try to get (at least) a preliminary implementation up this week.

@sfackler
Copy link
Member

sfackler commented Jun 3, 2019

To enable switching blocking strategies, it'd probably be easiest to move from an enum to a single type that just has a bool inside tracking if it should flush on linebreaks or not.

@Dylan-DPC-zz
Copy link

ping from triage @Arcterus
Unfortunately we haven't heard from you on this in a while, so I'm closing the PR to keep things tidy. Don't worry though, if you'll have time again in the future please reopen this PR, we'll be happy to review it again! Thanks

@nico-abram
Copy link
Contributor

It's still open. Did you forget to close it?

@Dylan-DPC-zz
Copy link

Dylan-DPC-zz commented Jul 3, 2019

@nico-abram yep 😄

@Dylan-DPC-zz Dylan-DPC-zz added S-inactive Status: Inactive and waiting on the author. This is often applied to closed PRs. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Jul 3, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
S-inactive Status: Inactive and waiting on the author. This is often applied to closed PRs.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

io::Stdout should use block bufferring when appropriate
6 participants