Merge pull request #154 from bquorning/consistent-logging

Consistent logging

Author: peterzhu2118

docs/CONFIGURATION.md

@@ -325,7 +325,7 @@ spawning the original workers.
 
 ```ruby
 after_monitor_ready do |server|
-  server.logger.info("Monitor pid=#{Process.pid} ready")
+  server.logger.info("monitor pid=#{Process.pid} ready")
 end
 ```
 

lib/pitchfork/configurator.rb

@@ -41,21 +41,17 @@ class Configurator
       :worker_processes => 1,
       :before_fork => nil,
       :after_worker_fork => lambda { |server, worker|
-        server.logger.info("worker=#{worker.nr} gen=#{worker.generation} pid=#{$$} spawned")
+        server.logger.info("#{worker.to_log} spawned")
       },
       :after_mold_fork => lambda { |server, worker|
-        server.logger.info("mold gen=#{worker.generation} pid=#{$$} spawned")
+        server.logger.info("#{worker.to_log} spawned")
       },
       :before_worker_exit => nil,
       :after_worker_exit => lambda { |server, worker, status|
         m = if worker.nil?
-          "repead unknown process (#{status.inspect})"
-        elsif worker.mold?
-          "mold pid=#{worker.pid rescue 'unknown'} gen=#{worker.generation rescue 'unknown'} reaped (#{status.inspect})"
-        elsif worker.service?
-          "service pid=#{worker.pid rescue 'unknown'} gen=#{worker.generation rescue 'unknown'} reaped (#{status.inspect})"
+          "reaped unknown process (#{status.inspect})"
         else
-          "worker=#{worker.nr rescue 'unknown'} pid=#{worker.pid rescue 'unknown'} gen=#{worker.generation rescue 'unknown'} reaped (#{status.inspect})"
+          "#{worker.to_log} reaped (#{status.inspect})"
         end
         if status.success?
           server.logger.info(m)
@@ -64,10 +60,10 @@ class Configurator
         end
       },
       :after_worker_ready => lambda { |server, worker|
-        server.logger.info("worker=#{worker.nr} gen=#{worker.generation} ready")
+        server.logger.info("#{worker.to_log} ready")
       },
       :after_monitor_ready => lambda { |server|
-        server.logger.info("Monitor pid=#{Process.pid} ready")
+        server.logger.info("monitor pid=#{Process.pid} ready")
       },
       :after_worker_timeout => nil,
       :after_worker_hard_timeout => nil,

lib/pitchfork/http_server.rb

@@ -50,7 +50,7 @@ def inspect
 
       def call(original_thread) # :nodoc:
         begin
-          @server.logger.error("worker=#{@worker.nr} pid=#{@worker.pid} timed out, exiting")
+          @server.logger.error("#{@worker.to_log} timed out, exiting")
           if @callback
             @callback.call(@server, @worker, Info.new(original_thread, @rack_env))
           end
@@ -363,19 +363,19 @@ def monitor_loop(sleep = true)
       when Message::WorkerSpawned
         worker = @children.update(message)
         # TODO: should we send a message to the worker to acknowledge?
-        logger.info "worker=#{worker.nr} pid=#{worker.pid} gen=#{worker.generation} registered"
+        logger.info "#{worker.to_log} registered"
       when Message::MoldSpawned
         new_mold = @children.update(message)
-        logger.info("mold pid=#{new_mold.pid} gen=#{new_mold.generation} spawned")
+        logger.info("#{new_mold.to_log} spawned")
       when Message::ServiceSpawned
         new_service = @children.update(message)
-        logger.info("service pid=#{new_service.pid} gen=#{new_service.generation} spawned")
+        logger.info("#{new_service.to_log} spawned")
       when Message::MoldReady
         old_molds = @children.molds
         new_mold = @children.update(message)
-        logger.info("mold pid=#{new_mold.pid} gen=#{new_mold.generation} ready")
+        logger.info("#{new_mold.to_log} ready")
         old_molds.each do |old_mold|
-          logger.info("Terminating old mold pid=#{old_mold.pid} gen=#{old_mold.generation}")
+          logger.info("Terminating old #{old_mold.to_log}")
           old_mold.soft_kill(:TERM)
         end
       else
@@ -413,7 +413,7 @@ def stop(graceful = true)
     end
 
     def worker_exit(worker)
-      logger.info "worker=#{worker.nr} pid=#{worker.pid} gen=#{worker.generation} exiting"
+      logger.info "#{worker.to_log} exiting"
       proc_name status: "exiting"
 
       if @before_worker_exit
