3

Context

I have a webservice writing a test id in a queue. Then, a listener reads the queue, searches the test and starts it. During those steps, it writes updates of the test in the database in order to be shown to the user. To be more precise: the test is launched in a docker container and at the end of it, I want to update the status of the test to FINISHED. For that, I use the docker java library with a callback.

Problem

When it comes to call the callback, I receive multiple error messages on the call to update the test (but it happens only once, if I try twice the second time works, but it still writes a lot of error messages from the transaction manager).

Here are the error messages logged:

2020-11-20 09:20:43,639 WARN  [docker-java-stream--1032099154] (org.jboss.jca.core.connectionmanager.listener.TxConnectionListener) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@600268e6[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@236f1a69 connection handles=1 lastReturned=1605860423264 lastValidated=1605860242146 lastCheckedOut=1605860443564 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@2efb0d3b mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@3e8e7a62[pool=ApplicationDS] xaResource=LocalXAResourceImpl@482fdad2[connectionListener=600268e6 connectionManager=4c83f895 warned=false currentXid=null productName=Oracle productVersion=Oracle Database 18c Enterprise Edition Release 18.0.0.0.0 - Production
Version 18.3.0.0.0 jndiName=java:/ApplicationDS] txSync=TransactionSynchronization@1387480544{tx=Local transaction (delegate=TransactionImple < ac, BasicAction: 0:ffffac110002:-50a6b0bf:5fb6bdb9:73db4 status: ActionStatus.ABORTING >, owner=Local transaction context for provider JBoss JTA transaction provider) wasTrackByTx=true enlisted=true cancel=false}]: java.sql.SQLRecoverableException: IO Error: Socket read interrupted
2020-11-20 09:20:43,647 INFO  [docker-java-stream--1032099154] (org.jboss.jca.core.connectionmanager.listener.TxConnectionListener) IJ000302: Unregistered handle that was not registered: org.jboss.jca.adapters.jdbc.jdk8.WrappedConnectionJDK8@4f3c1cb2 for managed connection: org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@236f1a69
2020-11-20 09:20:43,656 WARN  [docker-java-stream--1032099154] (com.arjuna.ats.jta) ARJUNA016031: XAOnePhaseResource.rollback for < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffffac110002:-50a6b0bf:5fb6bdb9:73db4, node_name=1, branch_uid=0:ffffac110002:-50a6b0bf:5fb6bdb9:73db8, subordinatenodename=null, eis_name=java:/ApplicationDS > failed with exception: org.jboss.jca.core.spi.transaction.local.LocalXAException: IJ001160: Could not rollback local transaction
Caused by: org.jboss.jca.core.spi.transaction.local.LocalResourceException: IO Error: Socket read interrupted
        at org.jboss.ironjacamar.jdbcadapters@1.4.22.Final//org.jboss.jca.adapters.jdbc.local.LocalManagedConnection.rollback(LocalManagedConnection.java:139)
        ...
Caused by: java.sql.SQLRecoverableException: IO Error: Socket read interrupted
        at com.oracle.jdbc//oracle.jdbc.driver.T4CConnection.doRollback(T4CConnection.java:1140)
        ...
Caused by: java.io.InterruptedIOException: Socket read interrupted
        at com.oracle.jdbc//oracle.net.nt.TimeoutSocketChannel.handleInterrupt(TimeoutSocketChannel.java:258)
        ...
Chavjoh
  • 466
  • 5
  • 13

1 Answers1

4

Explanation

At the beginning, I thought about a connection problem, maybe the the transaction is no more available at the callback time (because the docker run took too long), maybe it has to be invalidated.

But at the end, as written in the console, it came from an interruption of the thread when it tries to acquire the lock to update the test and I discovered where this interruption came from: I took a look at the method executeAndStream in DefaultInvocationBuilder from the docker java library and I discovered this:

Thread thread = new Thread(() -> {
    Thread streamingThread = Thread.currentThread();
    try (DockerHttpClient.Response response = execute(request)) {
        callback.onStart(() -> {
            streamingThread.interrupt();
            response.close();
        });

        sourceConsumer.accept(response);
        callback.onComplete();
    } catch (Exception e) {
        callback.onError(e);
    }
}, "docker-java-stream-" + Objects.hashCode(request));
thread.setDaemon(true);
thread.start();

And here it is, the closable given to onStart interrupts the thread. After that, I discovered in the method onComplete from ResultCallbackTemplate (that I was extending for my callback) a close on that closable:

@Override
public void onComplete() {
    try {
        close();
    } catch (IOException e) {
        throw new RuntimeException(e);
    }
}

Resolution

The problem finally came from the following code I wrote:

@Override
public void onComplete() {
    super.onComplete();
    updateTest(FINISHED);
}

I was calling the onComplete method from the parent without knowing what is does and as usual, first before doing anything else. To correct that, I only had to call the super method at the end:

@Override
public void onComplete() {
    updateTest(FINISHED);
    super.onComplete();
}
Chavjoh
  • 466
  • 5
  • 13