search

sparsick / testcontainers-git

This project contains a Testcontainers implementation for a plain git server based on the Docker image rockstorm/git-server
MIT License
31 stars 6 forks source link

Inadequate wait strategy? #91

Closed Mahoney closed 5 months ago

Mahoney commented 7 months ago

Using 0.6.0 with rockstorm/git-server:2.43 we have a flaky test on GitHub Actions.

All of our tests start a new container, but it's always the first test to start a git container that fails, we can see it's just after the pull.

It has thrown both an org.apache.sshd.common.SshException: Session is closed and a java.io.IOException: Broken pipe.

Relevant logs:

INFO  [2024-03-11 12:01:50,645] req= tc.rockstorm/git-server:2.43: Pulling docker image: rockstorm/git-server:2.43. Please be patient; this may take some time but only needs to be done once.
INFO  [2024-03-11 12:01:50,873] req= tc.rockstorm/git-server:2.43: Starting to pull image
INFO  [2024-03-11 12:01:50,873] req= tc.rockstorm/git-server:2.43: Pulling image layers:  0 pending,  0 downloaded,  0 extracted, (0 bytes/0 bytes)
INFO  [2024-03-11 12:01:51,030] req= tc.rockstorm/git-server:2.43: Pulling image layers:  9 pending,  1 downloaded,  0 extracted, (1 KB/? MB)
INFO  [2024-03-11 12:01:51,032] req= tc.rockstorm/git-server:2.43: Pulling image layers:  8 pending,  2 downloaded,  0 extracted, (4 KB/? MB)
INFO  [2024-03-11 12:01:51,103] req= tc.rockstorm/git-server:2.43: Pulling image layers:  7 pending,  3 downloaded,  0 extracted, (81 KB/? MB)
INFO  [2024-03-11 12:01:51,123] req= tc.rockstorm/git-server:2.43: Pulling image layers:  6 pending,  4 downloaded,  0 extracted, (81 KB/? MB)
INFO  [2024-03-11 12:01:51,163] req= tc.rockstorm/git-server:2.43: Pulling image layers:  5 pending,  5 downloaded,  0 extracted, (4 MB/? MB)
INFO  [2024-03-11 12:01:51,197] req= tc.rockstorm/git-server:2.43: Pulling image layers:  4 pending,  6 downloaded,  0 extracted, (4 MB/? MB)
INFO  [2024-03-11 12:01:51,212] req= tc.rockstorm/git-server:2.43: Pulling image layers:  3 pending,  7 downloaded,  0 extracted, (4 MB/? MB)
INFO  [2024-03-11 12:01:51,268] req= tc.rockstorm/git-server:2.43: Pulling image layers:  2 pending,  8 downloaded,  0 extracted, (4 MB/? MB)
INFO  [2024-03-11 12:01:51,285] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  0 extracted, (4 MB/? MB)
INFO  [2024-03-11 12:01:51,536] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  1 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,554] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  2 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,567] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  3 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,596] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  4 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,609] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  5 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,618] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  6 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,629] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  7 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,638] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  8 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,650] req= tc.rockstorm/git-server:2.43: Pulling image layers:  1 pending,  9 downloaded,  9 extracted, (7 MB/? MB)
INFO  [2024-03-11 12:01:51,654] req= tc.rockstorm/git-server:2.43: Image rockstorm/git-server:2.43 pull took PT1.009099217S
INFO  [2024-03-11 12:01:51,656] req= tc.rockstorm/git-server:2.43: Creating container for image: rockstorm/git-server:2.43
INFO  [2024-03-11 12:01:51,703] req= tc.rockstorm/git-server:2.43: Container rockstorm/git-server:2.43 is starting: 82c6b6499b53ec7f43e329e0433538a4e8a055bb18c334e00b865940d45d5673
INFO  [2024-03-11 12:01:52,458] req= tc.rockstorm/git-server:2.43: Container rockstorm/git-server:2.43 started in PT0.801877892S

