-
Notifications
You must be signed in to change notification settings - Fork 603
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
[PROTOCOL_ERROR] Strict KEX mode encountered a message that is not permitted at this time #966
Comments
Please try the latest release The release |
Hi @hpoettker , I have upgrade up to 0.39.0 and the 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. max |
Thanks for testing with 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)
|
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. |
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
|
Hi @hpoettker we have added logback.xml to the classpath and finally getting trace log level: 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 [[email protected], aes128-cbc, aes128-ctr, aes192-cbc, aes192-ctr, aes256-cbc, aes256-ctr, [email protected], [email protected], 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" |
Hi Team,
we get the exception at the bottom in connection to sftp client authentication:
lib version:
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.
The text was updated successfully, but these errors were encountered: