Skip to content
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

SSH_MSG_CHANNEL_EOF is sent after SSH_MSG_CHANNEL_CLOSE #410

Closed
mimaya opened this issue Aug 28, 2023 · 17 comments · Fixed by #413
Closed

SSH_MSG_CHANNEL_EOF is sent after SSH_MSG_CHANNEL_CLOSE #410

mimaya opened this issue Aug 28, 2023 · 17 comments · Fixed by #413
Assignees
Labels
bug An issue describing a bug in the code
Milestone

Comments

@mimaya
Copy link

mimaya commented Aug 28, 2023

Version

2.10.0

Bug description

when we close channelOutputStream and ClientChannel with in few milli seconds delay. some time sending of SSH_MSG_CHANNEL_EOF message goes after sending of SSH_MSG_CHANNEL_CLOSE message. If this happens then server is responding with "SSH_MSG_DISCONNECT reason=SSH2_DISCONNECT_PROTOCOL_ERROR " , close all channels and the session.

see sequence of all messages sent from channel it 8 and 9 from a session:

ChannelExec[id=8, recipient=-1]	
	packet #39 sending command=90[SSH_MSG_CHANNEL_OPEN] len=24
		process #60 SSH_MSG_CHANNEL_OPEN_CONFIRMATION
	packet #40 sending command=98[SSH_MSG_CHANNEL_REQUEST] len=81
		process #61 SSH_MSG_CHANNEL_WINDOW_ADJUST
	packet #41 sending command=94[SSH_MSG_CHANNEL_DATA] len=6417
		process #69 SSH_MSG_CHANNEL_EXTENDED_DATA
		process #70 SSH_MSG_CHANNEL_DATA
		process #71 SSH_MSG_CHANNEL_REQUEST exit-status wantReply=false
		process #72 SSH_MSG_CHANNEL_EOF
		process #73 SSH_MSG_CHANNEL_CLOSE
	packet #46 sending command=97[SSH_MSG_CHANNEL_CLOSE] len=5
	packet #47 sending command=96[SSH_MSG_CHANNEL_EOF] len=5
	process #74 SSH_MSG_DISCONNECT
	23662 2023-08-23 12:25:27,920 [6711:DFC17666:JobReaper-GCThread-6206-6711] INFO - Got exception from exitValue : Null exitStatus even after retries with closed clientchannel

ChannelExec[id=9, recipient=-1]
	packet #43 sending command=90[SSH_MSG_CHANNEL_OPEN] len=24
		process #67 SSH_MSG_CHANNEL_OPEN_CONFIRMATION
	packet #44 sending command=98[SSH_MSG_CHANNEL_REQUEST] len=81
		process #68 SSH_MSG_CHANNEL_WINDOW_ADJUST
	packet #45 sending command=94[SSH_MSG_CHANNEL_DATA] len=6417


---

