fetch hangs when trying to http-download from http://ftp5.de.FreeBSD.org/

[Josh Carroll]

On Fri, Nov 5, 2010 at 1:12 PM, Dominic Fandrey <kamikaze at bsdforen.de> wrote:
> On 05/11/2010 20:59, Jeremy Chadwick wrote:
>> On Fri, Nov 05, 2010 at 08:50:48PM +0100, Dominic Fandrey wrote:
>>> On 05/11/2010 19:17, Dominic Fandrey wrote:
>>>> This is an example, I can download the file with firefox,
>>>> but fetch hangs infinitely, even though HTTP_TIMEOUT is set.
>>>> http://ftp5.de.FreeBSD.org/pub/FreeBSD/ports/amd64/packages-8-stable/All/ecore-txt-0.9.9.042.tbz
>>>
>>> The problem has gone away.
>>>
>>> I suppose there's no way of debugging this without being able to
>>> reproduce it. :(
>>
>> There's a lot of ways of debugging this, but "fetch -v" isn't going to
>> provide enough information.  :-)  Hitting Control-T while the process is
>> hung would help, ditto with (in another window) running procstat -kk on
>> the PID of fetch, and "ps -axl | grep fetch".  ...
>
> All that requires me to reproduce it.

I can reproduce it. Here's the info Jeremy requested in a previous
mail from my machine where I'm still able to reproduce it (FreeBSD
8.1-STABLE #0 r214807M    amd64 arch):

floyd at pflog:~% fetch
http://ftp5.de.FreeBSD.org/pub/FreeBSD/ports/amd64/packages-8-stable/All/ecore-txt-0.9.9.042.tbz
ecore-txt-0.9.9.042.tbz                         0% of 6594  B    0  Bps

At this point it hangs, so I hit ctrl-T and get:

load: 0.06  cmd: fetch 97042 [sbwait] 3.50r 0.00u 0.00s 0% 2688k

And then ctrl-c'ing the process I see:

ecore-txt-0.9.9.042.tbz                        62% of 6594  B  744  Bps
fetch: transfer interrupted

ps -axl for fetch shows:

 1001  5382 28735   0  44  0 11964  2704 sbwait S+     2    0:00.00
fetch: ecore-txt-0.9.9.042.tbz [0% of 6594  B] (fet

And here is procstat -kk output:

  PID    TID COMM             TDNAME           KSTACK
 5382 100304 fetch            -                mi_switch+0x169
sleepq_catch_signals+0x300 sleepq_wait_sig+0xc _sleep+0x251
soreceive_generic+0xf0c dofileread+0x88 kern_readv+0x52 read+0x4e
syscallenter+0x181 syscall+0x40 Xfast_syscall+0xe2

ktrace on the process after it hangs shows nothing. I let it run for
30 seconds or more, then ktrace -C'd and don't see anything in the
kdump output:

root at pflog:~# kdump -f fetch.ktrace
root at pflog:~#

However, if I ktrace it from the beginning with:

ktrace fetch ....

Here's the last 30 lines of the output from kdump after it has hung
(the trace file no longer gets written to once the fetch process
hangs):

       0x01f0 f71b 1a83 ad6c 91a6 930e 26b3 8993 c859 f5a3 3dcb 683c
af54 621d 0544 b487 3f9d 5730 7e4f 15b8 52e5 f2b6 1584 3ef3 99fa 4326
2910 31b0 3598 c38e 0eae 6d0b
|.....l....&....Y..=.h<.Tb..D..?.W0~O..R.....>...C&).1.5.....m.|
       0x022e c354 7c11 264c ee0f e093 b2d0 4e32 a315 02f1 be3b 0553
7a2b 1466 5195 9a02 21ed 8dd9 99ae 1e03 1f21 0983 a1a3 57f8 fc0d bf49
126b c727 021e f882 edec a5f2
|.T|.&L......N2.....;.Sz+.fQ...!........!....W....I.k.'........|
       0x026c e969 905e 5f04 c9dd 36e1 7675 1090 04b0 5407 9129 b113
5127 9189 a83e f066 8088 32c0 b3a6 5fec b06f f67c 1f88 a318 c46d fdf9
66ea 06af 2d65 8cde c324 b6a6
|.i.^_...6.vu....T..)..Q'...>.f..2..._..o.|.....m..f...-e...$..|
       0x02aa 804e 91d2 08e2 7d53 5f13 76d6 c486 5168 d6d9 39c3 b88f
