mimaya opened a new issue, #410:
URL: https://github.com/apache/mina-sshd/issues/410
### 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_
--
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.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
