mention timeouts in log messages and make forced worker shutdown a wa…

…rning
mojolicious · Jul 4, 2017 · 8b02829 · 8b02829
1 parent 93e314e
commit 8b02829
Show file tree

Hide file tree

Showing 5 changed files with 18 additions and 16 deletions.
diff --git a/lib/Mojo/Server/Hypnotoad.pm b/lib/Mojo/Server/Hypnotoad.pm
@@ -123,15 +123,15 @@ sub _manage {
   if ($self->{upgrade} && !$self->{finished}) {
 
     # Fresh start
+    my $ut = $self->upgrade_timeout;
     unless ($self->{new}) {
-      $log->info('Starting zero downtime software upgrade');
+      $log->info("Starting zero downtime software upgrade ($ut seconds)");
       die "Can't fork: $!" unless defined(my $pid = $self->{new} = fork);
       exec $^X, $ENV{HYPNOTOAD_EXE} or die "Can't exec: $!" unless $pid;
     }
 
     # Timeout
-    kill 'KILL', $self->{new}
-      if $self->{upgrade} + $self->upgrade_timeout <= steady_time;
+    kill 'KILL', $self->{new} if $self->{upgrade} + $ut <= steady_time;
   }
 }
 

diff --git a/lib/Mojo/Server/Prefork.pm b/lib/Mojo/Server/Prefork.pm
@@ -112,19 +112,19 @@ sub _manage {
     next unless my $w = $self->{pool}{$pid};
 
     # No heartbeat (graceful stop)
-    $log->error("Worker $pid has no heartbeat, restarting")
+    $log->error("Worker $pid has no heartbeat ($ht seconds), restarting")
       and $w->{graceful} = $time
       if !$w->{graceful} && ($w->{time} + $interval + $ht <= $time);
 
     # Graceful stop with timeout
     my $graceful = $w->{graceful} ||= $self->{graceful} ? $time : undef;
-    $log->debug("Stopping worker $pid gracefully")
+    $log->debug("Stopping worker $pid gracefully ($gt seconds)")
       and (kill 'QUIT', $pid or $self->_stopped($pid))
       if $graceful && !$w->{quit}++;
     $w->{force} = 1 if $graceful && $graceful + $gt <= $time;
 
     # Normal stop
-    $log->debug("Stopping worker $pid immediately")
+    $log->warn("Stopping worker $pid immediately")
       and (kill 'KILL', $pid or $self->_stopped($pid))
       if $w->{force} || ($self->{finished} && !$graceful);
   }

diff --git a/lib/Mojolicious/Guides/FAQ.pod b/lib/Mojolicious/Guides/FAQ.pod
@@ -203,7 +203,7 @@ server closed the connection before the user agent could receive the whole
 response or that the user agent got destroyed, which forces all connections to
 be closed immediately.
 
-=head2 What does "Worker 31842 has no heartbeat, restarting" mean?
+=head2 What does "Worker 31842 has no heartbeat (20 seconds), restarting" mean?
 
 As long as they are accepting new connections, worker processes of all built-in
 pre-forking web servers send heartbeat messages to the manager process at

diff --git a/t/mojo/hypnotoad.t b/t/mojo/hypnotoad.t
@@ -250,9 +250,10 @@ sleep 1 while _port($port2);
 
 # Check log
 $log = $log->slurp;
-like $log, qr/Worker \d+ started/,                      'right message';
-like $log, qr/Starting zero downtime software upgrade/, 'right message';
-like $log, qr/Upgrade successful, stopping $old/,       'right message';
+like $log, qr/Worker \d+ started/, 'right message';
+like $log, qr/Starting zero downtime software upgrade \(60 seconds\)/,
+  'right message';
+like $log, qr/Upgrade successful, stopping $old/, 'right message';
 
 sub _pid {
   return undef unless open my $file, '<', $dir->child('hypnotoad.pid');

diff --git a/t/mojo/prefork.t b/t/mojo/prefork.t
@@ -79,12 +79,13 @@ 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/Stopping worker $spawn[0] gracefully/, 'right message';
-like $log, qr/Worker $spawn[0] stopped/,             'right message';
-like $log, qr/Manager $$ stopped/,                   'right message';
+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/Stopping worker $spawn[0] gracefully \(60 seconds\)/,
+  'right message';
+like $log, qr/Worker $spawn[0] stopped/, 'right message';
+like $log, qr/Manager $$ stopped/,       'right message';
 $prefork->app->log->unsubscribe(message => $cb);
 
 # Process id file