Debugging the Maven Deploy Plugin, sort of

Last modified by Vincent Massol on 2019/06/11 10:10

Sep 25 2013

You may have been hit by some error while calling mvn deploy and found unable to debug the issue. For example a common error you can get is "Cannot connect. Reason: Auth fail".

The problem is that the Deploy plugin doesn't offer any debugging option. Researching the topic you'll find that it actually uses the JSCH library and researching how to debug this library you'll discover that it provides its own logging facade interface and doesn't provide any logging implementation, leaving it to the user to implement its interface to get any log.

Thanks this blog post I found a SLF4J implementation of the JSCH logging interface and added it to the wagon-ssh artifact.

In short to get debug logs, do the following:

  • Install this version of wagon-ssh in your local repository using this POM file, as follows:
    mvn install:install-file -Dfile=wagon-ssh-2.6-20130924-debug.jar -DpomFile=pom.xml
  • Force using this Wagon SSH modified version by modifying your project's POM to add:
    ...
    <build>
     <plugins>
    ...
         <plugin>
           <groupId>org.apache.maven.plugins</groupId>
           <artifactId>maven-deploy-plugin</artifactId>
           <dependencies>
             <dependency>
               <groupId>org.apache.maven.wagon</groupId>
               <artifactId>wagon-ssh</artifactId>
               <version>2.6-20130924-debug</version>
             </dependency>
             <dependency>
               <groupId>ch.qos.logback</groupId>
               <artifactId>logback-classic</artifactId>
               <version>1.0.13</version>
             </dependency>
           </dependencies>
         </plugin>
    ...
     </plugins>
    </build>
    ...

Now when you do a mvn deploy you'll get debug logs such as:

[INFO] --- maven-deploy-plugin:2.7:deploy (default-deploy) @ xxx ---
Downloading: scp://xxx
19:03:00.666 [pool-3-thread-1] INFO  com.jcraft.jsch - Connecting to xxx port 22
19:03:00.717 [pool-3-thread-1] INFO  com.jcraft.jsch - Connection established
19:03:00.760 [pool-3-thread-1] INFO  com.jcraft.jsch - Remote version string: SSH-2.0-OpenSSH_5.6
19:03:00.760 [pool-3-thread-1] INFO  com.jcraft.jsch - Local version string: SSH-2.0-JSCH-0.1.44
19:03:00.760 [pool-3-thread-1] INFO  com.jcraft.jsch - CheckCiphers: aes256-xxx
19:03:00.873 [pool-3-thread-1] INFO  com.jcraft.jsch - SSH_MSG_KEXINIT sent
19:03:00.874 [pool-3-thread-1] INFO  com.jcraft.jsch - SSH_MSG_KEXINIT received
19:03:00.874 [pool-3-thread-1] INFO  com.jcraft.jsch - kex: server->client aes128-xxx
19:03:00.874 [pool-3-thread-1] INFO  com.jcraft.jsch - kex: client->server aes128-xxx
19:03:00.884 [pool-3-thread-1] INFO  com.jcraft.jsch - SSH_MSG_KEXDH_INIT sent
19:03:00.884 [pool-3-thread-1] INFO  com.jcraft.jsch - expecting SSH_MSG_KEXDH_REPLY
19:03:00.938 [pool-3-thread-1] INFO  com.jcraft.jsch - ssh_rsa_verify: signature true
19:03:00.939 [pool-3-thread-1] INFO  com.jcraft.jsch - Host 'xxx' is known and mathces the RSA host key
19:03:00.939 [pool-3-thread-1] INFO  com.jcraft.jsch - SSH_MSG_NEWKEYS sent
19:03:00.939 [pool-3-thread-1] INFO  com.jcraft.jsch - SSH_MSG_NEWKEYS received
19:03:00.940 [pool-3-thread-1] INFO  com.jcraft.jsch - SSH_MSG_SERVICE_REQUEST sent
19:03:00.999 [pool-3-thread-1] INFO  com.jcraft.jsch - SSH_MSG_SERVICE_ACCEPT received
19:03:01.055 [pool-3-thread-1] INFO  com.jcraft.jsch - Authentications that can continue: publickey,keyboard-interactive,password
19:03:01.055 [pool-3-thread-1] INFO  com.jcraft.jsch - Next authentication method: publickey
19:03:01.107 [pool-3-thread-1] INFO  com.jcraft.jsch - Disconnecting from xxx port 22
[WARNING] Could not transfer metadata xxx from/to xxx): Cannot connect. Reason: Auth fail

Unfortunately, as you can see, it doesn't really add a lot of information to help you debug the real issue. In this case I had just modified my username to be a wrong one and I don't see how I can guess this from this log... 

I'm just reporting this in case it helps someone emoticon_smile

Note that a better solution is to check the SSH logs on the server side. In my case when I had the problem I got the following:

Sep 25 14:55:54 xxx sshd[801]: reverse mapping checking getaddrinfo for xxx [xxxx] failed - POSSIBLE BREAK-IN ATTEMPT!

This means that the PTR of that IP must match the hostname.

Strangely it worked fine when using SSH directly. I'm assuming this is because this message is a warning and the standard SSH client continue whereas JSCH chokes on it and stops.

Created by Vincent Massol on 2013/09/25 09:56