Kafka dev service redpanda container failing with Text file busy

[mederel]

Describe the bug

While using the Kafka Dev service I entered into a racing condition on the writing of the startup redpanda.sh script and its execution resulting in the following stacktrace:

2022-07-07 09:04:17,861 INFO  [org.jbo.threads] (main)  JBoss Threads version 3.4.2.Final-redhat-00001
2022-07-07 09:04:18,933 WARN  [org.tes.uti.TestcontainersConfiguration] (build-11)  Attempted to read Testcontainers configuration file at file:/home/acs_dev/.testcontainers.properties but the file was not found. Exception message: FileNotFoundException: /home/acs_dev/.testcontainers.properties (No such file or directory)
2022-07-07 09:04:19,179 WARN  [io.qua.mic.dep.bin.mpm.MicroprofileMetricsProcessor] (build-21)  This application uses the MP Metrics API. The micrometer extension currently provides a compatibility layer that supports the MP Metrics API, but metric names and recorded values will be different. Note that the MP Metrics compatibility layer will move to a different extension in the future.
2022-07-07 09:04:19,193 INFO  [io.qua.sma.rea.kaf.dep.SmallRyeReactiveMessagingKafkaProcessor] (build-33)  Generating Jackson serializer for type com.amadeus.middleware.multipayload.MultiPayload
2022-07-07 09:04:19,681 INFO  [org.tes.doc.DockerClientProviderStrategy] (build-11)  Found Docker environment with Environment variables, system properties and defaults. Resolved dockerHost=unix:///var/run/swb_docker.sock
2022-07-07 09:04:19,704 INFO  [org.tes.DockerClientFactory] (build-11)  Docker host IP address is 192.168.0.1
2022-07-07 09:04:19,743 INFO  [org.tes.DockerClientFactory] (build-11)  Connected to docker: 
  Server Version: 20.10.17
  API Version: 1.41
  Operating System: RHEV
  Total Memory: 16027 MB
2022-07-07 09:04:19,752 INFO  [org.tes.uti.ImageNameSubstitutor] (build-11)  Image name substitution will be performed by: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor')
2022-07-07 09:04:19,754 WARN  [org.tes.uti.ConfigurationFileImageNameSubstitutor] (build-11)  Image name testcontainers/ryuk:0.3.3 was substituted by configuration to dockerhub.rnd.amadeus.net:5002/testcontainers/ryuk:0.3.3. This approach is deprecated and will be removed in the future
2022-07-07 09:04:19,755 INFO  [org.tes.uti.ImageNameSubstitutor] (build-11)  Using dockerhub.rnd.amadeus.net:5002/testcontainers/ryuk:0.3.3 as a substitute image for testcontainers/ryuk:0.3.3 (using image substitutor: DefaultImageNameSubstitutor (composite of 'ConfigurationFileImageNameSubstitutor' and 'PrefixingImageNameSubstitutor'))
2022-07-07 09:04:19,798 INFO  [org.tes.uti.RegistryAuthLocator] (build-11)  Failure when attempting to lookup auth config. Please ignore if you don't have images in an authenticated registry. Details: (dockerImageName: dockerhub.rnd.amadeus.net:5002/testcontainers/ryuk:0.3.3, configFile: /home/acs_dev/.docker/config.json. Falling back to docker-java default behaviour. Exception message: /home/acs_dev/.docker/config.json (No such file or directory)
2022-07-07 09:04:20,382 INFO  [org.tes.DockerClientFactory] (build-11)  Ryuk started - will monitor and terminate Testcontainers containers on JVM exit
2022-07-07 09:04:20,383 INFO  [org.tes.DockerClientFactory] (build-11)  Checking the system...
2022-07-07 09:04:20,384 INFO  [org.tes.DockerClientFactory] (build-11)  ?? Docker server version should be at least 1.6.0
2022-07-07 09:04:20,466 INFO  [org.tes.DockerClientFactory] (build-11)  ?? Docker environment should have more than 2GB free disk space
2022-07-07 09:04:20,654 INFO  [doc.rnd.ama.net.1.3]] (build-11)  Creating container for image: dockerhub.rnd.amadeus.net:5002/vectorized/redpanda:v22.1.3
2022-07-07 09:04:20,788 INFO  [doc.rnd.ama.net.1.3]] (build-11)  Container dockerhub.rnd.amadeus.net:5002/vectorized/redpanda:v22.1.3 is starting: e5dd590d0ec804d7c41a6a10e639e9eeed49c4fe14a2b036dc3337e27e2766d5
2022-07-07 09:04:21,531 ERROR [doc.rnd.ama.net.1.3]] (build-11)  Could not start container: java.lang.IllegalStateException: Container did not start correctly.
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:463)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:331)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:329)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:317)
	at io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor.lambda$startKafka$5(DevServicesKafkaProcessor.java:240)
	at java.base/java.util.Optional.orElseGet(Optional.java:364)
	at io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor.startKafka(DevServicesKafkaProcessor.java:248)
	at io.quarkus.kafka.client.deployment.DevServicesKafkaProcessor.startKafkaDevService(DevServicesKafkaProcessor.java:103)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at io.quarkus.deployment.ExtensionLoader$2.execute(ExtensionLoader.java:882)
	at io.quarkus.builder.BuildContext.run(BuildContext.java:277)
	at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
	at java.base/java.lang.Thread.run(Thread.java:833)
	at org.jboss.threads.JBossThread.run(JBossThread.java:501)