@@ -427,7 +427,7 @@ def worker_exit(worker)
     end
 
     def service_exit(service)
-      logger.info "service pid=#{service.pid} gen=#{service.generation} exiting"
+      logger.info "#{service.to_log} exiting"
       proc_name status: "exiting"
 
       if @before_service_worker_exit
@@ -548,11 +548,7 @@ def hard_timeout(child)
         end
       end
 
-      if child.mold?
-        logger.error "mold pid=#{child.pid} gen=#{child.generation} timed out, killing"
-      else
-        logger.error "worker=#{child.nr} pid=#{child.pid} gen=#{child.generation} timed out, killing"
-      end
+      logger.error "#{child.to_log} timed out, killing"
       @children.hard_kill(@timeout_signal.call(child.pid), child) # take no prisoners for hard timeout violations
     end
 
@@ -583,7 +579,7 @@ def after_fork_internal
     end
 
     def spawn_worker(worker, detach:)
-      logger.info("worker=#{worker.nr} gen=#{worker.generation} spawning...")
+      logger.info("#{worker.to_log} spawning...")
 
       # We set the deadline before spawning the child so that if for some
       # reason it gets stuck before reaching the worker loop,
@@ -646,7 +642,7 @@ def service_loop(service)
     end
 
     def spawn_service(service, detach:)
-      logger.info("service gen=#{service.generation} spawning...")
+      logger.info("#{service.to_log} spawning...")
 
       # We set the deadline before spawning the child so that if for some
       # reason it gets stuck before reaching the worker loop,
@@ -759,9 +755,9 @@ def restart_outdated_workers
       if service = @children.service
         if service.outdated?
           if service.soft_kill(:TERM)
-            logger.info("Sent SIGTERM to service pid=#{service.pid} gen=#{service.generation}")
+            logger.info("Sent SIGTERM to #{service.to_log}")
           else
-            logger.info("Failed to send SIGTERM to service pid=#{service.pid} gen=#{service.generation}")
+            logger.info("Failed to send SIGTERM to #{service.to_log}")
           end
         end
       end
@@ -770,10 +766,10 @@ def restart_outdated_workers
         outdated_workers = @children.workers.select { |w| !w.exiting? && w.generation < @children.mold.generation }
         outdated_workers.each do |worker|
           if worker.soft_kill(:TERM)
-            logger.info("Sent SIGTERM to worker=#{worker.nr} pid=#{worker.pid} gen=#{worker.generation}")
+            logger.info("Sent SIGTERM to #{worker.to_log}")
             workers_to_restart -= 1
           else
-            logger.info("Failed to send SIGTERM to worker=#{worker.nr} pid=#{worker.pid} gen=#{worker.generation}")
+            logger.info("Failed to send SIGTERM to #{worker.to_log}")
           end
           break if workers_to_restart <= 0
         end
@@ -985,7 +981,7 @@ def worker_loop(worker)
               if Info.fork_safe?
                 spawn_mold(worker)
               else
-                logger.error("worker=#{worker.nr} gen=#{worker.generation} is no longer fork safe, can't refork")
+                logger.error("#{worker.to_log} is no longer fork safe, can't refork")
               end
             when Message
               worker.update(client)
@@ -1005,7 +1001,7 @@ def worker_loop(worker)
             if @refork_condition.met?(worker, logger)
               proc_name status: "requests: #{worker.requests_count}, spawning mold"
               if spawn_mold(worker)
-                logger.info("worker=#{worker.nr} gen=#{worker.generation} Refork condition met, promoting ourselves")
+                logger.info("#{worker.to_log} refork condition met, promoting ourselves")
               end
               @refork_condition.backoff!
             end
@@ -1068,11 +1064,11 @@ def mold_loop(mold)
                 spawn_worker(Worker.new(message.nr, generation: mold.generation), detach: true)
               rescue ForkFailure
                 if retries > 0
-                  @logger.fatal("mold pid=#{mold.pid} gen=#{mold.generation} Failed to spawn a worker. Retrying.")
+                  @logger.fatal("#{mold.to_log} failed to spawn a worker, retrying")
                   retries -= 1
                   retry
                 else
-                  @logger.fatal("mold pid=#{mold.pid} gen=#{mold.generation} Failed to spawn a worker twice in a row. Corrupted mold process?")
+                  @logger.fatal("#{mold.to_log} failed to spawn a worker twice in a row - corrupted mold process?")
                   Process.exit(1)
                 end
               rescue => error
@@ -1084,11 +1080,11 @@ def mold_loop(mold)
                 spawn_service(Service.new(generation: mold.generation), detach: true)
               rescue ForkFailure
                 if retries > 0