23588 2023-08-23 12:25:27,390 [6707:8AA9545D:JobReader-GCThread-6202-6707] DEBUG - sendEof(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF (state=Opened)
23603 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - close(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) Closing gracefully

23608 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #46 sending command=97[SSH_MSG_CHANNEL_CLOSE] len=5

23621 2023-08-23 12:25:27,406 [6707:8AA9545D] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #47 sending command=96[SSH_MSG_CHANNEL_EOF] len=5

the above log shows "sendEof()" is called before channel close() method but the SSH_MSG_CHANNEL_EOF was send after close that cause the session to be closed.

Actual behavior

23489 2023-08-23 12:25:26,281 [6392:B737E7FE] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #39 sending command=90[SSH_MSG_CHANNEL_OPEN] len=24
23490 2023-08-23 12:25:26,281 [6392:B737E7FE] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 84 bytes
23491 2023-08-23 12:25:26,282 [499:E4A2A23A] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #60 SSH_MSG_CHANNEL_OPEN_CONFIRMATION
23492 2023-08-23 12:25:26,282 [499:E4A2A23A] DEBUG - channelOpenConfirmation(ChannelExec[id=8, recipient=-1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_OPEN_CONFIRMATION sender=1, window-size=0, packet-size=32768
23493 2023-08-23 12:25:26,283 [499:E4A2A23A] DEBUG - setRecipient(ChannelExec[id=8, recipient=-1]-ClientSessionImpl[siramach@/127.0.0.1:22]) recipient=1
23494 2023-08-23 12:25:26,283 [499:E4A2A23A] DEBUG - init(RemoteWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])) size=0, max=0, packet=32768
23495 2023-08-23 12:25:26,283 [499:E4A2A23A] DEBUG - doOpen(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) send SSH_MSG_CHANNEL_REQUEST exec command=/scratch/siramach/agents/agent1/agent_13.5.0.0.0/sbin/nmgsshe 1
--


23496 2023-08-23 12:25:26,283 [499:E4A2A23A] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #40 sending command=98[SSH_MSG_CHANNEL_REQUEST] len=81
23497 2023-08-23 12:25:26,283 [499:E4A2A23A] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 148 bytes
23498 2023-08-23 12:25:26,285 [6392:B737E7FE] DEBUG - SSHProcessBuilder: channel connected
23499 2023-08-23 12:25:26,293 [500:E4A2A23B] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #61 SSH_MSG_CHANNEL_WINDOW_ADJUST
23500 2023-08-23 12:25:26,293 [500:E4A2A23B] DEBUG - handleWindowAdjust(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_WINDOW_ADJUST window=2097152
23501 2023-08-23 12:25:26,293 [500:E4A2A23B] DEBUG - expand(RemoteWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])) increase window from 0 by 2097152 up to 2097152
23502 2023-08-23 12:25:26,293 [6392:B737E7FE] DEBUG - waitForSpace(RemoteWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])) available: 2097152
23503 2023-08-23 12:25:26,293 [6392:B737E7FE] DEBUG - waitForSpace(RemoteWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])) available: 2097152
23504 2023-08-23 12:25:26,293 [6392:B737E7FE] DEBUG - waitAndConsume(RemoteWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])) - requested=6408, available=2097152
23505 2023-08-23 12:25:26,293 [6392:B737E7FE] DEBUG - Consume RemoteWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) by 6408 down to 2090744
---

