Random Authentication Failed Errors unless Logging is set to DEBUG?

[mauho]

I have an interesting issue uploading and downloading data to an Axway secure transport server
I created a small project isolating the issue. When running the test n times it usually starts failing after 2 to 3 iterations with Authentication Failed Error
Interestingly, if I configure maverick to log in DEBUG mode, the error is gone and all connections are successful.
Using Loglevel TRACE I was able to reproduce the error a few times getting some logging information. Attached is the log from a run with a successful upload and a Authentication Failed error while trying to download the file.

synergy.log

The error happens after waiting for 30 seconds at 08:30:38

14 Dez. 2023 08:30:38,104 [     pool-3-thread-1]  TRACE - transport-protocol: No more tasks, will wait for a few more seconds before completing task
14 Dez. 2023 08:30:38,105 [     pool-3-thread-1]  TRACE - {}: Operation task has ended
14 Dez. 2023 08:30:38,105 [     SSHD-TRANSFER-1]  TRACE - transport-client has state ops=1 READ
14 Dez. 2023 08:31:08,111 [                main]  DEBUG - Authentication failed
14 Dez. 2023 08:31:08,111 [                main]   INFO - Disconnect host/ip:8022 By Application
14 Dez. 2023 08:31:08,111 [                main]  DEBUG - Posting message com.sshtools.synergy.ssh.TransportProtocol$DisconnectMessage to queue

I'm using Maverick in the version 3.0.11
The Axway host software has version: 5.5-20231130 (3201)

  static void uploadFile(String source, String fileName, String destination) throws Exception {
    Logger.info("Creating SSH Client... Connecting to host");

    try (SshClient ssh = new SshClient("host", 8022, "user", "pass")) {
      Logger.info("Creating SFTP Client...");
      SftpClient client = new SftpClient(ssh);
      client.cd(destination);
      client.put(source, fileName);
      client.quit();
      ssh.disconnect();
      await().forever().until(() -> !ssh.isConnected());

    } catch (PermissionDeniedException
        | SshException
        | IOException
        | TransferCancelledException
        | SftpStatusException e) {

      Logger.error(e.getMessage());
      throw new Exception();
    }
  }

  static void downloadFile(String source, String fileName, String destination) throws Exception {
    Logger.info("Creating SSH Client... Connecting to host");

    try (SshClient ssh = new SshClient("host", 8022, "user", "pass")) {
      Logger.info("Creating SFTP Client...");
      SftpClient client = new SftpClient(ssh);
      client.cd(source);
      client.get(fileName, destination);
      client.rm(fileName);
      client.quit();
      ssh.disconnect();
      Logger.info("Disconnecting ssh client");
      await().forever().until(() -> !ssh.isConnected());

    } catch (PermissionDeniedException
        | SshException
        | IOException
        | TransferCancelledException
        | SftpStatusException e) {

      Logger.error(e.getMessage());
      throw new Exception();
    }
  }

[mr-mister123]

Hi,

same problem here with version 3.0.9

I think it has to do with this related bug: [https://github.com//issues/13]
I thint it's still not properly fixed. Or let's say, it pointed me at the right direction, as i think, i've found the problem and was able to solve it.

There a several problems coming together:
first of all, it will only happen on servers, that support keyboard-interactive since only than there is the additional KeyboardInteractiveAuthenticator injected wich will then lead to a race-condition.

This will happen always, wether preferKeyboardInteractiveOverPassword is enabled or not, since there is a 'not' ('!') missing in AuthenticationProtocolClient

if(supportedAuths.contains("keyboard-interactive") &&
    (supportedAuths.contains("password") || context.getPreferKeyboardInteractiveOverPassword())) {

(i think this should be not supportedAuths.contains("password"))

additionally not all access to currentAuthenticator and authenticators is synchronized wich can lead to problems.

but the main problem is, that in addAuthentication doNextAuthentication is called if authenticators.isEmpty(). this leads to a problem: at the beginning there is the 'none'-authenticator. it will be started by start(). After the call to start() the authenticators-list is empty again. since none will lead to auth-failure in processMessage() the connected-event will be fired. this will release the connect-future. now we have the race: if the released thread is adding the two authenticators (Keyboard-Interactive and Password) before the processMessage-Thread reaches doNextAuthentication() we will have two calls to doNextAuthentication in parallel, since addAuthentication() will call doNextAuthentication on its own (authenticators was empty, although the none-authentication is not completely finished yet) and then processMessage will call doNextAuthentication, since there is still one more authenticator (two have been added before).

While investigating this, i recognized that the AbstractRequestFuture in method waitFor(long) is not protected against spurious wakeups as mentioned in the javadocs of wait().

I suggest to use a j.u.c.CountDownLatch instead of using wait / notify. Alternatively a loop is needed.

You could find two patched in the attachment that should fix the mentioned problems.

Greetz,
Karsten
AuthenticationProtocolClient.java.zip
AbstractRequestFuture.java.zip

[ludup]

Thanks,

I've added these fixes to the 3.1.0-SNAPSHOT which is to be released imminently.