another round of logging tests

mojolicious · Aug 31, 2013 · da2b5ff · da2b5ff
1 parent 1cea44e
commit da2b5ff
Show file tree

Hide file tree

Showing 6 changed files with 65 additions and 16 deletions.
diff --git a/t/mojo/prefork.t b/t/mojo/prefork.t
@@ -52,6 +52,8 @@ $prefork->once(
 );
 $prefork->on(reap => sub { push @reap, pop });
 $prefork->on(finish => sub { $graceful = pop });
+my $log = '';
+my $cb = $prefork->app->log->on(message => sub { $log .= pop });
 $prefork->run;
 is scalar @spawn, 4, 'four workers spawned';
 is scalar @reap,  4, 'four workers reaped';
@@ -60,6 +62,12 @@ ok $graceful, 'server has been stopped gracefully';
 is_deeply [sort @spawn], [sort @reap], 'same process ids';
 is $tx->res->code, 200,           'right status';
 is $tx->res->body, 'just works!', 'right content';
+like $log, qr/Listening at/,                                 'right message';
+like $log, qr/Manager $$ started\./,                         'right message';
+like $log, qr/Creating process id file/,                     'right message';
+like $log, qr/Trying to stop worker $spawn[0] gracefully\./, 'right message';
+like $log, qr/Worker $spawn[0] stopped\./,                   'right message';
+$prefork->app->log->unsubscribe(message => $cb);
 
 # Process id and lock files
 is $prefork->check_pid, $$, 'right process id';

diff --git a/t/mojolicious/app.t b/t/mojolicious/app.t
@@ -130,6 +130,15 @@ ok !!$t->app->plugins->emit_hook('does_not_exist'), 'hook has been emitted';
 ok !!$t->app->plugins->emit_hook_reverse('does_not_exist'),
   'hook has been emitted';
 
+# Replaced helper
+my $log = '';
+my $cb = $t->app->log->on(message => sub { $log .= pop });
+$t->app->helper(replaced_helper => sub { });
+$t->app->helper(replaced_helper => sub { });
+like $log, qr/Helper "replaced_helper" already exists, replacing\./,
+  'right message';
+$t->app->log->unsubscribe(message => $cb);
+
 # Custom hooks
 my $custom;
 $t->app->hook('custom_hook' => sub { $custom += shift });
@@ -150,8 +159,8 @@ $t->get_ok('/plugin-test-some_plugin2/register')->status_isnt(500)
   ->content_unlike(qr/Something/)->content_like(qr/Page not found/);
 
 # Plugin::Test::SomePlugin2::register (security violation again)
-my $log = '';
-my $cb = $t->app->log->on(message => sub { $log .= pop });
+$log = '';
+$cb = $t->app->log->on(message => sub { $log .= pop });
 $t->get_ok('/plugin-test-some_plugin2/register')->status_isnt(500)
   ->status_is(404)->header_is(Server => 'Mojolicious (Perl)')
   ->content_unlike(qr/Something/)->content_like(qr/Page not found/);
@@ -259,9 +268,13 @@ $t->get_ok('/foo/test' => {'X-Test' => 'Hi there!'})->status_is(200)
   ->header_is(Server     => 'Mojolicious (Perl)')->content_like(qr!/bar/test!);
 
 # Foo::index
+$log = '';
+$cb = $t->app->log->on(message => sub { $log .= pop });
 $t->get_ok('/foo' => {'X-Test' => 'Hi there!'})->status_is(200)
   ->header_is(Server => 'Mojolicious (Perl)')
   ->content_like(qr|<body>\s+23\nHello Mojo from the template /foo! He|);
+like $log, qr/Careful, "handler" is a reserved stash value\./, 'right message';
+$t->app->log->unsubscribe(message => $cb);
 
 # Foo::Bar::index
 $t->get_ok('/foo-bar' => {'X-Test' => 'Hi there!'})->status_is(200)

diff --git a/t/mojolicious/group_lite_app.t b/t/mojolicious/group_lite_app.t
@@ -242,37 +242,43 @@ $t->get_ok('/param_auth/too?name=Bender')->status_is(200)
 
 # No cookies, session or flash
 $t->get_ok('/bridge2stash' => {'X-Flash' => 1})->status_is(200)