INFO  [2024-03-11 12:01:53,267] req= mocklab.system.git.JGitOperations: Failed to ls remote repository ssh://git@localhost:32843/srv/git/testRepo.git
org.apache.sshd.common.SshException: Session is closed
    at org.apache.sshd.client.session.ClientUserAuthService.preClose(ClientUserAuthService.java:433)
    at org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:94)
    at org.apache.sshd.common.util.closeable.ParallelCloseable.doClose(ParallelCloseable.java:65)
    at org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:56)
    at org.apache.sshd.common.util.closeable.SequentialCloseable$1.operationComplete(SequentialCloseable.java:45)
    at org.apache.sshd.common.util.closeable.SequentialCloseable.doClose(SequentialCloseable.java:69)
    at org.apache.sshd.common.util.closeable.SimpleCloseable.close(SimpleCloseable.java:63)
    at org.apache.sshd.common.util.closeable.AbstractInnerCloseable.doCloseImmediately(AbstractInnerCloseable.java:48)
    at org.apache.sshd.common.util.closeable.AbstractCloseable.close(AbstractCloseable.java:95)
    at org.apache.sshd.common.session.helpers.SessionHelper.exceptionCaught(SessionHelper.java:1298)
    at org.apache.sshd.client.session.ClientSessionImpl.exceptionCaught(ClientSessionImpl.java:164)
    at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.exceptionCaught(AbstractSessionIoHandler.java:53)
    at org.apache.sshd.common.io.nio2.Nio2Session.exceptionCaught(Nio2Session.java:208)
    at org.apache.sshd.common.io.nio2.Nio2Session.handleWriteCycleFailure(Nio2Session.java:590)
    at org.apache.sshd.common.io.nio2.Nio2Session$2.onFailed(Nio2Session.java:548)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$failed$1(Nio2CompletionHandler.java:46)
    at java.base/java.security.AccessController.doPrivileged(AccessController.java:318)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.failed(Nio2CompletionHandler.java:45)
    at java.base/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:131)
    at java.base/sun.nio.ch.Invoker$2.run(Invoker.java:221)
    at java.base/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:113)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:840)
Wrapped by: org.apache.sshd.common.SshException: Session is closed
    at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:141)
    at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:56)
    at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:35)
    at org.apache.sshd.common.future.VerifiableFuture.verify(VerifiableFuture.java:74)
    at org.eclipse.jgit.transport.sshd.SshdSession.connect(SshdSession.java:172)
    at org.eclipse.jgit.transport.sshd.SshdSession.connect(SshdSession.java:101)
    at org.eclipse.jgit.transport.sshd.SshdSessionFactory.getSession(SshdSessionFactory.java:260)
    ... 35 common frames omitted
Wrapped by: org.eclipse.jgit.errors.TransportException: ssh://git@localhost:32843/srv/git/testRepo.git: Session is closed
    at org.eclipse.jgit.transport.sshd.SshdSessionFactory.getSession(SshdSessionFactory.java:267)
    at mocklab.system.git.KeysProvidedSshdSessionFactory.access$getSession$s-1587098576(JGitOperations.kt:429)
    at mocklab.system.git.KeysProvidedSshdSessionFactory$getSession$1.invoke(JGitOperations.kt:448)
    at mocklab.system.git.KeysProvidedSshdSessionFactory$getSession$1.invoke(JGitOperations.kt:448)
    at mocklab.security.keys.InstrumentedKeyEncrypterKt.time$lambda$0(InstrumentedKeyEncrypter.kt:27)
    at io.micrometer.core.instrument.composite.CompositeTimer.recordCallable(CompositeTimer.java:129)
    at mocklab.security.keys.InstrumentedKeyEncrypterKt.time(InstrumentedKeyEncrypter.kt:27)
    at mocklab.system.git.KeysProvidedSshdSessionFactory.getSession(JGitOperations.kt:448)
    at mocklab.system.git.KeysProvidedSshdSessionFactory.getSession(JGitOperations.kt:429)
    at org.eclipse.jgit.transport.SshTransport.getSession(SshTransport.java:107)
    at org.eclipse.jgit.transport.TransportGitSsh$SshFetchConnection.<init>(TransportGitSsh.java:279)
    at org.eclipse.jgit.transport.TransportGitSsh.openFetch(TransportGitSsh.java:152)
    at org.eclipse.jgit.api.LsRemoteCommand.execute(LsRemoteCommand.java:170)
    ... 23 common frames omitted

