sandboxed execution with --verbose_failures is really noisy

[bsilver8192]

With --verbose_failures, all sandboxed spawn actions spew out a bunch of debugging information about the sandbox setup, even successful ones.

I like the extra information when one fails, but it can become hard to find in the deluge.

Trivial example:
BUILD:

genrule(
  name = 'test',
  outs = ['file.txt'],
  cmd = 'echo a > $@',
)

Output:

$ ~/bazel/output/bazel build :test --verbose_failures
INFO: Found 1 target...
INFO: From Executing genrule //:test:
src/main/tools/namespace-sandbox.c:536: sandbox root is /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0
src/main/tools/namespace-sandbox.c:538: working dir is /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4
src/main/tools/namespace-sandbox.c:262: unshare succeeded after 1 tries
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /dev/shm /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/dev/shm
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /bin /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/bin
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /sbin /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/sbin
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /etc /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/etc
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /libx32 /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/libx32
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /lib32 /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/lib32
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /lib64 /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/lib64
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /lib /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/lib
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/include /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/include
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/games /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/games
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/libx32 /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/libx32
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/bin /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/bin
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/src /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/src
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/lib32 /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/lib32
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/sbin /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/sbin
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/share /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/share
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /usr/lib /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/usr/lib
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /home/brian/.cache/bazel/_bazel_brian/install/1a7b1ef7ee55f3c7c625e38adac42429/_embedded_binaries/build-runfiles /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/home/brian/.cache/bazel/_bazel_brian/install/1a7b1ef7ee55f3c7c625e38adac42429/_embedded_binaries/build-runfiles
src/main/tools/namespace-sandbox.c:385: mount -o rbind,ro /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/tools/genrule/genrule-setup.sh /home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/bazel-sandbox/2519c323-fb66-4267-b708-089c575c716f-0/home/brian/.cache/bazel/_bazel_brian/2cb83316f7e684104ff056b06e2f1dd5/test_workspace4/tools/genrule/genrule-setup.sh
src/main/tools/namespace-sandbox.c:476: arg: /bin/bash
src/main/tools/namespace-sandbox.c:476: arg: -c
src/main/tools/namespace-sandbox.c:476: arg: source tools/genrule/genrule-setup.sh; echo a > bazel-out/local_linux-fastbuild/genfiles/file.txt
Target //:test up-to-date:
  bazel-genfiles/file.txt
INFO: Elapsed time: 3.032s, Critical Path: 0.17s

[damienmg]

Philip: I know you somehow have noticed this problem. Don't hesitate to close it if it's a duplicate.

[philwo]

Acknowledged - there are currently two known issues with --verbose_failures and sandboxing:

1. It prints the debug info also when execution doesn't fail.
2. The output is not very readable for users.

I'll prepare a patch to fix both problems.

[philwo]

So, fixing 1) is actually not that easy, because both the sandbox wrapper (namespace-sandbox.c) and the child process that it launches log to stderr. Of course one always wants to see the output of the child process (compiler warnings, etc.), but one only wants to see the debug output of the sandbox when the child failed.

One way to fix this would be for the sandbox to log its debug output to a file and then Bazel could show whatever has been logged there in case execution failed. I haven't implemented that yet, though. (Patches are welcome ;))

For now, I'm introducing a flag --sandbox_debug and the output will be shown only when that flag is specified, making it independent of --verbose_failures.

I'm also improving the formatting of the output to make it easier to read.