Subject: [scp][recive] packet_type 100 but awaits 99

[scp][recive] packet_type 100 but awaits 99

From: Belau, Rene (ext) <belau.rene.ext_at_siemens.com>
Date: Wed, 12 Jun 2013 12:06:16 +0200

Hello,

I recive a wrong packet_type (packet_type 100, awaits 99) from ssh-demon on the server-side, so libssh2 returns a channel eof and closes/frees the channel without file transport.

Console output:
---------------------------------------
libssh2_scp_recv()!
libssh2_scp_recv() spin
libssh2_scp_recv() spin
channel: 00000000 << my own code
erronumber: -22 >> #define LIBSSH2_ERROR_CHANNEL_REQUEST_DENIED -22 << my own code
Unable to complete request for channel-process-startup

With debugger I walked throuth the code and the libssh2 seems to work fine.

Can I go around that issue ?

Putty can handle the packet_type 100. Putty resends the request channel_request multiply times with a packet of packet_type 2 between.
You can see it in the LOG at the end of this post.

Application-Code:
---------------------------

I use >> spc_nonblocking.c << for first test.

Server:
-----------

OS: self manufacted Linux i686
SSH-Demon: lshd SSH-2.0-lshd_1

Client:
----------

OS: Windows XP 32-Bit

Libssh2:
------------

libssh2-1.4.4-20130606 daily & stable 1.4.3 tested

Libssh2 was build with Visual Studio 2008, convertet.

Dependencies:
----------------------
>> Zlib 1.2.8.
>> Openssl 1.0.1.e

Compiler-Switches:
------------------------------

>> Nothing changed

Server-LOG:
------------------

lshd: DEBUG: Sent USERAUTH_SUCCESS lshd: (size 1 = 0x1)
00000000: 34 4

lshd: write_buffer: do_write length = 36
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 36
lshd: command_Bp
lshd: channel.c: do_connection_service
lshd: lsh_oop_cancel_callout: action: connection_timeout
lshd: Installing fix channel open handler for type 'session'
lshd: command_B, f = 808baf8, cf = 808baf8, g = 90a46c0, cg = 90a46c0
lshd: command_C
lshd: command_Bp
lshd: tcpforward_commands.c: make_tcpip_forward_handler
lshd: Installing global request handler for 'tcpip-forward'
lshd: Installing fix global request handler for 'cancel-tcpip-forward'
lshd: command_Bp
lshd: tcpforward_commands.c: do_make_open_tcp_handler
lshd: Installing channel open handler for 'direct-tcpip'
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: DEBUG: Received CHANNEL_OPEN lshd: (size 24 = 0x18)
00000000: 5a0000000773657373696f6e00000000 Z....session....
00000010: 0004000000008000 ........

lshd: handle_connection: Received packet of type 90 (CHANNEL_OPEN)
lshd: Allocated local channel number 0
lshd: server.c: do_open_session
lshd: make_resource_list: created 90b7e10
lshd: Registering local channel 0.
lshd: Taking channel 0 in use, (local 0).
lshd: check_rec_max_packet: Reduced rec_max_packet from 32768 to 32668.
lshd: format_open_confirmation: rec_window_size = 0,
                          rec_max_packet = 32668,