23506 2023-08-23 12:25:26,293 [6392:B737E7FE] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #41 sending command=94[SSH_MSG_CHANNEL_DATA] len=6417
23507 2023-08-23 12:25:26,293 [6392:B737E7FE] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 6484 bytes
23508 2023-08-23 12:25:26,462 [499:E4A2A23A] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #62 SSH_MSG_CHANNEL_EXTENDED_DATA
23509 2023-08-23 12:25:26,463 [499:E4A2A23A] DEBUG - Consume LocalWindow[client](ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) by 26 down to 2097126
23510 2023-08-23 12:25:26,463 [499:E4A2A23A] DEBUG - handleExtendedData(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_EXTENDED_DATA len=26
23511 2023-08-23 12:25:26,463 [6408:F8B818F0] INFO - >>> Reporting response: PerformStreamedOperationResponse (exitCode:0 output:null error:null) (request id 1) <<<
23512 2023-08-23 12:25:26,478 [500:E4A2A23B] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #63 SSH_MSG_CHANNEL_DATA
23513 2023-08-23 12:25:26,478 [500:E4A2A23B] DEBUG - Consume LocalWindow[client](ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) by 15 down to 2097111
23514 2023-08-23 12:25:26,478 [500:E4A2A23B] DEBUG - handleData(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_DATA len=15
23515 2023-08-23 12:25:26,488 [502:E4A2A23C] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #64 SSH_MSG_CHANNEL_REQUEST
23516 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - handleChannelRequest(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_REQUEST exit-status wantReply=false
23517 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - processRequestValue(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) status=0
23518 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - process(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[exit-status] wantReply=false: 0
23519 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - notifyEvent(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]): exit-status
23520 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - notifyStateChanged(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[exit-status] event=exit-status
23521 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - sendResponse(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) request=exit-status result=ReplySuccess, want-reply=false
23522 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #65 SSH_MSG_CHANNEL_EOF
23523 2023-08-23 12:25:26,489 [502:E4A2A23C:sshd-SshClient[77a5afe]-nio2-thread-3] DEBUG - handleEof(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF
23524 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #66 SSH_MSG_CHANNEL_CLOSE
23525 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - handleClose(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_CLOSE
23526 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - handleClose(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) prevent sending EOF
23527 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - close(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) Closing gracefully
23528 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - Closing LocalWindow[client](ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])
23529 2023-08-23 12:25:26,489 [502:E4A2A23C]
23530 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - sendEof(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) already sent (state=Graceful)
23531 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - close(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=false] processing
23532 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - close(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
--

23533 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #42 sending command=97[SSH_MSG_CHANNEL_CLOSE] len=5
23534 2023-08-23 12:25:26,489 [502:E4A2A23C] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 68 bytes
23535 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - handleClosePacketWritten(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=false] SSH_MSG_CHANNEL_CLOSE written on channel
23536 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - unregisterChannel(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) result=ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]
23537 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@4914e35b) signal close complete immediately=false
23538 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@56175a64) signal close complete immediately=false
23539 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@9e66d07) signal close complete immediately=false
23540 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - close(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=true] processing
23541 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - unregisterChannel(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) result=null
23542 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@5572ebef) signal close complete immediately=true
23543 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@3b92c421) signal close complete immediately=true
23544 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@573a7d4d) signal close complete immediately=true
23545 2023-08-23 12:25:26,490 [502:E4A2A23C] DEBUG - close(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]][Graceful] - operationComplete() closed
23546 2023-08-23 12:25:26,527 [6705:D5846291:JobReaper-GCThread-6200-6705] DEBUG - Exit Code=0
23547 2023-08-23 12:25:26,840 [6705:D5846291] INFO - JobTaskExitPacket for 2078092943 {JobTaskExitPacket[exitCode=0,msg=,nlsid=56]}
23548 2023-08-23 12:25:26,840 [6705:D5846291] DEBUG - Closing the streams
23549 2023-08-23 12:25:26,840 [6705:D5846291] DEBUG - Disconnecting the channel
23550 2023-08-23 12:25:26,840 [6705:D5846291] DEBUG - close(ChannelExec[id=7, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[Immediately] state already Closed
23551 2023-08-23 12:25:26,840 [6705:D5846291] DEBUG - Disconnecting the session
23552 2023-08-23 12:25:26,840 [6705:D5846291] DEBUG - CHANNEL_CLOSE : siramach@127.0.0.1:22[25] null openChannels=1
23553 2023-08-23 12:25:26,840 [6705:D5846291] DEBUG - SSHProcess destroyed

23554 2023-08-23 12:25:27,060 [5663:5FB17133:HTTPListener--5663 (~Task-free~ OMS.pbs@491@jobs-psr-3024-oms0-0-134373=>[169279352690001])] INFO - >>> Dispatching request: GetTargetEnvironmentRequest (host.jobs-psr-3024-target1-134369-1.subnet1rg2phxsu.emdevinfraphx1.oraclevcn.com) <<<
23555 2023-08-23 12:25:27,060 [5663:5FB17133] INFO - >>> Reporting response: GetPluginEnvironmentResponse ({EMSTATE=/scratch/siramach/agents/agent1/agent_inst,perlBin=/scratch/siramach/agents/agent1/agent_13.5.0.0.0/perl/bin,emdRoot=/scratch/siramach/agents/agent1/agent_13.5.0.0.0,pluginArchive=null,emStageDir=/tmp,sdkScriptsDir=/scratch/siramach/agents/agent1/agent_13.5.0.0.0/sysman/admin/scripts,agentStateDir=/scratch/siramach/agents/agent1/agent_inst,JAVA_HOME=/scratch/siramach/agents/agent1/agent_13.5.0.0.0/oracle_common/jdk,scriptsDir=/scratch/siramach/agents/agent1/agent_13.5.0.0.0/sysman/admin/scripts,PLUGIN_ROOT=null}) (request id 1) <<<
23556 2023-08-23 12:25:27,125 [6408:9C49D0B6:HTTPListener--6408 (DispatchRequests OMS.pbs@491@jobs-psr-3024-oms0-0-134373=>[169279352690002])] INFO - >>> Dispatching request: PerformStreamedOperationRequest (/bin/echo (targetId=host.jobs-psr-3024-target1-134369-1.subnet1rg2phxsu.emdevinfraphx1.oraclevcn.com) [unsafe!] NestedJobStep2 authscheme=SSH_KEYS username:siramach @ [HostInfo:jobs-psr-3024-target1-134369-1.subnet1rg2phxsu.emdevinfraphx1.oraclevcn.com 22] ASC jobId=2078092994 truncate:10485760) <<<
23557 2023-08-23 12:25:27,125 [6408:9C49D0B6] INFO - Job Attributes: {JobID=2078092994, KeepAliveRequest=false} Job Command: {/bin/echo NestedJobStep2}
23558 2023-08-23 12:25:27,125 [6408:9C49D0B6] DEBUG - SSHProcessBuilder: Launching command="/scratch/siramach/agents/agent1/agent_13.5.0.0.0/sbin/nmgsshe 1"
23559 2023-08-23 12:25:27,125 [6408:9C49D0B6] DEBUG - init() service=ClientConnectionService[ClientSessionImpl[siramach@/127.0.0.1:22]] session=ClientSessionImpl[siramach@/127.0.0.1:22] id=9
23560 2023-08-23 12:25:27,125 [6408:9C49D0B6] DEBUG - init(LocalWindow[client](ChannelExec[id=9, recipient=-1]-ClientSessionImpl[siramach@/127.0.0.1:22])) size=2097152, max=2097152, packet=32768
23561 2023-08-23 12:25:27,125 [6408:9C49D0B6] DEBUG - registerChannel(ClientConnectionService[ClientSessionImpl[siramach@/127.0.0.1:22]])[id=9, registered=true] ChannelExec[id=9, recipient=-1]-ClientSessionImpl[siramach@/127.0.0.1:22]
23562 2023-08-23 12:25:27,125 [6408:9C49D0B6] DEBUG - createExecChannel(ClientSessionImpl[siramach@/127.0.0.1:22])[/scratch/siramach/agents/agent1/agent_13.5.0.0.0/sbin/nmgsshe 1] created id=9 - PTY=null
23563 2023-08-23 12:25:27,125 [6408:9C49D0B6] DEBUG - CHANNEL_OPEN : siramach@127.0.0.1:22[25] null openChannels=2 maxOpenChannel2 totalChannelsCreated=10
23564 2023-08-23 12:25:27,125 [6408:9C49D0B6] DEBUG - open(ChannelExec[id=9, recipient=-1]-ClientSessionImpl[siramach@/127.0.0.1:22]) Send SSH_MSG_CHANNEL_OPEN - type=session
--

23565 2023-08-23 12:25:27,126 [6408:9C49D0B6] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #43 sending command=90[SSH_MSG_CHANNEL_OPEN] len=24
23566 2023-08-23 12:25:27,126 [6408:9C49D0B6] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 84 bytes
23567 2023-08-23 12:25:27,126 [499:E4A2A23A] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #67 SSH_MSG_CHANNEL_OPEN_CONFIRMATION
23568 2023-08-23 12:25:27,126 [499:E4A2A23A] DEBUG - channelOpenConfirmation(ChannelExec[id=9, recipient=-1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_OPEN_CONFIRMATION sender=0, window-size=0, packet-size=32768
23569 2023-08-23 12:25:27,126 [499:E4A2A23A] DEBUG - setRecipient(ChannelExec[id=9, recipient=-1]-ClientSessionImpl[siramach@/127.0.0.1:22]) recipient=0
23570 2023-08-23 12:25:27,126 [499:E4A2A23A] DEBUG - init(RemoteWindow[client](ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])) size=0, max=0, packet=32768
23571 2023-08-23 12:25:27,126 [499:E4A2A23A] DEBUG - doOpen(ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) send SSH_MSG_CHANNEL_REQUEST exec command=/scratch/siramach/agents/agent1/agent_13.5.0.0.0/sbin/nmgsshe 1
--

23572 2023-08-23 12:25:27,126 [499:E4A2A23A] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #44 sending command=98[SSH_MSG_CHANNEL_REQUEST] len=81
23573 2023-08-23 12:25:27,126 [499:E4A2A23A] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 148 bytes
23574 2023-08-23 12:25:27,128 [6408:9C49D0B6] DEBUG - SSHProcessBuilder: channel connected
23575 2023-08-23 12:25:27,143 [502:E4A2A23C] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #68 SSH_MSG_CHANNEL_WINDOW_ADJUST
23576 2023-08-23 12:25:27,143 [502:E4A2A23C] DEBUG - handleWindowAdjust(ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_WINDOW_ADJUST window=2097152
23577 2023-08-23 12:25:27,144 [502:E4A2A23C] DEBUG - expand(RemoteWindow[client](ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])) increase window from 0 by 2097152 up to 2097152
23578 2023-08-23 12:25:27,145 [6408:9C49D0B6] DEBUG - waitForSpace(RemoteWindow[client](ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])) available: 2097152
23579 2023-08-23 12:25:27,146 [6408:9C49D0B6] DEBUG - waitForSpace(RemoteWindow[client](ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])) available: 2097152
23580 2023-08-23 12:25:27,146 [6408:9C49D0B6] DEBUG - waitAndConsume(RemoteWindow[client](ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])) - requested=6408, available=2097152
23581 2023-08-23 12:25:27,146 [6408:9C49D0B6] DEBUG - Consume RemoteWindow[client](ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) by 6408 down to 2090744
--

