The Wayback Machine - https://web.archive.org/web/20201029080308/https://github.com/testcontainers/testcontainers-java/issues/2878
Skip to content

/ testcontainers-java

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

MySQL container started message is misleading #2878

Open
vmassol opened this issue Jun 15, 2020 · 3 comments · May be fixed by #3015
Open

MySQL container started message is misleading #2878

vmassol opened this issue Jun 15, 2020 · 3 comments · May be fixed by #3015
Labels
good first issue help wanted modules/jdbc

Comments

@vmassol
Copy link
Contributor

@vmassol vmassol commented Jun 15, 2020 •
edited

Hi,

Very regularly we see that the MySQL container fails to start under the default 2mn timeout (120s). We've even increased that to 4mn and still fails (I've now increased it to 15mn to see what happens).

Anyway the point is that TC tries issue a SQL query to verify it's started during the defined timeout and if it doesn't succeed it just says that the DB is started, with:

00:11:17.509 [main] DEBUG 🐳 [mysql:8.0] - Failure when trying test query
java.sql.SQLException: Could not create new connection
	at org.testcontainers.containers.JdbcDatabaseContainer.createConnection(JdbcDatabaseContainer.java:220)
	at org.testcontainers.containers.JdbcDatabaseContainer.waitUntilContainerStarted(JdbcDatabaseContainer.java:139)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:441)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:325)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:323)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:311)
	at org.xwiki.test.docker.internal.junit5.DockerTestUtils.startContainerInternal(DockerTestUtils.java:207)
	at org.xwiki.test.docker.internal.junit5.DockerTestUtils.startContainer(DockerTestUtils.java:170)
	at org.xwiki.test.docker.internal.junit5.AbstractContainerExecutor.start(AbstractContainerExecutor.java:56)
	at org.xwiki.test.docker.internal.junit5.database.DatabaseContainerExecutor.startDatabaseContainer(DatabaseContainerExecutor.java:277)
	at org.xwiki.test.docker.internal.junit5.database.DatabaseContainerExecutor.startMySQLContainer(DatabaseContainerExecutor.java:134)
	at org.xwiki.test.docker.internal.junit5.database.DatabaseContainerExecutor.startMySQLContainer(DatabaseContainerExecutor.java:105)
	at org.xwiki.test.docker.internal.junit5.database.DatabaseContainerExecutor.start(DatabaseContainerExecutor.java:62)
	at org.xwiki.test.docker.internal.junit5.XWikiDockerExtension.startDatabase(XWikiDockerExtension.java:410)
	at org.xwiki.test.docker.internal.junit5.XWikiDockerExtension.beforeAllInternal(XWikiDockerExtension.java:169)
	at org.xwiki.test.docker.internal.junit5.XWikiDockerExtension.beforeAll(XWikiDockerExtension.java:112)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.lambda$invokeBeforeAllCallbacks$7(ClassBasedTestDescriptor.java:359)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.invokeBeforeAllCallbacks(ClassBasedTestDescriptor.java:359)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:189)
	at org.junit.jupiter.engine.descriptor.ClassBasedTestDescriptor.before(ClassBasedTestDescriptor.java:78)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:132)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
	at java.util.ArrayList.forEach(ArrayList.java:1257)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:38)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$5(NodeTestTask.java:139)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$7(NodeTestTask.java:125)
	at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:135)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:123)
	at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:122)
	at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:80)
	at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:32)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57)
	at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:51)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:248)
	at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$5(DefaultLauncher.java:211)
	at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:226)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:199)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:132)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:150)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:124)
	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)
Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
	at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:836)
	at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:456)
	at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:246)
	at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:197)
	at org.testcontainers.containers.JdbcDatabaseContainer.createConnection(JdbcDatabaseContainer.java:211)
	... 53 common frames omitted
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
	at sun.reflect.GeneratedConstructorAccessor36.newInstance(Unknown Source)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)
	at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
	at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:538)
	at com.mysql.cj.protocol.a.NativeProtocol.readServerCapabilities(NativeProtocol.java:490)
	at com.mysql.cj.protocol.a.NativeProtocol.beforeHandshake(NativeProtocol.java:377)
	at com.mysql.cj.protocol.a.NativeProtocol.connect(NativeProtocol.java:1340)
	at com.mysql.cj.NativeSession.connect(NativeSession.java:157)
	at com.mysql.cj.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:956)
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:826)
	... 57 common frames omitted
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
	at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:67)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
	at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:532)
	... 63 common frames omitted
00:11:17.610 [main] INFO  🐳 [mysql:8.0] - Container is started (JDBC URL: jdbc:mysql://172.17.0.1:37489/xwiki)
00:11:17.610 [main] INFO  🐳 [mysql:8.0] - Container mysql:8.0 started in PT4M9.07S
00:11:17.610 [main] INFO  o.x.t.d.i.j.d.DatabaseContainerExecutor - Setting MySQL permissions to create subwikis
00:11:17.610 [main] DEBUG o.t.c.ExecInContainerPattern - /unruffled_allen: Running "exec" command: sh -c echo '[client]
user = root
password = xwiki' > credentials.cnf
00:11:17.783 [main] TRACE o.t.c.ExecInContainerPattern - /unruffled_allen: stdout: 
00:11:17.783 [main] TRACE o.t.c.ExecInContainerPattern - /unruffled_allen: stderr: 
00:11:17.783 [main] DEBUG o.t.c.ExecInContainerPattern - /unruffled_allen: Running "exec" command: mysql --defaults-extra-file=credentials.cnf --verbose -e grant all privileges on *.* to 'xwiki'@'%'
00:11:18.438 [main] TRACE o.t.c.ExecInContainerPattern - /unruffled_allen: stdout: 
00:11:18.438 [main] TRACE o.t.c.ExecInContainerPattern - /unruffled_allen: stderr: ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)

What happens here is:

  • The JDBC connection failed during the 4m timeout. The last try is showing the exception.
  • Yet TC says Container is started (JDBC URL: jdbc:mysql://172.17.0.1:37489/xwiki) and Container mysql:8.0 started in PT4M9.07S, which is not correct. The DB container logs show it's not started yet.
  • Thus when we try to issue some SQL query after it fails with ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock'

I find it misleading to consider it's started if the SQL hasn't worked. At least the message should be different in this case, something like "Failed to verify that MySQL was started during ... seconds and couldn't. It's possible it's not started.".

The alternative is to throw an exception, i.e. to not go further if it's not started within the timeout.

WDYT?
@vcvitaly
Copy link
Contributor

@vcvitaly vcvitaly commented Jun 15, 2020

@bsideup I could take it
@kiview
Copy link
Member

@kiview kiview commented Jun 27, 2020

I am not really sure what behaviour got observed in this issue. If the MySQLContainer would not launch with an active database, Testcontainers would throw an exception.

Since you were able to run exec commands against the container after startup, it seems startup wait strategy was successful and the container started successfully.

Or am I misunderstanding anything here?
@vcvitaly vcvitaly linked a pull request that will close this issue Jul 24, 2020
Open
vcvitaly added a commit to vcvitaly-forks/testcontainers-java that referenced this issue Aug 25, 2020
@vcvitaly
testcontainers#2878 write a test for the <exception> case
335fdec
@DevilzOwn
Copy link

@DevilzOwn DevilzOwn commented Oct 17, 2020

Can we close this issue?
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
good first issue help wanted modules/jdbc
5 participants
@vmassol @bsideup @kiview @vcvitaly @DevilzOwn
You can’t perform that action at this time.