java.lang.IllegalStateException: Authentication in progress!

[ext-marko-parikka]

We are running java application to move files from one place to another periodically by using Spring @scheduled annotation. In test environment, we are executing the process every minute. The process checks if there are files to be moved.

In this test case, there are no files at all to be moved. The sshclient is created like this:

SshClientBuilder.create()
          .addIdentities(sshKeyPair)
          .withHostname(host)
          .withPort(port)
          .withUsername(username)
          .build();

And sftp client like this: SftpClientBuilder.create().withClient(sshClient).build()

Once and a while this happens:
`29 May 2024 09:00:01,141 [ pool-746-thread-1] ERROR - Connection task failed with an error
java.lang.IllegalStateException: Authentication in progress!
at com.sshtools.client.AuthenticationProtocolClient.doNextAuthentication(AuthenticationProtocolClient.java:270)
at com.sshtools.client.AuthenticationProtocolClient.processMessage(AuthenticationProtocolClient.java:205)
at com.sshtools.synergy.ssh.TransportProtocol$5.doTask(TransportProtocol.java:2103)
at com.sshtools.common.ssh.ConnectionAwareTask.run(ConnectionAwareTask.java:49)
at com.sshtools.common.ssh.ExecutorOperationSupport$OperationTask.executeAllTasks(ExecutorOperationSupport.java:134)
at com.sshtools.common.ssh.ExecutorOperationSupport$OperationTask.run(ExecutorOperationSupport.java:89)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)

29 May 2024 09:13:01,114 [ pool-751-thread-1] ERROR - Connection task failed with an error
java.lang.IllegalStateException: Authentication in progress!
at com.sshtools.client.AuthenticationProtocolClient.doNextAuthentication(AuthenticationProtocolClient.java:270)
at com.sshtools.client.AuthenticationProtocolClient.processMessage(AuthenticationProtocolClient.java:205)
at com.sshtools.synergy.ssh.TransportProtocol$5.doTask(TransportProtocol.java:2103)
at com.sshtools.common.ssh.ConnectionAwareTask.run(ConnectionAwareTask.java:49)
at com.sshtools.common.ssh.ExecutorOperationSupport$OperationTask.executeAllTasks(ExecutorOperationSupport.java:134)
at com.sshtools.common.ssh.ExecutorOperationSupport$OperationTask.run(ExecutorOperationSupport.java:89)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)

29 May 2024 09:21:01,108 [ pool-755-thread-1] ERROR - Connection task failed with an error
java.lang.IllegalStateException: Authentication in progress!
at com.sshtools.client.AuthenticationProtocolClient.doNextAuthentication(AuthenticationProtocolClient.java:270)
at com.sshtools.client.AuthenticationProtocolClient.processMessage(AuthenticationProtocolClient.java:205)
at com.sshtools.synergy.ssh.TransportProtocol$5.doTask(TransportProtocol.java:2103)
at com.sshtools.common.ssh.ConnectionAwareTask.run(ConnectionAwareTask.java:49)
at com.sshtools.common.ssh.ExecutorOperationSupport$OperationTask.executeAllTasks(ExecutorOperationSupport.java:134)
at com.sshtools.common.ssh.ExecutorOperationSupport$OperationTask.run(ExecutorOperationSupport.java:89)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)`