23582 2023-08-23 12:25:27,146 [6408:9C49D0B6] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #45 sending command=94[SSH_MSG_CHANNEL_DATA] len=6417
23583 2023-08-23 12:25:27,146 [6408:9C49D0B6] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 6484 bytes
23584 2023-08-23 12:25:27,369 [500:E4A2A23B] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #69 SSH_MSG_CHANNEL_EXTENDED_DATA
23585 2023-08-23 12:25:27,369 [500:E4A2A23B] DEBUG - Consume LocalWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) by 26 down to 2097126
23586 2023-08-23 12:25:27,369 [500:E4A2A23B] DEBUG - handleExtendedData(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_EXTENDED_DATA len=26
23587 2023-08-23 12:25:27,369 [6392:B737E7FE] INFO - >>> Reporting response: PerformStreamedOperationResponse (exitCode:0 output:null error:null) (request id 1) <<<
23588 2023-08-23 12:25:27,390 [6707:8AA9545D:JobReader-GCThread-6202-6707] DEBUG - sendEof(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF (state=Opened)
23589 2023-08-23 12:25:27,400 [502:E4A2A23C] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #70 SSH_MSG_CHANNEL_DATA
23590 2023-08-23 12:25:27,400 [502:E4A2A23C] DEBUG - Consume LocalWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) by 15 down to 2097111
23591 2023-08-23 12:25:27,400 [502:E4A2A23C] DEBUG - handleData(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_DATA len=15
23592 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #71 SSH_MSG_CHANNEL_REQUEST
23593 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - handleChannelRequest(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_REQUEST exit-status wantReply=false
23594 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - processRequestValue(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) status=0
23595 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - process(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])[exit-status] wantReply=false: 0
23596 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - notifyEvent(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]): exit-status
23597 2023-08-23 12:25:27,401 [499:E4A2A23A:sshd-SshClient[77a5afe]-nio2-thread-1] DEBUG - notifyStateChanged(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])[exit-status] event=exit-status
23598 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - sendResponse(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) request=exit-status result=ReplySuccess, want-reply=false
23599 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #72 SSH_MSG_CHANNEL_EOF
23600 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - handleEof(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_EOF
23601 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #73 SSH_MSG_CHANNEL_CLOSE
23602 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - handleClose(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_CHANNEL_CLOSE
23603 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - close(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) Closing gracefully
23604 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - Closing LocalWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])
23605 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - Closing RemoteWindow[client](ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])
23606 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - close(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=false] processing
23607 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - close(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=false] send SSH_MSG_CHANNEL_CLOSE
--

