Bazel CI: Bazel server sometimes failed to bind a port when running inside integration tests

[meteorcloudy]

Description of the bug:

There are many flaky tests on macOS failing with something like:

** test_clean_color_nobuild ****************************************************
-- Test log: -----------------------------------------------------------
$TEST_TMPDIR defined: output root default is '/private/var/tmp/_bazel_buildkite/1c0ceab0af4031157e5d6c93b5a52b2e/sandbox/darwin-sandbox/8204/execroot/_main/_tmp/b4351c2a9b2566a3d9173bc00d39ec9b' and max_idle_secs default is '15'.
Starting local Bazel server and connecting to it...
INFO: Reading 'startup' options from /private/var/tmp/_bazel_buildkite/1c0ceab0af4031157e5d6c93b5a52b2e/sandbox/darwin-sandbox/8204/execroot/_main/_tmp/b4351c2a9b2566a3d9173bc00d39ec9b/bazelrc: --output_user_root=/private/var/tmp/_bazel_buildkite/1c0ceab0af4031157e5d6c93b5a52b2e/sandbox/darwin-sandbox/8204/execroot/_main/_tmp/b4351c2a9b2566a3d9173bc00d39ec9b/root --install_base=/Users/buildkite/bazeltest/install_base --host_jvm_args=-Djava.net.preferIPv6Addresses=true
Server crashed during startup. Now printing /private/var/tmp/_bazel_buildkite/1c0ceab0af4031157e5d6c93b5a52b2e/sandbox/darwin-sandbox/8204/execroot/_main/_tmp/b4351c2a9b2566a3d9173bc00d39ec9b/root/1cdf043d4d10d60fb094c46d302e5fea/server/jvm.out
OpenJDK 64-Bit Server VM warning: Options -Xverify:none and -noverify were deprecated in JDK 13 and will likely be removed in a future release.
gRPC server failed to bind to IPv4 and IPv6 localhosts on port 0: [IPv4] Failed to bind to address /127.0.0.1:0
[IPv6] Failed to bind to address /[0:0:0:0:0:0:0:1]:0
com.google.devtools.build.lib.util.AbruptExitException: gRPC server failed to bind to IPv4 and IPv6 localhosts on port 0: [IPv4] Failed to bind to address /127.0.0.1:0
[IPv6] Failed to bind to address /[0:0:0:0:0:0:0:1]:0
	at com.google.devtools.build.lib.server.GrpcServerImpl.serve(GrpcServerImpl.java:438)
	at com.google.devtools.build.lib.runtime.BlazeRuntime.serverMain(BlazeRuntime.java:1068)
	at com.google.devtools.build.lib.runtime.BlazeRuntime.main(BlazeRuntime.java:771)
	at com.google.devtools.build.lib.bazel.Bazel.main(Bazel.java:95)
Caused by: java.io.IOException: Failed to bind to address /127.0.0.1:0
	at io.grpc.netty.NettyServer.start(NettyServer.java:328)
	at io.grpc.internal.ServerImpl.start(ServerImpl.java:183)
	at io.grpc.internal.ServerImpl.start(ServerImpl.java:92)
	at com.google.devtools.build.lib.server.GrpcServerImpl.serve(GrpcServerImpl.java:435)
	... 3 more
Caused by: java.net.SocketException: Operation not permitted
	at java.base/sun.nio.ch.Net.bind0(Native Method)
	at java.base/sun.nio.ch.Net.bind(Unknown Source)
	at java.base/sun.nio.ch.ServerSocketChannelImpl.netBind(Unknown Source)
	at java.base/sun.nio.ch.ServerSocketChannelImpl.bind(Unknown Source)
	at io.netty.channel.socket.nio.NioServerSocketChannel.doBind(NioServerSocketChannel.java:141)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.bind(AbstractChannel.java:562)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.bind(DefaultChannelPipeline.java:1334)
	at io.netty.channel.AbstractChannelHandlerContext.invokeBind(AbstractChannelHandlerContext.java:600)
	at io.netty.channel.AbstractChannelHandlerContext.bind(AbstractChannelHandlerContext.java:579)
	at io.netty.channel.DefaultChannelPipeline.bind(DefaultChannelPipeline.java:973)
	at io.netty.channel.AbstractChannel.bind(AbstractChannel.java:260)
	at io.netty.bootstrap.AbstractBootstrap$2.run(AbstractBootstrap.java:356)
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Unknown Source)