2022-07-07 09:04:21,554 ERROR [doc.rnd.ama.net.1.3]] (build-11)  Log output from the failed container:
sh: 1: /var/lib/redpanda/redpanda.sh: Text file busy

Expected behavior

The dev services / redpanda container start correctly and the QuarkusTest depending on it executes correctly.

Actual behavior

In a racing condition the following startup line:

sh -c "while [ ! -f /var/lib/redpanda/redpanda.sh ]; do sleep 0.1; done; /var/lib/redpanda/redpanda.sh

fails with:

sh: 1: /var/lib/redpanda/redpanda.sh: Text file busy

In DevservicesKafkaProcessor we can see that a methods transfers this shell script contents after the docker container has been started, probably to inject configuration from Java.

I think the pb is that in my case is that the contents are still being written on disk while the condition of existence already becomes true and the startup comand gets executed. Indeed the Test file busy error is raised when executing an executable file that is being edited.

How to Reproduce?

As said it is not systematic... Happens only rarely.

Output of uname -a or ver

Linux 5.13.0-52-generic #59~20.04.1-Ubuntu SMP Thu Jun 16 21:21:28 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

Output of java -version

openjdk version "11.0.15" 2022-04-19 OpenJDK Runtime Environment (build 11.0.15+10-Ubuntu-0ubuntu0.20.04.1) OpenJDK 64-Bit Server VM (build 11.0.15+10-Ubuntu-0ubuntu0.20.04.1, mixed mode, sharing)

GraalVM version (if different from Java)

No response

Quarkus version or git rev

8ecbe2c

Build tool (ie. output of mvnw --version or gradlew --version)

Apache Maven 3.8.5 (3599d3414f046de2324203b78ddcf9b5e4388aa0) Maven home: /home/edeweerd/bin/apache-maven-3.8.5 Java version: 11.0.13.0.1, vendor: Oracle Corporation, runtime: /home/edeweerd/bin/java-11.0.3-oracle Default locale: en_US, platform encoding: UTF-8 OS name: "linux", version: "5.13.0-52-generic", arch: "amd64", family: "unix"

Additional information

No response

[quarkus-bot]

/cc @alesj, @cescoffier, @ozangunalp

[ozangunalp]

This is known and only happens rarely as you mentioned. I don't think we can have a fix. As container runtimes still don't support injection port mappings into the container (at least to my knowledge), we need to do this hack to start the broker with the correct advertised addresses.