23608 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #46 sending command=97[SSH_MSG_CHANNEL_CLOSE] len=5
23609 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 68 bytes
23610 2023-08-23 12:25:27,401 [499:E4A2A23A] DEBUG - handleClosePacketWritten(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=false] SSH_MSG_CHANNEL_CLOSE written on channel
23611 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - unregisterChannel(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) result=ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]
23612 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1e739a5b) signal close complete immediately=false
23613 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@df3430f) signal close complete immediately=false
23614 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@4b368eb7) signal close complete immediately=false
23615 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - close(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=true] processing
23616 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - unregisterChannel(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]) result=null
23617 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@26292498) signal close complete immediately=true
23618 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@240ac344) signal close complete immediately=true
23619 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@337607f1) signal close complete immediately=true
23620 2023-08-23 12:25:27,402 [499:E4A2A23A] DEBUG - close(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22]][Graceful] - operationComplete() closed
--

23621 2023-08-23 12:25:27,406 [6707:8AA9545D] DEBUG - encode(ClientSessionImpl[siramach@/127.0.0.1:22]) packet #47 sending command=96[SSH_MSG_CHANNEL_EOF] len=5
23622 2023-08-23 12:25:27,406 [6707:8AA9545D] DEBUG - writeBuffer(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) writing 68 bytes
23623 2023-08-23 12:25:27,409 [500:E4A2A23B] DEBUG - doHandleMessage(ClientSessionImpl[siramach@/127.0.0.1:22]) process #74 SSH_MSG_DISCONNECT
23624 2023-08-23 12:25:27,409 [500:E4A2A23B] DEBUG - signalAuthFailure(ClientSessionImpl[siramach@/127.0.0.1:22]) type=SshException, signalled=false, first=false: Received ieof for nonexistent channel 1.
23625 2023-08-23 12:25:27,409 [500:E4A2A23B] DEBUG - handleDisconnect(ClientSessionImpl[siramach@/127.0.0.1:22]) SSH_MSG_DISCONNECT reason=SSH2_DISCONNECT_PROTOCOL_ERROR, [lang=] msg=Received ieof for nonexistent channel 1.
23626 2023-08-23 12:25:27,409 [500:E4A2A23B] DEBUG - close(ClientSessionImpl[siramach@/127.0.0.1:22]) Closing immediately
23627 2023-08-23 12:25:27,409 [500:E4A2A23B] DEBUG - signalAuthFailure(ClientSessionImpl[siramach@/127.0.0.1:22]) type=SshException, signalled=false, first=false: Session is being closed
23628 2023-08-23 12:25:27,409 [500:E4A2A23B] DEBUG - sessionClosed(ClientSessionImpl[siramach@/127.0.0.1:22]) un-tracked
23629 2023-08-23 12:25:27,409 [500:E4A2A23B] DEBUG - close(ClientConnectionService[ClientSessionImpl[siramach@/127.0.0.1:22]]) Closing immediately
23630 2023-08-23 12:25:27,455 [6708:DAA2EC71:JobReaper-GCThread-6203-6708] DEBUG - Exit Code=0
23631 2023-08-23 12:25:27,459 [500:E4A2A23B] DEBUG - stopHeartBeat(ClientSessionImpl[siramach@/127.0.0.1:22]) no heartbeat to stop
23632 2023-08-23 12:25:27,459 [500:E4A2A23B] DEBUG - close(ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) Closing immediately
23633 2023-08-23 12:25:27,459 [500:E4A2A23B] DEBUG - close(ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) no EOF sent
23634 2023-08-23 12:25:27,459 [500:E4A2A23B] DEBUG - Closing LocalWindow[client](ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])
23635 2023-08-23 12:25:27,459 [500:E4A2A23B] DEBUG - Closing RemoteWindow[client](ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])
23636 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - sendEof(ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) already closing or closed - state=Immediate
23637 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - close(ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[immediately=true] processing
23638 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - unregisterChannel(ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]) result=ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22]
23639 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@5112b0c8) signal close complete immediately=true
23640 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@28c6daea) signal close complete immediately=true
23641 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@1588996c) signal close complete immediately=true
23642 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - close(ChannelExec[id=9, recipient=0]-ClientSessionImpl[siramach@/127.0.0.1:22])[Immediately] closed
23643 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - close(ClientConnectionService[ClientSessionImpl[siramach@/127.0.0.1:22]])[Immediately] closed
23644 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - close(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) Closing immediately
23645 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - doCloseImmediately(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) closing socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[connected local=/127.0.0.1:15494 remote=/127.0.0.1:22]
23646 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - doCloseImmediately(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) socket=sun.nio.ch.UnixAsynchronousSocketChannelImpl[closed] closed
23647 2023-08-23 12:25:27,460 [500:E4A2A23B:sshd-SshClient[77a5afe]-nio2-thread-2] DEBUG - unmapSession(id=125): Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]
23648 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - close(ClientSessionImpl[siramach@/127.0.0.1:22])[Immediately] state already Immediate
23649 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - close(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22])[Immediately] closed
23650 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - doClose(org.apache.sshd.common.util.closeable.SequentialCloseable$1@29f315b3) signal close complete immediately=true
3651 2023-08-23 12:25:27,461 [6408:9C49D0B6] WARN - Could not extract PID from SSH command executor
23652 2023-08-23 12:25:27,461 [6408:9C49D0B6] INFO - >>> Reporting response: PerformStreamedOperationResponse (exitCode:0 output:null error:null) (request id 1) <<<
23653 2023-08-23 12:25:27,460 [500:E4A2A23B] DEBUG - close(ClientSessionImpl[siramach@/127.0.0.1:22])[Immediately] closed
23654 2023-08-23 12:25:27,461 [500:E4A2A23B] DEBUG - handleReadCycleCompletion(Nio2Session[local=/127.0.0.1:15494, remote=/127.0.0.1:22]) IoSession has been closed, stop reading
23655 2023-08-23 12:25:27,646 [6708:DAA2EC71] INFO - JobTaskExitPacket for 2078092970 {JobTaskExitPacket[exitCode=0,msg=,nlsid=56]}
23656 2023-08-23 12:25:27,646 [6708:DAA2EC71] DEBUG - Closing the streams
23657 2023-08-23 12:25:27,646 [6708:DAA2EC71] DEBUG - Disconnecting the channel
23658 2023-08-23 12:25:27,646 [6708:DAA2EC71] DEBUG - close(ChannelExec[id=8, recipient=1]-ClientSessionImpl[siramach@/127.0.0.1:22])[Immediately] state already Closed
23659 2023-08-23 12:25:27,646 [6708:DAA2EC71] DEBUG - Disconnecting the session
23660 2023-08-23 12:25:27,646 [6708:DAA2EC71] DEBUG - CHANNEL_CLOSE : siramach@127.0.0.1:22[25] null openChannels=1
23661 2023-08-23 12:25:27,646 [6708:DAA2EC71] DEBUG - SSHProcess destroyed
23662 2023-08-23 12:25:27,920 [6711:DFC17666:JobReaper-GCThread-6206-6711] INFO - Got exception from exitValue : Null exitStatus even after retries with closed clientchannel
23663 2023-08-23 12:25:27,920 [6711:DFC17666] DEBUG - Exit Code=-1