This started to happen after when enabling ipv6 on macOS machines due to recent infrastructure changes.

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.

This error is so far only reproducible on CI when running a large number of tests together, see
https://buildkite.com/bazel/bazel-bazel/builds/26101#018cd24a-0086-4792-92bc-16b274588cb4

Which operating system are you running Bazel on?

macOS arm64

What is the output of bazel info release?

No response

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 master; git rev-parse HEAD ?

No response

Is this a regression? If yes, please try to identify the Bazel commit where the bug was introduced.

No response

Have you found anything relevant by searching the web?

Maybe related to #2486

Any other information, logs, or outputs that you want to share?

This seems to only happen with --sandbox_default_allow_network=false which we use to block internet access for all integration tests.

[meteorcloudy]

The code related to the failure:

bazel/src/main/java/com/google/devtools/build/lib/server/GrpcServerImpl.java

Lines 414 to 447 in 1f2d576

	// For reasons only Apple knows, you cannot bind to IPv4-localhost when you run in a sandbox
	// that only allows loopback traffic, but binding to IPv6-localhost works fine. This would
	// however break on systems that don't support IPv6. So what we'll do is to try to bind to IPv6
	// and if that fails, try again with IPv4.
	InetSocketAddress address = new InetSocketAddress("[::1]", port);
	try {
	// TODO(bazel-team): Remove the following check after upgrading netty to a version with a fix
	// for https://github.com/netty/netty/issues/10402
	if (Epoll.isAvailable() && !Socket.isIPv6Preferred()) {
	throw new IOException("ipv6 is not preferred on the system.");
	}
	server =
	NettyServerBuilder.forAddress(address).addService(this).directExecutor().build().start();
	} catch (IOException ipv6Exception) {
	address = new InetSocketAddress("127.0.0.1", port);
	try {
	server =
	NettyServerBuilder.forAddress(address)
	.addService(this)
	.directExecutor()
	.build()
	.start();
	} catch (IOException ipv4Exception) {
	throw new AbruptExitException(
	DetailedExitCode.of(
	createFailureDetail(
	String.format(
	"gRPC server failed to bind to IPv4 and IPv6 localhosts on port %d: [IPv4] "
	+ "%s\n[IPv6] %s",
	port, ipv4Exception.getMessage(), ipv6Exception.getMessage()),
	GrpcServer.Code.SERVER_BIND_FAILURE)),
	ipv4Exception);
	}
	}

[meteorcloudy]

We can temporarily set --sandbox_default_allow_network to true for macOS to mitigate the CI flakiness.

[meteorcloudy]

This is reproducible on CI with running bazel version inside a simple shell test with:

      - "--runs_per_test=10000"
      - "--local_test_jobs=100"
      - "--jobs=100"
      - "--flaky_test_attempts=1"

See https://bazel-review.git.corp.google.com/c/bazel/+/236871/8
Log: https://buildkite.com/bazel/google-bazel-presubmit/builds/75609#018cd47a-15c5-4d61-9741-85b51421a752

[meteorcloudy]

The issue doesn't seem to be reproducible with a simple Java binary trying to bind a port:
https://bazel-review.git.corp.google.com/c/bazel/+/236871/13
Log: https://buildkite.com/bazel/google-bazel-presubmit/builds/75615#_

[meteorcloudy]

Tried to bind with netty, still not reproducible:
https://bazel-review.git.corp.google.com/c/bazel/+/236871/14
Log: https://buildkite.com/bazel/google-bazel-presubmit/builds/75619#018cd4bd-77dd-4ffc-8b2e-bbc3c3c13fdd

[meteorcloudy]

Tried to carve out the grpc + netty code from GrpcServerImpl.java and bind a socket in a simple Java binary, now it's reproducible:
https://bazel-review.git.corp.google.com/c/bazel/+/236871/15
https://buildkite.com/bazel/google-bazel-presubmit/builds/75629#018cd4f9-b4e8-4abf-853b-c32dc85b134c

[lberki]