-                  @logger.fatal("mold pid=#{mold.pid} gen=#{mold.generation} Failed to spawn a service. Retrying.")
+                  @logger.fatal("#{mold.to_log} failed to spawn a service, retrying")
                   retries -= 1
                   retry
                 else
-                  @logger.fatal("mold pid=#{mold.pid} gen=#{mold.generation} Failed to spawn a service twice in a row. Corrupted mold process?")
+                  @logger.fatal("#{mold.to_log} failed to spawn a service twice in a row - corrupted mold process?")
                   Process.exit(1)
                 end
               rescue => error

lib/pitchfork/refork_condition.rb

@@ -19,7 +19,7 @@ def met?(worker, logger)
           if worker.requests_count >= limit
             return false if backoff?
 
-            logger.info("worker=#{worker.nr} pid=#{worker.pid} processed #{worker.requests_count} requests, triggering a refork")
+            logger.info("#{worker.to_log} processed #{worker.requests_count} requests, triggering a refork")
             return true
           end
         end

lib/pitchfork/worker.rb

@@ -208,6 +208,14 @@ def after_fork_in_child
       @master&.close
     end
 
+    def to_log
+      if mold?
+        pid ? "mold gen=#{generation} pid=#{pid}" : "mold gen=#{generation}"
+      else
+        pid ? "worker=#{nr} gen=#{generation} pid=#{pid}" : "worker=#{nr} gen=#{generation}"
+      end
+    end
+
     private
 
     def init_deadline
@@ -257,6 +265,10 @@ def register_to_master(control_socket)
       @master.close
     end
 
+    def to_log
+      pid ? "service gen=#{generation} pid=#{pid}" : "service gen=#{generation}"
+    end
+
     private
 
     def init_deadline

test/integration/test_boot.rb

@@ -104,9 +104,9 @@ def test_boot_worker_stuck_in_spawn
 
     assert_healthy("http://#{addr}:#{port}")
 
-    assert_stderr("worker=0 gen=0 ready")
-    assert_stderr(/worker=1 pid=(\d+) gen=0 registered/)
-    assert_stderr(/worker=1 pid=\d+ gen=0 timed out, killing/, timeout: 4)
+    assert_stderr(/worker=0 gen=0 pid=\d+ ready/)
+    assert_stderr(/worker=1 gen=0 pid=\d+ registered/)
+    assert_stderr(/worker=1 gen=0 pid=\d+ timed out, killing/, timeout: 4)
 
     assert_clean_shutdown(pid)
   end
@@ -126,14 +126,14 @@ def test_boot_worker_stuck_in_spawn
     RUBY
 
     assert_healthy("http://#{addr}:#{port}")
-    assert_stderr("worker=0 gen=0 ready")
-    assert_stderr("worker=1 gen=0 ready")
+    assert_stderr(/worker=0 gen=0 pid=\d+ ready/)
+    assert_stderr(/worker=1 gen=0 pid=\d+ ready/)
 
     Process.kill(:KILL, pid)
     Process.waitpid(pid)
 
-    assert_stderr(/worker=0 pid=(\d+) gen=0 exiting/, timeout: 5)
-    assert_stderr(/worker=1 pid=(\d+) gen=0 exiting/)
+    assert_stderr(/worker=0 gen=0 pid=(\d+) exiting/, timeout: 5)
+    assert_stderr(/worker=1 gen=0 pid=(\d+) exiting/)
 
     assert_raises Errno::ESRCH, Errno::ECHILD do
       25.times do

test/integration/test_info.rb

@@ -11,15 +11,15 @@ def test_after_request_complete
     CONFIG
 
     assert_healthy("http://#{addr}:#{port}")
-    assert_stderr "worker=3 gen=0 ready"
+    assert_stderr(/worker=3 gen=0 pid=\d+ ready/)
 
     response = http_get("http://#{addr}:#{port}/")
     assert_equal({workers_count: 4, live_workers_count: 4}.inspect, response.body)
 
     Process.kill(:TTOU, pid)
-    assert_stderr(/worker=3 pid=\d+ gen=0 reaped/)
+    assert_stderr(/worker=3 gen=0 pid=\d+ reaped/)
     Process.kill(:TTOU, pid)
-    assert_stderr(/worker=2 pid=\d+ gen=0 reaped/)
+    assert_stderr(/worker=2 gen=0 pid=\d+ reaped/)
 
     response = http_get("http://#{addr}:#{port}/")
     assert_equal({workers_count: 4, live_workers_count: 2}.inspect, response.body)