On Mon, Oct 1, 2012 at 9:33 AM, Peter Stuge <peter_at_stuge.se> wrote:
> Chris Harris wrote:
> > This is the snippet of trace where I get a -21 error code from libssh2:
>
> It would be good to also see libssh2 trace output with and without sleep.
>
>
Here are the traces. I added the following options: LIBSSH2_TRACE_CONN |
LIBSSH2_TRACE_TRANS | LIBSSH2_TRACE_ERROR
First without the sleep:
[libssh2] 8.271158 Conn: Channel 0 received request type exit-status (wr 0)
[libssh2] 8.271165 Conn: Exit status 0 received for channel 0/0
=> libssh2_transport_read() plain (80 bytes)
0000: 5E 00 00 00 00 00 00 00 47 20 31 30 3A 30 31 3A : ^.......G 10:01:
0010: 31 32 20 75 70 20 35 34 20 64 61 79 73 2C 20 31 : 12 up 54 days, 1
0020: 38 3A 33 38 2C 20 20 30 20 75 73 65 72 73 2C 20 : 8:38, 0 users,
0030: 20 6C 6F 61 64 20 61 76 65 72 61 67 65 3A 20 32 : load average: 2
0040: 2E 31 31 2C 20 32 2E 30 30 2C 20 31 2E 39 36 0A : .11, 2.00, 1.96.
[libssh2] 8.271180 Transport: Packet type 94 received, length=80
[libssh2] 8.271183 Conn: 71 bytes packet_add() for 0/0/0
=> libssh2_transport_read() plain (5 bytes)
0000: 60 00 00 00 00 : `....
[libssh2] 8.271190 Transport: Packet type 96 received, length=5
[libssh2] 8.271192 Conn: EOF received for channel 0/0
=> libssh2_transport_read() plain (5 bytes)
0000: 61 00 00 00 00 : a....
[libssh2] 8.271199 Transport: Packet type 97 received, length=5
[libssh2] 8.271201 Conn: Close received for channel 0/0
[libssh2] 8.271204 Conn: channel_read() got 71 of data from 0/0/0 [ul]
We read:
10:01:12 up 54 days, 18:38, 0 users, load average: 2.11, 2.00, 1.96
libssh2_channel_read returned 0
[libssh2] 8.271258 Conn: Sending EOF on channel 0/0
=> libssh2_transport_write plain (5 bytes)
0000: 60 00 00 00 00 : `....
=> libssh2_transport_write send() (36 bytes)
0000: C3 75 1C 44 54 E3 30 2C 65 CF 4C 35 88 E7 FC 57 : .u.DT.0,e.L5...W
0010: 17 24 9E 66 EB 5B 06 04 26 D4 5F 6D F4 E8 13 38 : .$.f.[..&._m...8
0020: 79 23 7D 70 : y#}p
[libssh2] 8.271281 Conn: Closing channel 0/0
=> libssh2_transport_write plain (5 bytes)
0000: 61 00 00 00 00 : a....
=> libssh2_transport_write send() (36 bytes)
0000: 88 48 C9 1B CD DB 13 40 4A C9 5B D3 8B 9A B7 1F : .H....._at_J.[.....
0010: 97 7C E3 5E F7 BE 39 FE B1 5A BB 84 8E A6 05 B7 : .|.^..9..Z......
0020: C4 AD 4C B0 : ..L.
[libssh2] 8.271298 Conn: Awaiting close of channel 0/0
EXIT: 0 bytecount: 71
[libssh2] 8.271312 Conn: Freeing channel 0/0 resources
[libssh2] 8.271314 Transport: Looking for packet of type: 94
[libssh2] 8.271316 Transport: Looking for packet of type: 95
[libssh2] 8.271318 Conn: Allocated new channel ID#1
[libssh2] 8.271320 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 01 : Z....session....
0010: 00 04 00 00 00 00 80 00 : ........
=> libssh2_transport_write send() (68 bytes)
0000: A7 47 26 76 FE 0B FD D3 2D 91 50 86 D4 12 57 1F : .G&v....-.P...W.
0010: E4 3E 63 71 27 35 22 AD D8 25 22 CF 41 9A 21 EB : .>cq'5"..%".A.!.
0020: E6 4A 45 52 9E DF 3E 42 55 68 2A 37 15 FF 9C F2 : .JER..>BUh*7....
0030: 0B 3C D7 8C 1B 85 8F 4B 47 92 33 58 BC 83 FA 88 : .<.....KG.3X....
0040: E1 95 8D 34 : ...4
[libssh2] 8.271343 Transport: Looking for packet of type: 91
[libssh2] 8.271344 Transport: Looking for packet of type: 92
[libssh2] 8.310148 Transport: Looking for packet of type: 91
[libssh2] 8.310163 Transport: Looking for packet of type: 92
=> libssh2_transport_read() raw (68 bytes)
0000: BD 33 F3 EE C2 7C C0 A1 E4 31 93 00 9C 87 6E 47 : .3...|...1....nG
0010: AB FA 1E 8A 62 30 7D D5 2F AB 69 76 13 5B 01 9D : ....b0}./.iv.[..
0020: 5E 6B 28 1B FC 12 09 85 91 02 7E 7B 45 BE 94 80 : ^k(.......~{E...
0030: 8E 72 B8 E1 29 36 5D F7 2C A6 EC 14 B3 CE 31 20 : .r..)6].,.....1
0040: 92 E7 63 31 : ..c1
=> libssh2_transport_read() plain (28 bytes)
0000: 5C 00 00 00 01 00 00 00 01 00 00 00 0B 6F 70 65 : \............ope
0010: 6E 20 66 61 69 6C 65 64 00 00 00 00 : n failed....
[libssh2] 8.310215 Transport: Packet type 92 received, length=28
[libssh2] 8.310220 Transport: Looking for packet of type: 91
[libssh2] 8.310224 Transport: Looking for packet of type: 92
[libssh2] 8.310228 Failure Event: -21 - Channel open failure
[libssh2] 8.310232 Transport: Looking for packet of type: 94
[libssh2] 8.310235 Transport: Looking for packet of type: 95
Error: -21
With the sleep:
[libssh2] 0.376790 Conn: Channel 0 received request type exit-status (wr 0)
[libssh2] 0.376797 Conn: Exit status 0 received for channel 0/0
=> libssh2_transport_read() plain (80 bytes)
0000: 5E 00 00 00 00 00 00 00 47 20 31 30 3A 30 34 3A : ^.......G 10:04:
0010: 30 37 20 75 70 20 35 34 20 64 61 79 73 2C 20 31 : 07 up 54 days, 1
0020: 38 3A 34 31 2C 20 20 30 20 75 73 65 72 73 2C 20 : 8:41, 0 users,
0030: 20 6C 6F 61 64 20 61 76 65 72 61 67 65 3A 20 31 : load average: 1
0040: 2E 38 32 2C 20 31 2E 39 31 2C 20 31 2E 39 34 0A : .82, 1.91, 1.94.
[libssh2] 0.376836 Transport: Packet type 94 received, length=80
[libssh2] 0.376842 Conn: 71 bytes packet_add() for 0/0/0
=> libssh2_transport_read() raw (72 bytes)
0000: 49 78 5B 5E F6 CB 0F 59 3D 7E E8 A1 90 62 92 56 : Ix[^...Y=~...b.V
0010: ED 08 1F B7 34 E0 B4 0B 6E 24 01 D2 2D 9F 23 A6 : ....4...n$..-.#.
0020: A9 FE 82 83 60 35 D3 C9 0B F3 3C 5E E3 39 0E 2B : ....`5....<^.9.+
0030: AD 33 70 2D 0F 5C B5 54 1E 80 FA ED 9F 7B 3D AC : .3p-.\.T.....{=.
0040: B4 64 E3 41 24 93 CD 08 : .d.A$...
=> libssh2_transport_read() plain (5 bytes)
0000: 60 00 00 00 00 : `....
[libssh2] 0.376892 Transport: Packet type 96 received, length=5
[libssh2] 0.376897 Conn: EOF received for channel 0/0
=> libssh2_transport_read() plain (5 bytes)
0000: 61 00 00 00 00 : a....
[libssh2] 0.376915 Transport: Packet type 97 received, length=5
[libssh2] 0.376921 Conn: Close received for channel 0/0
[libssh2] 0.376927 Conn: channel_read() got 71 of data from 0/0/0 [ul]
We read:
10:04:07 up 54 days, 18:41, 0 users, load average: 1.82, 1.91, 1.94
libssh2_channel_read returned 0
[libssh2] 0.377097 Conn: Sending EOF on channel 0/0
=> libssh2_transport_write plain (5 bytes)
0000: 60 00 00 00 00 : `....
=> libssh2_transport_write send() (36 bytes)
0000: 7F 42 AE 48 B5 17 0B D0 75 4C A2 FE A7 72 71 28 : .B.H....uL...rq(
0010: 8F 4C C3 05 60 DF 45 5B 30 D6 FA 86 9F 3B 03 03 : .L..`.E[0....;..
0020: D9 42 DE B9 : .B..
[libssh2] 0.377144 Conn: Closing channel 0/0
=> libssh2_transport_write plain (5 bytes)
0000: 61 00 00 00 00 : a....
=> libssh2_transport_write send() (36 bytes)
0000: EA 38 19 81 92 9C 86 9C D1 BE 87 4F D9 04 F1 56 : .8.........O...V
0010: 7B 1E E5 2F A7 67 73 B0 79 17 BB F7 B7 31 78 04 : {../.gs.y....1x.
0020: 8D 0D 04 30 : ...0
[libssh2] 0.377186 Conn: Awaiting close of channel 0/0
EXIT: 0 bytecount: 71
[libssh2] 0.377212 Conn: Freeing channel 0/0 resources
[libssh2] 0.377218 Transport: Looking for packet of type: 94
[libssh2] 0.377223 Transport: Looking for packet of type: 95
[libssh2] 1.377328 Conn: Allocated new channel ID#1
[libssh2] 1.377396 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 01 : Z....session....
0010: 00 04 00 00 00 00 80 00 : ........
=> libssh2_transport_write send() (68 bytes)
0000: 3E 7D D9 40 FB A9 71 C9 C8 60 3B B4 AA 0F 36 25 : >}.@..q..`;...6%
0010: A0 51 4F 01 26 AD 60 65 BD D0 0C 16 29 C6 49 C1 : .QO.&.`e....).I.
0020: 62 4E 23 E5 71 30 29 D5 01 64 9F 9C EE 69 E8 24 : bN#.q0)..d...i.$
0030: 7E 42 35 5A 34 64 4A 1A BC D5 75 69 62 D6 BA 60 : ~B5Z4dJ...uib..`
0040: 4A E9 2F FA : J./.
[libssh2] 1.377558 Transport: Looking for packet of type: 91
[libssh2] 1.377565 Transport: Looking for packet of type: 92
[libssh2] 1.377927 Transport: Looking for packet of type: 91
[libssh2] 1.377996 Transport: Looking for packet of type: 92
=> libssh2_transport_read() raw (52 bytes)
0000: 36 3F CD C5 F1 08 A7 4E FA C7 11 31 79 E3 DA F2 : 6?.....N...1y...
0010: F2 1A 1B 72 7B 4B 49 13 50 78 94 F5 CA F9 95 51 : ...r{KI.Px.....Q
0020: D7 AB 9C 13 E2 3A 20 22 C5 3B 78 DC 79 1E D8 7E : .....: ".;x.y..~
0030: 9E 31 86 60 : .1.`
=> libssh2_transport_read() plain (17 bytes)
0000: 5B 00 00 00 01 00 00 00 00 00 00 00 00 00 00 80 : [...............
0010: 00 : .
[libssh2] 1.378103 Transport: Packet type 91 received, length=17
[libssh2] 1.378111 Transport: Looking for packet of type: 91
[libssh2] 1.378118 Conn: Connection Established - ID: 1/0 win: 0/262144
pack: 32768/140733193420800
[libssh2] 1.378125 Conn: starting request(exec) on channel 1/0,
message=uptime
=> 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 06 : ..
=> libssh2_transport_write plain2 (6 bytes)
0000: 75 70 74 69 6D 65 : uptime
=> libssh2_transport_write send() (68 bytes)
0000: DA 18 E5 0F 7A 5D 07 E2 22 5C 09 84 CE 97 BD C7 : ....z].."\......
0010: E3 4A 4C 44 5D 01 12 83 22 EC 48 8D AD E8 83 45 : .JLD]...".H....E
0020: 7C EB BE 00 36 46 A3 3A 39 E1 4D 26 5E 42 9B 82 : |...6F.:9.M&^B..
0030: 56 75 1A AB 5C ED 51 32 46 A6 37 7C 4D F5 D0 D2 : Vu..\.Q2F.7|M...
0040: 1A 3C CB 3C : .<.<
[libssh2] 1.378213 Transport: Looking for packet of type: 99
[libssh2] 1.378220 Transport: Looking for packet of type: 100
[libssh2] 1.378918 Transport: Looking for packet of type: 99
[libssh2] 1.378948 Transport: Looking for packet of type: 100
=> libssh2_transport_read() raw (88 bytes)
0000: 4C 67 83 ED B5 AE AD A7 7F 02 6E CF 15 BE EE 7E : Lg........n....~
0010: 65 51 D0 1D 2E C4 5E 0B 1C F5 60 C2 06 9F F3 60 : eQ....^...`....`
0020: 60 0B 02 D9 79 77 77 69 46 3C F7 AA 43 61 1E 35 : `...ywwiF<..Ca.5
0030: D6 46 1A 79 30 D5 00 79 E8 68 BA 87 63 7F 55 2C : .F.y0..y.h..c.U,
0040: CE 38 D1 7D C1 83 7F EB 9A 65 C0 79 76 D8 9E 4A : .8.}.....e.yv..J
0050: 56 EE C8 06 64 F8 2B BC : V...d.+.
=> libssh2_transport_read() plain (9 bytes)
0000: 5D 00 00 00 01 00 20 00 00 : ]..... ..
[libssh2] 1.379028 Transport: Packet type 93 received, length=9
[libssh2] 1.379035 Conn: Window adjust for channel 1/0, adding 2097152
bytes, new window_size=2097152
=> libssh2_transport_read() plain (5 bytes)
0000: 63 00 00 00 01 : c....
[libssh2] 1.379059 Transport: Packet type 99 received, length=5
[libssh2] 1.379066 Transport: Looking for packet of type: 99
[libssh2] 1.379073 Conn: channel_read() wants 16384 bytes from channel 1/0
stream #0
[libssh2] 1.381917 Conn: channel_read() wants 16384 bytes from channel 1/0
stream #0
=> libssh2_transport_read() raw (116 bytes)
0000: 5A 92 15 0F 1E 2A FA FF 6C 80 52 19 A4 55 CC 73 : Z....*..l.R..U.s
0010: A2 8C 6D 70 EC BB 30 99 F1 EB 1E A8 C4 B3 78 ED : ..mp..0.......x.
0020: F0 D8 38 F5 FD CB 1B 70 BC DD BB 32 21 59 E0 10 : ..8....p...2!Y..
0030: 7A B2 7B 1D 38 7D 4F 09 F5 72 96 3A 90 42 DF EE : z.{.8}O..r.:.B..
0040: 5C 37 84 7C A2 EE 75 4C 83 C9 9F 3B 97 99 2E FE : \7.|..uL...;....
0050: B6 54 D8 D7 17 6A 33 DA BD B7 F4 19 18 A6 B2 17 : .T...j3.........
0060: 2E B1 9C B1 05 13 51 D2 FC 4D AB 97 DF 81 24 CB : ......Q..M....$.
0070: F6 10 81 60 : ...`
=> libssh2_transport_read() plain (80 bytes)
0000: 5E 00 00 00 01 00 00 00 47 20 31 30 3A 30 34 3A : ^.......G 10:04:
0010: 30 38 20 75 70 20 35 34 20 64 61 79 73 2C 20 31 : 08 up 54 days, 1
0020: 38 3A 34 31 2C 20 20 30 20 75 73 65 72 73 2C 20 : 8:41, 0 users,
0030: 20 6C 6F 61 64 20 61 76 65 72 61 67 65 3A 20 31 : load average: 1
0040: 2E 38 32 2C 20 31 2E 39 31 2C 20 31 2E 39 34 0A : .82, 1.91, 1.94.
[libssh2] 1.382138 Transport: Packet type 94 received, length=80
[libssh2] 1.382144 Conn: 71 bytes packet_add() for 1/0/0
[libssh2] 1.382151 Conn: channel_read() got 71 of data from 1/0/0 [ul]
We read:
10:04:08 up 54 days, 18:41, 0 users, load average: 1.82, 1.91, 1.94
[libssh2] 1.382546 Conn: channel_read() wants 16384 bytes from channel 1/0
stream #0
=> libssh2_transport_read() raw (140 bytes)
0000: EB EA AB E9 C1 47 F4 61 DB 88 F0 07 38 25 99 E9 : .....G.a....8%..
0010: B3 1E C0 4C C3 BB 07 72 19 8D 3B DA D4 62 E9 11 : ...L...r..;..b..
0020: D1 50 6B 8B 07 3B B6 F2 7F 4C A3 D1 76 48 0C 5C : .Pk..;...L..vH.\
0030: A9 1F CC 78 0E BB C3 24 64 C3 84 C4 8B 83 66 DA : ...x...$d.....f.
0040: 1E EE 9B 53 3A 12 BB 58 DF AB E0 D6 C3 02 F1 8A : ...S:..X........
0050: CE 99 90 EA 13 7C DB E6 A8 28 9C EE CF 35 F0 C1 : .....|...(...5..
0060: 11 CA 2A 73 04 21 C0 F6 FE E8 6A 5D D4 71 80 0C : ..*s.!....j].q..
0070: B2 32 C9 40 05 01 6C 4B B6 92 EE 39 DE 85 45 DB : .2.@..lK...9..E.
0080: B0 A9 CE F2 43 70 0E 7E 84 D1 F3 B9 : ....Cp.~....
=> libssh2_transport_read() plain (5 bytes)
0000: 60 00 00 00 01 : `....
[libssh2] 1.382695 Transport: Packet type 96 received, length=5
[libssh2] 1.382701 Conn: EOF received for channel 1/0
=> libssh2_transport_read() plain (25 bytes)
0000: 62 00 00 00 01 00 00 00 0B 65 78 69 74 2D 73 74 : b........exit-st
0010: 61 74 75 73 00 00 00 00 00 : atus.....
[libssh2] 1.382725 Transport: Packet type 98 received, length=25
[libssh2] 1.382730 Conn: Channel 1 received request type exit-status (wr 0)
[libssh2] 1.382736 Conn: Exit status 0 received for channel 1/0
=> libssh2_transport_read() plain (5 bytes)
0000: 61 00 00 00 01 : a....
[libssh2] 1.382754 Transport: Packet type 97 received, length=5
[libssh2] 1.382760 Conn: Close received for channel 1/0
libssh2_channel_read returned 0
[libssh2] 1.382771 Conn: Sending EOF on channel 1/0
=> libssh2_transport_write plain (5 bytes)
0000: 60 00 00 00 00 : `....
=> libssh2_transport_write send() (36 bytes)
0000: 76 AF 27 D5 14 82 32 02 B4 EB F4 91 9F A6 0E C9 : v.'...2.........
0010: 37 53 CE A4 BE 53 65 05 9A 0D B9 2C 6F BC 15 5F : 7S...Se....,o.._
0020: C4 00 CB D6 : ....
[libssh2] 1.382818 Conn: Closing channel 1/0
=> libssh2_transport_write plain (5 bytes)
0000: 61 00 00 00 00 : a....
=> libssh2_transport_write send() (36 bytes)
0000: 5D AA 85 0F 1D 0D 57 53 E3 0E 50 82 A0 7E 77 AA : ].....WS..P..~w.
0010: 1B 55 A4 5C 93 DC 1B 85 08 F8 7F 1E 0D 52 FD F6 : .U.\.........R..
0020: 17 00 81 33 : ...3
[libssh2] 1.382859 Conn: Awaiting close of channel 1/0
EXIT: 0 bytecount: 71
[libssh2] 1.382873 Conn: Freeing channel 1/0 resources
[libssh2] 1.382879 Transport: Looking for packet of type: 94
[libssh2] 1.382887 Transport: Looking for packet of type: 95
[libssh2] 1.382894 Transport: Disconnecting: reason=11, desc=Normal
Shutdown, Thank you for playing, lang=
=> libssh2_transport_write plain (51 bytes)
0000: 01 00 00 00 0B 00 00 00 26 4E 6F 72 6D 61 6C 20 : ........&Normal
0010: 53 68 75 74 64 6F 77 6E 2C 20 54 68 61 6E 6B 20 : Shutdown, Thank
0020: 79 6F 75 20 66 6F 72 20 70 6C 61 79 69 6E 67 00 : you for playing.
0030: 00 00 00 : ...
=> libssh2_transport_write plain2 (0 bytes)
=> libssh2_transport_write send() (84 bytes)
0000: C4 24 06 84 46 70 3C E8 05 77 8D EA 05 D9 6B 77 : .$..Fp<..w....kw
0010: A1 71 E2 34 8A F1 E3 46 CB 92 55 9D CC C9 F5 4E : .q.4...F..U....N
0020: F4 25 61 35 72 C6 0A B7 E5 A6 B5 1D CE 3C 24 0F : .%a5r........<$.
0030: 9F B2 54 01 3C 43 32 F0 16 60 E3 0B A9 94 31 15 : ..T.<C2..`....1.
0040: E8 DE 49 9C 88 F4 BF 5D 50 4A 39 85 36 A8 5B 83 : ..I....]PJ9.6.[.
0050: E7 B6 46 41 : ..FA
[libssh2] 1.382969 Transport: Freeing session resource
[libssh2] 1.382981 Transport: Extra packets left 0
all done
>
> > It looks to me like the GC step needs to complete before another
> > channel can be requested.
>
> Yes.
>
>
> > I am not familiar with the ssh protocol but should libssh2 be
> > waiting for this step to complete before
> > libssh2_channel_wait_closed() returns?
>
> The garbage collection is an implementation detail of OpenSSH, it
> has nothing to do with the protocol.
>
I assumed that this was the case but wasn't sure
>
> libssh2 trace output will show the actual protocol exchange details,
> which will help say if OpenSSH is misbehaving or not.
>
> I suspect MaxSessions 1 has not been tested a great deal and I do
> think that it is OpenSSH at fault here, but let's look at the trace
> to make sure before you post there.
>
> //Peter
> _______________________________________________
> libssh2-devel http://cool.haxx.se/cgi-bin/mailman/listinfo/libssh2-devel
>
_______________________________________________
libssh2-devel http://cool.haxx.se/cgi-bin/mailman/listinfo/libssh2-devel
Received on 2012-10-01