lib/pallets/middleware/job_logger.rb in pallets-0.8.0 vs lib/pallets/middleware/job_logger.rb in pallets-0.9.0

@@ -1,26 +1,37 @@
 module Pallets
   module Middleware
     class JobLogger
       def self.call(worker, job, context)
-        Pallets.logger.info 'Started', extract_metadata(worker.id, job)
-        result = yield
-        Pallets.logger.info 'Done', extract_metadata(worker.id, job)
-        result
-      rescue => ex
-        Pallets.logger.warn "#{ex.class.name}: #{ex.message}", extract_metadata(worker.id, job)
-        Pallets.logger.warn ex.backtrace.join("\n"), extract_metadata(worker.id, job) unless ex.backtrace.nil?
-        raise
+        start_time = current_time
+
+        Pallets.logger.with_metadata(extract_metadata(worker.id, job)) do
+          begin
+            Pallets.logger.info 'Started'
+            result = yield
+            Pallets.logger.info "Done in #{(current_time - start_time).round(3)}s"
+            result
+          rescue => ex
+            Pallets.logger.warn "Failed after #{(current_time - start_time).round(3)}s"
+            Pallets.logger.warn "#{ex.class.name}: #{ex.message}"
+            Pallets.logger.warn ex.backtrace.join("\n") unless ex.backtrace.nil?
+            raise
+          end
+        end
       end
 
       def self.extract_metadata(wid, job)
         {
           wid:  wid,
           wfid: job['wfid'],
           jid:  job['jid'],
           wf:   job['workflow_class'],
           tsk:  job['task_class'],
         }
+      end
+
+      def self.current_time
+        Process.clock_gettime(Process::CLOCK_MONOTONIC)
       end
     end
   end
 end