lshd: DEBUG: Sent CHANNEL_OPEN_CONFIRMATION lshd: (size 17 = 0x11)
00000000: 5b00000000000000000000000000007f [...............
00000010: 9c .

lshd: write_buffer: do_write length = 52
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 52
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: DEBUG: Received CHANNEL_REQUEST lshd: (size 56 = 0x38)
00000000: 62000000000000000465786563010000 b........exec...
00000010: 0026736370202d706620272f746d702f .&scp -pf '/tmp/
00000020: 54455354270097b5d4f405172a3e5369 TEST'.......*>Si
00000030: 8098b1cbe6020000 ........

lshd: handle_connection: Received packet of type 98 (CHANNEL_REQUEST)
lshd: DEBUG: Sent CHANNEL_FAILURE lshd: (size 5 = 0x5)
00000000: 6400000000 d....

lshd: write_buffer: do_write length = 36
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 36
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received CHANNEL_EOF lshd: (size 5 = 0x5)
00000000: 6000000000 `....

lshd: handle_connection: Received packet of type 96 (CHANNEL_EOF)
lshd: Receiving EOF on channel 0 (local 0)
lshd: No CHANNEL_EOF handler. Closing.
lshd: Sending CLOSE on channel 0
lshd: DEBUG: Sent CHANNEL_CLOSE lshd: (size 5 = 0x5)
00000000: 6100000000 a....

lshd: write_buffer: do_write length = 36
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 36
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: DEBUG: Received CHANNEL_CLOSE lshd: (size 5 = 0x5)
00000000: 6100000000 a....

lshd: handle_connection: Received packet of type 97 (CHANNEL_CLOSE)
lshd: Receiving CLOSE on channel 0 (local 0)
lshd: do_kill_all: resource_list 90b7e10
lshd: Deallocating local channel 0
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: DEBUG: Received DISCONNECT lshd: (size 34 = 0x22)
00000000: 010000000b0000001553534832577261 .........SSH2Wra
00000010: 707065722072656c65617365642e0000 pper released...
00000020: 0000 ..

lshd: handle_connection: Received packet of type 1 (DISCONNECT)
lshd: Disconnect for reason 11: SSH2Wrapper released.
lshd: io.c: Closing fd 6: accepted socket.
lshd: lsh_oop_cancel_read_fd: fd: 6, accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: Connection died.
lshd: do_kill_all: resource_list 90a5f78
lshd: do_kill_all: resource_list 90b7e10
lshd: lsh_oop_cancel_callout: action: reexchange_timeout
lshd: do_buffered_read: want_read = 0; handler needs a pause.

Client-LOG:
-----------------

[libssh2] 0.843750 SCP: Opening channel for SCP receive
[libssh2] 0.843750 Conn: Allocated new channel ID#0
[libssh2] 0.843750 Conn: Opening Channel - win 262144 pack 32768
=> libssh2_transport_write plain (24 bytes)
0000: 5A 00 00 00 07 73 65 73 73 69 6F 6E 00 00 00 00 : Z....session....
0010: 00 04 00 00 00 00 80 00 : ........
[libssh2] 0.843750 Socket: Sent 68/68 bytes at 00A341A4
=> libssh2_transport_write send() (68 bytes)
0000: F4 57 DE A4 93 4F B0 CD 0A F8 A6 CB AE 69 8A B1 : .W...O.......i..
0010: BA 6F AD BB 8C 2B 62 11 28 6E 44 EA 74 63 68 2C : .o...+b.(nD.tch,
0020: 19 AC FB 1D 44 32 BA 12 C6 E4 2C EC F6 02 1B BA : ....D2....,.....
0030: 96 AC 59 50 0F 22 A8 AA 97 A0 D7 C9 AA 59 96 CC : ..YP.".......Y..
0040: 81 3E 14 24 : .>.$
[libssh2] 0.843750 Transport: Looking for packet of type: 91
[libssh2] 0.843750 Transport: Looking for packet of type: 92
[libssh2] 0.843750 Transport: Looking for packet of type: 91
[libssh2] 0.843750 Transport: Looking for packet of type: 92
[libssh2] 0.843750 Socket: Recved 52/16384 bytes to 00A3017C+0
=> libssh2_transport_read() raw (52 bytes)
0000: F5 C7 FA 96 42 2D 47 AB C3 68 8D 41 1D 08 51 A5 : ....B-G..h.A..Q.
0010: 97 36 65 E5 34 42 4F 9B 31 C2 26 7C 79 52 EA 70 : .6e.4BO.1.&|yR.p
0020: F6 A2 23 1D 2A C6 5F 5B E1 0B C9 0E C0 F8 17 12 : ..#.*._[........
0030: DF 24 CD BF : .$..
=> libssh2_transport_read() plain (17 bytes)
0000: 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 7F : [...............
0010: 9C : .
[libssh2] 0.843750 Transport: Packet type 91 received, length=17
[libssh2] 0.843750 Transport: Looking for packet of type: 91
[libssh2] 0.843750 Conn: Connection Established - ID: 0/0 win: 0/262144 pack: 32668/32768
[libssh2] 0.843750 Conn: starting request(exec) on channel 0/0, message=scp -pf '/tmp/TEST'
=> libssh2_transport_write plain (18 bytes)
0000: 62 00 00 00 00 00 00 00 04 65 78 65 63 01 00 00 : b........exec...
0010: 00 26 : .&
=> libssh2_transport_write plain2 (38 bytes)
0000: 73 63 70 20 2D 70 66 20 27 2F 74 6D 70 2F 54 45 : scp -pf '/tmp/TE
0010: 53 54 27 00 2F 4D 6C 8C 9D AF C2 D6 EB 01 18 30 : ST'./Ml........0
0020: 49 63 7E 9A 00 00 : Ic~...
[libssh2] 0.843750 Socket: Sent 228/228 bytes at 00A341A4
=> libssh2_transport_write send() (228 bytes)
0000: 29 BA 89 28 77 51 11 F3 A1 94 A4 ED F9 B7 50 5E : )..(wQ........P^
0010: 45 A0 CC CA E1 E7 6E 2C 76 43 EB 2B 95 49 1A 89 : E.....n,vC.+.I..
0020: AA 79 4F A9 C3 B6 B3 3C A0 FD DA 2E B2 1C FC 7A : .yO....<.......z
0030: 67 14 A3 B2 2B 3D 14 12 86 D6 ED 03 F1 F1 AE 13 : g...+=..........
0040: 76 7C 94 C4 68 96 07 4B A4 19 70 78 FE 1C 35 6D : v|..h..K..px..5m
0050: BC 8E 3B 14 D4 72 C5 F5 2D 0F 90 95 17 FC 0C 27 : ..;..r..-......'
0060: 08 F7 47 83 57 8C BD BA 59 FD D4 D9 E3 C1 46 3D : ..G.W...Y.....F=
0070: 08 23 FD 20 A7 CE AA F8 57 DC BC 98 79 53 E2 55 : .#. ....W...yS.U
0080: 19 03 63 59 F0 49 C9 6B 5B D4 F5 19 3E AC 40 F2 : ..cY.I.k[...>.@.
0090: 40 33 BF B6 23 C6 9D 7A A3 A0 DA 60 76 18 20 11 : @3..#..z...`v. .
00a0: 65 12 75 FA 01 21 6B 29 4D 57 E4 05 04 85 F9 1D : e.u..!k)MW......
00b0: 1B 5E 23 15 CC 14 6A 86 3A 39 8F 8C 77 74 C1 79 : .^#...j.:9..wt.y
00c0: 97 1B 70 97 3E E0 4B E3 55 75 84 9B 77 EB 91 03 : ..p.>.K.Uu..w...
00d0: DD A6 7C A9 52 48 60 DB 42 F2 A8 24 1B EE 56 DF : ..|.RH`.B..$..V.
00e0: 00 F9 B8 9E : ....
[libssh2] 0.843750 Transport: Looking for packet of type: 99
[libssh2] 0.843750 Transport: Looking for packet of type: 100
[libssh2] 0.843750 Transport: Looking for packet of type: 99
[libssh2] 0.843750 Transport: Looking for packet of type: 100
[libssh2] 0.843750 Socket: Recved 36/16384 bytes to 00A3017C+0
=> libssh2_transport_read() raw (36 bytes)
0000: 53 DF 64 63 01 CE 54 49 FB E7 A9 ED 5C 8F 95 00 : S.dc..TI....\...
0010: F8 90 5F 3B A5 C8 23 AE CB AF C4 91 F8 21 13 9B : .._;..#......!..
0020: A1 D4 04 AA libssh2_scp_recv()!
libssh2_scp_recv() spin
libssh2_scp_recv() spin
Unable to complete request for channel-process-startup
                                : ....
=> libssh2_transport_read() plain (5 bytes)
0000: 64 00 00 00 00 : d....
[libssh2] 0.843750 Transport: Packet type 100 received, length=5
[libssh2] 0.843750 Transport: Looking for packet of type: 99
[libssh2] 0.843750 Transport: Looking for packet of type: 100
[libssh2] 0.843750 Failure Event: -22 - Unable to complete request for channel-process-startup
[libssh2] 0.843750 Conn: Freeing channel 0/0 resources
[libssh2] 0.843750 Conn: Sending EOF on channel 0/0
=> libssh2_transport_write plain (5 bytes)
0000: 60 00 00 00 00 : `....
[libssh2] 0.843750 Socket: Sent 36/36 bytes at 00A341A4
=> libssh2_transport_write send() (36 bytes)
0000: 1E FC FB 6B 72 12 E0 F9 93 EA AA A1 A1 7F 10 0F : ...kr...........
0010: FB F4 5C 01 F0 6C AB BE 4F A5 3E 84 1B 5A 25 CB : ..\..l..O.>..Z%.
0020: 4B 71 99 CC : Kq..
[libssh2] 0.843750 Conn: Closing channel 0/0
=> libssh2_transport_write plain (5 bytes)
0000: 61 00 00 00 00 : a....
[libssh2] 0.843750 Socket: Sent 52/52 bytes at 00A341A4
=> libssh2_transport_write send() (52 bytes)
0000: 78 C4 F9 9B 39 29 31 D8 96 32 E6 B6 80 43 2B 37 : x...9)1..2...C+7
0010: 3A 10 C8 E4 06 9C B2 97 36 71 9A 58 48 EC 56 B9 : :.......6q.XH.V.
0020: 96 B0 20 98 D1 D6 42 42 85 41 F6 87 60 5C 09 E8 : .. ...BB.A..`\..
0030: AB 5E 78 5F : .^x_
[libssh2] 0.843750 Socket: Recved 36/16384 bytes to 00A3017C+0
=> libssh2_transport_read() raw (36 bytes)
0000: 1E 36 AC 04 AA 7D 8E 44 4F 8A E0 ED D2 4A 5F 1C : .6...}.DO....J_.
0010: C7 D0 0B 50 92 EC F8 65 9A 64 7E EE 04 3C 3A AE : ...P...e.d~..<:.
0020: C1 C5 DC 37 : ...7
=> libssh2_transport_read() plain (5 bytes)
0000: 61 00 00 00 00 : a....
[libssh2] 0.843750 Transport: Packet type 97 received, length=5
[libssh2] 0.843750 Conn: Close received for channel 0/0
[libssh2] 0.843750 Transport: Looking for packet of type: 94
[libssh2] 0.843750 Transport: Looking for packet of type: 95
[libssh2] 0.843750 Transport: Disconnecting: reason=11, desc=SSH2Wrapper released., lang=
=> libssh2_transport_write plain (34 bytes)
0000: 01 00 00 00 0B 00 00 00 15 53 53 48 32 57 72 61 : .........SSH2Wra
0010: 70 70 65 72 20 72 65 6C 65 61 73 65 64 2E 00 00 : pper released...
0020: 00 00 : ..
=> libssh2_transport_write plain2 (0 bytes)
[libssh2] 0.843750 Socket: Sent 84/84 bytes at 00A341A4
=> libssh2_transport_write send() (84 bytes)
0000: 90 17 CE 70 AB 44 B6 F9 AD D7 B2 31 32 73 E5 1E : ...p.D.....12s..
0010: 1A BE FA D4 9B 4F 37 44 79 10 C4 DE D4 64 3D 71 : .....O7Dy....d=q
0020: 16 F0 2C 12 86 4B CB 96 34 CF 54 9D 8F DD A3 E8 : ..,..K..4.T.....
0030: DC 3C A2 3A 35 7F 78 97 28 1D B7 FE EB 08 AA BE : .<.:5.x.(.......
0040: CC 1B 64 DE 36 4B 76 B6 98 53 69 43 B1 7F 5B 83 : ..d.6Kv..SiC..[.
0050: C2 80 31 C9 : ..1.
[libssh2] 0.843750 Transport: Freeing session resource
[libssh2] 0.843750 Transport: Extra packets left 0

Client-LOG Putty:
-------------------------

lshd: DEBUG: Sent USERAUTH_SUCCESS lshd: (size 1 = 0x1)
00000000: 34 4

lshd: write_buffer: do_write length = 36
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 36
lshd: command_Bp
lshd: channel.c: do_connection_service
lshd: lsh_oop_cancel_callout: action: connection_timeout
lshd: Installing fix channel open handler for type 'session'
lshd: command_B, f = 808baf8, cf = 808baf8, g = 8db06c0, cg = 8db06c0
lshd: command_C
lshd: command_Bp
lshd: tcpforward_commands.c: make_tcpip_forward_handler
lshd: Installing global request handler for 'tcpip-forward'
lshd: Installing fix global request handler for 'cancel-tcpip-forward'
lshd: command_Bp
lshd: tcpforward_commands.c: do_make_open_tcp_handler
lshd: Installing channel open handler for 'direct-tcpip'
lshd: DEBUG: Received IGNORE lshd: (size 149 = 0x95)
00000000: 0200000090aba8ff4fd9bc9e9c6bb5c9 ........O....k..
00000010: 765328beb66c0875e89776918a6b9bd8 vS(..l.u..v..k..
00000020: 67c64537cafce0b5567940382bf83578 g.E7....Vy_at_8+.5x
00000030: f756d9745195e4f804833034a0546be8 .V.tQ.....04.Tk.
00000040: 40c34e1cab50c4567b0c0ba7a66d28ad @.N..P.V{....m(.
00000050: 9f1ed1d1ba2c69c1d968ca5c096428f5 .....,i..h.\.d(.
00000060: eea542a767451b94d3f912eac3d4a1fb ..B.gE..........
00000070: 03065a9665aafb7a48915bbe9cf41bff ..Z.e..zH.[.....
00000080: dc82f11e6bf20bda50b80a72a4c938a4 ....k...P..r..8.
00000090: 51759f8b57 Qu..W

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received IGNORE lshd: (size 5 = 0x5)
00000000: 0200000000 .....

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: DEBUG: Received CHANNEL_OPEN lshd: (size 24 = 0x18)
00000000: 5a0000000773657373696f6e00000100 Z....session....
00000010: 7fffffff00004000 ......@.

lshd: handle_connection: Received packet of type 90 (CHANNEL_OPEN)
lshd: Allocated local channel number 0
lshd: server.c: do_open_session
lshd: make_resource_list: created 8dc3d20
lshd: Registering local channel 0.
lshd: Taking channel 256 in use, (local 0).
lshd: check_rec_max_packet: Reduced rec_max_packet from 32768 to 32668.
lshd: format_open_confirmation: rec_window_size = 0,
                          rec_max_packet = 32668,
lshd: DEBUG: Sent CHANNEL_OPEN_CONFIRMATION lshd: (size 17 = 0x11)
00000000: 5b00000100000000000000000000007f [...............
00000010: 9c .

lshd: write_buffer: do_write length = 52
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 52
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received IGNORE lshd: (size 5 = 0x5)
00000000: 0200000000 .....

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: DEBUG: Received CHANNEL_REQUEST lshd: (size 44 = 0x2c)
00000000: 62000000000000002273696d706c6540 b......."simple@
00000010: 70757474792e70726f6a656374732e74 putty.projects.t
00000020: 617274617275732e6f726700 artarus.org.

lshd: handle_connection: Received packet of type 98 (CHANNEL_REQUEST)
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received IGNORE lshd: (size 5 = 0x5)
00000000: 0200000000 .....

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: DEBUG: Received CHANNEL_REQUEST lshd: (size 27 = 0x1b)
00000000: 62000000000000000973756273797374 b........subsyst
00000010: 656d010000000473667470 em.....sftp

lshd: handle_connection: Received packet of type 98 (CHANNEL_REQUEST)
lshd: DEBUG: Sent CHANNEL_FAILURE lshd: (size 5 = 0x5)
00000000: 6400000100 d....

lshd: write_buffer: do_write length = 36
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 36
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received IGNORE lshd: (size 5 = 0x5)
00000000: 0200000000 .....

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: DEBUG: Received CHANNEL_REQUEST lshd: (size 34 = 0x22)
00000000: 62000000000000000465786563010000 b........exec...
00000010: 0010736370202d66202f746d702f5445 ..scp -f /tmp/TE
00000020: 5354 ST

lshd: handle_connection: Received packet of type 98 (CHANNEL_REQUEST)
lshd: Created socket pair. Using fd:s 7 <-- 8
lshd: Created socket pair. Using fd:s 9 <-- 10
lshd: Created socket pair. Using fd:s 11 <-- 12
lshd: Created socket pair. Using fd:s 13 <-- 14
lshd: do_spawn: child process
lshd: do_spawn: child after chdir
lshd: do_spawn: child after pty
lshd: do_spawn: child before stderr dup
lshd: do_spawn: child after stderr dup
lshd: unix_user: exec_shell
lshd: exec_shell: Setting up environment.
lshd: exec_shell: Environment:
lshd: 'SHELL=/bin/sh'
lshd: 'HOME=/home/manufact'
lshd: 'PATH=/bin:/usr/bin'
lshd: 'USER=manufact'
lshd: 'LOGNAME=manufact'
lshd: 'TZ=UTC'
lshd: 'SSH_CLIENT=147.54.235.99 2792 22'
lshd: exec_shell: argv0 = '/bin/sh'.
lshd: exec_shell: After -u
lshd: exec_shell: After -g
lshd: exec_shell: After -i
lshd: exec_shell: Argument list:
lshd: 'lsh-execuv'
lshd: '-u'
lshd: '102'
lshd: '-g'
lshd: '102'
lshd: '-n'
lshd: 'manufact'
lshd: '-i'
lshd: '--'
lshd: '/bin/sh'
lshd: '/bin/sh'
lshd: '-c'
lshd: 'scp -f /tmp/TEST'
lshd: exec_shell: before exec
lshd: do_spawn: parent process
lshd: do_spawn: parent after sync
lshd: unix_process.c: make_unix_process
lshd: unix_process.c: unix_process_setup
lshd: unix_process.c: unix_process_setup, after utmp
lshd: do_spawn: parent after process setup
lshd: io.c: Preparing fd 8 for writing
lshd: io.c: Preparing fd 9 for reading
lshd: lsh_oop_register_read_fd: fd: 9, child stdout
lshd: io.c: Preparing fd 11 for reading
lshd: lsh_oop_register_read_fd: fd: 11, child stderr
lshd: DEBUG: Sent CHANNEL_WINDOW_ADJUST lshd: (size 9 = 0x9)
00000000: 5d0000010000002710 ]......'.

lshd: write_buffer: do_write length = 52
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 52
lshd: DEBUG: Sent CHANNEL_SUCCESS lshd: (size 5 = 0x5)
00000000: 6300000100 c....

lshd: write_buffer: do_write length = 36
lshd: write_buffer: do_write closure->length = 88
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received IGNORE lshd: (size 5 = 0x5)
00000000: 0200000000 .....

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: DEBUG: Received CHANNEL_DATA lshd: (size 10 = 0xa)
00000000: 5e000000000000000100 ^.........

lshd: handle_connection: Received packet of type 94 (CHANNEL_DATA)
lshd: write_buffer: do_write length = 1
lshd: lsh_oop_register_write_fd: fd: 8, child stdin
lshd: write_buffer: do_write closure->length = 1
lshd: lsh_oop_fd_write_callback: fd 8: child stdin
lshd: DEBUG: Sent CHANNEL_WINDOW_ADJUST lshd: (size 9 = 0x9)
00000000: 5d0000010000000001 ]........

lshd: write_buffer: do_write length = 52
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 52
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 8: child stdin
lshd: lsh_oop_cancel_write_fd: fd: 8, child stdin
lshd: lsh_oop_fd_read_callback: fd 9: child stdout
lshd: DEBUG: Sent CHANNEL_DATA lshd: (size 23 = 0x17)
00000000: 5e000001000000000e43303636342033 ^........C0664 3
00000010: 3720544553540a 7 TEST.

lshd: write_buffer: do_write length = 52
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 52
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received IGNORE lshd: (size 5 = 0x5)
00000000: 0200000000 .....

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: DEBUG: Received CHANNEL_DATA lshd: (size 10 = 0xa)
00000000: 5e000000000000000100 ^.........

lshd: handle_connection: Received packet of type 94 (CHANNEL_DATA)
lshd: write_buffer: do_write length = 1
lshd: lsh_oop_register_write_fd: fd: 8, child stdin
lshd: write_buffer: do_write closure->length = 1
lshd: lsh_oop_fd_write_callback: fd 8: child stdin
lshd: DEBUG: Sent CHANNEL_WINDOW_ADJUST lshd: (size 9 = 0x9)
00000000: 5d0000010000000001 ]........

lshd: write_buffer: do_write length = 52
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 52
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 8: child stdin
lshd: lsh_oop_cancel_write_fd: fd: 8, child stdin
lshd: lsh_oop_fd_read_callback: fd 9: child stdout
lshd: DEBUG: Sent CHANNEL_DATA lshd: (size 47 = 0x2f)
00000000: 5e000001000000002631323334353637 ^.......&1234567
00000010: 38393071776572747975696f70617364 890qwertyuiopasd
00000020: 6667686a6b6c7a786376626e6d0a00 fghjklzxcvbnm..

lshd: write_buffer: do_write length = 84
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 84
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received IGNORE lshd: (size 5 = 0x5)
00000000: 0200000000 .....

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: DEBUG: Received CHANNEL_DATA lshd: (size 10 = 0xa)
00000000: 5e000000000000000100 ^.........

lshd: handle_connection: Received packet of type 94 (CHANNEL_DATA)
lshd: write_buffer: do_write length = 1
lshd: lsh_oop_register_write_fd: fd: 8, child stdin
lshd: write_buffer: do_write closure->length = 1
lshd: lsh_oop_fd_write_callback: fd 8: child stdin
lshd: DEBUG: Sent CHANNEL_WINDOW_ADJUST lshd: (size 9 = 0x9)
00000000: 5d0000010000000001 ]........

lshd: write_buffer: do_write length = 52
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 52
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 8: child stdin
lshd: lsh_oop_cancel_write_fd: fd: 8, child stdin
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 9: child stdout
lshd: lsh_oop_cancel_read_fd: fd: 9, child stdout
lshd: io.c: Closing fd 9: child stdout.
lshd: lsh_oop_cancel_read_fd: fd: 9, child stdout
lshd: lsh_oop_cancel_write_fd: fd: 9, child stdout
lshd: channel_read_close_callback: File closed.
lshd: lsh_oop_fd_read_callback: fd 11: child stderr
lshd: Sending EOF on channel 256
lshd: DEBUG: Sent CHANNEL_EOF lshd: (size 5 = 0x5)
00000000: 6000000100 `....

