AnyEvent::Twitterのバグ？ - すぎゃーんメモ

最近AnyEvent::Twitterを使っていて、バグと思われるものを見つけたので書いてみる。
※追記しましたが0.27で既に修正されています。

AnyEvent::Twitterのバージョン

現時点で最新の 0.26

内容

Twitter API の friends_timeline もしくは mentions がステータスコード"400"を返してきたときの処理が間違っている

現象

APIの 150回/h の制限を超えたときなどに、400エラーが返ってきていても何度も連続でtimelineを取得しにいこうとしてしまう

再現コード

#!/usr/bin/perl
use strict;
use warnings;

use AnyEvent;
use AnyEvent::Twitter;
use Net::Twitter;

my %config = (
    username => 'twitter username',
    password => 'twitter password',
);

# make remaining_hits 0.
{
    my $twitter = Net::Twitter->new(%config);
    my $rate_limit_status = $twitter->rate_limit_status;
    my $time_for_reset = $rate_limit_status->{reset_time_in_seconds} - time;
    if ($time_for_reset < 200) {
        sleep $time_for_reset;
    }
    for (1 .. $rate_limit_status->{remaining_hits}) {
        $twitter->home_timeline;
        print $twitter->rate_limit_status->{remaining_hits}, "\n";
        sleep 1;
    }
}

# main
{
    local $AnyEvent::Twitter::DEBUG = 1;
    my $twitty = AnyEvent::Twitter->new(%config);
    $twitty->reg_cb(
        error => sub {
            my ($twitty, $error) = @_;
            warn "error: $error\n";
        },
        statuses_friends => sub { },
    );
    $twitty->receive_statuses_friends;
    $twitty->start;

    my $cv = AE::cv;
    my $w = AE::io *STDIN, 0, sub { $cv->send };
    $cv->recv;
}

これを実行すると、最初にAPIを全部使い切り(20000回とか与えられている人はムリかも)、その後AnyEvent::Twitterをstartさせる。
AnyEvent::Twitterでは既にAPIの回数制限を超えているため400エラーが返ってくるのだけど、それが1回で終わらずに連続でtimelineを取得しにいってerrorを吐き出し続けてしまう。

$ perl error.pl
TASK: statuses_friends => 1 | 1
MAXTASK: 1
error: error while fetching statuses for friends: 400 Bad Request
NEXT TICK IN -1257259142 seconds
TASK: statuses_friends => 1 | 1
MAXTASK: 1
error: error while fetching statuses for friends: 400 Bad Request
NEXT TICK IN -1257259142 seconds
TASK: statuses_friends => 1 | 1
MAXTASK: 1
...

問題の箇所

AnyEvent::Twitterのソース内のサブルーチン _schedule_next_tick 内での処理が原因と思われる。

sub _schedule_next_tick {
   my ($self, $last_req_hdrs) = @_;

   unless (defined $last_req_hdrs) {
      $self->_tick;
      return;
   }

   my $next_tick = 0;
   my $remaining_requests = $last_req_hdrs->{'x-ratelimit-remaining'};
   my $remaining_time     = $last_req_hdrs->{'x-ratelimit-reset'} - time;

   if (defined $self->{interval}) {
      $next_tick = $self->{interval};

   } elsif ($last_req_hdrs->{Status} eq '400'
            && $last_req_hdrs->{'x-ratelimit-reset'} > 0) {
      # probably not neccesary this special case, but better be safe...
      $next_tick = $last_req_hdrs->{'x-ratelimit-remaining'} - time;

   } elsif ($last_req_hdrs->{'x-ratelimit-reset'} > 0 # some basic sanity checks
            && $last_req_hdrs->{'x-ratelimit-limit'} != 0) {

      warn "REMAINING TIME: $remaining_time, "
           . "remaing reqs: $remaining_requests\n"
         if $DEBUG;

      if ($remaining_requests <= 0) {
         $next_tick = $remaining_time;

      } else {
         $next_tick = $remaining_time
                      / ($remaining_requests * $self->{bandwidth});
      }
   }

   warn "NEXT TICK IN $next_tick seconds\n" if $DEBUG;

   weaken $self;
   $self->{_tick_timer} =
      AnyEvent->timer (after => $next_tick, cb => sub {
         delete $self->{_tick_timer};
         $self->_tick;
      });

   $self->next_request_in ($next_tick, $remaining_requests, $remaining_time);
}

ここでは、直前のtimeline取得時のレスポンスヘッダの情報を元に、次にtimelineを取得しにいくまでの時間間隔を調整している。
次の取得までの待機時間に変数$next_tickが使われ、これを計算するための処理がなされている。ここに幾つかの分岐があり、$self->{interval}が定義されている場合はその値がそのまま使われる。問題はその次の分岐で、

   } elsif ($last_req_hdrs->{Status} eq '400'
            && $last_req_hdrs->{'x-ratelimit-reset'} > 0) {
      # probably not neccesary this special case, but better be safe...
      $next_tick = $last_req_hdrs->{'x-ratelimit-remaining'} - time;

となっていて、レスポンスのステータスコードが400のとき、かつ、'x-ratelimit-reset'が0より大きい場合、に$next_tickに代入する値が計算されている。
が、この減算の左辺：レスポンスヘッダの'x-ratelimit-remaining'は、APIの残り使用可能回数を表す値であり、一方、右辺：timeはepoch秒を表す。明らかに単位が違い、その結果は負の値になってしまう。
おそらく意図していた処理は

      $next_tick = $last_req_hdrs->{'x-ratelimit-reset'} - time;

で、'x-ratelimit-reset'には次に使用可能回数がリセットされる時刻のepoch秒が格納されている。こうすれば次にリセットされるまでの時間は、ひたすら待ち続けることになる。無駄に処理を繰り返してエラーを吐き出し続けることはない。
というか、その分岐の前に

   my $remaining_time     = $last_req_hdrs->{'x-ratelimit-reset'} - time;

というのが定義されている。明らかにこれを使うべき。

結論

このあたりの条件式などは色々とツッコミどころが多いのだけど、差し当たっては下記のように修正するべき。

196c196
<       $next_tick = $last_req_hdrs->{'x-ratelimit-remaining'} - time;
---
>       $next_tick = $remaining_time;

…で間違ってないかな？
CPANモジュールのバグ報告ってやったことないけど、どうすればいいんだろう？
→追記：メールで報告してみようと思います。tokuhiromさんありがとうございました。

追記(11/5)

メールを送ってみたらすぐに修正版があがって0.27になりました。素早い対応に感謝です。