Re: ssh_scp_close hangs

[Andreas Schneider <asn@xxxxxxxxxxxxxx>]

On Friday, 13 May 2016 11:17:50 CET Игорь Коваленко wrote:
> Hi!
> I'm developing a scp-server.
> Main loop is organized using events.
> Using pscp I'm trying to download one file.
> On the server ssh_scp_push_file and ssh_scp_write are working as expected
> and I see that a file is created localy.
> Then server is calling ssh_scp_close and it hangs.
> It hangs in ssh_scp_close at SECOND iteration of the following while loop:
>     while(!ssh_channel_is_eof(scp->channel)){
>       err=ssh_channel_read(scp->channel,buffer,sizeof(buffer),0); // HERE
> IT HANGS
>       if(err==SSH_ERROR || err==0)
>         break;
>     }
> At first iteration it receives 1 byte but it is not eof.
> 
> There are some several last lines of the server's log:
> ...
> PACKET ssh_channel_send_eof ssh_channel_send_eof: Sent a EOF on client
> channel (43:256)
> PACKET ssh_packet_socket_callback ssh_packet_socket_callback: packet: read
> type 94 [len=28,padding=17,comp=10,payload=10]
> PACKET ssh_packet_process ssh_packet_process: Dispatching handler for
> packet type 94
> PACKET channel_rcv_data channel_rcv_data: Channel receiving 1 bytes data in
> 0 (local win=1279999 remote win=2147478279)
> PACKET channel_default_bufferize channel_default_bufferize: placing 1 bytes
> into channel buffer (stderr=0)
> PACKET channel_rcv_data channel_rcv_data: Channel windows are now (local
> win=1279998 remote win=2147478279)
> PACKET ssh_socket_unbuffered_write ssh_socket_unbuffered_write: Enabling
> POLLOUT for socket
> PACKET ssh_channel_read_timeout ssh_channel_read_timeout: Read (128)
> buffered : 1 bytes. Window: 1279998
> 
> putty's log is:
> ....
> Incoming packet #0xc, type 94 / 0x5e (SSH2_MSG_CHANNEL_DATA)
>   00000000  00 00 01 00 00 00 00 01 00                       .........
> Incoming packet #0xd, type 96 / 0x60 (SSH2_MSG_CHANNEL_EOF)
>   00000000  00 00 01 00                                      ....
> 
> if I'm commenting while loop while(!ssh_channel_is_eof(scp->channel)){
> then scp closes normally.
> In that case several last lines of the server's log:
> PACKET ssh_channel_send_eof ssh_channel_send_eof: Sent a EOF on client
> channel (43:256)
> PACKET ssh_packet_socket_callback ssh_packet_socket_callback: packet: read
> type 94 [len=28,padding=17,comp=10,payload=10]
> PACKET ssh_packet_process ssh_packet_process: Dispatching handler for
> packet type 94
> PACKET channel_rcv_data channel_rcv_data: Channel receiving 1 bytes data in
> 0 (local win=1279999 remote win=2147478279)
> PACKET channel_default_bufferize channel_default_bufferize: placing 1 bytes
> into channel buffer (stderr=0)
> PACKET channel_rcv_data channel_rcv_data: Channel windows are now (local
> win=1279998 remote win=2147478279)
> PACKET ssh_socket_unbuffered_write ssh_socket_unbuffered_write: Enabling
> POLLOUT for socket
> PACKET packet_send2 packet_send2: packet: wrote
> [len=12,padding=6,comp=5,payload=5]
> PACKET ssh_channel_close ssh_channel_close: Sent a close on client channel
> (43:256)
> PACKET ssh_socket_unbuffered_write ssh_socket_unbuffered_write: Enabling
> POLLOUT for socket
> PACKET ssh_packet_socket_callback ssh_packet_socket_callback: packet: read
> type 96 [len=12,padding=6,comp=5,payload=5]
> PACKET ssh_packet_process ssh_packet_process: Dispatching handler for
> packet type 96
> WARNING channel_from_msg channel_from_msg: Server specified invalid channel
> 43
> PACKET ssh_packet_socket_callback ssh_packet_socket_callback: Processing 48
> bytes left in socket buffer
> PACKET ssh_packet_socket_callback ssh_packet_socket_callback: packet: read
> type 97 [len=12,padding=6,comp=5,payload=5]
> PACKET ssh_packet_process ssh_packet_process: Dispatching handler for
> packet type 97
> WARNING channel_from_msg channel_from_msg: Server specified invalid channel
> 43
> PACKET ssh_socket_unbuffered_write ssh_socket_unbuffered_write: Enabling
> POLLOUT for socket
> PACKET packet_send2 packet_send2: packet: wrote
> [len=28,padding=11,comp=16,payload=16]
> 
> And putty's log is:
> ...
> Incoming packet #0xd, type 96 / 0x60 (SSH2_MSG_CHANNEL_EOF)
>   00000000  00 00 01 00                                      ....
> Incoming packet #0xe, type 97 / 0x61 (SSH2_MSG_CHANNEL_CLOSE)
>   00000000  00 00 01 00                                      ....
> Outgoing packet #0xd, type 96 / 0x60 (SSH2_MSG_CHANNEL_EOF)
>   00000000  00 00 00 2b                                      ...+
> Outgoing packet #0xe, type 97 / 0x61 (SSH2_MSG_CHANNEL_CLOSE)
>   00000000  00 00 00 2b                                      ...+
> Event Log: Disconnected: All channels closed
> 
> It seems that putty is waiting for SSH2_MSG_CHANNEL_CLOSE but server
> doesn't send it because it waits eof.
> 
> Is it ok to remove the while loop? Or it could cause other problems?


You should really use sftp and not that broken scp protocol.


	Andreas

-- 
Andreas Schneider                   GPG-ID: CC014E3D
www.cryptomilk.org                asn@xxxxxxxxxxxxxx