zwisający curl (zepsuty kernel?)
Michal Moskal
malekith w pld.org.pl
Śro, 17 Paź 2001, 13:13:26 CEST
Poczyniłem pewne debugację znanego problemu zwisu curla
na ściąganiu plików.
Strace:
Server (pure-ftpd 0.99.1b-1) :
8879 read(0, "RETR 9wm-1.2-1.i686.rpm\r\n", 4111) = 25
8879 open("9wm-1.2-1.i686.rpm", O_RDONLY|O_LARGEFILE) = 5
8879 fstat(5, {st_mode=S_IFREG|0644, st_size=24519, ...}) = 0
8879 alarm(900) = 1800
8879 select(5, [4], NULL, NULL, {900, 0}) = 1 (in [4], left {900, 0})
8879 accept(4, {sin_family=AF_INET, sin_port=htons(1676), sin_addr=inet_addr("192.168.1.1")}}, [16]) = 6
8879 setsockopt(6, SOL_IP, IP_TOS, [8], 4) = 0
8879 setsockopt(6, SOL_SOCKET, SO_KEEPALIVE, [0], 4) = 0
8879 setsockopt(6, SOL_SOCKET, SO_LINGER, [0], 8) = 0
^^^^^^^^^ ^^^
To ciekawe, nie wiem czy dobrze rozumiem manpage socket(7), ale
LINGER==0 znaczy że wyśle reszte danych in background, czy, że
ich w ogóle nie wyśle? Pozostaje mi chyba tylko use the source
Luke... :^)
8879 write(1, "150-Accepted data connection\r\n15"..., 59) = 59
8879 semop(3, 0xbfffec44, 1) = 0
8879 time([1003266267]) = 1003266267
8879 semop(3, 0xbfffec44, 1) = 0
8879 alarm(86400) = 900
8879 gettimeofday({1003266267, 930716}, {4294967176, 0}) = 0
8879 setsockopt(6, IPPROTO_TCP3, [1], 4) = 0
8879 old_mmap(NULL, 24519, PROT_READ, MAP_SHARED, 5, 0) = 0x297000
8879 write(6, "\355\253\356\333\4\0\0\0\0\0019wm-1.2-1\0\0\0\0\0\0\0\0"..., 24519) = 24519
^^^^^ ^^^^^
8879 munmap(0x297000, 24519) = 0
8879 close(5) = 0
8879 close(6) = 0
Czyli server wysłał cały plik i zamnknął socket.
Teraz client (poldek (letest CVS) + curl 7.8.1):
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 6
connect(6, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}}, 28) = 0
send(6, "\342\223\1\0\0\1\0\0\0\0\0\0\0011\0011\003168\003192\7"..., 42, 0) = 42
gettimeofday({1003266267, 927545}, NULL) = 0
poll([{fd=6, events=POLLIN, revents=POLLIN}], 1, 5000) = 1
recvfrom(6, "\342\223\205\200\0\1\0\1\0\1\0\1\0011\0011\003168\0031"..., 1024, 0, {sin_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.1.1")}}, [16]) = 104
close(6) = 0
uname({sys="Linux", node="roke", ...}) = 0
socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 6
connect(6, {sin_family=AF_INET, sin_port=htons(26322), sin_addr=inet_addr("192.168.1.1")}}, 16) = 0
write(5, "TYPE I\r\n", 8) = 8
gettimeofday({1003266267, 928259}, NULL) = 0
select(6, [5], NULL, NULL, {120, 0}) = 1 (in [5], left {120, 0})
read(5, "200 TYPE is now 8-bit binary\r\n", 51200) = 30
write(5, "RETR 9wm-1.2-1.i686.rpm\r\n", 25) = 25
gettimeofday({1003266267, 928985}, NULL) = 0
select(6, [5], NULL, NULL, {120, 0}) = 1 (in [5], left {120, 0})
read(5, "150-Accepted data connection\r\n15"..., 51200) = 59
gettimeofday({1003266267, 930298}, NULL) = 0
alarm(0) = 0
gettimeofday({1003266267, 930358}, NULL) = 0
gettimeofday({1003266267, 930389}, NULL) = 0
select(7, [6], [], NULL, {1, 0}) = 1 (in [6], left {0, 990000})
read(6, "\355\253\356\333\4\0\0\0\0\0019wm-1.2-1\0\0\0\0\0\0\0\0"..., 51199) = 23232
^^^^^
write(4, "\355\253\356\333\4\0\0\0\0\0019wm-1.2-1\0\0\0\0\0\0\0\0"..., 20480) = 20480
gettimeofday({1003266267, 933107}, NULL) = 0
gettimeofday({1003266267, 933155}, NULL) = 0
write(1, ".", 1) = 1
write(1, ".", 1) = 1
write(1, ".", 1) = 1
write(1, ".", 1) = 1
write(1, ".", 1) = 1
select(7, [6], [], NULL, {1, 0}) = 0 (Timeout)
^^^ ^^^^^^^^^
gettimeofday({1003266268, 932817}, NULL) = 0
gettimeofday({1003266268, 932854}, NULL) = 0
select(7, [6], [], NULL, {1, 0}) = 0 (Timeout)
gettimeofday({1003266269, 932502}, NULL) = 0
gettimeofday({1003266269, 932540}, NULL) = 0
select(7, [6], [], NULL, {1, 0}) = 0 (Timeout)
gettimeofday({1003266270, 932507}, NULL) = 0
gettimeofday({1003266270, 932544}, NULL) = 0
select(7, [6], [], NULL, {1, 0}) = ? ERESTARTNOHAND (To be restarted)
--- SIGINT (Interrupt) ---
+++ killed by SIGINT +++
Interesujące fakty:
1. server wysłał 24519 bajtów i zamknął socket
2. klient przeczytał 23232 bajtów, po czym select() na tym
sockecie zwraca timeout!
a) gdzieś zniknęło 1287 bajtów
b) pominąwszy nawet te bajty, jeśli druga strona zamnkęła
połączenie, to select() powinien zwrócić read na tym
sockecie, a read() potem powinien zwrócić 0.
Jak łatwo zauważyć nie jest to wynik błędu w pure-ftpd, poldku,
curlu czy nawet glibc. Spieprzony jest kernel. Sprawdzałem na 2.2.19-22.
Potem małe testy na 2.4.7 (z kernel-source-2.4.7-11 + swój config).
No problems. To znaczy nie udało mi się go zawiesić (wcześniej, po
potraktowaniu servera i clienta strace wieszał się od razu na pierwszym
pliku). Teraz jest kwestia:
a) winny jest kernel servera czy klienta (może to jutro sprawdzę,
ale nie obiecuje).
b) czy spieprzony jest kernel od Linusa czy któryś z naszych patchy.
Potem zmieniłem server ftp na muddleftpd. Ściągnął ileśtam set plików
i echo... żadnego problemu. Z strace wynika, że a) muddle nie rusza
SO_LINGER, b) muddle używa sendfile() do przesyłania plików.
Następnie wrzuciłem proftpd-standalone. Znowu nie ma zwisu, ale:
pro używa (tak ja pure) SO_LINGER i read/write do przesyłania
plików, robi to jednak małymi kawałkami (po 1k, pure prubuje chyba
jakieś wielkie kawały po 30k wysyłać).
Domyślam się więc, że it's all about the timing :^)
Dodatkowo muddle i pro, gdy otwierają połączenie, piszą coś w
rodzaju:
150 Starting BINARY transfer. (761 bytes)
na control socket. Teraz curl wie ilu bajtów się spodziewać. Dlatego jest
normalny progress bar, a nie jak w poprzednim wypadku same kropki. Curl
IMHO powinien się zapytać (SIZE) o wielkość pliku przed ściągnięciem.
Ale nie wiem, na ile to ma znaczenie.
Wnioski: trzeba by sprawdzić 2.2.19 od Linusa (niestety nie mam źródeł
w domu :[ ), testy (nie wiem jakie robiłeś Pawle, czy mógłbyś je powtórzyć
z 2.4.* i 2.2.19 od Linusa) chyba najlepiej robić z pure-ftpd, bo
najczęściej się wiesza :^).
Aha, commitnąłem małą poprawke do poldka (vfile/vfcurl.c), która
drukuje \n po progress barze, jeśli go nie było i zmienia
ilość kropek na kilobajt (z 1 do 1/8 :^). Nic nie tagowałem bo
to tylko mała zmiana (kosmetyczna).
pozdrawiam
--
: Michal ``,/\/\, '' Moskal | | : GCS {C,UL}++++$
: | |alekith @ |)|(| . org . pl : {E--, W, w-,M}-
: Linux: We are dot in .ORG. | : {b,e>+}++ !tv h
: CurProj: ftp://ftp.pld.org.pl/people/malekith/ksi : PLD Team member
Więcej informacji o liście dyskusyjnej pld-installer