Closed tomaskir closed 1 year ago
Hi @tomaskir,
I'm afraid I'm not understanding your analysis. RFC 4253 section 6.1 states that:
All implementations MUST be able to process packets with an
uncompressed payload length of 32768 bytes or less and a total packet
size of 35000 bytes or less (including 'packet_length',
'padding_length', 'payload', 'random padding', and 'mac'). The
maximum of 35000 bytes is an arbitrarily chosen value that is larger
than the uncompressed length noted above.
I'm also not immediately seeing RFC-4253 state anywhere that the MAC "segment" length is capped at 20 bytes (since the length of the MAC digest is a function of the algorithm negotiated): can you point out the relevant part of this RFC that you believe indicates this?
Are you somehow seeing JSch produce SSH packets > 35000 bytes in length somehow due to the buffer_margin
of 32+64+32
defined in Session.java
?
Also, what kind of devices are you encountering this issue with?
Also, can you enabling logging in JSch and provide a copy of the logs when this failure occurs?
Thanks, Jeremy
Hi @norrisjeremy
I'm afraid I'm not understanding your analysis. RFC 4253 section 6.1 states that: ...
Yes, but this is for the entire packet. This is based on RMPS (Remote Maximum Packet Size) that I mentioned in the original post. This can be negotiated to any value (up to the mentioned maximums, which must be supported) during SSH session establishment.
HOWEVER, on top of RMPS, the length "header", paddings and then the MAC are added separately. In other words, if RMPS is negotiated for example at 1000 bytes, the packet should be:
4 + 1 + 1000 + 4 + 20
bytes long (using hmac-sha1
MAC).
However since JSch uses now a static 64
for the MAC segment size, packet is bigger than it should be (when using hmac-sha1
).
This is why I mentioned in the original post that the buffer_margin
needs to be calculated based on used MAC.
I'm also not immediately seeing RFC-4253 state anywhere that the MAC "segment" length is capped at 20 bytes
The 20
byte size for the MAC segment is defined in section 6.4 Data Integrity
(link). You can see that the only required MAC is hmac-sha1
, with key size of 20
bytes. This is why it was used in buffer_margin
calculation in older versions.
As mentioned, RFC6668 extends this to 32
and/or 64
based on used MAC.
Also, what kind of devices are you encountering this issue with?
We encountered this on quite a few devices. Notables examples (off top of my head) are:
I can check our internal notes for others if you are interested. It will take me a bit to dig that info up tho.
Like mentioned in the original post, after implementing our fix, all of these devices (broken in current 0.2.6
) again work correctly.
Also, can you enabling logging in JSch and provide a copy of the logs when this failure occurs?
I don't have a broken environment available anymore, since all our deploys are now fixed with our internal fix. If interested I can setup a broken version again to provide logs.
Hi @norrisjeremy
I'm afraid I'm not understanding your analysis. RFC 4253 section 6.1 states that: ...
Yes, but this is for the entire packet. This is based on RMPS (Remote Maximum Packet Size) that I mentioned in the original post. This can be negotiated to any value (up to the mentioned maximums, which must be supported) during SSH session establishment.
HOWEVER, on top of RMPS, the length "header", paddings and then the MAC are added separately. In other words, if RMPS is negotiated for example at 1000 bytes, the packet should be:
4 + 1 + 1000 + 4 + 20
bytes long (usinghmac-sha1
MAC).
That's not what I'm reading RFC-4253 section 6.1 as stating:
It seems to indicate a total packet size of 35000 bytes or less (including 'packet_length', 'padding_length', 'payload', 'random padding', and 'mac')
.
So long as JSch is producing packets <= 35000 bytes in length (including the 'packet_length', 'padding_length', 'payload', 'random padding', and 'mac')
, it would seem that it is compliant with RFC-4253.
However since JSch uses now a static
64
for the MAC segment size, packet is bigger than it should be (when usinghmac-sha1
).This is why I mentioned in the original post that the
buffer_margin
needs to be calculated based on used MAC.I'm also not immediately seeing RFC-4253 state anywhere that the MAC "segment" length is capped at 20 bytes
The
20
byte size for the MAC segment is defined in section6.4 Data Integrity
(link). You can see that the only required MAC ishmac-sha1
, with key size of20
bytes. This is why it was used inbuffer_margin
calculation.
I'm not seeing any language in RFC 4253 section 6.4 that states what your implying. All this section does is mention what the key and digest lengths are for several MAC algorithms.
Even so, I'm not understanding how Session.buffer_margin
even comes into play based upon what you have indicated above.
Can you point out where you believe JSch is using the Session.buffer_margin
computation in a way that is causing the failures you are experiencing with these devices? It seems to me that it is impacting the size of some internal buffers JSch constructs and doesn't seem to directly correlate to the length of any packet that it actually transmits to the remote device.
As mentioned, RFC6668 extends this to
32
and/or64
based on used MAC.Also, what kind of devices are you encountering this issue with?
We encountered this on quite a few devices. Notables examples (off top of my head) are:
- Dell Powerconnect switches (multiple in the 55xx series of switches)
- Cisco SF / SG 200 and 500 series of switches
I can check our internal notes for others if you are interested. It will take me a bit to dig that info up tho.
Like mentioned in the original post, after implementing our fix, all of these devices (broken in current
0.2.6
) again work correctly.Also, can you enabling logging in JSch and provide a copy of the logs when this failure occurs?
I don't have a broken environment available anymore, since all our deploys are now fixed with our internal fix. If interested I can setup a broken version again to provide logs.
Yes, if you can provide some logs from actual broken devices that would be helpful.
Also, it might be helpful if you can provide output of ssh -vvv
using OpenSSH client to connect to some of these devices, to see if OpenSSH has enabled some sort of compatibility workaround for them.
Thanks, Jeremy
Hi @norrisjeremy
Here are the logs:
Before our internal patch:
2023-01-09 21:57:58.908 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : Connecting to switch_ip port 22
2023-01-09 21:57:58.912 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : Connection established
2023-01-09 21:57:58.917 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : Remote version string: SSH-2.0-OpenSSH_3.4p1.RL
2023-01-09 21:57:58.917 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : Local version string: SSH-2.0-UNIMUS
2023-01-09 21:57:58.917 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : CheckCiphers: chacha20-poly1305@openssh.com
2023-01-09 21:57:58.918 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : CheckKexes: curve25519-sha256,curve25519-sha256@libssh.org,curve448-sha512
2023-01-09 21:57:58.924 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : CheckSignatures: ssh-ed25519,ssh-ed448
2023-01-09 21:57:58.924 TRACE 12 --- [discovery-9] com.jcraft.jsch.Logger : server_host_key proposal before known_host reordering is: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss
2023-01-09 21:57:58.925 TRACE 12 --- [discovery-9] com.jcraft.jsch.Logger : server_host_key proposal after known_host reordering is: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss
2023-01-09 21:57:58.925 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_KEXINIT sent
2023-01-09 21:57:58.925 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_KEXINIT received
2023-01-09 21:57:58.925 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
2023-01-09 21:57:58.925 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: ssh-rsa,ssh-dss
2023-01-09 21:57:58.925 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: aes128-cbc,3des-cbc,arcfour,aes192-cbc,aes256-cbc
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: aes128-cbc,3des-cbc,arcfour,aes192-cbc,aes256-cbc
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: hmac-sha1,hmac-md5
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: hmac-sha1,hmac-md5
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: none
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: none
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server:
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server:
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,diffie-hellman-group-exchange-sha1,ext-info-c
2023-01-09 21:57:58.926 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss
2023-01-09 21:57:58.927 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,aes256-cbc,3des-ctr
2023-01-09 21:57:58.927 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,aes256-cbc,3des-ctr
2023-01-09 21:57:58.927 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-md5,hmac-md5-96,hmac-sha1-96
2023-01-09 21:57:58.927 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-md5,hmac-md5-96,hmac-sha1-96
2023-01-09 21:57:58.927 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: none
2023-01-09 21:57:58.927 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: none
2023-01-09 21:57:58.927 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client:
2023-01-09 21:57:58.927 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client:
2023-01-09 21:57:58.928 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: algorithm: diffie-hellman-group1-sha1
2023-01-09 21:57:58.928 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: host key algorithm: ssh-rsa
2023-01-09 21:57:58.928 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server->client cipher: aes192-cbc MAC: hmac-sha1 compression: none
2023-01-09 21:57:58.928 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client->server cipher: aes192-cbc MAC: hmac-sha1 compression: none
2023-01-09 21:57:58.930 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_KEXDH_INIT sent
2023-01-09 21:57:58.930 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : expecting SSH_MSG_KEXDH_REPLY
2023-01-09 21:58:00.370 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : ssh_rsa_verify: ssh-rsa signature true
2023-01-09 21:58:00.370 INFO 12 --- [discovery-9] com.jcraft.jsch.Logger : Permanently added 'switch_ip' (RSA) to the list of known hosts.
2023-01-09 21:58:00.371 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_NEWKEYS sent
2023-01-09 21:58:00.383 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_NEWKEYS received
2023-01-09 21:58:00.384 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_SERVICE_REQUEST sent
2023-01-09 21:58:00.391 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_SERVICE_ACCEPT received
2023-01-09 21:58:00.407 DEBUG 12 --- [discovery-9] n.u.core.cli.login.CliLoginStateMachine : CLI login process for 'switch_ip:22' starting in CONNECTED state
2023-01-09 21:58:00.709 DEBUG 12 --- [discovery-9] n.u.core.cli.login.CliLoginStateMachine : CLI login process for 'switch_ip:22' moving to USERNAME_REQUIRED state
2023-01-09 21:58:00.709 TRACE 12 --- [discovery-9] n.u.c.c.l.r.UsernameRequiredResolver : Sending username to 'switch_ip:22'
2023-01-09 21:58:00.709 TRACE 12 --- [discovery-9] n.u.c.s.connection.ssh.SshConnection : Closing device CLI session
2023-01-09 21:58:00.710 TRACE 12 --- [discovery-9] n.u.c.s.connection.ssh.SshConnection : Closing SSH shell channel
2023-01-09 21:58:00.710 TRACE 12 --- [discovery-9] n.u.c.s.connection.ssh.SshConnection : Closing SSH session
This is a Dell PowerConnect 5448. Like I mentioned, same occurs on the 55xx line, as well as many other old switches we have in our lab.
Notice that the connection is closed (from the device side) imediatelly after sending the first post-session-establishment packet (with the username) to the device. On the server side (the device), we only see 09-Jan-2023 22:24:02 %SSH-REJECT: New ssh connection, source test_server_ip destination switch_ip rejected due to bad packet REJECTED
After our internal patch:
2023-01-09 22:04:57.590 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : Connecting to switch_ip port 22
2023-01-09 22:04:57.594 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : Connection established
2023-01-09 22:04:57.598 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : Remote version string: SSH-2.0-OpenSSH_3.4p1.RL
2023-01-09 22:04:57.598 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : Local version string: SSH-2.0-UNIMUS
2023-01-09 22:04:57.598 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : CheckCiphers: chacha20-poly1305@openssh.com
2023-01-09 22:04:57.598 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : CheckKexes: curve25519-sha256,curve25519-sha256@libssh.org,curve448-sha512
2023-01-09 22:04:57.600 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : CheckSignatures: ssh-ed25519,ssh-ed448
2023-01-09 22:04:57.601 TRACE 12 --- [discovery-9] com.jcraft.jsch.Logger : server_host_key proposal before known_host reordering is: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss
2023-01-09 22:04:57.601 TRACE 12 --- [discovery-9] com.jcraft.jsch.Logger : server_host_key proposal after known_host reordering is: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss
2023-01-09 22:04:57.601 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_KEXINIT sent
2023-01-09 22:04:57.607 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_KEXINIT received
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: ssh-rsa,ssh-dss
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: aes128-cbc,3des-cbc,arcfour,aes192-cbc,aes256-cbc
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: aes128-cbc,3des-cbc,arcfour,aes192-cbc,aes256-cbc
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: hmac-sha1,hmac-md5
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: hmac-sha1,hmac-md5
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: none
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server: none
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server:
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server:
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,diffie-hellman-group-exchange-sha1,ext-info-c
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,aes256-cbc,3des-ctr
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes192-cbc,aes128-cbc,blowfish-cbc,3des-cbc,aes256-cbc,3des-ctr
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-md5,hmac-md5-96,hmac-sha1-96
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-md5,hmac-md5-96,hmac-sha1-96
2023-01-09 22:04:57.608 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: none
2023-01-09 22:04:57.609 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client: none
2023-01-09 22:04:57.609 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client:
2023-01-09 22:04:57.609 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client:
2023-01-09 22:04:57.609 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: algorithm: diffie-hellman-group1-sha1
2023-01-09 22:04:57.609 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: host key algorithm: ssh-rsa
2023-01-09 22:04:57.609 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: server->client cipher: aes192-cbc MAC: hmac-sha1 compression: none
2023-01-09 22:04:57.609 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : kex: client->server cipher: aes192-cbc MAC: hmac-sha1 compression: none
2023-01-09 22:04:57.610 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_KEXDH_INIT sent
2023-01-09 22:04:57.610 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : expecting SSH_MSG_KEXDH_REPLY
2023-01-09 22:04:59.047 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : ssh_rsa_verify: ssh-rsa signature true
2023-01-09 22:04:59.047 INFO 12 --- [discovery-9] com.jcraft.jsch.Logger : Permanently added 'switch_ip' (RSA) to the list of known hosts.
2023-01-09 22:04:59.047 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_NEWKEYS sent
2023-01-09 22:04:59.059 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_NEWKEYS received
2023-01-09 22:04:59.061 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_SERVICE_REQUEST sent
2023-01-09 22:04:59.068 DEBUG 12 --- [discovery-9] com.jcraft.jsch.Logger : SSH_MSG_SERVICE_ACCEPT received
2023-01-09 22:04:59.083 DEBUG 12 --- [discovery-9] n.u.core.cli.login.CliLoginStateMachine : CLI login process for 'switch_ip:22' starting in CONNECTED state
2023-01-09 22:04:59.385 DEBUG 12 --- [discovery-9] n.u.core.cli.login.CliLoginStateMachine : CLI login process for 'switch_ip:22' moving to USERNAME_REQUIRED state
2023-01-09 22:04:59.385 TRACE 12 --- [discovery-9] n.u.c.c.l.r.UsernameRequiredResolver : Sending username to 'switch_ip:22'
2023-01-09 22:04:59.687 DEBUG 12 --- [discovery-9] n.u.core.cli.login.CliLoginStateMachine : CLI login process for 'switch_ip:22' moving to PASSWORD_REQUIRED state
2023-01-09 22:04:59.687 TRACE 12 --- [discovery-9] n.u.c.c.l.r.PasswordRequiredResolver : Sending login password to 'switch_ip:22'
2023-01-09 22:04:59.990 TRACE 12 --- [discovery-9] n.u.c.c.login.data.CliLoginDataAnalyzer : 'PROMPT_DETECTED' state detected on 'switch_ip:22', validating input before accepting state
2023-01-09 22:05:00.240 DEBUG 12 --- [discovery-9] n.u.core.cli.login.CliLoginStateMachine : CLI login process for 'switch_ip:22' moving to PROMPT_DETECTED state
2023-01-09 22:05:00.241 DEBUG 12 --- [discovery-9] n.u.core.cli.login.CliLoginStateMachine : CLI login process for 'switch_ip:22' moving to AUTHENTICATED state
The ONLY difference between the 2 above runs are our adjustment to buffer_margin
size.
We changed it like I mentioned in the above post to use 20
/ 32
/ 64
based on used MAC.
Here is an OpenSSH client connect:
ssh -vvv -oKexAlgorithms=+diffie-hellman-group1-sha1 -oHostKeyAlgorithms=+ssh-rsa -c aes128-cbc user@switch_ip
OpenSSH_9.1p1, OpenSSL 3.0.7 1 Nov 2022
debug1: Reading configuration data /some_path/.ssh/config
debug1: /some_path/.ssh/config line 1: Applying options for *
debug1: Reading configuration data /etc/ssh/ssh_config
debug2: resolve_canonicalize: hostname switch_ip is address
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts' -> '/some_path/.ssh/known_hosts'
debug3: expanded UserKnownHostsFile '~/.ssh/known_hosts2' -> '/some_path/.ssh/known_hosts2'
debug1: auto-mux: Trying existing master
debug1: Control socket "/some_path/.ssh/multiplex/some_hash.socket" does not exist
debug3: ssh_connect_direct: entering
debug1: Connecting to switch_ip [switch_ip] port 22.
debug3: set_sock_tos: set socket 3 IP_TOS 0x48
debug2: fd 3 setting O_NONBLOCK
debug1: fd 3 clearing O_NONBLOCK
debug1: Connection established.
debug3: timeout: 29997 ms remain after connect
debug1: identity file /some_path/.ssh/id_rsa type 0
debug1: identity file /some_path/.ssh/id_rsa-cert type -1
debug1: identity file /some_path/.ssh/id_ecdsa type -1
debug1: identity file /some_path/.ssh/id_ecdsa-cert type -1
debug1: identity file /some_path/.ssh/id_ecdsa_sk type -1
debug1: identity file /some_path/.ssh/id_ecdsa_sk-cert type -1
debug1: identity file /some_path/.ssh/id_ed25519 type -1
debug1: identity file /some_path/.ssh/id_ed25519-cert type -1
debug1: identity file /some_path/.ssh/id_ed25519_sk type -1
debug1: identity file /some_path/.ssh/id_ed25519_sk-cert type -1
debug1: identity file /some_path/.ssh/id_xmss type -1
debug1: identity file /some_path/.ssh/id_xmss-cert type -1
debug1: identity file /some_path/.ssh/id_dsa type -1
debug1: identity file /some_path/.ssh/id_dsa-cert type -1
debug1: Local version string SSH-2.0-OpenSSH_9.1
debug1: Remote protocol version 2.0, remote software version OpenSSH_3.4p1.RL
debug1: compat_banner: match: OpenSSH_3.4p1.RL pat OpenSSH_3.* compat 0x01000002
debug2: fd 3 setting O_NONBLOCK
debug1: Authenticating to switch_ip:22 as 'user'
debug1: load_hostkeys: fopen /some_path/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
debug3: order_hostkeyalgs: no algorithms matched; accept original
debug3: send packet: type 20
debug1: SSH2_MSG_KEXINIT sent
debug3: receive packet: type 20
debug1: SSH2_MSG_KEXINIT received
debug2: local client KEXINIT proposal
debug2: KEX algorithms: sntrup761x25519-sha512@openssh.com,curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256,diffie-hellman-group1-sha1,ext-info-c
debug2: host key algorithms: ssh-ed25519-cert-v01@openssh.com,ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,sk-ssh-ed25519-cert-v01@openssh.com,sk-ecdsa-sha2-nistp256-cert-v01@openssh.com,rsa-sha2-512-cert-v01@openssh.com,rsa-sha2-256-cert-v01@openssh.com,ssh-ed25519,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ssh-ed25519@openssh.com,sk-ecdsa-sha2-nistp256@openssh.com,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: aes128-cbc
debug2: ciphers stoc: aes128-cbc
debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: compression ctos: none,zlib@openssh.com,zlib
debug2: compression stoc: none,zlib@openssh.com,zlib
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug2: peer server KEXINIT proposal
debug2: KEX algorithms: diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: host key algorithms: ssh-rsa,ssh-dss
debug2: ciphers ctos: aes128-cbc,3des-cbc,arcfour,aes192-cbc,aes256-cbc
debug2: ciphers stoc: aes128-cbc,3des-cbc,arcfour,aes192-cbc,aes256-cbc
debug2: MACs ctos: hmac-sha1,hmac-md5
debug2: MACs stoc: hmac-sha1,hmac-md5
debug2: compression ctos: none
debug2: compression stoc: none
debug2: languages ctos:
debug2: languages stoc:
debug2: first_kex_follows 0
debug2: reserved 0
debug1: kex: algorithm: diffie-hellman-group1-sha1
debug1: kex: host key algorithm: ssh-rsa
debug1: kex: server->client cipher: aes128-cbc MAC: hmac-sha1 compression: none
debug1: kex: client->server cipher: aes128-cbc MAC: hmac-sha1 compression: none
debug2: bits set: 543/1024
debug3: send packet: type 30
debug1: expecting SSH2_MSG_KEX_ECDH_REPLY
debug3: receive packet: type 31
debug1: SSH2_MSG_KEX_ECDH_REPLY received
debug1: Server host key: ssh-rsa SHA256:/LKl/anonymized+EM
debug1: load_hostkeys: fopen /some_path/.ssh/known_hosts2: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts: No such file or directory
debug1: load_hostkeys: fopen /etc/ssh/ssh_known_hosts2: No such file or directory
Warning: Permanently added 'switch_ip' (RSA) to the list of known hosts.
debug1: check_host_key: hostkey not known or explicitly trusted: disabling UpdateHostkeys
debug2: bits set: 527/1024
debug3: send packet: type 21
debug2: ssh_set_newkeys: mode 1
debug1: rekey out after 4294967296 blocks
debug1: SSH2_MSG_NEWKEYS sent
debug1: expecting SSH2_MSG_NEWKEYS
debug3: receive packet: type 21
debug1: SSH2_MSG_NEWKEYS received
debug2: ssh_set_newkeys: mode 0
debug1: rekey in after 4294967296 blocks
debug3: ssh_get_authentication_socket_path: path '/tmp/ssh-XXXXXXQ61xZv/agent.1880'
debug1: get_agent_identities: bound agent to hostkey
debug1: get_agent_identities: ssh_fetch_identitylist: agent contains no identities
debug1: Will attempt key: /some_path/.ssh/id_rsa RSA SHA256:htl+anonymized+C1Q4
debug1: Will attempt key: /some_path/.ssh/id_ecdsa
debug1: Will attempt key: /some_path/.ssh/id_ecdsa_sk
debug1: Will attempt key: /some_path/.ssh/id_ed25519
debug1: Will attempt key: /some_path/.ssh/id_ed25519_sk
debug1: Will attempt key: /some_path/.ssh/id_xmss
debug1: Will attempt key: /some_path/.ssh/id_dsa
debug2: pubkey_prepare: done
debug3: send packet: type 5
debug3: receive packet: type 6
debug2: service_accept: ssh-userauth
debug1: SSH2_MSG_SERVICE_ACCEPT received
debug3: send packet: type 50
debug3: receive packet: type 52
Authenticated to switch_ip ([switch_ip]:22) using "none".
debug1: setting up multiplex master socket
debug3: muxserver_listen: temporary control path /some_path/.ssh/multiplex/some_hash.socket.6KRKLIAveCKqYj2I
debug2: fd 4 setting O_NONBLOCK
debug3: fd 4 is O_NONBLOCK
debug3: fd 4 is O_NONBLOCK
debug1: channel 0: new [/some_path/.ssh/multiplex/some_hash.socket]
debug3: muxserver_listen: mux listener channel 0 fd 4
debug2: fd 3 setting TCP_NODELAY
debug3: set_sock_tos: set socket 3 IP_TOS 0x20
debug1: control_persist_detach: backgrounding master process
debug2: control_persist_detach: background process is 4032557
debug2: fd 4 setting O_NONBLOCK
debug1: forking to background
debug1: Entering interactive session.
debug1: pledge: id
debug2: set_control_persist_exit_time: schedule exit in 30 seconds
debug1: multiplexing control connection
debug2: fd 5 setting O_NONBLOCK
debug3: fd 5 is O_NONBLOCK
debug1: channel 1: new [mux-control]
debug3: channel_post_mux_listener: new mux channel 1 fd 5
debug3: mux_master_read_cb: channel 1: hello sent
debug2: set_control_persist_exit_time: cancel scheduled exit
debug3: mux_master_read_cb: channel 1 packet type 0x00000001 len 4
debug2: mux_master_process_hello: channel 1 client version 4
debug2: mux_client_hello_exchange: master version 4
debug3: mux_client_forwards: request forwardings: 0 local, 0 remote
debug3: mux_client_request_session: entering
debug3: mux_client_request_alive: entering
debug3: mux_master_read_cb: channel 1 packet type 0x10000004 len 4
debug2: mux_master_process_alive_check: channel 1: alive check
debug3: mux_client_request_alive: done pid = 4032559
debug3: mux_client_request_session: session request sent
debug3: mux_master_read_cb: channel 1 packet type 0x10000002 len 50
debug2: mux_master_process_new_session: channel 1: request tty 1, X 0, agent 0, subsys 0, term "xterm-256color", cmd "", env 0
debug3: mux_master_process_new_session: got fds stdin 6, stdout 7, stderr 8
debug1: channel 2: new [client-session]
debug2: mux_master_process_new_session: channel_new: 2 linked to control channel 1
debug2: channel 2: send open
debug3: send packet: type 90
debug3: receive packet: type 91
debug2: channel_input_open_confirmation: channel 2: callback start
debug2: client_session2_setup: id 2
debug2: channel 2: request pty-req confirm 1
debug3: send packet: type 98
debug2: channel 2: request shell confirm 1
debug3: send packet: type 98
debug3: mux_session_confirm: sending success reply
debug2: channel_input_open_confirmation: channel 2: callback done
debug2: channel 2: open confirm rwindow 256 rmax 128
debug1: mux_client_request_session: master session id: 2
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 2
debug2: PTY allocation request accepted on channel 2
debug3: receive packet: type 99
debug2: channel_input_status_confirm: type 99 id 2
debug2: shell request accepted on channel 2
User Name:udebug2: channel 2: rcvd adjust 1
sdebug2: channel 2: rcvd adjust 1
edebug2: channel 2: rcvd adjust 1
rdebug2: channel 2: rcvd adjust 1
Password:debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
*debug2: channel 2: rcvd adjust 1
debug2: channel 2: rcvd adjust 1
console#
Hi @tomaskir,
I happen to have access to a Dell PowerConnect 55xx, so give me some time to try and reproduce this locally.
Thanks, Jeremy
Hi @tomaskir,
Ok, I think I finally understand the issue is that these problematic devices send an extremely small maximum packet size in their SSH_MSG_CHANNEL_OPEN_CONFIRMATION
message.
I instrumented JSch locally, and saw the following:
XXX: Session SSH_MSG_CHANNEL_OPEN_CONFIRMATION setRemotePacketSize() = 128
XXX: Channel.setRemotePacketSize() = 128
XXX: Channel.getOutputStream().init().rmpsize = 128
XXX: Channel.getOutputStream().init()._buf.length = 128
I.e., in SSH_MSG_CHANNEL_OPEN_CONFIRMATION
, the remote device is indicating their max packet size is 128 bytes.
This causes a failure in Channel.java#L243:
if(_buf.length-(14+0)-Session.buffer_margin<=0){
buffer=null;
packet=null;
throw new IOException("failed to initialize the channel.");
}
I need to think more on what the best way to handle this is.
Thanks, Jeremy
HI @tomaskir,
Can you take a look at the changes I've added in #264 and see if that address your issue? I have tested locally with a Dell PowerConnect 55xx and connect to it successfully with these changes.
Thanks, Jeremy
Hi @norrisjeremy, apologies for the late reply.
Our devs went over the PR, it is very similar to how we fixed this internally (but better due to not being thread-based). We built and tested this version, and can confirm it fixes the issue on our end as well.
Thank you very much for your work on this!
Hi @tomaskir,
Great, thanks for the confirmation! This fix should be included with the 0.2.7 release in the future.
Thanks, Jeremy
Greetings,
JSch fails to connect to older SSH servers, such as on embedded devices or network switches. We have put a lot of time into investigating this, and we believe this is an issue in JSch that needs to be solved in the library. This is actually an issue that has been introduced in original JSch 0.1.54 and therefore carried into this fork. Let me describe the problem:
A bit of history
According to the "original" SSH-2.0 RFC (RFC4253) an SSH packet looks like this:
In this, RMPS refers to Remote Maximum Packet Size, and is agreed to during SSH session negotiation / establishment. For the purposes of this ticket, it is not relevant. What is relevant and problematic is the MAC size.
In later SSH RFCs, the packet format was changed, RFC6668 specifies that MAC size CAN (but does NOT have to) be increased from
20
to32
when usingHMAC-SHA2-256
or to64
when usingHMAC-SHA2-512
.A breaking change in JSch 0.1.54
In JSch 0.1.52, SSH connections to "affected" devices worked without any issues. After upgrade to JSch 0.1.54, we noticed that quite a few of devices we connected to stopped working. The SSH session would simply die during authentication.
Reverting to 0.1.52 fixed the issue, so we confirmed the change was between these 2 versions. Migrating from original JSch to this fork's release of JSch (both 0.1.72 and latest 0.2.6) the issue persists - since it was taken in from the original JSch.
Why the issue occurs
The issue is rooted in incorrectly calculated
buffer_margin
inSession.java:130
. Here is how the buffer is currently calculated:Notice the
maximum mac length
part of the buffer. In 0.1.52, this value was set at20
. However, in 0.1.54 this was changed to64
- to support stronger MAC cyphers.Root cause of the issue
Older SSH servers simply will not accept such long packets. They expect for the MAC segment to be
20
bytes. As soon as this was increased, connections to devices running these old SSH servers simply fails.How this behaves is that you invoke
new JSch().getSession(...)
, which invokesnew Session(...)
, and during session establishment you just getConnection failed: Connection is closed by SSH Server
.When monitoring logs on the SSH server, you see the incoming connection, then the server closes it due to packet parsing errors.
How this needs to get fixed
JSch needs to use proper buffer sizes depending on used MAC. So by default MAC segment size in
buffer_margin
should be20
, and only be increased to32
or64
when usingHMAC-SHA2-256
orHMAC-SHA2-512
respectively.Our internal fix and testing
For us specifically, we use each JSch session on a separate thread, so we just created a
ThreadLocal
inSession.java
and use that forbuffer_margin
calculation depending on used MAC.We validated that this fixes the issue, and after implementing this fix, we are able to connect to devices which were failing before the fix using
0.2.6
Solution in JSch
We understand that this is not acceptable as a generic solution - since other users of JSch may run many sessions on a single thread. We could implement a fix and submit a PR - the question is how would this be best implemented? We could change the constructors or introduce setters / builders for relevant things across the relevant classes, but that requires a large change to the underlying JSch classes.
If a good design for dynamically calculating
buffer_margin
based on used MAC is found, we are happy to implement and submit a PR.