dragonknight88 commented on issue #403: URL: https://github.com/apache/mina-sshd/issues/403#issuecomment-1681870053
hi @tomaswolf it seem to be failing in `decode` method on `SSH_MSG_CHANNEL_DATA` size validation. pfa: trace log of server events. ``` 2023-08-16 11:13:23 2023-08-16T18:13:23.280Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.s.session.ServerConnectionService : unregisterChannel(ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]) result=ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279] 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z TRACE 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.u.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@37a4791b) closing [DefaultCloseFuture[id=ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]][value=null]] immediately=true 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] AbstractChannel$GracefulChannelCloseable : close(ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279])[immediately=true] processing 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z TRACE 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.u.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@37a4791b) closing GracefulChannelCloseable[ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]] immediately=true 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.c.ChannelAsyncOutputStream : close(ChannelAsyncOutputStream[ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]] cmd=SSH_MSG_CHANNEL_EXTENDED_DATA)[Immediately] closed 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.c.ChannelAsyncOutputStream : close(ChannelAsyncOutputStream[ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]] cmd=SSH_MSG_CHANNEL_EXTENDED_DATA) Closing immediately 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.c.ChannelAsyncOutputStream : close(ChannelAsyncOutputStream[ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]] cmd=SSH_MSG_CHANNEL_DATA)[Immediately] closed 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.c.ChannelAsyncOutputStream : close(ChannelAsyncOutputStream[ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]] cmd=SSH_MSG_CHANNEL_DATA) Closing immediately 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.sshd.common.channel.RemoteWindow : Closing RemoteWindow[server](ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]) 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.sshd.common.channel.LocalWindow : Closing LocalWindow[server](ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]) 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z TRACE 338 --- [] [] [] [)-nio2-thread-6] o.a.sshd.server.channel.ChannelSession : signalChannelClosed(ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279])[signalChannelClosed] 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.sshd.server.channel.ChannelSession : close(ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]) no EOF sent 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.sshd.server.channel.ChannelSession : close(ChannelSession[id=0, recipient=123773646]-ServerSessionImpl[sftpusername@/10.100.92.51:38279]) Closing immediately 2023-08-16 11:13:23 2023-08-16T18:13:23.279Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.s.session.ServerConnectionService : stopHeartBeat(ServerSessionImpl[sftpusername@/10.100.92.51:38279]) no heartbeat to stop 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.s.session.ServerConnectionService : close(ServerConnectionService[ServerSessionImpl[sftpusername@/10.100.92.51:38279]]) Closing immediately 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z TRACE 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.u.closeable.SequentialCloseable : doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@5246f14f) closing ParallelCloseable[DefaultCloseFuture[id=ServerSessionImpl[sftpusername@/10.100.92.51:38279]][value=null]] immediately=true 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z TRACE 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.s.h.SessionTimeoutListener : sessionClosed(ServerSessionImpl[sftpusername@/10.100.92.51:38279]) not tracked 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z INFO 338 --- [/34.210.81.97:17155] [699a6c79-2ea6-4a18-bbfa-4945e0402da4] [sftpusername] [)-nio2-thread-6] c.XXX.service.sftp.SessionListener : Session closed 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.server.session.ServerSessionImpl : close(ServerSessionImpl[sftpusername@/10.100.92.51:38279]) Closing immediately 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.s.h.SessionTimeoutListener : sessionClosed(ServerSessionImpl[sftpusername@/10.100.92.51:38279]) un-tracked 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z DEBUG 338 --- [] [] [] [)-nio2-thread-6] o.a.s.c.s.h.SessionTimeoutListener : sessionException(ServerSessionImpl[sftpusername@/10.100.92.51:38279]) IllegalStateException: Bad length (65600) for cmd=SSH_MSG_CHANNEL_DATA - max. allowed=65572 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z ERROR 338 --- [/34.210.81.97:17155] [699a6c79-2ea6-4a18-bbfa-4945e0402da4] [sftpusername] [)-nio2-thread-6] c.XXX.service.sftp.SessionListener : Session exception: java.lang.IllegalStateException: Bad length (65600) for cmd=SSH_MSG_CHANNEL_DATA - max. allowed=65572 2023-08-16 11:13:23 2023-08-16T18:13:23.278Z WARN 338 --- [/34.210.81.97:17155] [699a6c79-2ea6-4a18-bbfa-4945e0402da4] [sftpusername] [)-nio2-thread-6] c.XXX.service.sftp.SessionListener : Reporting the failure metric: java.lang.IllegalStateException: Bad length (65600) for cmd=SSH_MSG_CHANNEL_DATA - max. allowed=65572 2023-08-16 11:13:23 2023-08-16T18:13:23.277Z WARN 338 --- [/10.205.225.32:2572] [06e94709-083c-4920-b6e5-a358fb59229e] [sftpusername] [)-nio2-thread-6] o.a.s.server.session.ServerSessionImpl : exceptionCaught(ServerSessionImpl[sftpusername@/10.100.92.51:38279])[state=Opened] IllegalStateException: Bad length (65600) for cmd=SSH_MSG_CHANNEL_DATA - max. allowed=65572 2023-08-16 11:13:23 2023-08-16T18:13:23.277Z DEBUG 338 --- [/10.205.225.32:2572] [06e94709-083c-4920-b6e5-a358fb59229e] [sftpusername] [)-nio2-thread-6] o.a.s.server.session.ServerSessionImpl : doHandleMessage(ServerSessionImpl[sftpusername@/10.100.92.51:38279]) process #14 SSH_MSG_CHANNEL_DATA 2023-08-16 11:13:23 2023-08-16T18:13:23.277Z TRACE 338 --- [/10.205.225.32:2572] [06e94709-083c-4920-b6e5-a358fb59229e] [sftpusername] [)-nio2-thread-6] o.a.s.server.session.ServerSessionImpl : decode(ServerSessionImpl[sftpusername@/10.100.92.51:38279]) packet #15 [chunk #1026](65609/65609) 00 00 00 00 00 00 00 00 00 ``` Surprisingly client works without an issue with OpenSSH server. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org For queries about this service, please contact Infrastructure at: us...@infra.apache.org --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@mina.apache.org For additional commands, e-mail: dev-h...@mina.apache.org
