Test failure on MacOS when Docker is enabled

[garydgregory]

Description

[ERROR] DOCKER> I/O Error [[elasticsearch:8.17.3] "elasticsearch": Timeout after 60764 ms while waiting on tcp port '[/172.19.0.2:9200]']

Configuration

Version:
2.25.1 RC1

Operating system:
Darwin xxxx.local 24.5.0 Darwin Kernel Version 24.5.0: Tue Apr 22 19:53:27 PDT 2025; root:xnu-11417.121.6~2/RELEASE_ARM64_T6041 arm64

JDK:
openjdk version "17.0.15" 2025-04-15
OpenJDK Runtime Environment Homebrew (build 17.0.15+0)
OpenJDK 64-Bit Server VM Homebrew (build 17.0.15+0, mixed mode, sharing)

Logs

[INFO] --- docker:0.46.0:start (start) @ log4j-layout-template-json-test ---
[INFO] DOCKER> Pulling from library/elasticsearch
[INFO] DOCKER> Digest: sha256:2cc40b15dff85281ac804e7ff27cbc07b31fdd542e94ea7a2bdb6470e3b6bb68
[INFO] DOCKER> Status: Image is up to date for elasticsearch:8.17.3
[INFO] DOCKER> Pulled elasticsearch:8.17.3 in 1 second 
[INFO] DOCKER> [elasticsearch:8.17.3] "elasticsearch": Start container a095e36ff18f
[INFO] DOCKER> [elasticsearch:8.17.3] "elasticsearch": Network mode: log4j-layout-template-json-network
[INFO] DOCKER> [elasticsearch:8.17.3] "elasticsearch": Waiting for ports [9200] directly on container with IP (172.19.0.2).
[ES]CompileCommand: dontinline java/lang/invoke/MethodHandle.setAsTypeCache bool dontinline = true
[ES]CompileCommand: dontinline java/lang/invoke/MethodHandle.asTypeUncached bool dontinline = true
[ES]{"@timestamp":"2025-07-05T21:34:10.285Z", "log.level": "INFO", "message":"vec_caps=1", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.nativeaccess.jdk.JdkVectorLibrary","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:10.297Z", "log.level": "INFO", "message":"Using native vector library; to disable start with -Dorg.elasticsearch.nativeaccess.enableVectorLibrary=false", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.nativeaccess.NativeAccess","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:10.302Z", "log.level": "INFO", "message":"Using [jdk] native provider and native methods for [Linux]", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.nativeaccess.NativeAccess","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:10.352Z", "log.level": "INFO", "message":"Java vector incubator API enabled; uses preferredBitSize=128; FMA enabled", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.apache.lucene.internal.vectorization.PanamaVectorizationProvider","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:10.352Z", "log.level": "INFO", "message":"Bootstrapping java SecurityManager", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.jdk.JarHell","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:10.738Z", "log.level": "INFO", "message":"version[8.17.3], pid[75], build[docker/a091390de485bd4b127884f7e565c0cad59b10d2/2025-02-28T10:07:26.089129809Z], OS[Linux/6.10.14-linuxkit/aarch64], JVM[Oracle Corporation/OpenJDK 64-Bit Server VM/23/23+37-2369]", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.node.Node","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:10.739Z", "log.level": "INFO", "message":"JVM home [/usr/share/elasticsearch/jdk], using bundled JDK [true]", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.node.Node","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:10.739Z", "log.level": "INFO", "message":"JVM arguments [-Des.networkaddress.cache.ttl=60, -Des.networkaddress.cache.negative.ttl=10, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Dlog4j2.formatMsgNoLookups=true, -Djava.locale.providers=CLDR, -Des.distribution.type=docker, --enable-native-access=org.elasticsearch.nativeaccess,org.apache.lucene.core, -Des.cgroups.hierarchy.override=/, -XX:ReplayDataFile=logs/replay_pid%p.log, -Djava.security.manager=allow, -XX:+UseG1GC, -Djava.io.tmpdir=/tmp/elasticsearch-7937828610198152103, --add-modules=jdk.incubator.vector, -XX:CompileCommand=dontinline,java/lang/invoke/MethodHandle.setAsTypeCache, -XX:CompileCommand=dontinline,java/lang/invoke/MethodHandle.asTypeUncached, -XX:+HeapDumpOnOutOfMemoryError, -XX:+ExitOnOutOfMemoryError, -XX:HeapDumpPath=data, -XX:ErrorFile=logs/hs_err_pid%p.log, -Xlog:gc*,gc+age=trace,safepoint:file=logs/gc.log:utctime,level,pid,tags:filecount=32,filesize=64m, -Xms750m, -Xmx750m, -XX:MaxDirectMemorySize=393216000, -XX:G1HeapRegionSize=4m, -XX:InitiatingHeapOccupancyPercent=30, -XX:G1ReservePercent=15, --module-path=/usr/share/elasticsearch/lib, --add-modules=jdk.net, --add-modules=ALL-MODULE-PATH, -Djdk.module.main=org.elasticsearch.server]", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"main","log.logger":"org.elasticsearch.node.Node","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
...<snip>...
[ES]{"@timestamp":"2025-07-05T21:34:16.721Z", "log.level": "INFO", "message":"Node [{a095e36ff18f}{13i7T2GORDeL3EeLVRw7eA}] is selected as the current health node.", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch[a095e36ff18f][management][T#3]","log.logger":"org.elasticsearch.health.node.selection.HealthNodeTaskExecutor","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:16.764Z", "log.level": "INFO", "message":"license [39446f65-ce36-4e5d-99b7-7ae240837601] mode [basic] - valid", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch[a095e36ff18f][clusterApplierService#updateTask][T#1]","log.logger":"org.elasticsearch.license.ClusterStateLicenseService","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:16.776Z", "log.level": "INFO", "message":"adding ingest pipeline metrics-apm.internal@default-pipeline", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch[a095e36ff18f][masterService#updateTask][T#1]","log.logger":"org.elasticsearch.xpack.core.template.IndexTemplateRegistry","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:16.776Z", "log.level": "INFO", "message":"adding ingest pipeline traces-apm@pipeline", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch[a095e36ff18f][masterService#updateTask][T#1]","log.logger":"org.elasticsearch.xpack.core.template.IndexTemplateRegistry","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:34:16.776Z", "log.level": "INFO", "message":"adding ingest pipeline metrics-apm@pipeline", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch[a095e36ff18f][masterService#updateTask][T#1]","log.logger":"org.elasticsearch.xpack.core.template.IndexTemplateRegistry","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ERROR] DOCKER> [elasticsearch:8.17.3] "elasticsearch": Timeout after 60764 ms while waiting on tcp port '[/172.19.0.2:9200]'
[ERROR] DOCKER> Error occurred during container startup, shutting down...
[ES]{"@timestamp":"2025-07-05T21:35:09.597Z", "log.level": "INFO", "message":"stopping ...", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch-shutdown","log.logger":"org.elasticsearch.node.Node","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.598Z", "log.level": "INFO", "message":"shutting down watcher thread", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch[file-watcher[/usr/share/elasticsearch/config/operator/settings.json]]","log.logger":"org.elasticsearch.common.file.AbstractFileWatchingService","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.598Z", "log.level": "INFO", "message":"watcher service stopped", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch-shutdown","log.logger":"org.elasticsearch.common.file.AbstractFileWatchingService","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.599Z", "log.level": "INFO", "message":"stopping watch service, reason [shutdown initiated]", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch-shutdown","log.logger":"org.elasticsearch.xpack.watcher.WatcherService","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.599Z", "log.level": "INFO", "message":"[controller/116] [Main.cc@176] ML controller exiting", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"ml-cpp-log-tail-thread","log.logger":"org.elasticsearch.xpack.ml.process.logging.CppLogMessageHandler","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.600Z", "log.level": "INFO", "message":"Stopping watcher engine", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch-shutdown","log.logger":"org.elasticsearch.xpack.watcher.trigger.schedule.engine.TickerScheduleTriggerEngine","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.600Z", "log.level": "INFO", "message":"Native controller process has stopped - no new native processes can be started", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"ml-cpp-log-tail-thread","log.logger":"org.elasticsearch.xpack.ml.process.NativeController","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.600Z", "log.level": "INFO", "message":"watcher has stopped and shutdown", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch[a095e36ff18f][generic][T#3]","log.logger":"org.elasticsearch.xpack.watcher.WatcherLifeCycleService","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.684Z", "log.level": "INFO", "message":"stopped", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch-shutdown","log.logger":"org.elasticsearch.node.Node","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.684Z", "log.level": "INFO", "message":"closing ...", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch-shutdown","log.logger":"org.elasticsearch.node.Node","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}
[ES]{"@timestamp":"2025-07-05T21:35:09.690Z", "log.level": "INFO", "message":"closed", "ecs.version": "1.2.0","service.name":"ES_ECS","event.dataset":"elasticsearch.server","process.thread.name":"elasticsearch-shutdown","log.logger":"org.elasticsearch.node.Node","elasticsearch.cluster.uuid":"FPW8xxAqT3CDynepo_tR8A","elasticsearch.node.id":"13i7T2GORDeL3EeLVRw7eA","elasticsearch.node.name":"a095e36ff18f","elasticsearch.cluster.name":"docker-cluster"}

[INFO] DOCKER> [elasticsearch:8.17.3] "elasticsearch": Stop and removed container a095e36ff18f after 0 ms
[ERROR] DOCKER> I/O Error [[elasticsearch:8.17.3] "elasticsearch": Timeout after 60764 ms while waiting on tcp port '[/172.19.0.2:9200]']
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary for Apache Log4j BOM 2.25.1:
[INFO] 
[INFO] Apache Log4j BOM ................................... SUCCESS [  6.055 s]
[INFO] Apache Log4j Parent ................................ SUCCESS [  0.509 s]
[INFO] Apache Log4j API Java 9 support .................... SUCCESS [  3.446 s]
[INFO] Apache Log4j API ................................... SUCCESS [  8.604 s]
[INFO] Apache Log4j Implementation Java 9 support ......... SUCCESS [  2.289 s]
[INFO] Apache Log4j Core .................................. SUCCESS [ 18.460 s]
[INFO] Apache Log4j API Tests ............................. SUCCESS [ 10.840 s]
[INFO] Apache Log4j Core Tests ............................ SUCCESS [01:29 min]
[INFO] Apache Log4j 1.x Compatibility API ................. SUCCESS [ 11.511 s]
[INFO] Apache Log4j App Server Support .................... SUCCESS [  1.802 s]
[INFO] Log4j API to SLF4J Adapter ......................... SUCCESS [  3.457 s]
[INFO] SLF4J 1 Binding for Log4j API ...................... SUCCESS [  4.185 s]
[INFO] Apache Log4j Cassandra ............................. SUCCESS [  3.370 s]
[INFO] Apache Log4j fuzz tests ............................ SUCCESS [  1.948 s]
[INFO] Apache Log4j Core fuzz tests ....................... SUCCESS [  1.478 s]
[INFO] Apache Log4j Core Integration Tests ................ SUCCESS [  0.836 s]
[INFO] Apache Log4j CouchDB ............................... SUCCESS [  2.051 s]
[INFO] Apache Log4j Docker Library ........................ SUCCESS [  2.028 s]
[INFO] Apache Log4j Streaming Interface ................... SUCCESS [  5.049 s]
[INFO] Apache Log4j Jakarta JMS ........................... SUCCESS [  3.468 s]
[INFO] Apache Log4j Jakarta SMTP .......................... SUCCESS [  3.206 s]
[INFO] Apache Log4j Jakarta Web ........................... SUCCESS [  4.107 s]
[INFO] Apache Log4j Commons Logging Bridge ................ SUCCESS [  2.749 s]
[INFO] Apache Log4j JPA ................................... SUCCESS [  4.756 s]
[INFO] Apache Log4j JDK Platform Logging Adapter .......... SUCCESS [  2.719 s]
[INFO] Apache Log4j JDBC DBCP 2 ........................... SUCCESS [  2.991 s]
[INFO] Apache Log4j JUL Adapter ........................... SUCCESS [  6.793 s]
[INFO] Apache Log4j JSON Template Layout .................. SUCCESS [  4.556 s]
[INFO] Apache Log4j JSON Template Layout fuzz tests ....... SUCCESS [  1.573 s]
[INFO] Apache Log4j JSON Template Layout tests ............ FAILURE [01:13 min]
[INFO] Apache Log4j MongoDB 4 ............................. SKIPPED
[INFO] Apache Log4j MongoDB Appender ...................... SKIPPED
[INFO] Apache Log4j to JUL Bridge ......................... SKIPPED
[INFO] Apache Log4j OSGi tests ............................ SKIPPED
[INFO] Apache Log4J Performance Tests ..................... SKIPPED
[INFO] SLF4J 2 Provider for Log4j API ..................... SKIPPED
[INFO] SLF4J 2 Provider for Log4j API fuzz tests .......... SKIPPED
[INFO] Apache Log4j Spring Boot Support ................... SKIPPED
[INFO] Apache Log4j Spring Cloud Config Client Support .... SKIPPED
[INFO] Apache Log4j Web ................................... SKIPPED
[INFO] Apache Log4j Tag Library ........................... SKIPPED
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  04:47 min
[INFO] Finished at: 2025-07-05T17:35:12-04:00
[INFO] ------------------------------------------------------------------------

Reproduction

mvn clean verify -Pdocker -D'docker.showLogs=true'