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-адреса и файлы cookie скрыты):

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

Во время сообщений "Got response data chunk" и "BEGIN HTTP RESPONSE" вы видите разрыв в 121,5 секунды. У меня такое ощущение, что иногда LWP::UserAgent зависает в течение двух минут после получения полного объема данных.

Есть ли у вас какие-либо подсказки, откуда это может прийти?

РЕДАКТИРОВАТЬ вот скриншот в Wireshark: я получаю сообщение FIN/ACK через 120 секунд...

Отрывок Wireshark

Спасибо

Источник

4 ответа

Решение

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

Я модифицировал response_data обработчик события sub таким образом:

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 затем игнорировать ошибки в вызывающем абоненте.

Источник

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

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

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

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

Источник

Я знаю, что сейчас это очень старо, но у меня недавно возникла та же проблема. Это происходило только тогда, когда размер незашифрованного ответа HTTPS, включая заголовки, составлял ровно 1024 байта. Benoit, кажется, имеет ответы ровно 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;
}
Источник

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

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

Источник
Другие вопросы по тегам