Total job process time logged is not correct

[davidor]

For each processed job, the workers log some information like the process time, the total time (process time + time in the queue), etc.

The second is not correct. The reason is that the enqueue time is stored in Redis by a listener when it enqueues a job:

apisonator/lib/3scale/backend/transactor.rb

Line 204 in 18edf5c

Resque.enqueue(ReportJob, service_id, data, Time.now.getutc.to_f, context_info)

Whereas the total time is calculated by the worker when it finished processing a job:

apisonator/lib/3scale/backend/background_job.rb

Line 43 in 18edf5c

" #{(end_time.to_f - enqueue_time).round(5)}"+

That's the reason why sometimes we get inconsistent numbers in the logs. For example, sometimes we see that the process time is greater than the process time plus the time in the queue. In many deployments, those two timestamps always come from different machines (listeners vs background workers) so comparing them is not reliable.