And the other time:

INFO  [2024-03-11 05:06:16,605] req= mocklab.system.git.JGitOperations: Failed to ls remote repository ssh://git@localhost:32839/srv/git/testRepo.git
java.io.IOException: Broken pipe
    at java.base/sun.nio.ch.FileDispatcherImpl.write0(Native Method)
    at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:62)
    at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:132)
    at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:97)
    at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:60)
    at java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:713)
    at java.base/sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:382)
    at java.base/sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:399)
    at org.apache.sshd.common.io.nio2.Nio2Session.doWriteCycle(Nio2Session.java:534)
    at org.apache.sshd.common.io.nio2.Nio2Session.startWriting(Nio2Session.java:516)
    at org.apache.sshd.common.io.nio2.Nio2Session.writeBuffer(Nio2Session.java:191)
    at org.apache.sshd.common.session.helpers.AbstractSession.doWritePacket(AbstractSession.java:1154)
    at org.apache.sshd.common.session.helpers.KeyExchangeMessageHandler.writePacket(KeyExchangeMessageHandler.java:246)
    at org.apache.sshd.common.session.helpers.AbstractSession.writePacket(AbstractSession.java:1066)
    at org.apache.sshd.common.session.helpers.AbstractSession.sendKexInit(AbstractSession.java:1773)
    at org.apache.sshd.client.session.AbstractClientSession.sendKexInit(AbstractClientSession.java:578)
    at org.apache.sshd.common.session.helpers.AbstractSession.sendKexInit(AbstractSession.java:2664)
    at org.eclipse.jgit.internal.transport.sshd.JGitClientSession.sendKexInit(JGitClientSession.java:193)
    at org.apache.sshd.client.session.AbstractClientSession.initializeKeyExchangePhase(AbstractClientSession.java:319)
    at org.apache.sshd.client.session.ClientSessionImpl.<init>(ClientSessionImpl.java:98)
    at org.eclipse.jgit.internal.transport.sshd.JGitClientSession.<init>(JGitClientSession.java:107)
    at org.eclipse.jgit.internal.transport.sshd.JGitSshClient$JGitSessionFactory.doCreateSession(JGitSshClient.java:415)
    at org.apache.sshd.client.session.SessionFactory.doCreateSession(SessionFactory.java:31)
    at org.apache.sshd.common.session.helpers.AbstractSessionFactory.createSession(AbstractSessionFactory.java:47)
    at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.sessionCreated(AbstractSessionIoHandler.java:40)
    at org.apache.sshd.common.io.nio2.Nio2Connector$ConnectionCompletionHandler.onCompleted(Nio2Connector.java:216)
    at org.apache.sshd.common.io.nio2.Nio2Connector$ConnectionCompletionHandler.onCompleted(Nio2Connector.java:182)
    at org.apache.sshd.common.io.nio2.Nio2Connector.lambda$connect$1(Nio2Connector.java:111)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:840)
Wrapped by: org.apache.sshd.common.SshException: [ssh-connection]: Failed (IOException) to execute: Broken pipe
    at org.apache.sshd.common.future.AbstractSshFuture.lambda$verifyResult$2(AbstractSshFuture.java:146)
    at org.apache.sshd.common.future.AbstractSshFuture.formatExceptionMessage(AbstractSshFuture.java:206)
    at org.apache.sshd.common.future.AbstractSshFuture.verifyResult(AbstractSshFuture.java:145)
    at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:56)
    at org.apache.sshd.client.future.DefaultAuthFuture.verify(DefaultAuthFuture.java:35)
    at org.apache.sshd.common.future.VerifiableFuture.verify(VerifiableFuture.java:74)
    at org.eclipse.jgit.transport.sshd.SshdSession.connect(SshdSession.java:172)
    at org.eclipse.jgit.transport.sshd.SshdSession.connect(SshdSession.java:101)
    at org.eclipse.jgit.transport.sshd.SshdSessionFactory.getSession(SshdSessionFactory.java:260)
    ... 35 common frames omitted
