Plack/PSGIでアクセス数を計数するとsleipnirでは変になる

結論

sleipnir for Macのバグでした。

---

開発中のコードより、ざっくりと削ってみても再現するのでこれはもうよく分からない。
ググっても出ないのでQiitaのみんな、オラに力を分けてくれ！

コード

test.pl

use strict;
use warnings;
use Carp;

use Plack::App::Path::Router::PSGI;
use Path::Router;
use Plack::Builder;
use Plack::Request;

use lib './lib';    # Pwd.pl の保存先

use Data::Section::Simple;
my $vpath = Data::Section::Simple->new()->get_data_section();

use Text::Xslate;
my $tx = Text::Xslate->new(
    syntax => 'Kolon',
    cache => 0,
    verbose => 1,
    path => [$vpath],
);

use CGI::Session;
my $session = CGI::Session->new(undef, undef, {Directory=>'./sessions'});
my $sid = $session->param('CGISESSID') || undef;
$session = CGI::Session->new(undef, $sid, {Directory=>'./sessions'});
$session->expire('+2y');

use DBI;
my $mysqlPasswd = require 'Pwd.pl';
my $dbh = DBI->connect("DBI:mysql:TEST", 'TEST', $mysqlPasswd, {'RaiseError' => 1} );
use Storable qw(nfreeze thaw);

my $router = Path::Router->new;
$router->add_route( '/'         => target => \&root );
$router->add_route( '/download'   => target => \&download );

# now create the Plack app
my $app = Plack::App::Path::Router::PSGI->new( router => $router );
use File::RotateLogs;
my $rotatelogs = File::RotateLogs->new(
    logfile => './log/access_log.%Y%m%d',
    linkname => './log/access_log',
    maxage => 86400 * 30, #30day
);

use Log::Dispatch;
my $logger = Log::Dispatch->new;
use Log::Dispatch::Config;
Log::Dispatch::Config->configure('./log.conf');
my $dispatcher = Log::Dispatch::Config->instance();
$dispatcher->info('再起動');

builder {
    if ( !$app && ( my $error = $@ || $! )) { die $error; }
    enable "Plack::Middleware::Static",  path => qr{^/static}, root => './common';
    enable 'AccessLog', logger => sub { $rotatelogs->print(@_) };
    enable 'LogErrors', logger => sub {
        my $args = shift;
        $logger->log(%$args);
    };

    $app->to_app();
};

#===============================================================================
sub download {
    my $env = shift;
    my $req = Plack::Request->new($env);
    my $ip = $env->{'REMOTE_ADDR'};
    my $sth = $dbh->prepare('SELECT * FROM Counter WHERE ip_address = ?')  or die $dbh->errstr;
    $sth->execute($ip) or die $sth->errstr;
    my $hash = $sth->fetchrow_hashref();
    $sth->finish;

    my $count = thaw( $hash->{'referer'} );
    my $ref = $req->query_parameters->{'ref'};
    $count->{ $ref }++ if exists $count->{ $ref };
    $count->{ 'total' }++ if $ref ne 'total';
    $hash->{'referer'} = nfreeze($count);

    $sth = $dbh->prepare('UPDATE Counter SET referer = ? WHERE ip_address = ?')  or die $dbh->errstr;
    $sth->execute( $hash->{'referer'}, $ip ) or die $sth->errstr;
    $sth->finish;

    use Text::vCard;
    my $vc = Text::vCard->new( { 'encoding_out' => 'none', } );
    $vc->version('4.0');
    my $vcf = $vc->as_string();
    $dispatcher->info("ダウンロード $ip:ref=$ref is $count->{ $ref }" );
    $dispatcher->info("総ダウンロード $ip is $count->{ 'total' }" );
    response( $env, $vcf,
        -MIME => 'text/vcard; charset=utf-8', -headers => {
            'Content-Disposition' => qq|attachment; filename="test.vcf"|,
            'Content-Length' => length $vcf,
            'Pragma' => 'no-cache',
            'Cache-Control' => 'private, no-store, no-cache, must-revalidate',
        }
    );
}

sub root {
    my $env = shift;
    my $req = Plack::Request->new($env);
    my %param = %{ $req->query_parameters };
    my $render;

    my $sth = $dbh->prepare("INSERT INTO Counter VALUES(?,?)") or die $dbh->errstr;
    $sth->execute(
        $env->{'REMOTE_ADDR'},
        nfreeze({ total => 0, reload => 0 }),
    ) or die $dbh->errstr;
    $sth->finish;

    $dispatcher->info('データベースの初期化に成功');

    # 以下画面表示
    $render = $tx->render( 'template.tx');
    response( $env, $render );
}

sub response {
    my $env = shift;
    my $body = shift || croak 'empty body!';
    my %ARG = @_;
    my $status = $ARG{'-status'} || 200;
    croak "unvalid status: $status" if $status !~ /\d{3}/s;
    my $mime = $ARG{'-MIME'} || 'text/html; charset=utf-8';
    my $headers = $ARG{'-headers'} || {};
    my $req = Plack::Request->new($env);
    my $res = $req->new_response($status);
    $res->content_type($mime);
    $res->header({
        'Set-Cookie' => $session->cookie,
        %$headers
    });
    $res->body($body);
    $res->finalize;
}

__DATA__

@@ template.tx
    <meta charset="UTF-8">

    <h2>データベース初期化完了</h2>
    <p><a href="/download?ref=reload">こちらをクリックしてダウンロード</a></p>

エラーの概要

まぁ適当に空のvCardファイルをダウンロードさせるんだが、

error.log

[Fri Oct 21 21:26:08 2016] [info] 再起動 
HTTP::Server::PSGI: Accepting connections at http://0:5000/
[Fri Oct 21 21:39:16 2016] [info] ダウンロード 127.0.0.1:ref=reload is 11 
[Fri Oct 21 21:39:16 2016] [info] 総ダウンロード 127.0.0.1 is 13 
[Fri Oct 21 21:39:16 2016] [info] ダウンロード 127.0.0.1:ref=reload is 12 
[Fri Oct 21 21:39:16 2016] [info] 総ダウンロード 127.0.0.1 is 14 ```

↑sleipnilからのアクセスでは不思議なことに1アクセスにつき2回、sub downloadが呼ばれてるっぽい。しかしアクセスログには1クリックにつきGETリクエスト1回限り。

（11/2追記）Chorome,Safariでの検証結果

正常に動作しました。お騒がせしました。