From 42b3ff3bd2894105231d5e3311cd561fb1ac55b3 Mon Sep 17 00:00:00 2001
From: dakkar <dakkar@thenautilus.net>
Date: Sun, 23 Oct 2016 15:34:04 +0100
Subject: logging & request id work

---
 lib/IO/Async/PSGI.pm |  13 ++-----
 t/tests/logging.t    | 105 +++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 108 insertions(+), 10 deletions(-)
 create mode 100644 t/tests/logging.t

diff --git a/lib/IO/Async/PSGI.pm b/lib/IO/Async/PSGI.pm
index 99f7d23..2154e2c 100644
--- a/lib/IO/Async/PSGI.pm
+++ b/lib/IO/Async/PSGI.pm
@@ -6,6 +6,7 @@ use Future;
 use HTTP::Status ();
 use Safe::Isa;
 use Plack::Middleware::HTTPExceptions;
+use Class::Method::Modifiers 'install_modifier';
 
 {
     my $logging_requestid_cb;
@@ -23,7 +24,7 @@ use Plack::Middleware::HTTPExceptions;
 }
 
 our $_current_request_id;
-around 'Future::wrap_cb' => sub {
+install_modifier Future => around => wrap_cb => sub {
     my $orig = shift;
     my $cb = $orig->(@_);
     my $reqid = $_current_request_id;
@@ -77,20 +78,12 @@ sub psgi_app {
 
         return sub {
             my ($responder) = @_;
-            $f->on_done(
-                sub{
-                    $responder->(@_);
-                    # I'm not sure why I may have to set it again
-                    # _invoke_logging_cb($reqid);
-                },
-            );
+            $f->on_done($responder);
             $f->on_fail(
                 sub{
                     my ($exc,@details) = @_;
                     my $response = $self->on_app_failure($env,$exc,@details);
                     $responder->($response);
-                    # I'm not sure why I may have to set it again
-                    # _invoke_logging_cb($reqid);
                 }
             );
 
diff --git a/t/tests/logging.t b/t/tests/logging.t
new file mode 100644
index 0000000..390dd91
--- /dev/null
+++ b/t/tests/logging.t
@@ -0,0 +1,105 @@
+#!perl
+use strict;
+use warnings;
+
+use IO::Async::PSGI;
+
+use IO::Async::Loop;
+use IO::Async::Test;
+use HTTP::Request;
+use HTTP::Message::PSGI;
+use Future;
+use Plack::Util;
+use Plack::Middleware::RequestId;
+use Plack::Builder;
+use Log::Any::Test;
+use Log::Any qw($log);
+
+use Test2::Bundle::Extended;
+use Data::Printer;
+
+my $app_f = sub {
+    my ($env) = @_;
+    my $loop = $env->{'io.async.loop'};
+
+    $log->info('starting');
+    $loop
+        ->delay_future(after=>0.1)
+        ->then(sub{
+                   $log->info('first step');
+                   $loop->delay_future(after=>0.1);
+               })
+        ->then(sub{
+                   $log->info('second step');
+                   $loop->delay_future(after=>0.1);
+               })
+        ->then(sub{
+                   $log->info('third step');
+                   Future->done([200,[],['']]);
+               });
+};
+
+my $loop = IO::Async::Loop->new;
+testing_loop $loop;
+
+my $psgi = IO::Async::PSGI->new({
+    app => $app_f,
+});
+my $app = builder {
+    enable 'RequestId';
+    $psgi->psgi_app;
+};
+
+IO::Async::PSGI->logging_requestid_cb(
+    sub {
+        my ($req_id) = @_;
+        if ($req_id) { $log->{prefix} = "$req_id " }
+        else { $log->{prefix} = undef }
+    }
+);
+
+my @res;
+for my $i (0..2) {
+    my $req = HTTP::Request->new(GET => 'http://localhost/')->to_psgi;
+    $req->{'io.async.loop'}=$loop;
+
+    my $raw_res = $app->($req);
+    $raw_res->(sub{$res[$i]=shift});
+}
+
+wait_for { $res[0] && $res[1] && $res[2] };
+
+is($res[$_]->[0],200,"response $_ ok")
+    for 0..2;
+
+my @ids = map { Plack::Util::header_get($_->[1],'X-Request-Id') } @res;
+
+my @log_lines =
+    map { [$_->{category},split / /,$_->{message},2] }
+    @{ $log->msgs };
+
+my %log_lines_for_req;
+push @{$log_lines_for_req{$_->[1]}},$_ for @log_lines;
+
+is(
+    \@ids,
+    bag { item $_ for keys %log_lines_for_req; end },
+    'request ids match',
+);
+
+for my $req_id (keys %log_lines_for_req) {
+    subtest "request $req_id" => sub {
+        is(
+            $log_lines_for_req{$req_id},
+            [
+                ['main',$req_id,'starting'],
+                ['main',$req_id,'first step'],
+                ['main',$req_id,'second step'],
+                ['main',$req_id,'third step'],
+            ],
+            'correct events',
+        );
+    };
+}
+
+done_testing;
-- 
cgit v1.2.3