Well that's impressive work. I'm surprised that this is something specific to gRPC + Netty and neither Netty alone nor plain Java reproduces the problem. Maybe ktrace would shed some light on what's going on behind the scenes? (I'm not very familiar with Mac OS, but that seems to be the "dump all the system calls a process does" equivalent of strace)

(Also, it's probably easier to choose either IPv6 or IPv4 for the testing code)

[meteorcloudy]

I managed to reproduce with

import io.grpc.Server;
import io.grpc.netty.NettyServerBuilder;
import java.net.InetSocketAddress;

public class SocketBindingExample {

  public static void main(String[] args) throws Exception {
    InetSocketAddress address = new InetSocketAddress("[::1]", 0);
    Server server = NettyServerBuilder.forAddress(address).directExecutor().build().start();
    System.out.println("Server successfully started with IPv6 at port: " + server.getPort());
  }
}

built with the following BUILD file in the Bazel repo

java_binary(
    name = "bind",
    srcs = ["SocketBindingExample.java"],
    main_class = "SocketBindingExample",
    deps = [
        "//third_party:netty",
        "//third_party/grpc-java:grpc-jar",
    ],
)

and run /usr/bin/sandbox-exec -f no-internet.sb /Users/ci/workdir-pcloudy/bazel/bazel-bin/src/test/shell/bazel/bind with config

(version 1)
(debug deny)
(allow default)
(allow process-exec (with no-sandbox) (literal "/bin/ps"))
(deny network*)
(allow network-inbound (local ip "localhost:*"))
(allow network* (remote ip "localhost:*"))
(allow network* (remote unix-socket))

which failed on macstudio9 with (after a few tries)

ci@bk-macstudio-9 sandbox_grpc_bug % /usr/bin/sandbox-exec -f no-internet.sb /Users/ci/workdir-pcloudy/bazel/bazel-bin/src/test/shell/bazel/bind
Exception in thread "main" java.io.IOException: Failed to bind to address /0:0:0:0:0:0:0:1:0
	at io.grpc.netty.NettyServer.start(NettyServer.java:328)
	at io.grpc.internal.ServerImpl.start(ServerImpl.java:185)
	at io.grpc.internal.ServerImpl.start(ServerImpl.java:94)
	at SocketBindingExample.main(SocketBindingExample.java:23)
Caused by: java.net.SocketException: Operation not permitted
	at java.base/sun.nio.ch.Net.bind0(Native Method)
	at java.base/sun.nio.ch.Net.bind(Net.java:459)
	at java.base/sun.nio.ch.Net.bind(Net.java:448)
	at java.base/sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:227)
	at io.netty.channel.socket.nio.NioServerSocketChannel.doBind(NioServerSocketChannel.java:141)
	at io.netty.channel.AbstractChannel$AbstractUnsafe.bind(AbstractChannel.java:562)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.bind(DefaultChannelPipeline.java:1334)
	at io.netty.channel.AbstractChannelHandlerContext.invokeBind(AbstractChannelHandlerContext.java:600)
	at io.netty.channel.AbstractChannelHandlerContext.bind(AbstractChannelHandlerContext.java:579)
	at io.netty.channel.DefaultChannelPipeline.bind(DefaultChannelPipeline.java:973)
	at io.netty.channel.AbstractChannel.bind(AbstractChannel.java:260)
	at io.netty.bootstrap.AbstractBootstrap$2.run(AbstractBootstrap.java:356)
	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:569)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:829)

[tjgq]

Is it because localhost in the sandbox-exec config means specifically 127.0.0.1, not ::1?

[meteorcloudy]

Is it because localhost in the sandbox-exec config means specifically 127.0.0.1, not ::1?

This shouldn't happen randomly right?

[meteorcloudy]

Retrying seems to work:

public class SocketBindingExample {

    public static void main(String[] args) throws Exception {
        InetSocketAddress address = new InetSocketAddress("[::1]", 0);
        int maxRetries = 5; // Maximum number of retries
        int retryDelay = 100; // Delay in milliseconds before retrying

        for (int attempt = 1; attempt <= maxRetries; attempt++) {
            try {
                Server server = NettyServerBuilder.forAddress(address).directExecutor().build().start();
                System.out.println("Server successfully started with IPv6 at port: " + server.getPort());
                break; // Break the loop if the server starts successfully
            } catch (IOException e) {
                System.err.println("Attempt " + attempt + " failed: " + e.getMessage());
                if (attempt == maxRetries) {
                    throw e; // Rethrow the exception if the maximum number of retries is reached
                }
                Thread.sleep(retryDelay); // Wait for a while before retrying
            }
        }
    }
}