Wrapped by: org.eclipse.jgit.errors.TransportException: ssh://git@localhost:32839/srv/git/testRepo.git: [ssh-connection]: Failed (IOException) to execute: Broken pipe
    at org.eclipse.jgit.transport.sshd.SshdSessionFactory.getSession(SshdSessionFactory.java:267)
    at mocklab.system.git.KeysProvidedSshdSessionFactory.access$getSession$s-1587098576(JGitOperations.kt:429)
    at mocklab.system.git.KeysProvidedSshdSessionFactory$getSession$1.invoke(JGitOperations.kt:448)
    at mocklab.system.git.KeysProvidedSshdSessionFactory$getSession$1.invoke(JGitOperations.kt:448)
    at mocklab.security.keys.InstrumentedKeyEncrypterKt.time$lambda$0(InstrumentedKeyEncrypter.kt:27)
    at io.micrometer.core.instrument.composite.CompositeTimer.recordCallable(CompositeTimer.java:129)
    at mocklab.security.keys.InstrumentedKeyEncrypterKt.time(InstrumentedKeyEncrypter.kt:27)
    at mocklab.system.git.KeysProvidedSshdSessionFactory.getSession(JGitOperations.kt:448)
    at mocklab.system.git.KeysProvidedSshdSessionFactory.getSession(JGitOperations.kt:429)
    at org.eclipse.jgit.transport.SshTransport.getSession(SshTransport.java:107)
    at org.eclipse.jgit.transport.TransportGitSsh$SshFetchConnection.<init>(TransportGitSsh.java:279)
    at org.eclipse.jgit.transport.TransportGitSsh.openFetch(TransportGitSsh.java:152)
    at org.eclipse.jgit.api.LsRemoteCommand.execute(LsRemoteCommand.java:170)
    ... 23 common frames omitted
Mahoney commented 7 months ago

Our code is as follows:

String sshPublicKey = "valid ssh public key, this all passes locally and 90% of the time on GHA";
GitServerContainer gitRepoContainer =
        new GitServerContainer(GitServerVersions.V2_43.getDockerImageName())
                .withGitRepo("testRepo")
                .withClasspathResourceMapping("sshd_config", "/etc/ssh/sshd_config", READ_ONLY);

gitRepoContainer.withCopyToContainer(Transferable.of(sshPublicKey), "/home/git/.ssh/authorized_keys");
gitRepoContainer.start();

// code that interacts with the container
sparsick commented 5 months ago

I saw this phenomen on some GHA. Could you please paste your GHA code?

sparsick commented 5 months ago

Hi @Mahoney,

I have thought about this problem. Maybe I can solve this problem if I change the waiting strategy from log checking to port checking.

Meanwhile, perhaps adding a Startup check strategy could help you with your problem.

Mahoney commented 5 months ago

Sorry, didn't mean to ignore this.

I haven't actually seen it fail for a while now... yes, I could look into a custom wait strategy if needed.

Our GHA is pretty simple:

name: Build branch

on:
  push:
    branches-ignore:
      - 'master'

env:
  DOCKER_BUILDKIT: 1
  BUILDKIT_PROGRESS: plain
  PROGRESS_NO_TRUNC: 1

permissions: write-all

jobs:
  test:
    runs-on: ubuntu-16-core

    steps:
      - uses: actions/checkout@v4
      - uses: actions/setup-java@v4
        with:
          distribution: 'temurin'
          java-version: '17'

      - name: Setup Gradle
        uses: gradle/actions/setup-gradle@v3
        with:
          validate-wrappers: true

      - uses: docker/login-action@v3
        with:
          registry: ghcr.io
          username: ${{ github.actor }}
          password: ${{ secrets.GITHUB_TOKEN }}

      - name: Run tests
        env:
          DB_TYPE: LOCAL_POSTGRES
          DB_CONNECTION_TIMEOUT: 20
          OT_LOG_LEVEL: WARN
        run: ./gradlew check