Perl LWP :: UserAgent se bloque pendant 120 secondes apparemment de manière aléatoire contre un serveur donné

Question

J'ai remarqué un délai d'environ 120 secondes entre la gestion des événements response_data et response_done en WWW::Mechanize avec un site Web https donné. J'ai vérifié avec un navigateur Web normal et ne pas éprouver cette lenteur ainsi je soupçonne qu'il y a quelque chose que je dois faire mal.

Voici ce que je faisais de retracer les événements (pour une raison use LWP::Debug qw(+) ne rien faire):

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 
    } 
); 

Et voici un extrait des traces (les URL et les cookies sont brouillées):

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 === 

Au cours des messages «Got response data chunk» et «BEGIN HTTP RESPONSE», vous pouvez voir un intervalle de 121,5 secondes. J'ai le sentiment que parfois LWP::UserAgent se bloque pendant deux minutes après avoir reçu la totalité des données.

Avez-vous la moindre idée d'où cela pourrait provenir?

EDIT est ici une capture d'écran dans Wireshark: Je reçois le FIN/message ACK après 120 secondes ...

Merci

Answer 1

Merci à la réponse de Borodine je trouve un moyen de le réparer:

Je modifié sous cette façon de gestionnaire d'événements 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 

Et puis, si l'en-tête X-Died est égal à OK, ignorez les erreurs dans l'appelant.

Answer 2

Je pense qu'il est probable que votre transaction prend effectivement c'est long. La documentation pour LWP::UserAgent dit que ce

[Le gestionnaire response_data] doit retourner une valeur TRUE pour être appelé à nouveau pour les morceaux suivants pour la même demande

, parce que votre gestionnaire ne retourne rien, vous ne suivent que le premier paquet de données renvoyé

Selon votre sortie, les 4 premiers Ko de données arrivent en 2,2 secondes, soit environ 2 Ko par seconde. La longueur totale des données est de 369 Ko, donc vous devriez recevoir 92 paquets de données de plus, et à 2 Ko par seconde, cela prendrait trois minutes à transmettre. Vous obtenez votre réponse en deux minutes, je pense que vos heures sont

raisonnables

Answer 3

Je sais que c'est très vieux maintenant, mais j'ai eu ce qui semble être le même problème récemment. Cela ne s'est produit que lorsque la taille de la réponse HTTPS non cryptée, y compris les en-têtes, était exactement de 1024 octets. Benoit semble avoir eu des réponses de 4096 octets exactement, alors peut-être que des multiples de 1024 sont significatifs. Je n'avais pas le contrôle du serveur, donc je ne pouvais pas produire de réponses de test de longueur arbitraire, ni reproduire le problème sur un autre serveur. L'occurrence à 1024 octets était cependant répétable.

En regardant autour du code LWP (v6.05), j'ai trouvé que sysread est invité à lire 1024 octets à la fois. Ainsi, la première fois qu'il renvoie tous les 1024 octets. Il est alors immédiatement appelé une seconde fois, et plutôt que de retourner 0, indiquant qu'il n'y a plus de données, il renvoie undef, indiquant une erreur, et place errno dans EAGAIN, indiquant qu'il y a plus de données, mais ce n'est pas encore disponible . Cela conduit à une sélection sur le socket, qui se bloque car il n'y aura pas plus de données. Il faut 120 secondes pour expirer, après quoi les données que nous avons sont renvoyées, ce qui s'avère être le bon résultat. Par conséquent, nous n'obtenons pas d'erreurs, juste un long délai. Je n'avais pas assez d'accès pratique pour utiliser la solution de Benoit. Au lieu de cela, ma solution était d'étendre le code de gestion HTTPS pour vérifier la situation ci-dessus et retourner 0 au lieu de FNUD:

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

Alan, j'ai reçu le même comportement sur mon système. Pour une longueur de contenu 1024, 2048, 3072 octets et ainsi de suite

La solution de ce problème consiste à améliorer Net :: HTTP à la version 6.09 et au-dessus