Perl LWP::UserAgent зависает на 120 секунд, по-видимому, случайным образом на заданном сервере

Я заметил задержку примерно в 120 секунд между обработкой событий response_data и response_done в WWW::Mechanize с указан https веб-сайт. Я проверил с помощью обычного веб-браузера и не заметил такой медлительности, поэтому я подозреваю, что должен что-то сделать не так.

Вот что я сделал для отслеживания событий (почему-то 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 ===

Во время сообщений «Получен фрагмент данных ответа» и «НАЧАТЬ ОТВЕТ HTTP» вы можете увидеть разрыв в 121,5 секунды. Такое ощущение, что иногда LWP::UserAgent зависает минуты на две после получения полного объема данных.

У вас есть предположения, откуда это могло взяться?

EDIT вот скриншот в Wireshark: я получаю сообщение FIN/ACK через 120 секунд…

Выдержка из Wireshark

Спасибо


person Benoit    schedule 12.09.2012    source источник
comment
В документации для LWP::Debug сказано следующее: LWP::Debug раньше предоставлял средства трассировки, но они больше не используются LWP   -  person Borodin    schedule 12.09.2012
comment
@Borodin: Спасибо, это решает еще одну проблему :)   -  person Benoit    schedule 13.09.2012


Ответы (4)


Я думаю, вполне вероятно, что ваша транзакция на самом деле занимает так много времени. Об этом говорится в документации для LWP::UserAgent.

[Обработчик response_data] должен возвращать значение TRUE для повторного вызова для последующих фрагментов для одного и того же запроса.

поэтому, поскольку ваш обработчик ничего не возвращает, вы отслеживаете только первый возвращенный пакет данных

Согласно вашему выводу, первые 4 КБ данных поступают за 2,2 секунды или примерно 2 КБ в секунду. Все данные имеют длину 369 КБ, поэтому вы ожидаете получить еще 92 пакета данных, а при скорости 2 КБ в секунду для передачи потребуется три минуты. Вы получите ответ через две минуты, поэтому я думаю, что ваше время разумно.

person Borodin    schedule 12.09.2012
comment
Спасибо за ваш ответ. Я действительно забыл вернуть 1 в этом обработчике, но на самом деле это не то, что мне нужно (2,2 секунды включают время обработки на сервере, которое долго. На самом деле следующие фрагменты приходят очень быстро. См. Скриншот Wireshark.) Хотя +1 за help и примечание к этому обработчику. - person Benoit; 12.09.2012
comment
Благодаря вашему ответу я нашел способ обойти проблему. Спасибо еще раз. - person Benoit; 12.09.2012

Благодаря ответу Бородина я нашел способ исправить это:

Я изменил обработчик событий 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, то игнорируйте ошибки в вызывающем.

person Benoit    schedule 12.09.2012

Я знаю, что сейчас это очень старо, но недавно у меня была такая же проблема. Это происходило только тогда, когда размер незашифрованного HTTPS-ответа, включая заголовки, составлял ровно 1024 байта. Бенуа, похоже, получил ответы размером ровно 4096 байт, поэтому, возможно, число, кратное 1024, имеет значение. У меня не было контроля над сервером, поэтому я не мог создавать тестовые ответы произвольной длины и не мог воспроизвести проблему на каком-либо другом сервере. Однако появление в 1024 байтах было повторяемым.

Просматривая код LWP (v6.05), я обнаружил, что sysread запрашивает чтение 1024 байт за раз. Итак, в первый раз он возвращает все 1024 байта. Затем он немедленно вызывается во второй раз, и вместо возврата 0, указывающего, что данных больше нет, он возвращает undef, указывающий на ошибку, и устанавливает для errno значение EAGAIN, указывающее, что есть еще данные, но они еще недоступны. . Это приводит к выбору в сокете, который зависает, потому что больше данных не будет. Для тайм-аута требуется 120 секунд, после чего возвращаются те данные, которые у нас есть, что оказывается правильным результатом. Поэтому мы не получаем никаких ошибок, только большую задержку.

У меня не было достаточно удобного доступа, чтобы использовать решение Бенуа. Вместо этого мой обходной путь состоял в том, чтобы расширить код обработки HTTPS, чтобы проверить вышеописанную ситуацию и вернуть 0 вместо undef:

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;
}
person Alan    schedule 29.11.2016

Алан, я получил такое же поведение в своей системе. Для контента длиной 1024, 2048, 3072 байта и т. д.

Решение этой проблемы — обновить Net::HTTP до версии 6.09 и выше.

person d0as8    schedule 29.06.2017