Skip to content

[PROTOCOL_ERROR] Strict KEX mode encountered a message that is not permitted at this time #966

Open

Description

@massimiliano-brenna

Hi Team,

we get the exception at the bottom in connection to sftp client authentication:

client = new SSHClient();
client.loadKnownHosts();
client.addHostKeyVerifier(new PromiscuousVerifier());
client.setConnectTimeout(12000);
client.getConnection().getKeepAlive().setKeepAliveInterval(12000);
client.connect(host, port);
client.authPassword(uname, password);	
net.schmizz.sshj.transport.TransportException: 
[PROTOCOL_ERROR] Strict KEX mode encountered a message that is not permitted at this time
net.schmizz.sshj.transport.TransportImpl.gotDisconnect(TransportImpl.java:533)
net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:489)
net.schmizz.sshj.transport.Decoder.decode(Decoder.java:113)
net.schmizz.sshj.transport.Decoder.received(Decoder.java:200)
net.schmizz.sshj.transport.Reader.run(Reader.java:60)

lib version:

OS_ARCH="x86_64"
OS_NAME="Linux"
SOURCE=".:git:8f83880405cb"
BUILD_SOURCE="git:7c3aa6443f9d395b8603d37ebf8107e12bfc3e91"
BUILD_SOURCE_REPO="https://github.com/adoptium/temurin-build.git"
SOURCE_REPO="https://github.com/adoptium/jdk11u.git"
FULL_VERSION="11.0.19+7"
SEMANTIC_VERSION="11.0.19+7"
BUILD_INFO="OS: Linux Version: 5.15.0-48-generic"
JVM_VARIANT="Hotspot"
JVM_VERSION="11.0.19+7"
IMAGE_TYPE="JDK"

sshj:0.34.0

the same java client on windows server works:
OpenJDK 64-Bit Server VM; 11.0.4; 11.0.4+11; mixed mode

regards.

