[
https://issues.apache.org/jira/browse/NIFI-9989?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17600931#comment-17600931
]
David Handermann commented on NIFI-9989:
----------------------------------------
[~Kirhold] I was able to reproduce the {{SSH_MSG_UNIMPLEMENTED}} error by
configuring multiple ListSFTP Processors connecting to the same host, scheduled
with {{0 sec}} as the interval.
In process of reviewing the detailed packet logs, the problem is indeed related
to having keep alive enabled.
For the ListSFTP Processor, {{Send Keep Alive}} should be disabled because the
Processor does not reuse the connection in the current implementation. This
behavior should be revisited in a separate issue, but the abstract List
Processor closes the Transfer object after returning the listing of items,
which closes the SSH connection.
The problem in this scenario is that the SSHJ library starts a background
thread immediately after completing the initial socket connection. As a result
of this behavior, the keep alive thread can send a message while the initial
Key Exchange is still in process. This can result in different types of
problematic behavior, including multiple Key Exchange Initialization (KEXINIT)
messages, which the OpenSSH server handles as failures. The SSHJ client
receives these failure messages and throws the TransportException. Most of this
behavior is internal to the SSHJ library, so the best solution will involve
some changes upstream in the library itself.
For NiFi 1.16 and 1.17, the {{Send Keep Alive}} property in ListSFTP should be
set to {{false}}, avoiding the potential for unnecessary keep alive messages.
> sftp processors Received SSH_MSG_UNIMPLEMENTED
> ----------------------------------------------
>
> Key: NIFI-9989
> URL: https://issues.apache.org/jira/browse/NIFI-9989
> Project: Apache NiFi
> Issue Type: Bug
> Components: Core Framework
> Affects Versions: 1.17.0, 1.16.1
> Environment: Ubuntu 20.04, openjdk version "1.8.0_312"
> OpenJDK Runtime Environment (build 1.8.0_312-8u312-b07-0ubuntu1~20.04-b07)
> OpenJDK 64-Bit Server VM (build 25.312-b07, mixed mode)
> Reporter: Jens M Kofoed
> Assignee: David Handermann
> Priority: Major
> Attachments: image-2022-08-16-09-44-10-682.png
>
>
> After upgrading from single instance version 1.13.2 to a 3 node cluster
> version 1.16.1 All sftp processors occasionally report errors:
> 2022-05-05 07:26:08,318 INFO [Timer-Driven Process Thread-7]
> net.schmizz.sshj.transport.random.JCERandom Creating new SecureRandom.
> 2022-05-05 07:26:08,318 DEBUG [Timer-Driven Process Thread-7]
> net.schmizz.sshj.transport.random.JCERandom Random creation took 0 ms
> 2022-05-05 07:26:08,318 DEBUG [Timer-Driven Process Thread-7]
> net.schmizz.sshj.DefaultConfig Available cipher factories:
> [[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]
> 2022-05-05 07:26:08,319 INFO [Timer-Driven Process Thread-7]
> net.schmizz.sshj.transport.TransportImpl Client identity string:
> SSH-2.0-SSHJ_0.33.0
> 2022-05-05 07:26:08,334 INFO [Timer-Driven Process Thread-7]
> net.schmizz.sshj.transport.TransportImpl Server identity string:
> SSH-2.0-OpenSSH_8.2p1 Ubuntu-4ubuntu0.4
> 2022-05-05 07:26:08,339 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.KeyExchanger Received SSH_MSG_KEXINIT
> 2022-05-05 07:26:08,340 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.KeyExchanger Sending SSH_MSG_KEXINIT
> 2022-05-05 07:26:08,340 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.KeyExchanger Negotiated algorithms: [
> kex=curve25519-sha256; sig=ssh-ed25519;
> [email protected];
> [email protected]; c2sMAC=hmac-sha1; s2cMAC=hmac-sha1;
> c2sComp=none; s2cComp=none; ]
> 2022-05-05 07:26:08,340 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.kex.Curve25519SHA256 Sending SSH_MSG_KEXDH_INIT
> 2022-05-05 07:26:08,349 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.KeyExchanger Received kex followup data
> 2022-05-05 07:26:08,349 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.kex.Curve25519SHA256 Received SSH_MSG_KEXDH_REPLY
> 2022-05-05 07:26:08,349 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.common.KeyType Key algo: ssh-ed25519, Key curve: 25519, Key
> Len: 32p: [52, 76, 38, 101, -74, -101, -94, -14, 109, -121, -87, -122, -50,
> -103, -88, -87, -50, -64, -55, 41, -109, -93, 60, 84, -75, -85, 59, -48, -34,
> 25, -77, -53]
> 2022-05-05 07:26:08,351 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.KeyExchanger Trying to verify host key with
> net.schmizz.sshj.transport.verification.PromiscuousVerifier@45c3e734
> 2022-05-05 07:26:08,351 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.KeyExchanger Sending SSH_MSG_NEWKEYS
> 2022-05-05 07:26:08,351 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.KeyExchanger Received SSH_MSG_NEWKEYS
> 2022-05-05 07:26:08,351 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.TransportImpl Received SSH_MSG_EXT_INFO
> 2022-05-05 07:26:08,354 DEBUG [Timer-Driven Process Thread-7]
> net.schmizz.sshj.transport.KeyExchanger Sending SSH_MSG_KEXINIT
> 2022-05-05 07:26:08,355 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.TransportImpl Received SSH_MSG_UNIMPLEMENTED #3
> 2022-05-05 07:26:08,355 ERROR [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.TransportImpl Dying because - Received
> SSH_MSG_UNIMPLEMENTED while exchanging keys
> net.schmizz.sshj.transport.TransportException: Received SSH_MSG_UNIMPLEMENTED
> while exchanging keys
> at
> net.schmizz.sshj.transport.TransportImpl.gotUnimplemented(TransportImpl.java:565)
> at
> net.schmizz.sshj.transport.TransportImpl.handle(TransportImpl.java:495)
> at net.schmizz.sshj.transport.Decoder.decode(Decoder.java:113)
> at net.schmizz.sshj.transport.Decoder.received(Decoder.java:200)
> at net.schmizz.sshj.transport.Reader.run(Reader.java:60)
> 2022-05-05 07:26:08,355 INFO [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.TransportImpl Disconnected - UNKNOWN
> 2022-05-05 07:26:08,355 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.KeyExchanger Got notified of
> net.schmizz.sshj.transport.TransportException: Received SSH_MSG_UNIMPLEMENTED
> while exchanging keys
> 2022-05-05 07:26:08,355 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.TransportImpl$NullService Notified of
> net.schmizz.sshj.transport.TransportException: Received SSH_MSG_UNIMPLEMENTED
> while exchanging keys
> 2022-05-05 07:26:08,355 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.TransportImpl Setting active service to
> null-service
> 2022-05-05 07:26:08,358 DEBUG [sshj-Reader-hostname/192.168.1.3:22]
> net.schmizz.sshj.transport.Reader Stopping
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
