[Bug]: The very presence of HostConfig CPU quota leads to startup timeout exception #9580
Closed as not planned
Description
Module
Core
Testcontainers version
1.19.7
Using the latest Testcontainers version?
Yes (tried the latest with same outcome)
Host OS
Linux and macOS
Host Arch
x86 Linux and arm macOS
Docker version
Client:
Version: 25.0.5
API version: 1.44
Go version: go1.22.5
Git commit: 5dc9bcc
Built: Wed Aug 21 00:00:00 2024
OS/Arch: linux/amd64
Context: default
Server:
Engine:
Version: 25.0.6
API version: 1.44 (minimum version 1.24)
Go version: go1.22.5
Git commit: b08a51f
Built: Wed Aug 21 00:00:00 2024
OS/Arch: linux/amd64
Experimental: false
containerd:
Version: 1.7.23
GitCommit: 57f17b0a6295a39009d861b89e3b3b87b005ca27
runc:
Version: 1.1.14
GitCommit: 2c9f5602f0ba3d9da1c2596322dfc4e156844890
docker-init:
Version: 0.19.0
GitCommit: de40ad0What happened?
As I try to limit resource usage by test containers on CI builds (by setting cpu quota) I started to experience same, consistent startup timeouts.
org.testcontainers.shaded.org.awaitility.core.ConditionTimeoutException
org.testcontainers.containers.GenericContainer$$Lambda/0x00007fa08c5d19b0 expected the predicate to return <true> but it returned <false> for input of <InspectContainerResponse...> within 5 seconds
It seems that the very fact of CPU quota being defined leads to such behavior. I tried setting up CpuPeriod to 100_000 and CpuQuota to 1_600_000 (16 cores) for the container and still get the error.
It happens consistently for both containers I tried setting the limit for - postgres and rabbitmq.
As a side note, I'd imagine hardcoded 5 seconds timeout can be either parameterized as separate timeout or updated in order to use existing timeout set by withStartupTimeout.
So that total startup time should not exceed parameter value, but without any specific breakdown on how much time any given step of startup process took.
Is there any reasons why it is implemented this way?
Relevant log output
16:10:15 15:10:15.040 [Test worker] ERROR tc.xxxxxxxxxxxx.dkr.ecr.us-east-1.amazonaws.com/rabbitmq:3.12.13-management-alpine - Could not start container
16:10:15 org.testcontainers.shaded.org.awaitility.core.ConditionTimeoutException: org.testcontainers.containers.GenericContainer$$Lambda/0x00007f9af03e3730 expected the predicate to return <true> but it returned <false> for input of <InspectContainerResponse(args=[rabbitmq-server], config=ContainerConfig(attachStderr=false, attachStdin=false, attachStdout=false, cmd=[rabbitmq-server], domainName=, entrypoint=[docker-entrypoint.sh], env=[PATH=/opt/rabbitmq/sbin:/opt/erlang/bin:/opt/openssl/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin, ERLANG_INSTALL_PATH_PREFIX=/opt/erlang, OPENSSL_INSTALL_PATH_PREFIX=/opt/openssl, RABBITMQ_DATA_DIR=/var/lib/rabbitmq, RABBITMQ_VERSION=3.12.13, RABBITMQ_PGP_KEY_ID=0x0A9AF2115F4687BD29803A206B73A36E6026DFCA, RABBITMQ_HOME=/opt/rabbitmq, HOME=/var/lib/rabbitmq, LANG=C.UTF-8, LANGUAGE=C.UTF-8, LC_ALL=C.UTF-8], exposedPorts=[15671/tcp, 15672/tcp, 15691/tcp, 15692/tcp, 25672/tcp, 4369/tcp, 5671/tcp, 5672/tcp], hostName=c8115a7b819e, image=xxxxxxxxxxxx.dkr.ecr.us-east-1.amazonaws.com/rabbitmq:3.12.13-management-alpine, labels={org.testcontainers=true, org.testcontainers.lang=java, org.testcontainers.sessionId=5137bf9f-5782-44e1-85c8-b3f9a71b3071, org.testcontainers.version=1.19.7}, macAddress=null, networkDisabled=null, onBuild=null, stdinOpen=false, portSpecs=null, stdInOnce=false, tty=false, user=, volumes={/var/lib/rabbitmq={}}, workingDir=, healthCheck=null), created=2024-12-01T15:10:09.558756367Z, driver=overlay2, execDriver=null, hostConfig=HostConfig(binds=[], blkioWeight=0, blkioWeightDevice=null, blkioDeviceReadBps=null, blkioDeviceWriteBps=null, blkioDeviceReadIOps=null, blkioDeviceWriteIOps=null, memorySwappiness=null, nanoCPUs=0, capAdd=null, capDrop=null, containerIDFile=, cpuPeriod=100000, cpuRealtimePeriod=0, cpuRealtimeRuntime=0, cpuShares=0, cpuQuota=1600000, cpusetCpus=, cpusetMems=, devices=null, deviceCgroupRules=null, deviceRequests=null, diskQuota=null, dns=null, dnsOptions=null, dnsSearch=null, extraHosts=null, groupAdd=null, ipcMode=shareable, cgroup=, links=[], logConfig=LogConfig(type=json-file, config={}), lxcConf=null, memory=0, memorySwap=0, memoryReservation=0, kernelMemory=null, networkMode=default, oomKillDisable=null, init=null, autoRemove=false, oomScoreAdj=0, portBindings=null, privileged=false, publishAllPorts=false, readonlyRootfs=false, restartPolicy=no, ulimits=[Ulimit(name=nofile, soft=32768, hard=65536)], cpuCount=0, cpuPercent=0, ioMaximumIOps=0, ioMaximumBandwidth=0, volumesFrom=null, mounts=null, pidMode=, isolation=null, securityOpts=null, storageOpt=null, cgroupParent=, volumeDriver=, shmSize=67108864, pidsLimit=null, runtime=runc, tmpFs=null, utSMode=, usernsMode=, sysctls=null, consoleSize=[0, 0], cgroupnsMode=private), hostnamePath=/var/lib/docker/containers/c8115a7b819ea2631bde909aeb76e9efc01a97292f38bcd5685f2cd10900092a/hostname, hostsPath=/var/lib/docker/containers/c8115a7b819ea2631bde909aeb76e9efc01a97292f38bcd5685f2cd10900092a/hosts, logPath=/var/lib/docker/containers/c8115a7b819ea2631bde909aeb76e9efc01a97292f38bcd5685f2cd10900092a/c8115a7b819ea2631bde909aeb76e9efc01a97292f38bcd5685f2cd10900092a-json.log, id=c8115a7b819ea2631bde909aeb76e9efc01a97292f38bcd5685f2cd10900092a, sizeRootFs=null, sizeRw=null, imageId=sha256:34d834f9cc56ee9fdd31bce056fc4824311d87fdfc493af7e00fce54ca5f6009, mountLabel=, name=/zealous_shockley, restartCount=0, networkSettings=NetworkSettings(bridge=, sandboxId=09bbb4ef45c247b209ac4406840a7aed70af1effb63d4642c572aa7181c129ed, hairpinMode=false, linkLocalIPv6Address=, linkLocalIPv6PrefixLen=0, ports={15671/tcp=null, 5672/tcp=null, 25672/tcp=null, 4369/tcp=null, 15692/tcp=null, 5671/tcp=null, 15672/tcp=null, 15691/tcp=null}, sandboxKey=/var/run/docker/netns/09bbb4ef45c2, secondaryIPAddresses=null, secondaryIPv6Addresses=null, endpointID=ef3db543b4ce43a4af4f19ffcb8162cec7f19283b9ecc31aa786e0197d44ac45, gateway=172.17.0.1, portMapping=null, globalIPv6Address=, globalIPv6PrefixLen=0, ipAddress=172.17.0.3, ipPrefixLen=16, ipV6Gateway=, macAddress=02:42:ac:11:00:03, networks={bridge=ContainerNetwork(ipamConfig=null, links=[], aliases=null, networkID=e456b81f67fe925fb5269ea0b47193f80b81b1983f3f957ecfb8d80c03408504, endpointId=ef3db543b4ce43a4af4f19ffcb8162cec7f19283b9ecc31aa786e0197d44ac45, gateway=172.17.0.1, ipAddress=172.17.0.3, ipPrefixLen=16, ipV6Gateway=, globalIPv6Address=, globalIPv6PrefixLen=0, macAddress=02:42:ac:11:00:03)}), path=docker-entrypoint.sh, processLabel=, resolvConfPath=/var/lib/docker/containers/c8115a7b819ea2631bde909aeb76e9efc01a97292f38bcd5685f2cd10900092a/resolv.conf, execIds=null, state=InspectContainerResponse.ContainerState(status=running, running=true, paused=false, restarting=false, oomKilled=false, dead=false, pid=481180, exitCode=0, error=, startedAt=2024-12-01T15:10:09.98154266Z, finishedAt=0001-01-01T00:00:00Z, health=null), volumes=null, volumesRW=null, node=null, mounts=[InspectContainerResponse.Mount(name=45ff00503315abe52264d4b5e194208e4dd308a7ff2273d197b6fd3a0d0cde7b, source=/var/lib/docker/volumes/45ff00503315abe52264d4b5e194208e4dd308a7ff2273d197b6fd3a0d0cde7b/_data, destination=/var/lib/rabbitmq, driver=local, mode=, rw=true)], graphDriver=GraphDriver(name=overlay2, data=GraphData(rootDir=null, deviceId=null, deviceName=null, deviceSize=null, dir=null)), platform=linux)> within 5 seconds.
16:10:15 at org.testcontainers.shaded.org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:167) ~[testcontainers-1.19.7.jar:1.19.7]
16:10:15 at org.testcontainers.shaded.org.awaitility.core.AbstractHamcrestCondition.await(AbstractHamcrestCondition.java:86) ~[testcontainers-1.19.7.jar:1.19.7]
16:10:15 at org.testcontainers.shaded.org.awaitility.core.ConditionFactory.until(ConditionFactory.java:985) ~[testcontainers-1.19.7.jar:1.19.7]
16:10:15 at org.testcontainers.shaded.org.awaitility.core.ConditionFactory.until(ConditionFactory.java:691) ~[testcontainers-1.19.7.jar:1.19.7]
16:10:15 at org.testcontainers.shaded.org.awaitility.core.ConditionFactory.until(ConditionFactory.java:708) ~[testcontainers-1.19.7.jar:1.19.7]
16:10:15 at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:466) ~[testcontainers-1.19.7.jar:1.19.7]
16:10:15 at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:354) ~[testcontainers-1.19.7.jar:1.19.7]
16:10:15 at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81) [duct-tape-1.0.8.jar:?]
16:10:15 at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:344) [testcontainers-1.19.7.jar:1.19.7]
16:10:15 at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:330) [testcontainers-1.19.7.jar:1.19.7]
16:10:15 at my.TestContainerUtils.startContainer(TestContainerUtils.kt:56) [common-test-5.2.0.jar:?]
16:10:15 at my.TestContainerUtils.startContainer$default(TestContainerUtils.kt:36) [common-test-5.2.0.jar:?]
16:10:15 at my.RabbitMQInitializer.<clinit>(RabbitMQInitializer.kt:23) [common-test-5.2.0.jar:?]
16:10:15 at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized0(Native Method) ~[?:?]
16:10:15 at java.base/jdk.internal.misc.Unsafe.ensureClassInitialized(Unsafe.java:1160) [?:?]
16:10:15 at java.base/jdk.internal.reflect.MethodHandleAccessorFactory.ensureClassInitialized(MethodHandleAccessorFactory.java:300) [?:?]
16:10:15 at java.base/jdk.internal.reflect.MethodHandleAccessorFactory.newConstructorAccessor(MethodHandleAccessorFactory.java:103) [?:?]
16:10:15 at java.base/jdk.internal.reflect.ReflectionFactory.newConstructorAccessor(ReflectionFactory.java:200) [?:?]
16:10:15 at java.base/java.lang.reflect.Constructor.acquireConstructorAccessor(Constructor.java:549) [?:?]
16:10:15 at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499) [?:?]
16:10:15 at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:486) [?:?]
16:10:15 at org.springframework.beans.BeanUtils$KotlinDelegate.instantiateClass(BeanUtils.java:904) [spring-beans-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:189) [spring-beans-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:150) [spring-beans-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.boot.test.context.SpringBootContextLoader.getInitializers(SpringBootContextLoader.java:311) [spring-boot-test-3.2.5.jar:3.2.5]
16:10:15 at org.springframework.boot.test.context.SpringBootContextLoader.configure(SpringBootContextLoader.java:187) [spring-boot-test-3.2.5.jar:3.2.5]
16:10:15 at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:135) [spring-boot-test-3.2.5.jar:3.2.5]
16:10:15 at org.springframework.boot.test.context.SpringBootContextLoader.loadContext(SpringBootContextLoader.java:108) [spring-boot-test-3.2.5.jar:3.2.5]
16:10:15 at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContextInternal(DefaultCacheAwareContextLoaderDelegate.java:225) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.loadContext(DefaultCacheAwareContextLoaderDelegate.java:152) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.support.DefaultTestContext.getApplicationContext(DefaultTestContext.java:130) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.web.ServletTestExecutionListener.setUpRequestContextIfNecessary(ServletTestExecutionListener.java:191) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.web.ServletTestExecutionListener.prepareTestInstance(ServletTestExecutionListener.java:130) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:260) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:228) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:289) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) [junit-4.13.2.jar:4.13.2]
16:10:15 at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:291) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:247) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:97) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) [junit-4.13.2.jar:4.13.2]
16:10:15 at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) [junit-4.13.2.jar:4.13.2]
16:10:15 at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) [junit-4.13.2.jar:4.13.2]
16:10:15 at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) [junit-4.13.2.jar:4.13.2]
16:10:15 at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) [junit-4.13.2.jar:4.13.2]
16:10:15 at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) [junit-4.13.2.jar:4.13.2]
16:10:15 at org.junit.runners.ParentRunner.run(ParentRunner.java:413) [junit-4.13.2.jar:4.13.2]
16:10:15 at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:191) [spring-test-6.1.6.jar:6.1.6]
16:10:15 at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.runTestClass(JUnitTestClassExecutor.java:112) [gradle-testing-jvm-infrastructure-8.9.jar:8.9]
16:10:15 at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:58) [gradle-testing-jvm-infrastructure-8.9.jar:8.9]
16:10:15 at org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecutor.execute(JUnitTestClassExecutor.java:40) [gradle-testing-jvm-infrastructure-8.9.jar:8.9]
16:10:15 at org.gradle.api.internal.tasks.testing.junit.AbstractJUnitTestClassProcessor.processTestClass(AbstractJUnitTestClassProcessor.java:54) [gradle-testing-jvm-infrastructure-8.9.jar:8.9]
16:10:15 at org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:53) [gradle-testing-base-infrastructure-8.9.jar:8.9]
16:10:15 at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[?:?]
16:10:15 at java.base/java.lang.reflect.Method.invoke(Method.java:580) ~[?:?]
16:10:15 at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:36) [gradle-messaging-8.9.jar:8.9]
16:10:15 at org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) [gradle-messaging-8.9.jar:8.9]
16:10:15 at org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:33) [gradle-messaging-8.9.jar:8.9]
16:10:15 at org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:92) [gradle-messaging-8.9.jar:8.9]
16:10:15 at jdk.proxy2/jdk.proxy2.$Proxy6.processTestClass(Unknown Source) [?:?]
16:10:15 at org.gradle.api.internal.tasks.testing.worker.TestWorker$2.run(TestWorker.java:181) [gradle-testing-base-infrastructure-8.9.jar:8.9]
16:10:15 at org.gradle.api.internal.tasks.testing.worker.TestWorker.executeAndMaintainThreadName(TestWorker.java:130) [gradle-testing-base-infrastructure-8.9.jar:8.9]
16:10:15 at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:101) [gradle-testing-base-infrastructure-8.9.jar:8.9]
16:10:15 at org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:61) [gradle-testing-base-infrastructure-8.9.jar:8.9]
16:10:15 at org.gradle.process.internal.worker.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:56) [gradle-worker-main-8.9.jar:8.9]
16:10:15 at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:122) [gradle-worker-main-8.9.jar:8.9]
16:10:15 at org.gradle.process.internal.worker.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:69) [gradle-worker-main-8.9.jar:8.9]
16:10:15 at worker.org.gradle.process.internal.worker.GradleWorkerMain.run(GradleWorkerMain.java:69) [gradle-worker.jar:?]
16:10:15 at worker.org.gradle.process.internal.worker.GradleWorkerMain.main(GradleWorkerMain.java:74) [gradle-worker.jar:?]
16:10:15 15:10:15.089 [Test worker] ERROR tc.xxxxxxxxxxxx.dkr.ecr.us-east-1.amazonaws.com/rabbitmq:3.12.13-management-alpine - Log output from the failed container:
16:10:15 2024-12-01 15:10:12.282457+00:00 [notice] <0.44.0> Application syslog exited with reason: stopped
16:10:15 2024-12-01 15:10:12.286569+00:00 [notice] <0.230.0> Logging: switching to configured handler(s); following messages may not be visible in this log output
16:10:15 2024-12-01 15:10:12.287054+00:00 [notice] <0.230.0> Logging: configured log handlers are now ACTIVE
16:10:15 2024-12-01 15:10:12.420616+00:00 [info] <0.230.0> ra: starting system quorum_queues
16:10:15 2024-12-01 15:10:12.420683+00:00 [info] <0.230.0> starting Ra system: quorum_queues in directory: /var/lib/rabbitmq/mnesia/rabbit@c8115a7b819e/quorum/rabbit@c8115a7b819e
16:10:15 2024-12-01 15:10:12.461883+00:00 [info] <0.261.0> ra system 'quorum_queues' running pre init for 0 registered servers
16:10:15 2024-12-01 15:10:12.468515+00:00 [info] <0.262.0> ra: meta data store initialised for system quorum_queues. 0 record(s) recovered
16:10:15 2024-12-01 15:10:12.477759+00:00 [notice] <0.267.0> WAL: ra_log_wal init, open tbls: ra_log_open_mem_tables, closed tbls: ra_log_closed_mem_tables
16:10:15 2024-12-01 15:10:12.482237+00:00 [info] <0.230.0> ra: starting system coordination
16:10:15 2024-12-01 15:10:12.482272+00:00 [info] <0.230.0> starting Ra system: coordination in directory: /var/lib/rabbitmq/mnesia/rabbit@c8115a7b819e/coordination/rabbit@c8115a7b819e
16:10:15 2024-12-01 15:10:12.482922+00:00 [info] <0.274.0> ra system 'coordination' running pre init for 0 registered servers
16:10:15 2024-12-01 15:10:12.483380+00:00 [info] <0.275.0> ra: meta data store initialised for system coordination. 0 record(s) recovered
16:10:15 2024-12-01 15:10:12.483498+00:00 [notice] <0.280.0> WAL: ra_coordination_log_wal init, open tbls: ra_coordination_log_open_mem_tables, closed tbls: ra_coordination_log_closed_mem_tables
16:10:15 2024-12-01 15:10:12.485366+00:00 [info] <0.230.0>
16:10:15 2024-12-01 15:10:12.485366+00:00 [info] <0.230.0> Starting RabbitMQ 3.12.13 on Erlang 25.3.2.12 [jit]
16:10:15 2024-12-01 15:10:12.485366+00:00 [info] <0.230.0> Copyright (c) 2007-2024 Broadcom Inc and/or its subsidiaries
16:10:15 2024-12-01 15:10:12.485366+00:00 [info] <0.230.0> Licensed under the MPL 2.0. Website: https://rabbitmq.com
16:10:15
16:10:15 ## ## RabbitMQ 3.12.13
16:10:15 ## ##
16:10:15 ########## Copyright (c) 2007-2024 Broadcom Inc and/or its subsidiaries
16:10:15 ###### ##
16:10:15 ########## Licensed under the MPL 2.0. Website: https://rabbitmq.com
16:10:15
16:10:15 Erlang: 25.3.2.12 [jit]
16:10:15 TLS Library: OpenSSL - OpenSSL 3.1.5 30 Jan 2024
16:10:15 Release series support status: supported
16:10:15
16:10:15 Doc guides: https://rabbitmq.com/documentation.html
16:10:15 Support: https://rabbitmq.com/contact.html
16:10:15 Tutorials: https://rabbitmq.com/getstarted.html
16:10:15 Monitoring: https://rabbitmq.com/monitoring.html
16:10:15
16:10:15 Logs: <stdout>
16:10:15
16:10:15 Config file(s): /etc/rabbitmq/conf.d/10-defaults.conf
16:10:15
16:10:15 Starting broker...2024-12-01 15:10:12.491451+00:00 [info] <0.230.0>
16:10:15 2024-12-01 15:10:12.491451+00:00 [info] <0.230.0> node : rabbit@c8115a7b819e
16:10:15 2024-12-01 15:10:12.491451+00:00 [info] <0.230.0> home dir : /var/lib/rabbitmq
16:10:15 2024-12-01 15:10:12.491451+00:00 [info] <0.230.0> config file(s) : /etc/rabbitmq/conf.d/10-defaults.conf
16:10:15 2024-12-01 15:10:12.491451+00:00 [info] <0.230.0> cookie hash : 5qrxzXjw9n6ZcYkpp5JgMw==
16:10:15 2024-12-01 15:10:12.491451+00:00 [info] <0.230.0> log(s) : <stdout>
16:10:15 2024-12-01 15:10:12.491451+00:00 [info] <0.230.0> data dir : /var/lib/rabbitmq/mnesia/rabbit@c8115a7b819e
16:10:15 2024-12-01 15:10:14.570486+00:00 [info] <0.230.0> Running boot step pre_boot defined by app rabbit
16:10:15 2024-12-01 15:10:14.570543+00:00 [info] <0.230.0> Running boot step rabbit_global_counters defined by app rabbit
16:10:15 2024-12-01 15:10:14.570928+00:00 [info] <0.230.0> Running boot step rabbit_osiris_metrics defined by app rabbit
16:10:15 2024-12-01 15:10:14.571036+00:00 [info] <0.230.0> Running boot step rabbit_core_metrics defined by app rabbit
16:10:15 2024-12-01 15:10:14.572012+00:00 [info] <0.230.0> Running boot step rabbit_alarm defined by app rabbit
16:10:15 2024-12-01 15:10:14.574789+00:00 [info] <0.299.0> Memory high watermark set to 12017 MiB (12601240780 bytes) of 30043 MiB (31503101952 bytes) total
16:10:15 2024-12-01 15:10:14.576456+00:00 [info] <0.301.0> Enabling free disk space monitoring (disk free space: 153140719616, total memory: 31503101952)
16:10:15 2024-12-01 15:10:14.576498+00:00 [info] <0.301.0> Disk free limit set to 50MB
16:10:15 2024-12-01 15:10:14.577458+00:00 [info] <0.230.0> Running boot step code_server_cache defined by app rabbit
16:10:15 2024-12-01 15:10:14.577516+00:00 [info] <0.230.0> Running boot step file_handle_cache defined by app rabbit
16:10:15 2024-12-01 15:10:14.577716+00:00 [info] <0.304.0> Limiting to approx 32671 file handles (29401 sockets)
16:10:15 2024-12-01 15:10:14.577813+00:00 [info] <0.305.0> FHC read buffering: OFF
16:10:15 2024-12-01 15:10:14.577842+00:00 [info] <0.305.0> FHC write buffering: ON
16:10:15 2024-12-01 15:10:14.578147+00:00 [info] <0.230.0> Running boot step worker_pool defined by app rabbit
16:10:15 2024-12-01 15:10:14.578196+00:00 [info] <0.282.0> Will use 16 processes for default worker pool
16:10:15 2024-12-01 15:10:14.578228+00:00 [info] <0.282.0> Starting worker pool 'worker_pool' with 16 processes in it
16:10:15 2024-12-01 15:10:14.578765+00:00 [info] <0.230.0> Running boot step database defined by app rabbit
16:10:15 2024-12-01 15:10:14.579038+00:00 [info] <0.230.0> Node database directory at /var/lib/rabbitmq/mnesia/rabbit@c8115a7b819e is empty. Assuming we need to join an existing cluster or initialise from scratch...
16:10:15 2024-12-01 15:10:14.579084+00:00 [info] <0.230.0> Configured peer discovery backend: rabbit_peer_discovery_classic_config
16:10:15 2024-12-01 15:10:14.579118+00:00 [info] <0.230.0> Will try to lock with peer discovery backend rabbit_peer_discovery_classic_config
16:10:15 2024-12-01 15:10:14.579200+00:00 [info] <0.230.0> All discovered existing cluster peers:
16:10:15 2024-12-01 15:10:14.579243+00:00 [info] <0.230.0> Discovered no peer nodes to cluster with. Some discovery backends can filter nodes out based on a readiness criteria. Enabling debug logging might help troubleshoot.
16:10:15 2024-12-01 15:10:14.581264+00:00 [notice] <0.44.0> Application mnesia exited with reason: stopped
16:10:15 2024-12-01 15:10:14.643204+00:00 [info] <0.230.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
16:10:15 2024-12-01 15:10:14.643306+00:00 [info] <0.230.0> Successfully synced tables from a peer
16:10:15 2024-12-01 15:10:14.643622+00:00 [notice] <0.283.0> Feature flags: attempt to enable `stream_sac_coordinator_unblock_group`...
16:10:15 2024-12-01 15:10:14.667716+00:00 [notice] <0.283.0> Feature flags: `stream_sac_coordinator_unblock_group` enabled
16:10:15 2024-12-01 15:10:14.667807+00:00 [notice] <0.283.0> Feature flags: attempt to enable `restart_streams`...
16:10:15 2024-12-01 15:10:14.688836+00:00 [notice] <0.283.0> Feature flags: `restart_streams` enabled
16:10:15 2024-12-01 15:10:14.689123+00:00 [info] <0.230.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
16:10:15 2024-12-01 15:10:14.689240+00:00 [info] <0.230.0> Successfully synced tables from a peer
16:10:15 2024-12-01 15:10:14.695356+00:00 [info] <0.230.0> Waiting for Mnesia tables for 30000 ms, 9 retries left
16:10:15 2024-12-01 15:10:14.695491+00:00 [info] <0.230.0> Successfully synced tables from a peer
16:10:15 2024-12-01 15:10:14.695535+00:00 [info] <0.230.0> Peer discovery backend rabbit_peer_discovery_classic_config does not support registration, skipping registration.
16:10:15 2024-12-01 15:10:14.695623+00:00 [info] <0.230.0> Will try to unlock with peer discovery backend rabbit_peer_discovery_classic_config
16:10:15 2024-12-01 15:10:14.695832+00:00 [info] <0.230.0> Running boot step tracking_metadata_store defined by app rabbit
16:10:15 2024-12-01 15:10:14.695923+00:00 [info] <0.494.0> Setting up a table for connection tracking on this node: tracked_connection
16:10:15 2024-12-01 15:10:14.695986+00:00 [info] <0.494.0> Setting up a table for per-vhost connection counting on this node: tracked_connection_per_vhost
16:10:15 2024-12-01 15:10:14.696069+00:00 [info] <0.494.0> Setting up a table for per-user connection counting on this node: tracked_connection_per_user
16:10:15 2024-12-01 15:10:14.696128+00:00 [info] <0.494.0> Setting up a table for channel tracking on this node: tracked_channel
16:10:15 2024-12-01 15:10:14.696160+00:00 [info] <0.494.0> Setting up a table for channel tracking on this node: tracked_channel_per_user
16:10:15 2024-12-01 15:10:14.696204+00:00 [info] <0.230.0> Running boot step networking_metadata_store defined by app rabbit
16:10:15 2024-12-01 15:10:14.696280+00:00 [info] <0.230.0> Running boot step feature_flags defined by app rabbit
16:10:15 2024-12-01 15:10:14.696422+00:00 [info] <0.230.0> Running boot step codec_correctness_check defined by app rabbit
16:10:15 2024-12-01 15:10:14.696472+00:00 [info] <0.230.0> Running boot step external_infrastructure defined by app rabbit
16:10:15 2024-12-01 15:10:14.696519+00:00 [info] <0.230.0> Running boot step rabbit_event defined by app rabbit
16:10:15 2024-12-01 15:10:14.696593+00:00 [info] <0.230.0> Running boot step rabbit_registry defined by app rabbit
16:10:15 2024-12-01 15:10:14.696686+00:00 [info] <0.230.0> Running boot step rabbit_auth_mechanism_amqplain defined by app rabbit
16:10:15 2024-12-01 15:10:14.696764+00:00 [info] <0.230.0> Running boot step rabbit_auth_mechanism_cr_demo defined by app rabbit
16:10:15 2024-12-01 15:10:14.696830+00:00 [info] <0.230.0> Running boot step rabbit_auth_mechanism_plain defined by app rabbit
16:10:15 2024-12-01 15:10:14.696887+00:00 [info] <0.230.0> Running boot step rabbit_exchange_type_direct defined by app rabbit
16:10:15 2024-12-01 15:10:14.696945+00:00 [info] <0.230.0> Running boot step rabbit_exchange_type_fanout defined by app rabbit
16:10:15 2024-12-01 15:10:14.696998+00:00 [info] <0.230.0> Running boot step rabbit_exchange_type_headers defined by app rabbit
16:10:15 2024-12-01 15:10:14.697066+00:00 [info] <0.230.0> Running boot step rabbit_exchange_type_topic defined by app rabbit
16:10:15 2024-12-01 15:10:14.697125+00:00 [info] <0.230.0> Running boot step rabbit_mirror_queue_mode_all defined by app rabbit
16:10:15 2024-12-01 15:10:14.697182+00:00 [info] <0.230.0> Running boot step rabbit_mirror_queue_mode_exactly defined by app rabbit
16:10:15 2024-12-01 15:10:14.697242+00:00 [info] <0.230.0> Running boot step rabbit_mirror_queue_mode_nodes defined by app rabbit
16:10:15 2024-12-01 15:10:14.697305+00:00 [info] <0.230.0> Running boot step rabbit_priority_queue defined by app rabbit
16:10:15 2024-12-01 15:10:14.697341+00:00 [info] <0.230.0> Priority queues enabled, real BQ is rabbit_variable_queue
16:10:15 2024-12-01 15:10:14.697403+00:00 [info] <0.230.0> Running boot step rabbit_queue_location_client_local defined by app rabbit
16:10:15 2024-12-01 15:10:14.697458+00:00 [info] <0.230.0> Running boot step rabbit_queue_location_min_masters defined by app rabbit
16:10:15 2024-12-01 15:10:14.697526+00:00 [info] <0.230.0> Running boot step rabbit_queue_location_random defined by app rabbit
16:10:15 2024-12-01 15:10:14.697574+00:00 [info] <0.230.0> Running boot step kernel_ready defined by app rabbit
16:10:15 2024-12-01 15:10:14.697610+00:00 [info] <0.230.0> Running boot step rabbit_sysmon_minder defined by app rabbit
16:10:15 2024-12-01 15:10:14.697788+00:00 [info] <0.230.0> Running boot step rabbit_epmd_monitor defined by app rabbit
16:10:15 2024-12-01 15:10:14.698402+00:00 [info] <0.502.0> epmd monitor knows us, inter-node communication (distribution) port: 25672
16:10:15 2024-12-01 15:10:14.698500+00:00 [info] <0.230.0> Running boot step guid_generator defined by app rabbit
16:10:15 2024-12-01 15:10:14.700456+00:00 [info] <0.230.0> Running boot step rabbit_node_monitor defined by app rabbit
16:10:15 2024-12-01 15:10:14.700644+00:00 [info] <0.506.0> Starting rabbit_node_monitor (in ignore mode)
16:10:15 2024-12-01 15:10:14.700737+00:00 [info] <0.230.0> Running boot step delegate_sup defined by app rabbit
16:10:15 2024-12-01 15:10:14.701130+00:00 [info] <0.230.0> Running boot step rabbit_memory_monitor defined by app rabbit
16:10:15 2024-12-01 15:10:14.701304+00:00 [info] <0.230.0> Running boot step rabbit_fifo_dlx_sup defined by app rabbit
16:10:15 2024-12-01 15:10:14.701362+00:00 [info] <0.230.0> Running boot step core_initialized defined by app rabbit
16:10:15 2024-12-01 15:10:14.701397+00:00 [info] <0.230.0> Running boot step rabbit_channel_tracking_handler defined by app rabbit
16:10:15 2024-12-01 15:10:14.701451+00:00 [info] <0.230.0> Running boot step rabbit_connection_tracking_handler defined by app rabbit
16:10:15 2024-12-01 15:10:14.701508+00:00 [info] <0.230.0> Running boot step rabbit_definitions_hashing defined by app rabbit
16:10:15 2024-12-01 15:10:14.701562+00:00 [info] <0.230.0> Running boot step rabbit_exchange_parameters defined by app rabbit
16:10:15 2024-12-01 15:10:14.701778+00:00 [info] <0.230.0> Running boot step rabbit_mirror_queue_misc defined by app rabbit
16:10:15 2024-12-01 15:10:14.702119+00:00 [info] <0.230.0> Running boot step rabbit_policies defined by app rabbit
16:10:15 2024-12-01 15:10:14.702424+00:00 [info] <0.230.0> Running boot step rabbit_policy defined by app rabbit
16:10:15 2024-12-01 15:10:14.702470+00:00 [info] <0.230.0> Running boot step rabbit_queue_location_validator defined by app rabbit
16:10:15 2024-12-01 15:10:14.702521+00:00 [info] <0.230.0> Running boot step rabbit_quorum_memory_manager defined by app rabbit
16:10:15 2024-12-01 15:10:14.702569+00:00 [info] <0.230.0> Running boot step rabbit_stream_coordinator defined by app rabbit
16:10:15 2024-12-01 15:10:14.702664+00:00 [info] <0.230.0> Running boot step rabbit_vhost_limit defined by app rabbit
16:10:15 2024-12-01 15:10:14.702723+00:00 [info] <0.230.0> Running boot step rabbit_mgmt_reset_handler defined by app rabbitmq_management
16:10:15 2024-12-01 15:10:14.702769+00:00 [info] <0.230.0> Running boot step rabbit_mgmt_db_handler defined by app rabbitmq_management_agent
16:10:15 2024-12-01 15:10:14.702806+00:00 [info] <0.230.0> Management plugin: using rates mode 'basic'
16:10:15 2024-12-01 15:10:14.703063+00:00 [info] <0.230.0> Running boot step recovery defined by app rabbit
16:10:15 2024-12-01 15:10:14.703657+00:00 [info] <0.230.0> Running boot step empty_db_check defined by app rabbit
16:10:15 2024-12-01 15:10:14.703709+00:00 [info] <0.230.0> Will seed default virtual host and user...
16:10:15 2024-12-01 15:10:14.703781+00:00 [info] <0.230.0> Adding vhost '/' (description: 'Default virtual host', tags: [])
16:10:15 2024-12-01 15:10:14.705642+00:00 [info] <0.230.0> Inserted a virtual host record {vhost,<<"/">>,[],
16:10:15 2024-12-01 15:10:14.705642+00:00 [info] <0.230.0> #{description =>
16:10:15 2024-12-01 15:10:14.705642+00:00 [info] <0.230.0> <<"Default virtual host">>,
16:10:15 2024-12-01 15:10:14.705642+00:00 [info] <0.230.0> tags => []}}
16:10:15 2024-12-01 15:10:14.718415+00:00 [info] <0.551.0> Making sure data directory '/var/lib/rabbitmq/mnesia/rabbit@c8115a7b819e/msg_stores/vhosts/628WB79CIFDYO9LJI6DKMI09L' for vhost '/' exists
16:10:15 2024-12-01 15:10:14.718962+00:00 [info] <0.551.0> Setting segment_entry_count for vhost '/' with 0 queues to '2048'
16:10:15 2024-12-01 15:10:14.721332+00:00 [info] <0.551.0> Starting message stores for vhost '/'
16:10:15 2024-12-01 15:10:14.721475+00:00 [info] <0.561.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_transient": using rabbit_msg_store_ets_index to provide index
16:10:15 2024-12-01 15:10:14.722285+00:00 [info] <0.551.0> Started message store of type transient for vhost '/'
16:10:15 2024-12-01 15:10:14.722439+00:00 [info] <0.565.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": using rabbit_msg_store_ets_index to provide index
16:10:15 2024-12-01 15:10:14.722831+00:00 [warning] <0.565.0> Message store "628WB79CIFDYO9LJI6DKMI09L/msg_store_persistent": rebuilding indices from scratch
16:10:15 2024-12-01 15:10:14.723934+00:00 [info] <0.551.0> Started message store of type persistent for vhost '/'
16:10:15 2024-12-01 15:10:14.724039+00:00 [info] <0.551.0> Recovering 0 queues of type rabbit_classic_queue took 4ms
16:10:15 2024-12-01 15:10:14.724083+00:00 [info] <0.551.0> Recovering 0 queues of type rabbit_quorum_queue took 0ms
16:10:15 2024-12-01 15:10:14.724138+00:00 [info] <0.551.0> Recovering 0 queues of type rabbit_stream_queue took 0ms
16:10:15 2024-12-01 15:10:14.726575+00:00 [info] <0.230.0> Created user 'guest'
16:10:15 2024-12-01 15:10:14.727872+00:00 [info] <0.230.0> Successfully set user tags for user 'guest' to [administrator]
16:10:15 2024-12-01 15:10:14.729290+00:00 [info] <0.230.0> Successfully set permissions for user 'guest' in virtual host '/' to '.*', '.*', '.*'
16:10:15 2024-12-01 15:10:14.729331+00:00 [info] <0.230.0> Running boot step rabbit_observer_cli defined by app rabbit
16:10:15 2024-12-01 15:10:14.729369+00:00 [info] <0.230.0> Running boot step rabbit_looking_glass defined by app rabbit
16:10:15 2024-12-01 15:10:14.729388+00:00 [info] <0.230.0> Running boot step rabbit_core_metrics_gc defined by app rabbit
16:10:15 2024-12-01 15:10:14.729507+00:00 [info] <0.230.0> Running boot step background_gc defined by app rabbit
16:10:15 2024-12-01 15:10:14.729651+00:00 [info] <0.230.0> Running boot step routing_ready defined by app rabbit
16:10:15 2024-12-01 15:10:14.729689+00:00 [info] <0.230.0> Running boot step pre_flight defined by app rabbit
16:10:15 2024-12-01 15:10:14.729707+00:00 [info] <0.230.0> Running boot step notify_cluster defined by app rabbit
16:10:15 2024-12-01 15:10:14.729723+00:00 [info] <0.230.0> Running boot step networking defined by app rabbit
16:10:15 2024-12-01 15:10:14.729743+00:00 [info] <0.230.0> Running boot step definition_import_worker_pool defined by app rabbit
16:10:15 2024-12-01 15:10:14.729800+00:00 [info] <0.282.0> Starting worker pool 'definition_import_pool' with 16 processes in it
16:10:15 2024-12-01 15:10:14.730599+00:00 [info] <0.230.0> Running boot step cluster_name defined by app rabbit
16:10:15 2024-12-01 15:10:14.730658+00:00 [info] <0.230.0> Initialising internal cluster ID to 'rabbitmq-cluster-id-KqgEr2_kqbvIIHdlSjcrEA'
16:10:15 2024-12-01 15:10:14.732181+00:00 [info] <0.230.0> Running boot step direct_client defined by app rabbit
16:10:15 2024-12-01 15:10:14.732261+00:00 [info] <0.230.0> Running boot step rabbit_maintenance_mode_state defined by app rabbit
16:10:15 2024-12-01 15:10:14.732285+00:00 [info] <0.230.0> Creating table rabbit_node_maintenance_states for maintenance mode status
16:10:15 2024-12-01 15:10:14.734945+00:00 [info] <0.230.0> Running boot step rabbit_management_load_definitions defined by app rabbitmq_management
16:10:15 2024-12-01 15:10:14.735028+00:00 [info] <0.617.0> Resetting node maintenance status
16:10:15 2024-12-01 15:10:14.745514+00:00 [info] <0.676.0> Management plugin: HTTP (non-TLS) listener started on port 15672
16:10:15 2024-12-01 15:10:14.745608+00:00 [info] <0.704.0> Statistics database started.
16:10:15 2024-12-01 15:10:14.745665+00:00 [info] <0.703.0> Starting worker pool 'management_worker_pool' with 3 processes in it
16:10:15 2024-12-01 15:10:14.752172+00:00 [info] <0.718.0> Prometheus metrics: HTTP (non-TLS) listener started on port 15692
16:10:15 2024-12-01 15:10:14.752253+00:00 [info] <0.617.0> Ready to start client connection listeners
16:10:15 2024-12-01 15:10:14.753950+00:00 [info] <0.762.0> started TCP listener on [::]:5672
16:10:15 completed with 4 plugins.
16:10:15 2024-12-01 15:10:14.809291+00:00 [info] <0.617.0> Server startup complete; 4 plugins started.
16:10:15 2024-12-01 15:10:14.809291+00:00 [info] <0.617.0> * rabbitmq_prometheus
16:10:15 2024-12-01 15:10:14.809291+00:00 [info] <0.617.0> * rabbitmq_management
16:10:15 2024-12-01 15:10:14.809291+00:00 [info] <0.617.0> * rabbitmq_management_agent
16:10:15 2024-12-01 15:10:14.809291+00:00 [info] <0.617.0> * rabbitmq_web_dispatch
16:10:15 2024-12-01 15:10:14.935710+00:00 [info] <0.9.0> Time to start RabbitMQ: 4733761 usAdditional Information
No response