And when I check the code, it should never happen:
if (currentAuthenticator != null) { // should never happen throw new IllegalStateException("Authentication in progress!"); }

[ext-marko-parikka]

These errors started to occur when we started to use version: 3.1.1. With 3.0.11 version, we did not face these kind of exceptions.

[mr-mister123]

Yes, it has to do with a fix i proposed for issue 82.

now the problem happens much less often (authentication failed) but when it happens, it will result in that exception, since there is still an race-condition anywhere. i will dig deeper into it in the next days.

[ext-marko-parikka]

We are facing the same issues with 3.1.2:

...
01 Oct 2024 12:16:30,309 [ pool-8-thread-1] DEBUG - SSH_MSG_USERAUTH_FAILURE received auths=publickey,password,keyboard-interactive
01 Oct 2024 12:16:30,309 [ pool-8-thread-1] DEBUG - none authentication failed
01 Oct 2024 12:16:30,309 [ scheduling-1] DEBUG - Authenticating with publickey
01 Oct 2024 12:16:30,309 [ scheduling-1] DEBUG - Authentication protocol is NOT ready
01 Oct 2024 12:16:30,310 [ scheduling-1] DEBUG - Authentication protocol is ready
01 Oct 2024 12:16:30,310 [ scheduling-1] DEBUG - Adding publickey authentication
01 Oct 2024 12:16:30,310 [ scheduling-1] DEBUG - Starting publickey authentication
01 Oct 2024 12:16:30,310 [ scheduling-1] DEBUG - Authenticating with ecdsa-sha2 ...
01 Oct 2024 12:16:30,310 [ scheduling-1] DEBUG - Verifying key ecdsa-sha2-nistp256
01 Oct 2024 12:16:30,310 [ scheduling-1] DEBUG - Encoded key ...
01 Oct 2024 12:16:30,310 [ pool-8-thread-1] ERROR - Connection task failed with an error
java.lang.IllegalStateException: Authentication in progress!
at com.sshtools.client.AuthenticationProtocolClient.doNextAuthentication(AuthenticationProtocolClient.java:275)
at com.sshtools.client.AuthenticationProtocolClient.processMessage(AuthenticationProtocolClient.java:210)
at com.sshtools.synergy.ssh.TransportProtocol$5.doTask(TransportProtocol.java:2103)
at com.sshtools.common.ssh.ConnectionAwareTask.run(ConnectionAwareTask.java:49)
at com.sshtools.common.ssh.ExecutorOperationSupport$OperationTask.executeAllTasks(ExecutorOperationSupport.java:134)
at com.sshtools.common.ssh.ExecutorOperationSupport$OperationTask.run(ExecutorOperationSupport.java:89)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)

[mr-mister123]

I'm working on this right now. This may take some time since race-conditions a hard to find and hard to reproduce. I hope i'll find a way to fix it soon...

[ludup]

Given that its checking the currentAuthenticator. I suspect that the future listener is not synchronized correctly when it is setting this to null. Whist the listener is synchronizing on the AuthenticationProtocolClient instance to set the value to null, preventing anything from reading the value, the event that generates that is not, and therefore, there is the oppurtunity for the listener to report complete, without currentAuthenticator being null.

It would help if log files of the failed scenario were posted.

[ludup]

I've committed a potential fix for this to the 3.2.0-SNAPSHOT branch (develop). This removes the use of the Future listener and instead sets the value to null at the correct time, before doNextAuthentication is called.

[mr-mister123]

I have to think about that...
But on first sight i don't think, that this will help. Once the ConnectFuture is released by calling transport.getConnectFuture().connected(transport, transport.getConnection()); the released thread may add more authenticators (Keyboard interactive) and then (by calling addAuthentication) call doNextAuthentication() before the thread running processMessage calls doNextAuthentication() (or in your fixed version reaches the new synchronized block freeing the currentAuthenticator) - but as said before i have to think about it slightly longer.

i had an other approach that i will test this afternoon: grab the monitor/lock before releasing the ConnectFuture and release it just before the return true by wrapping that block in a synchronized block. This should completely prevent doNextAuthentication from being called twice.

[mr-mister123]

I've tested my fix on one of our customers machines. Previously the Exception occurred about once or twice every two hours. With my patch it didn't happen any more. The fixed version is installed for about 20 hours right now. So it seems to be fixed but further testing is needed.

Please note: The supplied patch is based on the 3.0.9-version, since we need compatibility to java8. But it should be easy to port this for implementing it in the current version.

AuthenticationProtocolClient.java.zip