Perl LWP :: UserAgent在給定的服務器上似乎隨機地掛起了120秒

Question

我注意到在012ff中處理response_data和response_done事件與給定https網站之間的延遲大約爲120秒。我用普通的網頁瀏覽器進行了檢查，並且沒有遇到這種緩慢的情況，所以我懷疑有一些事情我必須做錯。

這裏是我做過什麼追查事件（由於某種原因use LWP::Debug qw(+)沒做什麼）：

use WWW::Mechanize; 
use Time::HiRes qw(gettimeofday); 
use IO::Handle; 

my $mech = WWW::Mechanize->new(
    timeout  => 3, 
    autocheck => 1,  # check success of each query 
    stack_depth => 0,  # no keeping history 
    keep_alive => 50,  # connection pool 
); 

$mech->agent_alias('Windows IE 6'); 
open my $debugfile, '>traffic.txt'; 
$debugfile->autoflush(1); 

$mech->add_handler(request_send => sub { 
    my $cur_time = gettimeofday(); 
    my $req = shift; 
    print $debugfile "\n$cur_time === BEGIN HTTP REQUEST ===\n"; 
    print $debugfile $req->dump(); 
    print $debugfile "\n$cur_time === END HTTP REQUEST ===\n"; 
    return 
    } 
); 
$mech->add_handler(response_header => sub { 
    my $cur_time = gettimeofday(); 
    my $res = shift; 
    print $debugfile "\n$cur_time === GOT RESPONSE HDRS ===\n"; 
    print $debugfile $res->dump(); 
    return 
    } 
); 
$mech->add_handler(response_data => sub { 
    my $cur_time = gettimeofday(); 
    my $res = shift; 
    my $content_length = length($res->content); 
    print $debugfile "$cur_time === Got response data chunk resp size = $content_length ===\n"; 
    return 
    } 
); 
$mech->add_handler(response_done => sub { 
    my $cur_time = gettimeofday(); 
    my $res = shift; 
    print $debugfile "\n$cur_time === BEGIN HTTP RESPONSE ===\n"; 
    print $debugfile $res->dump(); 
    print $debugfile "\n=== END HTTP RESPONSE ===\n"; 
    return 
    } 
); 

這裏是痕跡的摘錄（URL和餅乾混淆）：

1347463214.24724 === BEGIN HTTP REQUEST === 
GET https://... 
Accept-Encoding: gzip 
Referer: https://... 
User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1) 
Cookie: ... 
Cookie2: $Version="1" 

(no content) 

1347463214.24724 === END HTTP REQUEST === 

1347463216.13134 === GOT RESPONSE HDRS === 
HTTP/1.1 200 OK 
Date: Wed, 12 Sep 2012 15:20:08 GMT 
Accept-Ranges: bytes 
... 
Server: Lotus-Domino 
Content-Length: 377806 
Content-Type: application/octet-stream 
Last-Modified: Fri, 07 Sep 2012 06:25:33 GMT 
Client-Peer: ... 
Client-Response-Num: 1 
Client-SSL-Cert-Issuer: ... 
Client-SSL-Cert-Subject: ... 
Client-SSL-Cipher: DES-CBC3-SHA 
Client-SSL-Socket-Class: IO::Socket::SSL 

(no content) 
1347463216.48305 === Got response data chunk resp size = 4096 === 

1347463337.98131 === BEGIN HTTP RESPONSE === 
HTTP/1.1 200 OK 
Date: Wed, 12 Sep 2012 15:20:08 GMT 
Accept-Ranges: bytes 
... 
Server: Lotus-Domino 
Content-Length: 377806 
Content-Type: application/octet-stream 
Last-Modified: Fri, 07 Sep 2012 06:25:33 GMT 
Client-Date: Wed, 12 Sep 2012 15:22:17 GMT 
Client-Peer: ... 
Client-Response-Num: 1 
Client-SSL-Cert-Issuer: ... 
Client-SSL-Cert-Subject: ... 
Client-SSL-Cipher: DES-CBC3-SHA 
Client-SSL-Socket-Class: IO::Socket::SSL 