channel 8 send eof after close message that disconnect the session.

Expected behavior

I guess there should be some synchronization between sending of these 2 messages

Relevant log output

No response

Other information

No response

@tomaswolf
Copy link
Member

Can you provide code for reproducing this?

@tomaswolf
Copy link
Member

Though maybe not necessary. I think I see where this is coming from: the CloseFuture returned here should be fulfilled only once the future returned by sendEof() is fulfilled. But the current code simply ignores that.

@mimaya
Copy link
Author

mimaya commented Aug 29, 2023

will the below changes fix the issue ?

AbstractChannel
line 101

protected IoWriteFuture sendEofFuture;

AbstractChannel.sendEof()
line: 961
this.sendEofFuture = s.writePacket(buffer); return this.sendEofFuture;

AbstractChannel.handleClose()
line: 552

if (this.sendEofFuture != null) { try { this.sendEofFuture.verify(0L); }catch (IOException e) { log.error("Waiting for sendEof failed", e); } }

@tomaswolf
Copy link
Member

will the below changes fix the issue ?

I don't think so. First, storing that IoWriteFuture in a field is kind of hacky, and second, handleClose() handles reception of the peer's CLOSE message. As I understood the problem is that the client sends its EOF after it has already sent its CLOSE.

I have another fix in the works, but I need to see if I can provoke that error reliably so that I can write a unit test for it.

