diff --git a/docs/CONFIGURATION.md b/docs/CONFIGURATION.md index d2a821fd..564b1808 100644 --- a/docs/CONFIGURATION.md +++ b/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 ``` diff --git a/lib/pitchfork/configurator.rb b/lib/pitchfork/configurator.rb index e9896911..ec77dd47 100644 --- a/lib/pitchfork/configurator.rb +++ b/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, diff --git a/lib/pitchfork/http_server.rb b/lib/pitchfork/http_server.rb index edf7b39f..a0b75936 100644 --- a/lib/pitchfork/http_server.rb +++ b/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 diff --git a/lib/pitchfork/refork_condition.rb b/lib/pitchfork/refork_condition.rb index 2aaf289a..e50628c5 100644 --- a/lib/pitchfork/refork_condition.rb +++ b/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 diff --git a/lib/pitchfork/worker.rb b/lib/pitchfork/worker.rb index 26bb7a98..89990fb2 100644 --- a/lib/pitchfork/worker.rb +++ b/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 diff --git a/test/integration/test_boot.rb b/test/integration/test_boot.rb index d53e9b90..0cb94a8c 100644 --- a/test/integration/test_boot.rb +++ b/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 diff --git a/test/integration/test_info.rb b/test/integration/test_info.rb index f65170a8..67f7172c 100644 --- a/test/integration/test_info.rb +++ b/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) diff --git a/test/integration/test_reforking.rb b/test/integration/test_reforking.rb index 7762dbfc..fbb57e37 100644 --- a/test/integration/test_reforking.rb +++ b/test/integration/test_reforking.rb @@ -13,17 +13,17 @@ def test_reforking CONFIG 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/) 9.times do assert_equal true, healthy?("http://#{addr}:#{port}") end - assert_stderr "Refork condition met, promoting ourselves", timeout: 3 - assert_stderr "Terminating old mold pid=" - assert_stderr "worker=0 gen=1 ready" - assert_stderr "worker=1 gen=1 ready" + assert_stderr "refork condition met, promoting ourselves", timeout: 3 + assert_stderr "Terminating old mold gen=0 pid=" + assert_stderr(/worker=0 gen=1 pid=\d+ ready/) + assert_stderr(/worker=1 gen=1 pid=\d+ ready/) File.truncate("stderr.log", 0) @@ -31,8 +31,8 @@ def test_reforking assert_equal true, healthy?("http://#{addr}:#{port}") end - assert_stderr "worker=0 gen=2 ready", timeout: 3 - assert_stderr "worker=1 gen=2 ready" + assert_stderr(/worker=0 gen=2 pid=\d+ ready/, timeout: 3) + assert_stderr(/worker=1 gen=2 pid=\d+ ready/) assert_clean_shutdown(pid) end @@ -50,15 +50,15 @@ def test_reforking_broken_after_mold_fork_hook CONFIG 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/) 9.times do assert_equal true, healthy?("http://#{addr}:#{port}") end - assert_stderr "Refork condition met, promoting ourselves", timeout: 3 - assert_stderr(/mold pid=\d+ gen=1 reaped/) + assert_stderr "refork condition met, promoting ourselves", timeout: 3 + assert_stderr(/mold gen=1 pid=\d+ reaped/) assert_equal true, healthy?("http://#{addr}:#{port}") @@ -86,17 +86,17 @@ def Process.fork CONFIG assert_healthy("http://#{addr}:#{port}") - assert_stderr "worker=0 gen=0 ready" - assert_stderr "worker=1 gen=0 ready", timeout: 5 + assert_stderr(/worker=0 gen=0 pid=\d+ ready/) + assert_stderr(/worker=1 gen=0 pid=\d+ ready/, timeout: 5) 9.times do assert_equal true, healthy?("http://#{addr}:#{port}") end - assert_stderr "Refork condition met, promoting ourselves", timeout: 3 + assert_stderr "refork condition met, promoting ourselves", timeout: 3 - assert_stderr "Failed to spawn a worker. Retrying." - assert_stderr "Failed to spawn a worker twice in a row. Corrupted mold process?" + assert_stderr "failed to spawn a worker, retrying" + assert_stderr "failed to spawn a worker twice in a row - corrupted mold process?" assert_stderr "No mold alive, shutting down" assert_exited(pid, 1, timeout: 5) @@ -126,23 +126,23 @@ def test_exiting_mold CONFIG assert_healthy("http://#{addr}:#{port}") - assert_stderr "worker=0 gen=0 ready" - assert_stderr "worker=1 gen=0 ready", timeout: 5 + assert_stderr(/worker=0 gen=0 pid=\d+ ready/) + assert_stderr(/worker=1 gen=0 pid=\d+ ready/, timeout: 5) 7.times do assert_equal true, healthy?("http://#{addr}:#{port}") end - assert_stderr(/mold pid=\d+ gen=1 spawned/) + assert_stderr(/mold gen=1 pid=\d+ spawned/) assert_stderr("[mold crashing]") - assert_stderr(/mold pid=\d+ gen=1 reaped/) + assert_stderr(/mold gen=1 pid=\d+ reaped/) 10.times do assert_equal true, healthy?("http://#{addr}:#{port}") end - assert_stderr "worker=0 gen=1 ready", timeout: 15 - assert_stderr "worker=1 gen=1 ready" + assert_stderr(/worker=0 gen=1 pid=\d+ ready/, timeout: 15) + assert_stderr(/worker=1 gen=1 pid=\d+ ready/) assert_clean_shutdown(pid) end @@ -171,23 +171,23 @@ def test_stuck_mold CONFIG assert_healthy("http://#{addr}:#{port}") - assert_stderr "worker=0 gen=0 ready" - assert_stderr "worker=1 gen=0 ready", timeout: 5 + assert_stderr(/worker=0 gen=0 pid=\d+ ready/) + assert_stderr(/worker=1 gen=0 pid=\d+ ready/, timeout: 5) 7.times do assert_equal true, healthy?("http://#{addr}:#{port}") end - assert_stderr(/mold pid=\d+ gen=1 spawned/) + assert_stderr(/mold gen=1 pid=\d+ spawned/) assert_stderr("[mold locking-up]") - assert_stderr(/mold pid=\d+ gen=1 reaped/, timeout: 10) + assert_stderr(/mold gen=1 pid=\d+ reaped/, timeout: 10) 10.times do assert_equal true, healthy?("http://#{addr}:#{port}") end - assert_stderr "worker=0 gen=1 ready", timeout: 5 - assert_stderr "worker=1 gen=1 ready" + assert_stderr(/worker=0 gen=1 pid=\d+ ready/, timeout: 5) + assert_stderr(/worker=1 gen=1 pid=\d+ ready/) assert_clean_shutdown(pid) end @@ -202,14 +202,14 @@ def test_fork_unsafe CONFIG 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/) 20.times do assert_equal true, healthy?("http://#{addr}:#{port}") end - refute_match("Refork condition met, promoting ourselves", read_stderr) + refute_match("refork condition met, promoting ourselves", read_stderr) assert_clean_shutdown(pid) end @@ -223,14 +223,14 @@ def test_reforking_on_USR2 CONFIG 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(:USR2, pid) - assert_stderr "Terminating old mold pid=" - assert_stderr "worker=0 gen=1 ready" - assert_stderr "worker=1 gen=1 ready" + assert_stderr "Terminating old mold gen=0 pid=" + assert_stderr(/worker=0 gen=1 pid=\d+ ready/) + assert_stderr(/worker=1 gen=1 pid=\d+ ready/) assert_healthy("http://#{addr}:#{port}") assert_clean_shutdown(pid) @@ -251,7 +251,7 @@ def test_reforking_on_USR2_fork_unsafe_worker CONFIG assert_healthy("http://#{addr}:#{port}") - assert_stderr "worker=0 gen=0 ready" + assert_stderr(/worker=0 gen=0 pid=\d+ ready/) Process.kill(:USR2, pid) @@ -275,16 +275,16 @@ def test_slow_worker_rollout CONFIG assert_healthy("http://#{addr}:#{port}") - assert_stderr "worker=0 gen=0 ready" - assert_stderr "worker=4 gen=0 ready" + assert_stderr(/worker=0 gen=0 pid=\d+ ready/) + assert_stderr(/worker=4 gen=0 pid=\d+ ready/) Process.kill(:USR2, pid) - assert_stderr "worker=0 gen=1 ready" - assert_stderr "worker=1 gen=1 ready" - assert_stderr "worker=2 gen=1 ready" - assert_stderr "worker=3 gen=1 ready" - assert_stderr "worker=4 gen=1 ready" + assert_stderr(/worker=0 gen=1 pid=\d+ ready/) + assert_stderr(/worker=1 gen=1 pid=\d+ ready/) + assert_stderr(/worker=2 gen=1 pid=\d+ ready/) + assert_stderr(/worker=3 gen=1 pid=\d+ ready/) + assert_stderr(/worker=4 gen=1 pid=\d+ ready/) assert_clean_shutdown(pid)