PK\3\4\24\0\6\0\10\0\0\0!\0\x88\xBC\21Xi\2\0\0\x84\22\0\0\23\0\10\2[Content_Types].xml \xA2... 
(+ 377294 more bytes not shown) 

=== END HTTP RESPONSE === 

在「獲得響應數據塊」和「BEGIN HTTP RESPONSE」消息期間，您可以看到121.5秒的間隔。我感覺有時候LWP::UserAgent在收到全部數據後掛了兩分鐘。

你有什麼線索可以從哪裏來？

編輯這裏是Wireshark的截圖：我得到的FIN/ACK消息後120秒......

感謝

Answer 1

由於鮑羅廷的答案，我找到了一種方法來解決這個問題：我修改了response_data事件處理子這樣

：

if($res->header('Content-Length') == length($res->content)) { 
    die "OK"; # Got whole data, not waiting for server to end the communication channel. 
} 
return 1; # In other cases make sure the handler is called for subsequent chunks 

然後如果X-Died標頭等於OK則忽略調用者中的錯誤。

Answer 2

我認爲這很可能是您的交易實際上正在那麼長。爲LWP::UserAgent文檔說這個

[該RESPONSE_DATA處理]需要再次進行後續塊返回真值被稱爲 相同請求

如此，是因爲你的處理器返回什麼都沒有，你僅追蹤第一個返回的數據包

根據您的輸出，第一個4KB數據以2.2秒或大約2KB每秒到達。整個數據長度爲369KB，因此您希望能夠再接收92個數據包，並且每秒2KB需要三分鐘的時間來傳輸。你得到你在兩分鐘內響應，所以我覺得你的時間是合理的

Answer 3

我知道現在這已經很老了，但我最近似乎有同樣的問題。只有在未加密的HTTPS響應（包括頭部）的大小恰好爲1024字節時纔會發生。 Benoit似乎已經有完全4096字節的響應，所以也許有1024的倍數是重要的。我沒有控制服務器，所以我不能產生任意長度的測試響應，也不能在任何其他服務器上重現問題。儘管如此，1024字節的出現是可重複的。

環顧LWP代碼（v6。05），我發現sysread一次要求讀取1024個字節。所以，它第一次返回全部1024個字節。然後立即再次調用它，而不是返回0，表示沒有更多的數據，它返回undef，指示錯誤，並將errno設置爲EAGAIN，表示存在更多數據，但它尚不可用。這會導致套接字上的選擇，因爲不會有更多的數據而掛起。超時需要120秒，之後我們返回哪些數據，這恰好是正確的結果。因此，我們沒有錯誤，只是很長的延遲。

我沒有足夠方便的使用Benoit的解決方案。相反，我的解決方法是延長HTTPS處理代碼來檢查了上述情況，並返回0而不是民主基金：

package LWP::Protocol::https::Socket; 

sub sysread { 
    my $self = shift; 
    my $result = $self->SUPER::sysread(@_); 
    # If we get undef back then some error occurred. If it's EAGAIN 
    # then that ought to mean that there is more data to read but 
    # it's not available yet. We suspect the error may be false. 
    # $_[2] is the offset, so if it's defined and non-zero we have 
    # some data in the buffer. 
    # $_[0] is the buffer, so check it for an entire HTTP response, 
    # including the headers and the body. If the length specified 
    # by Content-Length is exactly the length of the body we have in 
    # the buffer, then take that as being complete and return a length 
    # here instead. Since it's unlikely that anything was read, the 
    # buffer will not have increased in size and the result will be zero 
    # (which was the expected result anyway). 
    if (!defined($result) && 
     $!{EAGAIN} && 
     $_[2] && 
     $_[0] =~ /^HTTP\/\d+\.\d+\s+\d+\s+.*\s+content-length\s*:\s*(\d+).*?\r?\n\r?\n(.*)$/si && 
     length($2) == $1) { 
      return length($_[0]) - $_[2]; # bufferlen - offset 
    } 
    return $result; 
} 

Answer 4

艾倫， 我收到我的系統上相同的行爲。 對於內容長度1024，2048，3072個字節等

這個問題的解決辦法是升級的Net :: HTTP至6.09以上的版本