lshd: write_buffer: do_write length = 36
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 36
lshd: lsh_oop_cancel_read_fd: fd: 11, child stderr
lshd: io.c: Closing fd 11: child stderr.
lshd: lsh_oop_cancel_read_fd: fd: 11, child stderr
lshd: lsh_oop_cancel_write_fd: fd: 11, child stderr
lshd: channel_read_close_callback: File closed.
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_signal_callback: Signal 17, handler: reaper_callback
lshd: Child 1598 died with exit code 0.
lshd: unix_process: do_logout_notice
lshd: server_session.c: do_exit_shell
lshd: server_session.c: Sending exit-status message on channel 256
lshd: DEBUG: Sent CHANNEL_REQUEST lshd: (size 25 = 0x19)
00000000: 62000001000000000b657869742d7374 b........exit-st
00000010: 617475730000000000 atus.....

lshd: write_buffer: do_write length = 68
lshd: lsh_oop_register_write_fd: fd: 6, accepted socket
lshd: write_buffer: do_write closure->length = 68
lshd: Sending CLOSE on channel 256
lshd: DEBUG: Sent CHANNEL_CLOSE lshd: (size 5 = 0x5)
00000000: 6100000100 a....

lshd: write_buffer: do_write length = 36
lshd: write_buffer: do_write closure->length = 104
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_fd_write_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received IGNORE lshd: (size 5 = 0x5)
00000000: 0200000000 .....