@tomaswolf tomaswolf self-assigned this Aug 29, 2023
@tomaswolf tomaswolf added the bug An issue describing a bug in the code label Aug 29, 2023
@tomaswolf tomaswolf added this to the 2.10.1 milestone Aug 29, 2023
@tomaswolf
Copy link
Member

I think I need code that shows this problem all the same. So far I have not been able to provoke this condition.

@mimaya
Copy link
Author

mimaya commented Aug 30, 2023

handleClose() handles reception of the peer's CLOSE message. As I understood the problem is that the client sends its EOF after it has already sent its CLOSE.

We always call close channel immediately after exitStatus is read. this does not call graceful close and send SSH_MSG_CHANNEL_CLOSE.

My understandingof the issue is on reception of peer's SSH_MSG_CHANNEL_CLOSE, handleClose is calling close(false) that sends SSH_MSG_CHANNEL_CLOSE from client

// Thread1: on outStream.close() call from client
protected IoWriteFuture sendEof() throws IOException {

        if (eofSent.getAndSet(true)) {
            if (log.isDebugEnabled()) {
                log.debug("sendEof({}) already sent (state={})", this, channelState);
            }
            return null;
        }
		....
		// Thread1 read eofSent as false and set to true and reach here
        Session s = getSession();
        Buffer buffer = s.createBuffer(SshConstants.SSH_MSG_CHANNEL_EOF, Short.SIZE);
        buffer.putUInt(getRecipient());
// Thread2: On receive of SSH_MSG_CHANNEL_CLOSE from server
public void handleClose() throws IOException {
	boolean debugEnabled = log.isDebugEnabled();
	if (debugEnabled) {
		log.debug("handleClose({}) SSH_MSG_CHANNEL_CLOSE", this);
	}

	try {
		if (!eofSent.getAndSet(true)) {
			if (debugEnabled) {
				log.debug("handleClose({}) prevent sending EOF", this);
			}
		}		
	
		....
		// Thread2 read eofSent as true and reach here
		Session s = getSession();
		Buffer buffer = s.createBuffer(SshConstants.SSH_MSG_CHANNEL_CLOSE, Short.SIZE);
		buffer.putUInt(recipient);
		

@mimaya
Copy link
Author

mimaya commented Aug 30, 2023

I also couldn't reproduce this issue with sample code. this comes only in our application during PSR testing where more than 50k command are executed over ssh.

@tomaswolf
Copy link
Member

I'm getting confused.

Who initiates the channel closing when that problem occurs? Client or server? Or both?

Is client code closing the output stream explicitly, or does that happen during the graceful channel closing?

Is the server also an Apche MINA sshd 2.10.0 server? If not, what is it?

@tomaswolf
Copy link
Member

All right. I have now a test case that reproduces this. It's hyper-ugly test code, and to reproduce the race I had to instrument the code in AbstractChannel. But there is definitely a race, and it looks as if it's not easily solvable. With a default Apache MINA sshd server it's even harder to reproduce because a default server ignores requests for unknown channels. (The EOF sent after the close would arrive at the server for an unknown channel.) But making the server close the session on requests for unknown channels (which is the OpenSSH behavior) I can reproduce this consistently now.

The race will not be fixed by the proposal you made. That still has the race : first, the field would have to be volatile at least, and second, handleClose() might still reach the (this.sendEofFuture != null) { before sendEof() has set it.

Fixing this will require a bit more work. I don't think it's solvable with the AtomicBoolean eofSent; this needs to be done more carefully. I have some ideas and will take another look over the week-end.

tomaswolf added a commit to tomaswolf/mina-sshd that referenced this issue Sep 1, 2023
When a channel using a ChannelAsyncOutputStream, do not only wait until
all pending data has been written but also wait for the EOF having been
sent before proceeding with closing the channel.

For channels using a synchronous ChannelOutputStream, no local fix was
found. Instead give the channel access to the IoWriteFuture for sending
the EOF packet, and if one was sent, ensure that closing the channel
proceeds only after the EOF has been sent.

Otherwise there may be a race between sending that EOF and sending the
CLOSE, and sometimes the EOF might be sent after the CLOSE.

Bug: apache#410
tomaswolf added a commit to tomaswolf/mina-sshd that referenced this issue Sep 2, 2023
When a channel using a ChannelAsyncOutputStream, do not only wait until
all pending data has been written but also wait for the EOF having been
sent before proceeding with closing the channel.

For channels using a synchronous ChannelOutputStream, no local fix was
found. Instead give the channel access to the IoWriteFuture for sending
the EOF packet, and if one was sent, ensure that closing the channel
proceeds only after the EOF has been sent.

Otherwise there may be a race between sending that EOF and sending the
CLOSE, and sometimes the EOF might be sent after the CLOSE.

Bug: apache#410
@mimaya
Copy link
Author

mimaya commented Sep 6, 2023

Do you have any tentative date 2.10.1 release that has the fix?

@tomaswolf
Copy link
Member

No, I don't. The 2.10.1-SNAPSHOT from the Apache Snapshot repository does have the fix.

There is no fixed release schedule; the project is maintained by private individuals in their spare time. I think it would be good if we could do a release in October, but I cannot promise anything.

@mimaya
Copy link
Author

mimaya commented Oct 5, 2023

I'm wondering if there is any update on the release date.
I understand that there is no fixed schedule, but any information would be greatly appreciated as we need to plan accordingly

@tomaswolf
Copy link
Member

Thanks for reminding me. I've asked for a new release.

@mimaya
Copy link
Author

mimaya commented Oct 17, 2023

Is 2.9.3 release only for CVE fixes ? If you are planning to release 2.9.3 before 2.11.0 . would it be possible to include this fix in 2.9.3 ?

@tomaswolf
Copy link
Member

Guillaume just included the CVE fix in 2.9.3. I don't have time to backport this fix and ask for a respin.

@mimaya
Copy link
Author

mimaya commented Oct 17, 2023

We are using this in a large enterprise product. To fix an issue, we were upgrading the SSH client to 2.9.2, but we found the following problem during PSR testing:

https://issues.apache.org/jira/browse/SSHD-1316

This forced us to move to 2.10.0 and also make code changes related to CancelOption in Future calls. Then, we hit a race condition message error.

#410

We spent more than 3 months on upgrading sshd client as we were iteratively working on multiple versions and postponing our release a few times. Now, we are facing a lot of pressure from customers to release soon. These bugs are having a significant impact on our product and our customers. I hope you understand our situation.

I understand that you are very busy, and I appreciate your time and consideration. I would like to ask if it would be possible to include these 2 bug fixes in the next release of 2.9.3.

@mimaya
Copy link
Author

mimaya commented Oct 26, 2023

Thanks , I see 2.11.0 version is released now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An issue describing a bug in the code
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants