You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
{{ message }}
Repository navigation
[PROTOCOL_ERROR] Strict KEX mode encountered a message that is not permitted at this time #966
This snippet above would work for logback. How it works in your application depends on the logging implementation and potentially the application framework.
This snippet above would work for logback. How it works in your application depends on the logging implementation and potentially the application framework.
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)
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.
Activity
hpoettker commentedon Dec 11, 2024
Please try the latest release
0.39.0.The release
0.34.0is older than the OpenSSH strict key exchange extension, which has been published end of last year.massimiliano-brenna commentedon Dec 11, 2024
Hi @hpoettker ,
thanks for reply.
I have upgrade up to 0.39.0 and the
[PROTOCOL_ERROR] Strict KEX modehas gone but now not it is not connecting: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
hpoettker commentedon Dec 11, 2024
Thanks for testing with
0.39.0.Please share debug logs from the application. And also from the server, if you can.
massimiliano-brenna commentedon Dec 11, 2024
here the java client code with row number on left side:
here the logs with row number in the middle:
hpoettker commentedon Dec 13, 2024
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?
This snippet above would work for logback. How it works in your application depends on the logging implementation and potentially the application framework.
massimiliano-brenna commentedon Dec 13, 2024
we added log4j config, here the logs:
we also check by command line to see any fw issue:
massimiliano-brenna commentedon Dec 18, 2024
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 ?)
ENV:
hpoettker commentedon Jan 1, 2025
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
sshjof version0.34.0as strict KEX mode should only get enabled if the client advertizes that it understands strict KEX, which0.34.0doesn't do.