[7.4.1] Bazel test actions hangs in "[Prepa]" when fall back to local in Mariner2 OS
- Dominant language
- Java
- Stars
- 25.8k
- Forks
- 4.6k
- Avg merge
- 2d 18h
- Merged PRs (30d)
- 75
Description
### Description of the bug:
#### Summary
Hi team, I am testing the `--remote_local_fallback` behavior and I noticed for one internal repo, the combination of `bazel build //... && bazel run foo && bazel test //...` caused Bazel hang when the RBE service is not available.
This is not an issue when building locally or remotely, and only happens when falling back to local running this particular Bazel invocation.
Note that is only reproducible in Mariner2 OS, but not reproducible in RedHat 8 OS.
When this happened, I did not see the expected output `ERROR: Failed to query remote execution capabilities: UNAVAILABLE: io exception` in the terminal. The log is like this.
```
[0 / 1] [Prepa] BazelWorkspaceStatusAction stable-status.txt
INFO: Analyzed 263 targets (297 packages loaded, 28905 targets configured).
[4,372 / 4,635] [Prepa] Testing //:shellcheck_test ... (200 actions, 0 running)
[4,372 / 4,635] [Prepa] Testing //:shellcheck_test; 11s ... (200 actions, 0 running)
...
[4,372 / 4,635] [Prepa] Testing //:shellcheck_test; 2021s ... (200 actions, 0 running)
```
#### Workaround
`bazel shutdown` before the test can fix this issue: `bazel build //... && bazel run foo && bazel shutdown && bazel test //...`. The test can start and I see the expected `ERROR: Failed to query remote execution capabilities: UNAVAILABLE: io exception`
```
INFO: Analyzed 263 targets (297 packages loaded, 28905 targets configured).
[4,372 / 4,635] [Prepa] Testing //:shellcheck_test ... (200 actions, 0 running)
[4,372 / 4,635] [Prepa] Testing //:shellcheck_test; 10s ... (200 actions, 0 running)
ERROR: Failed to query remote execution capabilities: UNAVAILABLE: io exception
[4,372 / 4,635] [Prepa] Testing //k8s-deployment-utilities/ctrlutil/conditions:conditions_test; 21s ... (200 actions, 0 running)
[4,372 / 4,635] Testing //dashboards/tools:tools_test; 1s remote, remote-cache ... (200 actions, 0 running)
[4,372 / 4,635] Testing //dashboards/tools:tools_test; 2s remote, remote-cache ... (200 actions, 0 running)
[4,446 / 4,635] 74 / 263 tests; Testing //:shellcheck_test; 1s local, remote, remote-cache ... (189 actions, 34 running)
```
#### JStack
Note: The JStack is for 7.1.2, but I could also reproduce this with 7.4.1.
Attached are the JStacks. [jstack_dump.zip](https://github.com/user-attachments/files/19250358/jstack_dump.zip)
The first 3 was collected at the beginning of the hanging. The last one `bazel_thread_dump_2892-3.txt` was collected it stuck ~10 mins.
From the Jstack seems Bazel entered a deadlock. Because `ERROR: Failed to query remote execution capabilities: UNAVAILABLE: io exception` was not printed, I searched `GoogleChannelConnectionFactory` in the Jstack, seems Bazel stuck at the UiEventHandler.
```
"pool-2-thread-1" #1229 [4209] prio=5 os_prio=0 cpu=3890.40ms elapsed=967.19s tid=0x0000732c98002c70 nid=4209 in Object.wait() [0x0000732d783fd000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait0(java.base@21/Native Method)
- waiting on
at java.lang.Object.wait(java.base@21/Unknown Source)
at java.lang.Object.wait(java.base@21/Unknown Source)
at com.google.devtools.build.lib.server.GrpcServerImpl$BlockingStreamObserver.onNext(GrpcServerImpl.java:175)
- locked <0x00000000b64667d0> (a com.google.devtools.build.lib.server.GrpcServerImpl$BlockingStreamObserver)
at com.google.devtools.build.lib.server.GrpcServerImpl$RpcOutputStream.write(GrpcServerImpl.java:253)
at com.google.devtools.build.lib.util.io.DelegatingOutErr$DelegatingOutputStream.write(DelegatingOutErr.java:89)
at java.io.BufferedOutputStream.flushBuffer(java.base@21/Unknown Source)
at java.io.BufferedOutputStream.implFlush(java.base@21/Unknown Source)
at java.io.BufferedOutputStream.flush(java.base@21/Unknown Source)
at com.google.devtools.build.lib.runtime.UiEventHandler$FullyBufferedOutputStream.flush(UiEventHandler.java:146)
at com.google.devtools.build.lib.util.io.AnsiTerminal.flush(AnsiTerminal.java:192)
at com.google.devtools.build.lib.runtime.UiEventHandler.handleLocked(UiEventHandler.java:373)
- locked <0x00000000b6434608> (a com.google.devtools.build.lib.runtime.UiEventHandler)
at com.google.devtools.build.lib.runtime.UiEventHandler.handleInternal(UiEventHandler.java:443)
at com.google.devtools.build.lib.runtime.UiEventHandler.handle(UiEventHandler.java:471)
at com.google.devtools.build.lib.events.Reporter.handle(Reporter.java:127)
at com.google.devtools.build.lib.remote.GoogleChannelConnectionFactory$1.onFailure(GoogleChannelConnectionFactory.java:153)
at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1119)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1286)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:1055)
at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:807)
at com.google.common.util.concurrent.AbstractTransformFuture.run(AbstractTransformFuture.java:105)
at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:31)
at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1286)
at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:1055)
at com.google.common.util.concurrent.AbstractFuture.setFuture(AbstractFuture.java:850)
at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleAsyncTask.afterRanInterruptiblySuccess(TrustedListenableFutureTask.java:175)
at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleAsyncTask.afterRanInterruptiblySuccess(TrustedListenableFutureTask.java:150)
at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:88)
at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:82)
at java.util.concurrent.Executors$RunnableAdapter.call(java.base@21/Unknown Source)
at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:131)
at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:75)
at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:82)
at java.util.concurrent.Executors$RunnableAdapter.call(java.base@21/Unknown Source)
at java.util.concurrent.FutureTask.run(java.base@21/Unknown Source)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@21/Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@21/Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@21/Unknown Source)
at java.lang.Thread.runWith(java.base@21/Unknown Source)
at java.lang.Thread.run(java.base@21/Unknown Source)
Locked ownable synchronizers:
- <0x00000000a6154d70> (a java.util.concurrent.ThreadPoolExecutor$Worker)
- <0x00000000b646a148> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
```
#### OS Config Comparison
I have no idea why this only happens in Mariner2 OS. I was thinking maybe the OS config can be different, so I compared the `sudo sysctl -a` between Mariner2 and RedHat 8.
Attached is the diff, the upper one is from RedHat, and the lower one is from Mariner2. But none of the diff seems alarming, most of them are system limit diffs. The system limit in RedHat is higher, but this internal repo is not big. I don't think it will ever hit the system limit. In fact when this happened, we still have plenty of resources.

```
46,47c43,44
< fs.aio-nr = 2661
< fs.dentry-state = 2151253 2003357 45 0 159548 0
---
> fs.aio-nr = 0
> fs.dentry-state = 1369950 1321714 45 0 105523 0
49c46
< fs.epoll.max_user_watches = 88139330
---
> fs.epoll.max_user_watches = 58730273
54,56c51,53
< fs.file-nr = 4832 0 9223372036854775807
< fs.inode-nr = 1975385 626
< fs.inode-state = 1975385 626 0 0 0 0 0
---
> fs.file-nr = 4512 0 9223372036854775807
> fs.inode-nr = 1249730 626
> fs.inode-state = 1249730 626 0 0 0 0 0
84c81
< fs.quota.syncs = 400
---
> fs.quota.syncs = 178
150c147
< kernel.ns_last_pid = 202021
---
> kernel.ns_last_pid = 151400
179c176
< kernel.pty.nr = 11
---
> kernel.pty.nr = 5
181c178
< kernel.random.boot_id = d2201315-0983-4869-a5f1-67ee507427ff
---
> kernel.random.boot_id = 9639f382-8124-4cb7-ad90-49297ccd5952
185c182
< kernel.random.uuid = 3983875c-e45e-4c0e-af77-620f1984fbbc
---
> kernel.random.uuid = ad694d03-022c-4998-a742-9af849346f19
215c212
< kernel.threads-max = 3093269
---
> kernel.threads-max = 2061152
226c223
< kernel.watchdog_cpumask = 0-95
---
> kernel.watchdog_cpumask = 0-63
816c813
< net.netfilter.nf_conntrack_max = 3145728
---
> net.netfilter.nf_conntrack_max = 2097152
856c853
< user.max_cgroup_namespaces = 1546634
---
> user.max_cgroup_namespaces = 1030576
861,867c858,864
< user.max_ipc_namespaces = 1546634
< user.max_mnt_namespaces = 1546634
< user.max_net_namespaces = 1546634
< user.max_pid_namespaces = 1546634
< user.max_time_namespaces = 1546634
< user.max_user_namespaces = 1546634
< user.max_uts_namespaces = 1546634
---
> user.max_ipc_namespaces = 1030576
> user.max_mnt_namespaces = 1030576
> user.max_net_namespaces = 1030576
> user.max_pid_namespaces = 1030576
> user.max_time_namespaces = 1030576
> user.max_user_namespaces = 1030576
> user.max_uts_namespaces = 1030576
886c883
< vm.min_free_kbytes = 79592
---
> vm.min_free_kbytes = 67584
```
#### gRPC log
The stuck Bazel invocation has the gRPC log as below. The gRPC invocation went through with the expected timed out without issue.
```
metadata {
tool_details {
tool_name: "bazel"
tool_version: "7.4.1"
}
action_id: "capabilities"
tool_invocation_id: "d9475b6a-5c26-4366-b64b-dfebd334f441"
correlated_invocations_id: "254786ba-05a9-48f6-9b7f-eb766e2e4073"
}
status {
code: 14
message: "io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection timed out: /1.2.3.4:8980"
}
method_name: "build.bazel.remote.execution.v2.Capabilities/GetCapabilities"
details {
get_capabilities {
request {
}
}
}
start_time {
seconds: 1741926226
nanos: 384000000
}
end_time {
seconds: 1741926246
nanos: 621000000
}
```
### Which category does this issue belong to?
_No response_
### What's the simplest, easiest way to reproduce this bug? Please provide a minimal example if possible.
Unfortunately this cannot be reproduced easily with a sample project.
I can only reproduce this issue in our cloudIDE with one internal repo with the combination of `bazel build //... && bazel run foo && bazel test //...` command.
These are the snippets of our `.bazelrc` for this repo
```
--jobs=200
--define=EXECUTOR=remote
--spawn_strategy=remote,sandboxed,local
--disk_cache=
--incompatible_strict_action_env=true
--remote_timeout=600
--grpc_keepalive_time=61s
--remote_local_fallback
# Use a dummy IP address to simulate the RBE service is down
--remote_executor=grpc://1.2.3.4:8980
```
### Which operating system are you running Bazel on?
Linux Mariner 2.0.20241208
### What is the output of `bazel info release`?
release 7.4.1
### If `bazel info release` returns `development version` or `(@non-git)`, tell us how you built Bazel.
_No response_
### What's the output of `git remote get-url origin; git rev-parse HEAD` ?
```text
```
### If this is a regression, please try to identify the Bazel commit where the bug was introduced with bazelisk --bisect.
_No response_
### Have you found anything relevant by searching the web?
The log in #13985 seems similar. But it is just a visual bug and is different
### Any other information, logs, or outputs that you want to share?
Contributor guide
Assessment
This issue has not been assessed yet.