lshd: handle_connection: Received packet of type 2 (IGNORE)
lshd: read_packet.c: Going directly to the WAIT_MAC state
lshd: DEBUG: Received CHANNEL_CLOSE lshd: (size 5 = 0x5)
00000000: 6100000000 a....

lshd: handle_connection: Received packet of type 97 (CHANNEL_CLOSE)
lshd: Receiving CLOSE on channel 256 (local 0)
lshd: do_kill_all: resource_list 8dc3d20
lshd: io.c: close_fd_nicely called on fd 8: child stdin
lshd: lsh_oop_cancel_read_fd: fd: 8, child stdin
lshd: io.c: Closing fd 8: child stdin.
lshd: lsh_oop_cancel_read_fd: fd: 8, child stdin
lshd: lsh_oop_cancel_write_fd: fd: 8, child stdin
lshd: Deallocating local channel 0
lshd: lsh_oop_fd_read_callback: fd 6: accepted socket
lshd: lsh_oop_cancel_read_fd: fd: 6, accepted socket
lshd: read_packet: EOF in state 0
lshd: io.c: close_fd_nicely called on fd 6: accepted socket
lshd: lsh_oop_cancel_read_fd: fd: 6, accepted socket
lshd: io.c: Closing fd 6: accepted socket.
lshd: lsh_oop_cancel_read_fd: fd: 6, accepted socket
lshd: lsh_oop_cancel_write_fd: fd: 6, accepted socket
lshd: Connection died.
lshd: do_kill_all: resource_list 8db1f78
lshd: do_kill_all: resource_list 8dc3d20
lshd: lsh_oop_cancel_callout: action: reexchange_timeout

_______________________________________________
libssh2-devel http://cool.haxx.se/cgi-bin/mailman/listinfo/libssh2-devel
Received on 2013-06-12