ci@bk-macstudio-9 sandbox_grpc_bug % /usr/bin/sandbox-exec -f no-internet.sb /Users/ci/workdir-pcloudy/bazel/bazel-bin/src/test/shell/bazel/bind
Attempt 1 failed: Failed to bind to address /0:0:0:0:0:0:0:1:0
Server successfully started with IPv6 at port: 65220

might be an acceptable workaround? @lberki

[lberki]

I'm not really happy about it but it sure beats disabling the sandbox on our CI machines.

[meteorcloudy]

disabling the sandbox on our CI machines.

To be precise, we are only turning --sandbox_default_allow_network on, but not disabling sandbox, however that still makes our tests less hermetic on macOS.

Yeah, I guess this has to be fixed on the grpc side, so there isn't a quick fix likely.

[sergiitk]

Hi, grpc team here. Not sure what do you mean has to be fixed on our side. Wouldn't it rather be a /usr/bin/sandbox-exec issue? gRPC server just reports it couldn't bind the ip:port, this could be cause by any number of issues, including a propagation delay in sandbox network permissions.

For the sake of experiment, I've tried to run it on my mac, all worked well:

❯ bazel version
Bazelisk version: v1.11.0
Build label: 7.0.0
Build target: @@//src/main/java/com/google/devtools/build/lib/bazel:BazelServer
Build time: Mon Dec 11 17:00:42 2023 (1702314042)
Build timestamp: 1702314042
Build timestamp as int: 1702314042

❯ bazel build //:bind
INFO: Analyzed target //:bind (4 packages loaded, 305 targets configured).
INFO: Found 1 target...
Target //:bind up-to-date:
  bazel-bin/bind
  bazel-bin/bind.jar
INFO: Elapsed time: 0.875s, Critical Path: 0.01s
INFO: 1 process: 1 internal.
INFO: Build completed successfully, 1 total action

❯ /usr/bin/sandbox-exec -f no-internet.sb /private/var/tmp/_bazel_sergiitk/e46e3a2c1d64f631a3a8e66ff55aab83/execroot/_main/bazel-out/darwin_x86_64-fastbuild/bin/bind
Server successfully started with IPv6 at port: 64249
❯ /usr/bin/sandbox-exec -f no-internet.sb /private/var/tmp/_bazel_sergiitk/e46e3a2c1d64f631a3a8e66ff55aab83/execroot/_main/bazel-out/darwin_x86_64-fastbuild/bin/bind
Server successfully started with IPv6 at port: 64250
❯ /usr/bin/sandbox-exec -f no-internet.sb /private/var/tmp/_bazel_sergiitk/e46e3a2c1d64f631a3a8e66ff55aab83/execroot/_main/bazel-out/darwin_x86_64-fastbuild/bin/bind
Server successfully started with IPv6 at port: 64258
❯ /usr/bin/sandbox-exec -f no-internet.sb /private/var/tmp/_bazel_sergiitk/e46e3a2c1d64f631a3a8e66ff55aab83/execroot/_main/bazel-out/darwin_x86_64-fastbuild/bin/bind
Server successfully started with IPv6 at port: 64259
❯ /usr/bin/sandbox-exec -f no-internet.sb /private/var/tmp/_bazel_sergiitk/e46e3a2c1d64f631a3a8e66ff55aab83/execroot/_main/bazel-out/darwin_x86_64-fastbuild/bin/bind
Server successfully started with IPv6 at port: 64261
❯ /usr/bin/sandbox-exec -f no-internet.sb /private/var/tmp/_bazel_sergiitk/e46e3a2c1d64f631a3a8e66ff55aab83/execroot/_main/bazel-out/darwin_x86_64-fastbuild/bin/bind
Server successfully started with IPv6 at port: 64268
❯ /usr/bin/sandbox-exec -f no-internet.sb /private/var/tmp/_bazel_sergiitk/e46e3a2c1d64f631a3a8e66ff55aab83/execroot/_main/bazel-out/darwin_x86_64-fastbuild/bin/bind
Server successfully started with IPv6 at port: 64271
❯ /usr/bin/sandbox-exec -f no-internet.sb /private/var/tmp/_bazel_sergiitk/e46e3a2c1d64f631a3a8e66ff55aab83/execroot/_main/bazel-out/darwin_x86_64-fastbuild/bin/bind
Server successfully started with IPv6 at port: 64274