Activity

  1. hpoettker commented on Dec 11, 2024

    @hpoettker
    Contributor

    Please try the latest release 0.39.0.

    The release 0.34.0 is older than the OpenSSH strict key exchange extension, which has been published end of last year.

  2. massimiliano-brenna commented on Dec 11, 2024

    @massimiliano-brenna
    Author

    Please try the latest release 0.39.0.

    The release 0.34.0 is older than the OpenSSH strict key exchange extension, which has been published end of last year.

    Hi @hpoettker ,
    thanks for reply.

    I have upgrade up to 0.39.0 and the [PROTOCOL_ERROR] Strict KEX mode has gone but now not it is not connecting:

    java.lang.IllegalStateException: Not connected
    net.schmizz.sshj.SSHClient.checkConnected(SSHClient.java:841)
    net.schmizz.sshj.SSHClient.auth(SSHClient.java:203)
    net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:290)
    net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:260)
    net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:244)

    P.S.
    executing pure sftp command line on linux machine it works with the same user and password a and also I download files.

    max

  3. hpoettker commented on Dec 11, 2024

    @hpoettker
    Contributor

    Thanks for testing with 0.39.0.

    Please share debug logs from the application. And also from the server, if you can.

  4. massimiliano-brenna commented on Dec 11, 2024

    @massimiliano-brenna
    Author

    Thanks for testing with 0.39.0.

    Please share debug logs from the application. And also from the server, if you can.

    here the java client code with row number on left side:

    public class _schedService {
    ....
          client = new SSHClient();	
    303 Log.APPLICATION.info("exec client");
           //client.loadKnownHosts();
           client.addHostKeyVerifier(new PromiscuousVerifier());	
    306  Log.APPLICATION.info("exec addHostKeyVerifier");
            client.setConnectTimeout(30000);
    309  Log.APPLICATION.info("exec setConnectTimeout");
            client.getConnection().getKeepAlive().setKeepAliveInterval(30000);
    311  Log.APPLICATION.info("exec getKeepAlive");
            client.connect(host, port);
    313  Log.APPLICATION.info("exec connect");
    314  client.authPassword(uname, pwd);
    315  Log.APPLICATION.info("exec authPassword");
            sftp1 = client.newSFTPClient();
            Log.APPLICATION.info("Creato SFTPClient");
    
    
    
    }

    here the logs with row number in the middle:

    Dec 11, 2024 @ 09:55:52.395	 - 	 - 	303	 - 		exec client	RMI TCP Connection(6)-127.0.0.1	 - 
    Dec 11, 2024 @ 09:55:52.396	 - 	 - 	306	 - 		exec addHostKeyVerifier	RMI TCP Connection(6)-127.0.0.1	 - 
    Dec 11, 2024 @ 09:55:52.396	 - 	 - 	309	 - 		exec setConnectTimeout	RMI TCP Connection(6)-127.0.0.1	 - 
    Dec 11, 2024 @ 09:55:52.396	 - 	 - 	311	 - 		exec getKeepAlive	RMI TCP Connection(6)-127.0.0.1	 - 
    Dec 11, 2024 @ 09:55:52.866	 - 	 - 	313	 - 		exec connect	RMI TCP Connection(6)-127.0.0.1
    net.schmizz.sshj.transport.TransportException: [PROTOCOL_ERROR] invalid packet length: 274966857
    	at net.schmizz.sshj.transport.Decoder.checkPacketLength(Decoder.java:185)
    	at net.schmizz.sshj.transport.Decoder.decryptLength(Decoder.java:173)
    	at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:86)
    	at net.schmizz.sshj.transport.Decoder.received(Decoder.java:200)
    	at net.schmizz.sshj.transport.Reader.run(Reader.java:60)
    
  5. hpoettker commented on Dec 13, 2024

    @hpoettker
    Contributor

    sshj (like most libraries) has built in logging that you can parametrize to log at different levels.

    Can you apply for example the following configuration to produce more granular logging and post the logs?

    <logger name="net.schmizz.sshj" level="debug"/>
    <logger name="net.schmizz.sshj.transport" level="trace" />
    

    This snippet above would work for logback. How it works in your application depends on the logging implementation and potentially the application framework.

  6. massimiliano-brenna commented on Dec 13, 2024

    @massimiliano-brenna
    Author

    sshj (like most libraries) has built in logging that you can parametrize to log at different levels.

    Can you apply for example the following configuration to produce more granular logging and post the logs?

    <logger name="net.schmizz.sshj" level="debug"/>
    <logger name="net.schmizz.sshj.transport" level="trace" />
    

    This snippet above would work for logback. How it works in your application depends on the logging implementation and potentially the application framework.

    we added log4j config, here the logs:

    Socket closed
    net.schmizz.sshj.transport.TransportException: Socket closed
    at 
    net.schmizz.sshj.transport.TransportImpl.write(TransportImpl.java:437) 
    	at net.schmizz.sshj.transport.TransportImpl.sendServiceRequest(TransportImpl.java:340) 
    	at net.schmizz.sshj.transport.TransportImpl.reqService(TransportImpl.java:323) 
    	at net.schmizz.sshj.AbstractService.request(AbstractService.java:74) 
    	at net.schmizz.sshj.userauth.UserAuthImpl.authenticate(UserAuthImpl.java:66) 	at net.schmizz.sshj.SSHClient.auth(SSHClient.java:223) 
    	at net.schmizz.sshj.SSHClient.auth(SSHClient.java:204) 
    	at net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:290) 	at net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:260)
     	at net.schmizz.sshj.SSHClient.authPassword(SSHClient.java:244) 
    	at service.threads.DeleteFileThread.run(DeleteFileThread.java:104)
     Caused by: java.net.SocketException: Socket closed 	
    at java.base/java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113) 
    	at java.base/java.net.SocketOutputStream.write(SocketOutputStream.java:150) 
    	at net.schmizz.sshj.transport.TransportImpl.write(TransportImpl.java:434) 
    	... 10 more

    we also check by command line to see any fw issue:

    sftp -P XXX YYYY@ZZZZZ .
    sh: sftp: not found
    / # sftp
    sh: sftp: not found
    / # apk add openssh
    fetch https://dl-cdn.alpinelinux.org/alpine/v3.14/main/x86_64/APKINDEX.tar.gz
    fetch https://dl-cdn.alpinelinux.org/alpine/v3.14/community/x86_64/APKINDEX.tar.gz
    (1/10) Installing openssh-keygen (8.6_p1-r3)
    (2/10) Installing ncurses-terminfo-base (6.2_p20210612-r1)
    (3/10) Installing ncurses-libs (6.2_p20210612-r1)
    (4/10) Installing libedit (20210216.3.1-r0)
    (5/10) Installing openssh-client-common (8.6_p1-r3)
    (6/10) Installing openssh-client-default (8.6_p1-r3)
    (7/10) Installing openssh-sftp-server (8.6_p1-r3)
    (8/10) Installing openssh-server-common (8.6_p1-r3)
    (9/10) Installing openssh-server (8.6_p1-r3)
    (10/10) Installing openssh (8.6_p1-r3)
    Executing busybox-1.33.1-r8.trigger
    Executing glibc-bin-2.33-r0.trigger
    /usr/glibc-compat/sbin/ldconfig: /usr/glibc-compat/lib/ld-linux-x86-64.so.2 is not a symbolic link
    
    OK: 51 MiB in 41 packages
    / # sftp
    usage: sftp [-46AaCfNpqrv] [-B buffer_size] [-b batchfile] [-c cipher]
             [-D sftp_server_path] [-F ssh_config] [-i identity_file]
             [-J destination] [-l limit] [-o ssh_option] [-P port]
             [-R num_requests] [-S program] [-s subsystem | sftp_server]
             destination
    / # sftp -P XXX YYYY@ZZZZZ 
    The authenticity of host-P XXX YYYY@ZZZZZ  can't be established.
    RSA key fingerprint is ********************************************.
    This key is not known by any other names
    Are you sure you want to continue connecting (yes/no/[fingerprint])? yes
    Warning: Permanently added '-P XXX YYYY@ZZZZZ ' (RSA) to the list of known hosts.
    Password Authentication
    Enter password for YYYY
    Connected to YYYY@ZZZZZ 
    
  7. massimiliano-brenna commented on Dec 18, 2024

    @massimiliano-brenna
    Author

    Hi @hpoettker

    we have added logback.xml to the classpath and finally getting trace log level:
    I noticed also the issue start just after Heartbeater starts ( it may be similar to #910 ?)

    Dec 18, 2024 @ 14:15:20.645	jaf.model2.workspace	 - 	Beginning user transaction on jaf.model2.Workspace@3bd4c240	RMI TCP Connection(4)-127.0.0.1	 - 
    Dec 18, 2024 @ 14:15:20.656	jaf.model2.workspace	 - 	Committing user transaction on jaf.model2.Workspace@3bd4c240	RMI TCP Connection(4)-127.0.0.1	 - 
    Dec 18, 2024 @ 14:15:20.669	jaf.application	 - 	Mi collego AL *************:22	RMI TCP Connection(4)-127.0.0.1	 - 
    Dec 18, 2024 @ 14:15:20.673	 - 	14:15:20.672 [RMI TCP Connection(4)-127.0.0.1] INFO net.schmizz.sshj.transport.random.JCERandom -- Creating new SecureRandom.	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.673	 - 	14:15:20.673 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.sshj.transport.random.JCERandom -- Random creation took 1 ms	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.675	jaf.application	 - 	 *************** RecuperaElaborazioniSospeseThread ********************	Thread-43	 - 
    Dec 18, 2024 @ 14:15:20.740	 - 	14:15:20.740 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.sshj.DefaultConfig -- Available Ciphers [chacha20-poly1305@openssh.com, aes128-cbc, aes128-ctr, aes192-cbc, aes192-ctr, aes256-cbc, aes256-ctr, aes128-gcm@openssh.com, aes256-gcm@openssh.com, blowfish-cbc, blowfish-ctr, cast128-cbc, cast128-ctr, idea-cbc, idea-ctr, serpent128-cbc, serpent128-ctr, serpent192-cbc, serpent192-ctr, serpent256-cbc, serpent256-ctr, 3des-cbc, 3des-ctr, twofish128-cbc, twofish128-ctr, twofish192-cbc, twofish192-ctr, twofish256-cbc, twofish256-ctr, twofish-cbc, arcfour, arcfour128, arcfour256]	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.740	jaf.application	 - 	 eseguita client.addHostKeyVerifier(new PromiscuousVerifier())	RMI TCP Connection(4)-127.0.0.1	 - 
    Dec 18, 2024 @ 14:15:20.741	jaf.application	 - 	 eseguita client.setConnectTimeout(30000)	RMI TCP Connection(4)-127.0.0.1	 - 
    Dec 18, 2024 @ 14:15:20.741	jaf.application	 - 	 eseguita client.getConnection().getKeepAlive().setKeepAliveInterval(30000)	RMI TCP Connection(4)-127.0.0.1	 - 
    Dec 18, 2024 @ 14:15:20.748	 - 	14:15:20.748 [RMI TCP Connection(4)-127.0.0.1] INFO net.schmizz.sshj.transport.TransportImpl -- Client identity string: SSH-2.0-SSHJ_0.39.0	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.755	 - 	14:15:20.755 [RMI TCP Connection(4)-127.0.0.1] INFO net.schmizz.sshj.transport.TransportImpl -- Server identity string: SSH-2.0-SSHD	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.756	 - 	14:15:20.755 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Initiating key exchange	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.756	 - 	14:15:20.755 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.concurrent.Promise -- Clearing <<kex done>>	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.756	 - 	14:15:20.756 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Sending SSH_MSG_KEXINIT	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.757	 - 	14:15:20.756 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.concurrent.Promise -- Setting <<kexinit sent>> to `SOME`	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.757	 - 	14:15:20.756 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.concurrent.Promise -- Awaiting <<kex done>>	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.757	 - 	14:15:20.756 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Received SSH_MSG_KEXINIT	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.757	 - 	14:15:20.757 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Enabling strict key exchange extension	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.758	 - 	14:15:20.757 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Negotiated algorithms: [ kex=curve25519-sha256; sig=rsa-sha2-512; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha2-256; s2cMAC=hmac-sha2-256; c2sComp=none; s2cComp=none;  ]	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.759	 - 	14:15:20.759 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.kex.Curve25519SHA256 -- Sending SSH_MSG_KEXDH_INIT	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.780	 - 	14:15:20.779 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Received kex followup data	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.780	 - 	14:15:20.779 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.kex.Curve25519SHA256 -- Received SSH_MSG_KEXDH_REPLY	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.815	 - 	14:15:20.815 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Trying to verify host key with net.schmizz.sshj.transport.verification.PromiscuousVerifier@455508ec	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.815	 - 	14:15:20.815 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Sending SSH_MSG_NEWKEYS	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.816	 - 	14:15:20.815 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Received SSH_MSG_NEWKEYS	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.816	 - 	14:15:20.816 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.concurrent.Promise -- Clearing <<kexinit sent>>	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.817	 - 	14:15:20.816 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.concurrent.Promise -- Setting <<kex done>> to `SOME`	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.817	 - 	14:15:20.817 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.sshj.SSHClient -- Key exchange took 0.062 seconds	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.819	jaf.application	 - 	eseguita client.connect(host, port)	RMI TCP Connection(4)-127.0.0.1	 - 
    Dec 18, 2024 @ 14:15:20.820	 - 	14:15:20.819 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.concurrent.Promise -- Clearing <<service accept>>	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.820	 - 	14:15:20.820 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.sshj.transport.TransportImpl -- Sending SSH_MSG_SERVICE_REQUEST for ssh-userauth	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.820	 - 	14:15:20.820 [RMI TCP Connection(4)-127.0.0.1] DEBUG net.schmizz.concurrent.Promise -- Awaiting <<service accept>>	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.820	 - 	14:15:20.820 [sshj-Heartbeater-***.*****.****/###########:####-1734527720819] DEBUG net.schmizz.keepalive.Heartbeater -- Heartbeater Started with interval [30000 seconds]	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.822	 - 	14:15:20.822 [sshj-Heartbeater-***.*****.****/###########:####-1734527720819] DEBUG net.schmizz.keepalive.Heartbeater -- Heartbeater Sending after interval [30000 seconds]	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.822	 - 	14:15:20.822 [sshj-Reader-***.*****.****/###########:####-1734527720755] ERROR net.schmizz.sshj.transport.Decoder -- Error decoding packet (invalid length) 61 27 dc 57 6d 18 e3 a7 1f 5b 67 11	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 	14:15:20.822 [sshj-Reader-***.*****.****/###########:####-1734527720755] ERROR net.schmizz.sshj.transport.TransportImpl -- Dying because - invalid packet length: -572990191	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 	net.schmizz.sshj.transport.TransportException: invalid packet length: -572990191	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 		at net.schmizz.sshj.transport.Decoder.checkPacketLength(Decoder.java:185)	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 		at net.schmizz.sshj.transport.Decoder.decryptLength(Decoder.java:173)	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 		at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:86)	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 		at net.schmizz.sshj.transport.Decoder.received(Decoder.java:200)	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 		at net.schmizz.sshj.transport.Reader.run(Reader.java:60)	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 	14:15:20.822 [sshj-Reader-***.*****.****/###########:####-1734527720755] INFO net.schmizz.sshj.transport.TransportImpl -- Disconnected - PROTOCOL_ERROR	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.823	 - 	14:15:20.823 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.KeyExchanger -- Got notified of net.schmizz.sshj.transport.TransportException: [PROTOCOL_ERROR] invalid packet length: -572990191	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.825	 - 	14:15:20.823 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.TransportImpl$NullService -- Notified of net.schmizz.sshj.transport.TransportException: [PROTOCOL_ERROR] invalid packet length: -572990191	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.825	 - 	14:15:20.823 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.TransportImpl -- Setting active service to null-service	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.825	 - 	14:15:20.823 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.TransportImpl -- Sending SSH_MSG_DISCONNECT: reason=[PROTOCOL_ERROR], msg=[invalid packet length: -572990191]	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.825	 - 	14:15:20.824 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.concurrent.Promise -- Setting <<transport close>> to `SOME`	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.825	 - 	14:15:20.824 [sshj-Reader-***.*****.****/###########:####-1734527720755] DEBUG net.schmizz.sshj.transport.Reader -- Stopping	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.827	 - 	14:15:20.827 [RMI TCP Connection(4)-127.0.0.1] ERROR net.schmizz.concurrent.Promise -- <<service accept>> woke to: net.schmizz.sshj.transport.TransportException: [PROTOCOL_ERROR] invalid packet length: -572990191	 - 	 - 	 - 
    Dec 18, 2024 @ 14:15:20.827	jaf.application	 - 	ERRORE 	RMI TCP Connection(4)-127.0.0.1	net.schmizz.sshj.transport.TransportException: [PROTOCOL_ERROR] invalid packet length: -572990191
    	at net.schmizz.sshj.transport.Decoder.checkPacketLength(Decoder.java:185)

    ENV:

    /opt/java/openjdk # cat release
    IMPLEMENTOR="Eclipse Adoptium"
    IMPLEMENTOR_VERSION="Temurin-11.0.19+7"
    JAVA_VERSION="11.0.19"
    JAVA_VERSION_DATE="2023-04-18"
    LIBC="gnu"
    MODULES="java.base java.compiler java.datatransfer java.xml java.prefs java.desktop java.instrument java.logging java.management java.security.sasl java.naming java.rmi java.management.rmi jav
    a.net.http java.scripting java.security.jgss java.transaction.xa java.sql java.sql.rowset java.xml.crypto java.se java.smartcardio jdk.accessibility jdk.internal.vm.ci jdk.management jdk.unsup
    ported jdk.internal.vm.compiler jdk.aot jdk.internal.jvmstat jdk.attach jdk.charsets jdk.compiler jdk.crypto.ec jdk.crypto.cryptoki jdk.dynalink jdk.internal.ed jdk.editpad jdk.hotspot.agent j
    dk.httpserver jdk.internal.le jdk.internal.opt jdk.internal.vm.compiler.management jdk.jartool jdk.javadoc jdk.jcmd jdk.management.agent jdk.jconsole jdk.jdeps jdk.jdwp.agent jdk.jdi jdk.jfr j
    dk.jlink jdk.jshell jdk.jsobject jdk.jstatd jdk.localedata jdk.management.jfr jdk.naming.dns jdk.naming.ldap jdk.naming.rmi jdk.net jdk.pack jdk.rmic jdk.scripting.nashorn jdk.scripting.nashor
    n.shell jdk.sctp jdk.security.auth jdk.security.jgss jdk.unsupported.desktop jdk.xml.dom jdk.zipfs"
    OS_ARCH="x86_64"
    OS_NAME="Linux"
    SOURCE=".:git:8f83880405cb"
    BUILD_SOURCE="git:7c3aa6443f9d395b8603d37ebf8107e12bfc3e91"
    BUILD_SOURCE_REPO="https://github.com/adoptium/temurin-build.git"
    SOURCE_REPO="https://github.com/adoptium/jdk11u.git"
    FULL_VERSION="11.0.19+7"
    SEMANTIC_VERSION="11.0.19+7"
    BUILD_INFO="OS: Linux Version: 5.15.0-48-generic"
    JVM_VARIANT="Hotspot"
    JVM_VERSION="11.0.19+7"
    IMAGE_TYPE="JDK"
  8. hpoettker commented on Jan 1, 2025

    @hpoettker
    Contributor

    Thanks for the client logs and sorry for the late reply!

    According to the logs the sshj client and the server seem to successfully complete the key exchange. But then the client fails to decode the first subsequent package from the server since a negative package length doesn't make sense, which looks like they are not actually using the same keys.

    I don't think it's the same problem as in #910, which should no longer occur with 0.39.0. In that case it was the server that failed to decode the client's message that was encoded with an old key. In your case, it's the client that fails to decode the server's message.

    Do you know what exact server (including the version) it is? Do you have access to the logs of the server? It would be helpful to know what message the server is trying to send.

    It's also surprising that the server was complaining about strict KEX mode against sshj of version 0.34.0 as strict KEX mode should only get enabled if the client advertizes that it understands strict KEX, which 0.34.0 doesn't do.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions