search

hierynomus / sshj

ssh, scp and sftp for java
Apache License 2.0
2.5k stars 601 forks source link

Find out why sometimes ecdh-sha2-nistp521 fails with Key verification exception #218

Closed hierynomus closed 8 years ago

hierynomus commented 8 years ago 
✓ Test com.hierynomus.sshj.transport.DisconnectionTest; Executed: 4/4/0

com.hierynomus.sshj.transport.kex.KeyExchangeTest > shouldKexWithEllipticCurveDiffieHellmanNistP521 FAILED
    net.schmizz.sshj.transport.TransportException: [KEY_EXCHANGE_FAILED] KeyExchange signature verification failed
✘ Test com.hierynomus.sshj.transport.kex.KeyExchangeTest; Executed: 5/4/1
hierynomus commented 8 years ago

For now it is not part of the default configured kex algorithms and test is disabled by default.

hierynomus commented 8 years ago

Logging from failing test.

16:29:25.476 [Test worker] DEBUG o.a.sshd.common.io.nio2.Nio2Acceptor - Creating Nio2Acceptor
16:29:25.477 [Test worker] DEBUG o.a.sshd.common.io.nio2.Nio2Acceptor - Binding Nio2Acceptor to address 0.0.0.0/0.0.0.0:58981
16:29:25.484 [Test worker] INFO  n.schmizz.sshj.common.SecurityUtils - BouncyCastle already registered as a JCE provider
16:29:25.510 [Test worker] INFO  n.s.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_13_0
16:29:25.513 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Creating IoSession on /127.0.0.1:58981 from /127.0.0.1:58982
16:29:25.516 [pool-2-thread-1] INFO  o.a.s.server.session.ServerSession - Server session created from /127.0.0.1:58982
16:29:25.516 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Writing 26 bytes
16:29:25.517 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Finished writing
16:29:25.517 [Test worker] INFO  n.s.sshj.transport.TransportImpl - Server identity string: SSH-2.0-SSHD-CORE-0.11.0
16:29:25.518 [Test worker] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
16:29:25.518 [Test worker] DEBUG n.s.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
16:29:25.521 [Test worker] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
16:29:25.521 [Test worker] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
16:29:25.547 [pool-2-thread-1] DEBUG o.a.s.server.session.ServerSession - Send SSH_MSG_KEXINIT
16:29:25.548 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Writing 408 bytes
16:29:25.548 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Finished writing
16:29:25.548 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
16:29:25.549 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Read 477 bytes
16:29:25.549 [pool-2-thread-1] DEBUG o.a.s.server.session.ServerSession - Client version string: SSH-2.0-SSHJ_0_13_0
16:29:25.549 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Negotiated algorithms: [ kex=ecdh-sha2-nistp521; sig=ssh-rsa; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
16:29:25.549 [pool-2-thread-1] DEBUG o.a.s.server.session.ServerSession - Received SSH_MSG_KEXINIT
16:29:25.549 [pool-2-thread-1] INFO  o.a.s.server.session.ServerSession - Kex: server->client aes128-ctr hmac-sha1 none
16:29:25.549 [pool-2-thread-1] INFO  o.a.s.server.session.ServerSession - Kex: client->server aes128-ctr hmac-sha1 none
16:29:25.677 [reader] DEBUG n.s.sshj.transport.kex.ECDHNistP - Sending SSH_MSG_KEXDH_INIT
16:29:25.677 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Read 152 bytes
16:29:25.677 [pool-2-thread-1] DEBUG org.apache.sshd.server.kex.ECDHP521 - Received SSH_MSG_KEXDH_INIT
16:29:25.700 [pool-2-thread-1] DEBUG org.apache.sshd.server.kex.ECDHP521 - K_S:  00 00 00 07 73 73 68 2d 72 73 61 00 00 00 03 01 00 01 00 00 00 81 00 dd 7c 85 9e 49 5e 28 eb c7 51 ac a4 b3 15 df c1 93 9d 44 eb 95 13 9a 64 ab 99 6d 0e d6 88 6d ce 2e 87 ce c0 cf 8d 78 02 b6 54 ed dc 5a 93 71 f1 5f 23 dd 88 95 3a f8 25 6a 82 f5 42 b5 41 3d 59 4d e9 e0 d0 c9 0f 42 6b fa f2 10 c0 34 76 ed e4 2a 44 4d 91 e3 5b 9a b8 38 e8 16 85 5b e3 e4 8c 8e 0b 63 59 1e d2 a5 24 19 1d b0 c0 1a d7 9a 2e 38 e2 4b cc 1b c0 bd ba 8e 47 fc 94 44 eb 04 89
16:29:25.700 [pool-2-thread-1] DEBUG org.apache.sshd.server.kex.ECDHP521 - f:    04 01 92 b4 81 f0 14 91 5b cc 9f 2b bf bf 8c 57 29 2d aa b0 46 33 7b c9 ea 3e f4 f2 34 5b 5c 60 d2 2f ba 3a 77 8f a1 a8 53 68 67 29 03 97 bb 8b da 5b 00 7e 51 00 c7 73 36 34 fc 2e e9 82 21 2f 14 ee e1 01 e8 69 24 05 68 b3 43 83 40 2d 76 51 f2 42 52 4f a0 b5 17 32 c6 01 36 0c d5 d2 d2 2e 0c 8a 65 fe b8 9c b8 be d8 61 f6 64 a8 c3 9d 63 5c 2c b2 46 73 f1 7b 4b 37 12 0d b3 f5 65 85 a9 68 f3 da 52 4f
16:29:25.700 [pool-2-thread-1] DEBUG org.apache.sshd.server.kex.ECDHP521 - sigH: 00 00 00 07 73 73 68 2d 72 73 61 00 00 00 80 96 6e 2c 33 93 51 42 26 72 d7 4a cb 6b 7b 11 2a 16 b7 32 36 50 7d 7c 4f 11 a7 49 2f 62 c5 6d e6 8f eb 33 b2 fe 6c ff 06 a6 9a 36 d2 bf 71 e8 12 55 24 25 53 fa ed 06 c9 5a fa 53 fc 5d 7e 98 24 ce 1e dd be f7 41 c7 fb 34 8f dd 7c 95 6a 6a 8f 77 09 37 c7 3d d0 12 0c ca 6f bd ab 3d 20 3b b8 d0 80 d1 0a 3b a3 fb f4 20 62 75 fd 7a b9 c2 84 bd d5 4d 6e 9b 1a c0 4f c0 a5 55 d8 93 d4 62 85
16:29:25.700 [pool-2-thread-1] DEBUG org.apache.sshd.server.kex.ECDHP521 - Send SSH_MSG_KEXDH_REPLY
16:29:25.700 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Writing 456 bytes
16:29:25.701 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Finished writing
16:29:25.701 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Received kex followup data
16:29:25.701 [pool-2-thread-1] DEBUG o.a.s.server.session.ServerSession - Send SSH_MSG_NEWKEYS
16:29:25.701 [reader] DEBUG n.s.sshj.transport.kex.ECDHNistP - Received SSH_MSG_KEXDH_REPLY
16:29:25.701 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Writing 16 bytes
16:29:25.701 [pool-2-thread-1] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Finished writing
16:29:25.711 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Trying to verify host key with net.schmizz.sshj.SSHClient$1@40462fce
16:29:25.712 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Sending SSH_MSG_NEWKEYS
16:29:25.712 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Received SSH_MSG_NEWKEYS
16:29:25.712 [pool-2-thread-2] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Read 16 bytes
16:29:25.713 [pool-2-thread-2] DEBUG o.a.s.server.session.ServerSession - Received SSH_MSG_NEWKEYS
16:29:25.716 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `null`
16:29:25.716 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `SOME`
16:29:25.716 [Test worker] DEBUG net.schmizz.sshj.SSHClient - Key exchange took 0.199 seconds
16:29:25.718 [Test worker] INFO  n.s.sshj.transport.TransportImpl - Disconnected - BY_APPLICATION
16:29:25.718 [Test worker] DEBUG n.s.s.t.TransportImpl$NullService - Notified of net.schmizz.sshj.transport.TransportException: [BY_APPLICATION] Disconnected
16:29:25.718 [Test worker] DEBUG n.s.sshj.transport.TransportImpl - Sending SSH_MSG_DISCONNECT: reason=[BY_APPLICATION], msg=[]
16:29:25.719 [Test worker] DEBUG net.schmizz.concurrent.Promise - Setting <<transport close>> to `SOME`
16:29:25.719 [reader] DEBUG net.schmizz.sshj.transport.Reader - Stopping
16:29:25.719 [pool-2-thread-3] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Read 68 bytes
16:29:25.719 [Test worker] INFO  c.h.s.transport.kex.KeyExchangeTest - --> Attempt 1
16:29:25.719 [pool-2-thread-3] DEBUG o.a.s.server.session.ServerSession - Received SSH_MSG_DISCONNECT (reason=11, msg=)
16:29:25.719 [pool-2-thread-3] DEBUG o.a.s.server.session.ServerSession - Closing ServerSession[null@/127.0.0.1:58982] immediately
16:29:25.721 [Test worker] INFO  n.s.sshj.transport.TransportImpl - Client identity string: SSH-2.0-SSHJ_0_13_0
16:29:25.721 [pool-2-thread-3] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Closing Nio2Session[local=/127.0.0.1:58981, remote=/127.0.0.1:58982] immediately
16:29:25.721 [pool-2-thread-4] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Creating IoSession on /127.0.0.1:58981 from /127.0.0.1:58983
16:29:25.722 [pool-2-thread-4] INFO  o.a.s.server.session.ServerSession - Server session created from /127.0.0.1:58983
16:29:25.722 [pool-2-thread-4] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Writing 26 bytes
16:29:25.722 [pool-2-thread-4] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Finished writing
16:29:25.722 [Test worker] INFO  n.s.sshj.transport.TransportImpl - Server identity string: SSH-2.0-SSHD-CORE-0.11.0
16:29:25.722 [pool-2-thread-3] DEBUG o.a.s.server.session.ServerSession - ServerSession[null@/127.0.0.1:58982] is already closing
16:29:25.722 [Test worker] DEBUG net.schmizz.concurrent.Promise - Setting <<kex done>> to `null`
16:29:25.722 [pool-2-thread-3] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Nio2Session[local=/127.0.0.1:58981, remote=/127.0.0.1:58982] closed
16:29:25.723 [Test worker] DEBUG n.s.sshj.transport.KeyExchanger - Sending SSH_MSG_KEXINIT
16:29:25.723 [Test worker] DEBUG net.schmizz.concurrent.Promise - Setting <<kexinit sent>> to `SOME`
16:29:25.723 [Test worker] DEBUG net.schmizz.concurrent.Promise - Awaiting <<kex done>>
16:29:25.723 [pool-2-thread-3] DEBUG o.a.s.server.session.ServerSession - ServerSession[null@/127.0.0.1:58982] closed
16:29:25.723 [pool-2-thread-4] DEBUG o.a.s.server.session.ServerSession - Send SSH_MSG_KEXINIT
16:29:25.723 [pool-2-thread-3] DEBUG o.a.sshd.common.io.nio2.Nio2Session - IoSession has been closed, stop reading
16:29:25.724 [pool-2-thread-4] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Writing 408 bytes
16:29:25.724 [pool-2-thread-4] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Finished writing
16:29:25.724 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Received SSH_MSG_KEXINIT
16:29:25.724 [pool-2-thread-4] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Read 477 bytes
16:29:25.724 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Negotiated algorithms: [ kex=ecdh-sha2-nistp521; sig=ssh-rsa; c2sCipher=aes128-ctr; s2cCipher=aes128-ctr; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1; c2sComp=none; s2cComp=none ]
16:29:25.724 [pool-2-thread-4] DEBUG o.a.s.server.session.ServerSession - Client version string: SSH-2.0-SSHJ_0_13_0
16:29:25.724 [pool-2-thread-4] DEBUG o.a.s.server.session.ServerSession - Received SSH_MSG_KEXINIT
16:29:25.725 [pool-2-thread-4] INFO  o.a.s.server.session.ServerSession - Kex: server->client aes128-ctr hmac-sha1 none
16:29:25.725 [pool-2-thread-4] INFO  o.a.s.server.session.ServerSession - Kex: client->server aes128-ctr hmac-sha1 none
16:29:25.737 [reader] DEBUG n.s.sshj.transport.kex.ECDHNistP - Sending SSH_MSG_KEXDH_INIT
16:29:25.738 [pool-2-thread-5] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Read 152 bytes
16:29:25.738 [pool-2-thread-5] DEBUG org.apache.sshd.server.kex.ECDHP521 - Received SSH_MSG_KEXDH_INIT
16:29:25.750 [pool-2-thread-5] DEBUG org.apache.sshd.server.kex.ECDHP521 - K_S:  00 00 00 07 73 73 68 2d 72 73 61 00 00 00 03 01 00 01 00 00 00 81 00 dd 7c 85 9e 49 5e 28 eb c7 51 ac a4 b3 15 df c1 93 9d 44 eb 95 13 9a 64 ab 99 6d 0e d6 88 6d ce 2e 87 ce c0 cf 8d 78 02 b6 54 ed dc 5a 93 71 f1 5f 23 dd 88 95 3a f8 25 6a 82 f5 42 b5 41 3d 59 4d e9 e0 d0 c9 0f 42 6b fa f2 10 c0 34 76 ed e4 2a 44 4d 91 e3 5b 9a b8 38 e8 16 85 5b e3 e4 8c 8e 0b 63 59 1e d2 a5 24 19 1d b0 c0 1a d7 9a 2e 38 e2 4b cc 1b c0 bd ba 8e 47 fc 94 44 eb 04 89
16:29:25.750 [pool-2-thread-5] DEBUG org.apache.sshd.server.kex.ECDHP521 - f:    04 01 3a 4b e8 aa d1 81 82 78 3f 23 83 d4 33 2a 35 74 8d 44 a2 52 ad 74 8a af e6 e3 04 d7 3c 20 05 2e 15 74 aa 53 58 0e 62 45 0d 1a 13 92 c8 a5 6a 62 1e d1 c9 9f bc 51 bf 9b c4 02 33 40 81 42 e6 54 e6 00 f2 61 ea d9 19 1b 9f e7 8a ed 0c 2d 7b 17 73 e6 7e db 4c 38 9b 94 54 b3 aa 58 7f 26 2c bc f8 c3 cc 44 2f be d3 56 08 ba 41 e1 65 5d 07 da 64 0d 8b 3f 31 f5 b8 97 8c 09 31 ee 21 9c a6 c1 ae 87 00
16:29:25.750 [pool-2-thread-5] DEBUG org.apache.sshd.server.kex.ECDHP521 - sigH: 00 00 00 07 73 73 68 2d 72 73 61 00 00 00 80 4f c0 5b ba 6f 37 0c 5b 54 6e e5 90 ae be eb 8d 39 00 39 0b 7d cf bb b5 27 3c a7 d2 8d 69 ff 18 cf 1b 3c 0c 34 b7 19 8e 19 7e f7 8a b1 83 55 cc b2 56 4f bb c6 21 ee 6c 20 38 3d 81 ed c6 50 e4 4b 86 2c 94 db 9a 39 4d 28 9e 80 cb fb a6 81 ef 94 5d 14 e1 5e c4 15 97 6a 80 be f4 fc bb 58 4e 53 10 aa 16 98 10 4d ab bf 06 e9 7f d9 30 17 09 14 bf 71 bb e4 35 d7 31 41 3f 94 53 ad 34 c7 cb
16:29:25.750 [pool-2-thread-5] DEBUG org.apache.sshd.server.kex.ECDHP521 - Send SSH_MSG_KEXDH_REPLY
16:29:25.751 [pool-2-thread-5] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Writing 456 bytes
16:29:25.751 [pool-2-thread-5] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Finished writing
16:29:25.751 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Received kex followup data
16:29:25.751 [pool-2-thread-5] DEBUG o.a.s.server.session.ServerSession - Send SSH_MSG_NEWKEYS
16:29:25.751 [reader] DEBUG n.s.sshj.transport.kex.ECDHNistP - Received SSH_MSG_KEXDH_REPLY
16:29:25.751 [pool-2-thread-5] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Writing 16 bytes
16:29:25.751 [pool-2-thread-5] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Finished writing
16:29:25.761 [reader] ERROR n.s.sshj.transport.TransportImpl - Dying because - {}
net.schmizz.sshj.transport.TransportException: KeyExchange signature verification failed
    at net.schmizz.sshj.transport.kex.AbstractDHG.next(AbstractDHG.java:95) ~[main/:na]
    at net.schmizz.sshj.transport.KeyExchanger.handle(KeyExchanger.java:367) ~[main/:na]
    at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:493) ~[main/:na]
    at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107) ~[main/:na]
    at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175) ~[main/:na]
    at net.schmizz.sshj.transport.Reader.run(Reader.java:60) ~[main/:na]
16:29:25.762 [reader] INFO  n.s.sshj.transport.TransportImpl - Disconnected - KEY_EXCHANGE_FAILED
16:29:25.762 [reader] DEBUG n.s.sshj.transport.KeyExchanger - Got notified of net.schmizz.sshj.transport.TransportException: [KEY_EXCHANGE_FAILED] KeyExchange signature verification failed
16:29:25.762 [reader] DEBUG n.s.s.t.TransportImpl$NullService - Notified of net.schmizz.sshj.transport.TransportException: [KEY_EXCHANGE_FAILED] KeyExchange signature verification failed
16:29:25.763 [Test worker] ERROR net.schmizz.concurrent.Promise - <<kex done>> woke to: net.schmizz.sshj.transport.TransportException: [KEY_EXCHANGE_FAILED] KeyExchange signature verification failed
16:29:25.763 [reader] DEBUG n.s.sshj.transport.TransportImpl - Setting active service to null-service
16:29:25.763 [reader] DEBUG n.s.sshj.transport.TransportImpl - Sending SSH_MSG_DISCONNECT: reason=[KEY_EXCHANGE_FAILED], msg=[KeyExchange signature verification failed]
16:29:25.763 [Test worker] DEBUG o.a.sshd.common.io.nio2.Nio2Acceptor - Unbinding
16:29:25.763 [reader] DEBUG net.schmizz.concurrent.Promise - Setting <<transport close>> to `SOME`
16:29:25.763 [reader] DEBUG net.schmizz.sshj.transport.Reader - Stopping
16:29:25.763 [pool-2-thread-6] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Read 72 bytes
16:29:25.763 [Test worker] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Closing Nio2Session[local=/127.0.0.1:58981, remote=/127.0.0.1:58983] gracefully
16:29:25.763 [pool-2-thread-6] DEBUG o.a.s.server.session.ServerSession - Received SSH_MSG_DISCONNECT (reason=3, msg=KeyExchange signature verification failed)
16:29:25.764 [pool-2-thread-6] DEBUG o.a.s.server.session.ServerSession - Closing ServerSession[null@/127.0.0.1:58983] immediately
16:29:25.764 [pool-2-thread-6] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Closing Nio2Session[local=/127.0.0.1:58981, remote=/127.0.0.1:58983] immediately
16:29:25.764 [pool-2-thread-6] DEBUG o.a.s.server.session.ServerSession - ServerSession[null@/127.0.0.1:58983] is already closing
16:29:25.764 [pool-2-thread-6] DEBUG o.a.sshd.common.io.nio2.Nio2Session - Nio2Session[local=/127.0.0.1:58981, remote=/127.0.0.1:58983] closed
16:29:25.764 [pool-2-thread-6] DEBUG o.a.s.server.session.ServerSession - ServerSession[null@/127.0.0.1:58983] closed
16:29:25.765 [pool-2-thread-6] DEBUG o.a.sshd.common.io.nio2.Nio2Session - IoSession has been closed, stop reading

KeyExchange signature verification failed
net.schmizz.sshj.transport.TransportException: [KEY_EXCHANGE_FAILED] KeyExchange signature verification failed
    at net.schmizz.sshj.transport.kex.AbstractDHG.next(AbstractDHG.java:95)
    at net.schmizz.sshj.transport.KeyExchanger.handle(KeyExchanger.java:367)
    at net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:493)
    at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:107)
    at net.schmizz.sshj.transport.Decoder.received(Decoder.java:175)
    at net.schmizz.sshj.transport.Reader.run(Reader.java:60)
hierynomus commented 8 years ago

This was a bug in Apache Mina. Solved in 7973cb1

dkocher commented 8 years ago

:sunglasses: