Parser friendly, more complete logs

CHANGELOG.md

@@ -1,5 +1,7 @@
 ## Main
 
+- Parser friendly, more complete logs (#97)
+
 ## 0.3.1
 
 - Relax puma dependency (#94)
@@ -43,4 +45,3 @@
 ## 0.0.3
 
 - Fix memory metrics in on linux
-

README.md

@@ -129,13 +129,13 @@ PumaWorkerKiller.start
 By default Puma Worker Killer will emit a log when a worker is being killed
 
 ```
-PumaWorkerKiller: Out of memory. 5 workers consuming total: 500 mb out of max: 450 mb. Sending TERM to pid 23 consuming 53 mb.
+PumaWorkerKiller: Out of memory. 5 workers and master consuming total: 500 mb out of max: 450 mb. Sending TERM to pid 23 consuming 53 mb.
 ```
 
 or
 
 ```
-PumaWorkerKiller: Rolling Restart. 5 workers consuming total: 650mb mb. Sending TERM to pid 34.
+PumaWorkerKiller: Rolling Restart. 5 workers and master consuming total: 650mb mb. Sending TERM to pid 34.
 ```
 
 However you may want to collect more data, such as sending an event to an error collection service like rollbar or airbrake. The `pre_term` lambda gets called before any worker is killed by PWK for any reason.

lib/puma_worker_killer/puma_memory.rb

@@ -49,9 +49,9 @@ def largest_worker_memory
       largest_memory_used
     end
 
-    # Will refresh @workers
+    # Will refresh @workers and @master_memory
     def get_total(workers = set_workers)
-      master_memory = GetProcessMem.new(Process.pid).mb
+      master_memory = set_master_memory
       worker_memory = workers.values.inject(:+) || 0
       worker_memory + master_memory
     end
@@ -61,6 +61,10 @@ def workers
       @workers || set_workers
     end
 
+    def master_memory
+      @master_memory || set_master_memory
+    end
+
     private
 
     def get_master
@@ -80,5 +84,9 @@ def set_workers
         {}
       end
     end
+
+    def set_master_memory
+      @master_memory = GetProcessMem.new(Process.pid).mb
+    end
   end
 end

lib/puma_worker_killer/reaper.rb

@@ -21,23 +21,34 @@ def reap
       total = get_total_memory
       @on_calculation&.call(total)
 
-      if total > @max_ram
-        @cluster.master.log "PumaWorkerKiller: Out of memory. #{@cluster.workers.count} workers consuming total: #{total} mb out of max: #{@max_ram} mb. Sending TERM to pid #{@cluster.largest_worker.pid} consuming #{@cluster.largest_worker_memory} mb."
-
-        # Fetch the largest_worker so that both `@pre_term` and `term_worker` are called with the same worker
-        # Avoids a race condition where:
-        #   Worker A consume 100 mb memory
-        #   Worker B consume 99 mb memory
-        #   pre_term gets called with Worker A
-        #   A new request comes in, Worker B takes it, and consumes 101 mb memory
-        #   term_largest_worker (previously here) gets called and terms Worker B (thus not passing the about-to-be-terminated worker to `@pre_term`)
-        largest_worker = @cluster.largest_worker
-        @pre_term&.call(largest_worker)
-        @cluster.term_worker(largest_worker)
-
-      elsif @reaper_status_logs
-        @cluster.master.log "PumaWorkerKiller: Consuming #{total} mb with master and #{@cluster.workers.count} workers."
+      if @reaper_status_logs
+        @cluster.master.log 'PumaWorkerKiller: Status log. ' \
+          "total=#{total}mb " \
+          "master=#{@cluster.master_memory}md " \
+          "worker_count=#{@cluster.workers.count} " \
+          "#{@cluster.workers.map { |worker, mem| "worker_#{worker.pid}=#{mem}mb" } * " "}"
       end
+
+      kill(total) if total > @max_ram
+    end
+
+    private
+
+    def kill(total_mem)
+      @cluster.master.log "PumaWorkerKiller: Out of memory. #{@cluster.workers.count} " \
+        "workers and master consuming total: #{total_mem} mb out of max: #{@max_ram} mb. " \
+        "Sending TERM to pid #{@cluster.largest_worker.pid} consuming #{@cluster.largest_worker_memory} mb."
+
+      # Fetch the largest_worker so that both `@pre_term` and `term_worker` are called with the same worker
+      # Avoids a race condition where:
+      #   Worker A consume 100 mb memory
+      #   Worker B consume 99 mb memory
+      #   pre_term gets called with Worker A
+      #   A new request comes in, Worker B takes it, and consumes 101 mb memory
+      #   term_largest_worker (previously here) gets called and terms Worker B (thus not passing the about-to-be-terminated worker to `@pre_term`)
+      largest_worker = @cluster.largest_worker
+      @pre_term&.call(largest_worker)
+      @cluster.term_worker(largest_worker)
     end
   end
 end

lib/puma_worker_killer/rolling_restart.rb

@@ -18,7 +18,7 @@ def reap(seconds_between_worker_kill = 60)
       return false unless @cluster.running?
 
       @cluster.workers.each do |worker, _ram|
-        @cluster.master.log "PumaWorkerKiller: Rolling Restart. #{@cluster.workers.count} workers consuming total: #{total_memory} mb. Sending TERM to pid #{worker.pid}."
+        @cluster.master.log "PumaWorkerKiller: Rolling Restart. #{@cluster.workers.count} workers and master consuming total: #{total_memory} mb. Sending TERM to pid #{worker.pid}."
         @rolling_pre_term&.call(worker)
 
         worker.term

puma_worker_killer.gemspec

@@ -3,6 +3,7 @@
 lib = File.expand_path('lib', __dir__)
 $LOAD_PATH.unshift(lib) unless $LOAD_PATH.include?(lib)
 require 'puma_worker_killer/version'
+require 'english'
 
 Gem::Specification.new do |gem|
   gem.name          = 'puma_worker_killer'