fixed bug in Mojo::Log that prevented some message events from being …

…emitted
mojolicious · Aug 19, 2012 · 3200504 · 3200504
1 parent 58863ef
commit 3200504
Show file tree

Hide file tree

Showing 5 changed files with 37 additions and 47 deletions.
diff --git a/Changes b/Changes
@@ -10,6 +10,8 @@
   - Improved documentation.
   - Improved tests.
   - Fixed json_has method in Test::Mojo.
+  - Fixed bug in Mojo::Log that prevented some message event from being
+    emitted.
   - Fixed small class_to_file bug.
   - Fixed a few small namespace handling bugs.
 

diff --git a/lib/Mojo/Log.pm b/lib/Mojo/Log.pm
@@ -58,21 +58,16 @@ sub is_warn { shift->is_level('warn') }
 
 # "If The Flintstones has taught us anything,
 #  it's that pelicans can be used to mix cement."
-sub log {
-  my $self  = shift;
-  my $level = lc shift;
-  return $self unless $self->is_level($level);
-  return $self->emit(message => $level => @_);
-}
+sub log { shift->emit('message', lc(shift), @_) }
 
 sub warn { shift->log(warn => @_) }
 
 sub _message {
-  my $self = shift;
-  return unless my $handle = $self->handle;
+  my ($self, $level) = (shift, shift);
+  return unless $self->is_level($level) && (my $handle = $self->handle);
   flock $handle, LOCK_EX;
   croak "Can't write to log: $!"
-    unless defined $handle->syswrite($self->format(@_));
+    unless defined $handle->syswrite($self->format($level, @_));
   flock $handle, LOCK_UN;
 }
 

diff --git a/t/mojo/log.t b/t/mojo/log.t
@@ -1,6 +1,6 @@
 use Mojo::Base -strict;
 
-use Test::More tests => 45;
+use Test::More tests => 47;
 
 # "Don't let Krusty's death get you down, boy.
 #  People die all the time, just like that.
@@ -13,14 +13,15 @@ use Mojo::Log;
 # Logging to file
 my $dir = tempdir CLEANUP => 1;
 my $path = catdir $dir, 'test.log';
-my $log = Mojo::Log->new(level => 'debug', path => $path);
-$log->debug('Just works.');
+my $log = Mojo::Log->new(level => 'error', path => $path);
+$log->error('Just works.');
+$log->fatal('Works too.');
+$log->debug('Does not work.');
 undef $log;
-like(
-  Mojo::Asset::File->new(path => $path)->slurp,
-  qr/^\[.*\] \[debug\] Just works\.\n$/,
-  'right content'
-);
+my $content = Mojo::Asset::File->new(path => $path)->slurp;
+like $content,   qr/\[.*\] \[error\] Just works\.\n/,    'has error message';
+like $content,   qr/\[.*\] \[fatal\] Works too\.\n/,     'has fatal message';
+unlike $content, qr/\[.*\] \[debug\] Does not work\.\n/, 'no debug message';
 
 # Formatting
 $log = Mojo::Log->new;
@@ -37,19 +38,23 @@ $log->unsubscribe('message')->on(
     push @$messages, $level, @lines;
   }
 );
-$log->info('Whatever.');
-is_deeply $messages, [qw(info Whatever.)], 'right messages';
-$log->level('error')->info('Again.');
-is_deeply $messages, [qw(info Whatever.)], 'right messages';
-$log->fatal('Test', 123);
-is_deeply $messages, [qw(info Whatever. fatal Test 123)], 'right messages';
+$log->debug('Test', 1, 2, 3);
+is_deeply $messages, [qw(debug Test 1 2 3)], 'right message';
+$messages = [];
+$log->info('Test', 1, 2, 3);
+is_deeply $messages, [qw(info Test 1 2 3)], 'right message';
+$messages = [];
+$log->warn('Test', 1, 2, 3);
+is_deeply $messages, [qw(warn Test 1 2 3)], 'right message';
+$messages = [];
+$log->error('Test', 1, 2, 3);
+is_deeply $messages, [qw(error Test 1 2 3)], 'right message';
+$messages = [];
+$log->fatal('Test', 1, 2, 3);
+is_deeply $messages, [qw(fatal Test 1 2 3)], 'right message';
 $messages = [];
-$log->level('debug')->log(info => 'Whatever.');
-is_deeply $messages, [qw(info Whatever.)], 'right messages';
-$log->level('error')->log(info => 'Again.');
-is_deeply $messages, [qw(info Whatever.)], 'right messages';
-$log->log(fatal => 'Test', 1, 2, 3);
-is_deeply $messages, [qw(info Whatever. fatal Test 1 2 3)], 'right messages';
+$log->log('fatal', 'Test', 1, 2, 3);
+is_deeply $messages, [qw(fatal Test 1 2 3)], 'right message';
 
 # "debug"
 is $log->level('debug')->level, 'debug', 'right level';

diff --git a/t/mojo/user_agent.t b/t/mojo/user_agent.t
@@ -156,17 +156,13 @@ is $code,    200, 'right status';
 is $body,    'works!', 'right content';
 
 # Error in callback is logged
-my $message = app->log->subscribers('message')->[0];
-app->log->unsubscribe(message => $message);
-app->log->level('error');
 app->ua->once(error => sub { Mojo::IOLoop->stop });
 ok app->ua->has_subscribers('error'), 'has subscribers';
 my $err;
-app->log->once(message => sub { $err .= pop });
+my $message = app->log->on(message => sub { $err .= pop });
 app->ua->get('/' => sub { die 'error event works' });
 Mojo::IOLoop->start;
-app->log->level('fatal');
-app->log->on(message => $message);
+app->log->unsubscribe(message => $message);
 like $err, qr/error event works/, 'right error';
 
 # GET / (HTTPS request without TLS support)
@@ -266,13 +262,9 @@ is $body,    '{"hello":"world"}', 'right content';
 
 # GET /timeout (built-in web server times out)
 my $log = '';
-$message = app->log->subscribers('message')->[0];
-app->log->unsubscribe(message => $message);
-app->log->level('debug');
-app->log->on(message => sub { $log .= pop });
+$message = app->log->on(message => sub { $log .= pop });
 $tx = $ua->get('/timeout?timeout=0.25');
-app->log->level('fatal');
-app->log->on(message => $message);
+app->log->unsubscribe(message => $message);
 ok !$tx->success, 'not successful';
 is $tx->error, 'Premature connection close', 'right error';
 is $timeout, 1, 'finish event has been emitted';

diff --git a/t/mojo/websocket.t b/t/mojo/websocket.t
@@ -486,18 +486,14 @@ is $result, 'hi!' x 100, 'right result';
 
 # WebSocket /timeout
 my $log = '';
-$message = app->log->subscribers('message')->[0];
-app->log->unsubscribe(message => $message);
-app->log->level('debug');
-app->log->on(message => sub { $log .= pop });
+$message = app->log->on(message => sub { $log .= pop });
 $ua->websocket(
   '/timeout' => sub {
     pop->on(finish => sub { Mojo::IOLoop->stop });
   }
 );
 Mojo::IOLoop->start;
-app->log->level('fatal');
-app->log->on(message => $message);
+app->log->unsubscribe(message => $message);
 is $timeout, 'works!', 'finish event has been emitted';
 like $log, qr/Inactivity timeout\./, 'right log message';