Simplify the log format for Dry Run

app/concerns/dry_runnable.rb

@@ -5,21 +5,34 @@ def dry_run!(event = nil)
     @dry_run = true
 
     log = StringIO.new
-    @dry_run_logger = Logger.new(log)
+    @dry_run_started_at = Time.zone.now
+    @dry_run_logger = Logger.new(log).tap { |logger|
+      logger.formatter = proc { |severity, datetime, progname, message|
+        elapsed_time = '%02d:%02d:%02d' % 2.times.inject([datetime - @dry_run_started_at]) { |(x, *xs)|
+          [*x.divmod(60), *xs]
+        }
+
+        "[#{elapsed_time}] #{severity} -- #{progname}: #{message}\n"
+      }
+    }
     @dry_run_results = {
       events: [],
     }
 
     begin
       raise "#{short_type} does not support dry-run" unless can_dry_run?
       readonly!
+      @dry_run_started_at = Time.zone.now
+      @dry_run_logger.info('Dry Run started')
       if event
         raise "This agent cannot receive an event!" unless can_receive_events?
         receive([event])
       else
         check
       end
+      @dry_run_logger.info('Dry Run finished')
     rescue => e
+      @dry_run_logger.info('Dry Run failed')
       error "Exception during dry-run. #{e.message}: #{e.backtrace.join("\n")}"
     end
 

spec/concerns/dry_runnable_spec.rb

@@ -70,7 +70,7 @@ def counts
       [@agent.memory, counts]
     }
 
-    expect(results[:log]).to match(/\AE, .+ ERROR -- : Exception during dry-run. SandboxedAgent does not support dry-run: /)
+    expect(results[:log]).to match(/\A\[\d\d:\d\d:\d\d\] INFO -- : Dry Run failed\n\[\d\d:\d\d:\d\d\] ERROR -- : Exception during dry-run. SandboxedAgent does not support dry-run: /)
     expect(results[:events]).to eq([])
     expect(results[:memory]).to eq({})
   end
@@ -86,7 +86,7 @@ def counts
         [@agent.memory, counts]
       }
 
-      expect(results[:log]).to match(/\AI, .+ INFO -- : Logging\nE, .+ ERROR -- : Recording error\n/)
+      expect(results[:log]).to match(/\A\[\d\d:\d\d:\d\d\] INFO -- : Dry Run started\n\[\d\d:\d\d:\d\d\] INFO -- : Logging\n\[\d\d:\d\d:\d\d\] ERROR -- : Recording error\n/)
       expect(results[:events]).to eq([{ 'test' => 'foo' }, { 'test' => 'bar' }])
       expect(results[:memory]).to eq({ 'last_status' => 'ok', 'dry_run' => true })
     end
@@ -101,7 +101,7 @@ def counts
         [@agent.memory, counts]
       }
 
-      expect(results[:log]).to match(/\AI, .+ INFO -- : Logging\nE, .+ ERROR -- : Recording error\n/)
+      expect(results[:log]).to match(/\A\[\d\d:\d\d:\d\d\] INFO -- : Dry Run started\n\[\d\d:\d\d:\d\d\] INFO -- : Logging\n\[\d\d:\d\d:\d\d\] ERROR -- : Recording error\n/)
       expect(results[:events]).to eq([{ 'test' => 'superfoo' }, { 'test' => 'superbar' }])
       expect(results[:memory]).to eq({ 'last_status' => 'ok', 'dry_run' => true })
     end

spec/controllers/agents_controller_spec.rb

@@ -406,7 +406,7 @@ def valid_attributes(options = {})
         [users(:bob).agents.count, users(:bob).events.count, users(:bob).logs.count, agent.name, agent.updated_at]
       }
       json = JSON.parse(response.body)
-      expect(json['log']).to match(/^I, .* : Fetching #{Regexp.quote(url_from_event)}$/)
+      expect(json['log']).to match(/^\[\d\d:\d\d:\d\d\] INFO -- : Fetching #{Regexp.quote(url_from_event)}$/)
     end
   end