[sergiitk]

I'm not running on arm though:
23.2.0 Darwin Kernel Version 23.2.0: Wed Nov 15 21:54:10 PST 2023; root:xnu-10002.61.3~2/RELEASE_X86_64 x86_64

[lberki]

FWIW, from the symptoms I saw, it's not clear whether it's an issue with the sandbox or gRPC.

Also, one could make the case that even if it's a bug in sandbox, it would be nice to have a workaround in gRPC because gRPC is more malleable than the operating system.

[meteorcloudy]

@sergiitk @lberki Now I believe this is probably an issue of the macOS sandbox-exec. @hvadehra managed to reproduce the same issue with a simple http server written in Python. So grpc is likely only a victim.

[lberki]

Well kudos to @hvadehra then :) -- Then the involvement of gRPC is probably limited to a workaround, if that.

[sergiitk]

Thanks for investigating this!

@lberki To be clear, grpc-java and grpc-python share no code at all, so I doubt workaround in grpc makes sense. I would understand if it was a bug in the java implementation, or JDK-specific (or, for that matter, a bug in py impl, or Python-interpreter specific). Retrying on the app side, as you did in #20755 is a very approach.

[meteorcloudy]

grpc-java and grpc-python share no code at all

I meant we reproduced with some minimal python code without grpc at all. So we are pretty sure this is a macOS sandbox problem instead of a grpc problem. Thanks for looking into this!

[fmeum]

@meteorcloudy Could you share @hvadehra's reproducer?

[meteorcloudy]

https://bazel-review.git.corp.google.com/c/bazel/+/237247/19/src/test/shell/darwin_sandbox_bind_test.sh

But so far, we have only managed to reproduce on certain CI machines, @hvadehra can probably share more findings?

[illicitonion]

@meteorcloudy That's a corp URL - could you push a branch or patch to github? Thanks!

[hvadehra]

// server.py

import socket
import http
from http.server import HTTPServer
import threading
import sys

class HTTPServerV6(HTTPServer):
    address_family = socket.AF_INET6

PORT = 0
Handler = http.server.SimpleHTTPRequestHandler
with HTTPServerV6(("::1", PORT), Handler) as httpd:
    thread = threading.Thread(target=httpd.serve_forever)
    thread.daemon = True
    thread.start()
    sys.exit(0)

repro one-liner:
while date && /usr/bin/sandbox-exec -p '(version 1) (debug deny) (allow default) (deny network*) (allow network* (local ip "localhost:*"))' python server.py || true; do sleep 1; done

^ On the problematic CI machines, when run in isolation, this fails reliably exactly every 15 seconds. If run in parallel with other bind attempts or test runs, one or both fail (once every 15 seconds).

sample: https://pastebin.com/raw/SEQQWrsX

[meteorcloudy]

That's a corp URL - could you push a branch or patch to github?

Looks like some recent change redirected me to the corp link, the original link is https://bazel-review.googlesource.com/c/bazel/+/237247. Hopefully it'll keep working.

[illicitonion]

@hvadehra Can you share uname -a from one of the bad machines? And do you have any information about what proportion of the machines are bad, and any correlating information between them?

[hvadehra]

Good: Darwin bk-macstudio-7 22.6.0 Darwin Kernel Version 22.6.0: Tue Nov 7 21:40:08 PST 2023; root:xnu-8796.141.3.702.9~2/RELEASE_ARM64_T6000 arm64

Bad: Darwin bk-macstudio-1 22.6.0 Darwin Kernel Version 22.6.0: Tue Nov 7 21:40:08 PST 2023; root:xnu-8796.141.3.702.9~2/RELEASE_ARM64_T6000 arm64

7/10 are bad. The evidence notwithstanding, to our knowledge there shouldn't be and isn't any difference between them.