-  ->content_is("stash too!!!!!!!\n");
+  ->content_is("stash too!!!!!!!!\n");
 ok $t->tx->res->cookie('mojolicious')->expires, 'has expiration';
 is $stash->{_name}, 'stash', 'right "_name" value';
 
 # Cookies, session and flash
+$log = '';
+$cb = $t->app->log->on(message => sub { $log .= pop });
 $t->get_ok('/bridge2stash')->status_is(200)
   ->content_is(
-  "stash too!cookie!signed_cookie!!bad_cookie--12345678!session!flash!\n");
+  "stash too!cookie!!signed_cookie!!bad_cookie--12345678!session!flash!\n");
+like $log, qr/Cookie "foo" not signed\./, 'right message';
+like $log, qr/Bad signed cookie "bad", possible hacking attempt\./,
+  'right message';
 ok $t->tx->res->cookie('mojolicious')->httponly,
   'session cookie has HttpOnly flag';
+$t->app->log->unsubscribe(message => $cb);
 
 # Broken session cookie
 $t->reset_session;
 my $session = b("☃☃☃☃☃")->encode->b64_encode('');
 my $hmac    = $session->clone->hmac_sha1_sum($t->app->secret);
 $t->get_ok('/bridge2stash' => {Cookie => "mojolicious=$session--$hmac"})
-  ->status_is(200)->content_is("stash too!!!!!!!\n");
+  ->status_is(200)->content_is("stash too!!!!!!!!\n");
 
 # Without cookie jar
 $t->ua->cookie_jar(0);
 $t->get_ok('/bridge2stash' => {'X-Flash' => 1})->status_is(200)
-  ->content_is("stash too!!!!!!!\n");
+  ->content_is("stash too!!!!!!!!\n");
 
 # Again without cookie jar
 $t->get_ok('/bridge2stash' => {'X-Flash' => 1})->status_is(200)
-  ->content_is("stash too!!!!!!!\n");
+  ->content_is("stash too!!!!!!!!\n");
 $t->reset_session->ua->cookie_jar(Mojo::UserAgent::CookieJar->new);
 
 # Fresh start without cookies, session or flash
 $t->get_ok('/bridge2stash' => {'X-Flash' => 1})->status_is(200)
-  ->content_is("stash too!!!!!!!\n");
+  ->content_is("stash too!!!!!!!!\n");
 
 # Random static requests
 $t->get_ok('/mojo/logo-white.png')->status_is(200);
@@ -283,18 +289,18 @@ $t->get_ok('/mojo/logo-black.png')->status_is(200);
 # With cookies, session and flash again
 $t->get_ok('/bridge2stash')->status_is(200)
   ->content_is(
-  "stash too!cookie!signed_cookie!!bad_cookie--12345678!session!flash!\n");
+  "stash too!cookie!!signed_cookie!!bad_cookie--12345678!session!flash!\n");
 
 # With cookies and session but no flash
 $t->get_ok('/bridge2stash' => {'X-Flash2' => 1})->status_is(200)
   ->content_is(
-  "stash too!cookie!signed_cookie!!bad_cookie--12345678!session!!\n");
+  "stash too!cookie!!signed_cookie!!bad_cookie--12345678!session!!\n");
 ok $t->tx->res->cookie('mojolicious')->expires->epoch < time,
   'session cookie expires';
 
 # With cookies and session cleared
 $t->get_ok('/bridge2stash')->status_is(200)
-  ->content_is("stash too!cookie!signed_cookie!!bad_cookie--12345678!!!\n");
+  ->content_is("stash too!cookie!!signed_cookie!!bad_cookie--12345678!!!\n");
 
 # Late session does not affect rendering
 $t->get_ok('/late/session')->status_is(200)->content_is('not yet!');