dbaa 2452 81a9 ce18 1117 31a7 4690 0883 c944 9804 8858 469c 65e5 3c4e
12e7 d582 9cb4 10b6 3b02 e42e
|.N....}S_.v...Qh..9.....$R......1.F....D...XF.e.<N........;...|
       0x02e8 41c6 51d7 5e90 6626 4700 55ef 1f2e c809 1a82 72bf 4420
1b5e 94a2 53df f0c3 9fac 8030 dfac 0340 34fa 855b 39d1 1d78 69cc f41a
2eb3 b039 6588 0971 a45c ce4e  |A.Q.^.f&G.U.......r.D
.^..S......0... at 4..[9..xi......9e..q.\.N|
       0x0326 d049 bba6 2b86 d18a 3889 bbef 64ff 6f04 1f60 e40c c9fc
2689 44ad 350d c15b eb77 a57c c9b4 bc92 693f 8fe0 f814 eba4 51d5 d7cb
d5ef 1ced 0bb4 2a01 b561 8054
|.I..+...8...d.o..`....&.D.5..[.w.|....i?......Q.........*..a.T|
       0x0364 55d8 2629 758a 17a8 8cdd 2e40 6448 6b13 dbb1 30f6 8a21
0786 a2b3 957a ba39 4373 4d05 de6c 11d5 3c3f 5709 3b70 af5b 02aa a533
3c19 f0f9 be56 c786 59b3 0847
|U.&)u...... at dHk...0..!.....z.9CsM..l..<?W.;p.[...3<....V..Y..G|
       0x03a2 ba02 44b0 1db2 d585 a350 d7b4 3b3a bb7d cfb5 3f6c ff82
075b 9739 7326 f8df de4a beb0 6506 6d33 e22d 7327 0d4c 42f2 6205 1bd2
8808 8409 ae1f 6e5a 2ebc 5b9d
|..D......P..;:.}..?l...[.9s&...J..e.m3.-s'.LB.b.........nZ..[.|
       0x03e0 4440 b689 0754 dd08 502b a24c f752 906e 4dda c1d4 2fb7
de08 417c a4ee ac05 e6ab
                              |D at ...T..P+.L.R.nM.../...A|......|

 38016 fetch    RET   read 1024/0x400
 38016 fetch    CALL  ioctl(0x2,TIOCGPGRP,0x7fffffffe22c)
 38016 fetch    RET   ioctl 0
 38016 fetch    CALL  gettimeofday(0x7fffffffe210,0)
 38016 fetch    RET   gettimeofday 0
 38016 fetch    CALL  fstat(0x4,0x7fffffffe0d0)
 38016 fetch    STRU  struct stat {dev=121, ino=111872461,
mode=-rw-r--r-- , nlink=1, uid=1001, gid=1001, rdev=0,
atime=1288988994, stime=1288988994, ctime=1288988994,
birthtime=1288988994, size=0, blksize=16384, blocks=0, flags=0x0 }
 38016 fetch    RET   fstat 0
 38016 fetch    CALL  gettimeofday(0x7fffffffe110,0)
 38016 fetch    RET   gettimeofday 0
 38016 fetch    CALL  gettimeofday(0x7fffffffe120,0)
 38016 fetch    RET   gettimeofday 0
 38016 fetch    CALL  select(0x4,0x7fffffffe080,0,0,0x7fffffffe100)
 38016 fetch    RET   select 1
 38016 fetch    CALL  read(0x3,0x81006800,0x400)
 38016 fetch    GIO   fd 3 read 53 bytes
       0x0000 d65d f798 1663 e5ec f90d 542e 8d20 5978 8e65 00e6 92f6
f51d 9fb0 4f1f 364c 7d8b 644d 293d fd8c ce31 9a69 a12e c456 0da4 b1c0
b534 44                        |.]...c....T..
Yx.e........O.6L}.dM)=...1.i...V.....4D|

 38016 fetch    RET   read 53/0x35
 38016 fetch    CALL  read(0x3,0x81006835,0x3cb)

Shouldn't I be seeing a syscall to alarm() somewhere in the kdump
output? Because I currently do not. Perhaps I need ktrace -d -i
(and/or other flags)? If so, let me know and I can re-run ktrace with
additional flags if it would help.

Thanks,
Josh