@@ -314,17 +320,17 @@ is $stash->{_name}, undef, 'no "_name" value';
 # Cookies, session and no flash again
 $t->get_ok('/bridge2stash' => {'X-Flash' => 1})->status_is(200)
   ->content_is(
-  "stash too!cookie!signed_cookie!!bad_cookie--12345678!session!!\n");
+  "stash too!cookie!!signed_cookie!!bad_cookie--12345678!session!!\n");
 
 # With cookies, session and flash
 $t->get_ok('/bridge2stash')->status_is(200)
   ->content_is(
-  "stash too!cookie!signed_cookie!!bad_cookie--12345678!session!flash!\n");
+  "stash too!cookie!!signed_cookie!!bad_cookie--12345678!session!flash!\n");
 
 # With cookies and session but no flash
 $t->get_ok('/bridge2stash' => {'X-Flash2' => 1})->status_is(200)
   ->content_is(
-  "stash too!cookie!signed_cookie!!bad_cookie--12345678!session!!\n");
+  "stash too!cookie!!signed_cookie!!bad_cookie--12345678!session!!\n");
 
 # Prefix
 $t->get_ok('/prefix')->status_is(200)
@@ -438,6 +444,7 @@ Not Bender!
 @@ bridge2stash.html.ep
 % my $cookie = $self->req->cookie('mojolicious');
 <%= stash('_name') %> too!<%= $self->cookie('foo') %>!\
+<%= $self->signed_cookie('foo') %>!\
 <%= $self->signed_cookie('bar')%>!<%= $self->signed_cookie('bad')%>!\
 <%= $self->cookie('bad') %>!<%= session 'foo' %>!\
 <%= flash 'foo' %>!

diff --git a/t/mojolicious/json_config_lite_app.t b/t/mojolicious/json_config_lite_app.t
@@ -20,8 +20,13 @@ is_deeply app->config, {it => 'works'}, 'right value';
 # Load plugins
 my $config
   = plugin j_s_o_n_config => {default => {foo => 'baz', hello => 'there'}};
-plugin JSONConfig => {file =>
-    abs_path(catfile(dirname(__FILE__), 'json_config_lite_app_abs.json'))};
+my $log = '';
+my $cb = app->log->on(message => sub { $log .= pop });
+my $path
+  = abs_path(catfile(dirname(__FILE__), 'json_config_lite_app_abs.json'));
+plugin JSONConfig => {file => $path};
+like $log, qr/Reading config file "\Q$path\E"\./, 'right message';
+app->log->unsubscribe(message => $cb);
 is $config->{foo},          'bar',            'right value';
 is $config->{hello},        'there',          'right value';
 is $config->{utf},          'утф',         'right value';

diff --git a/t/mojolicious/lite_app.t b/t/mojolicious/lite_app.t
@@ -733,8 +733,13 @@ $t->get_ok('/source')->status_is(200)->header_isnt('X-Missing' => 1)
   ->content_like(qr!get_ok\('/source!);
 
 # File does not exist
+$log = '';
+$cb = $t->app->log->on(message => sub { $log .= pop });
 $t->get_ok('/source?fail=1')->status_is(404)->header_is('X-Missing' => 1)
   ->content_is("Oops!\n");
+like $log, qr/File "does_not_exist.txt" not found, public directory missing\?/,
+  'right message';
+$t->app->log->unsubscribe(message => $cb);
 
 # With body and max message size
 {

diff --git a/t/mojolicious/renderer.t b/t/mojolicious/renderer.t
@@ -42,7 +42,18 @@ is_deeply [$r->render($c)], ['Hello Mojo!', 'test'],
   'rendering a path with dots';
 
 # Unrecognized handler
+my $log = '';
+my $cb = $c->app->log->on(message => sub { $log .= pop });
 $c->stash->{handler} = 'not_defined';
 is $r->render($c), undef, 'return undef for unrecognized handler';
+like $log, qr/No handler for "not_defined" available\./, 'right message';
+$c->app->log->unsubscribe(message => $cb);
+
+# Big cookie
+$log = '';
+$cb = $c->app->log->on(message => sub { $log .= pop });
+$c->cookie(foo => 'x' x 4097);
+like $log, qr/Cookie "foo" is bigger than 4096 bytes\./, 'right message';
+$c->app->log->unsubscribe(message => $cb);
 
 done_testing();