Job Logging

Description

To help with tracking job changes and job process debugging, rethinkdb-job-queue logs major state changes against jobs in the queue database. These log entries are either automatically added or can be manually added.

There is a default limit applied to the log entries restricting the number of entries to 1000. See the Queue option limitJobLogs for more detail.

Automatic Logging

The following is a list of job events that will cause rethinkdb-job-queue to add a log entry against a job:

• Job added to the queue.
• Job retrieved for processing.
• Job failed processing.
• Job cancelled by user.
• Job completed processing.

In the above list only cancelled and failed jobs give the user some control over the information that is added to the log entry.

When you call next(error) in your Queue.process handler function the error details will be logged. Specifically the Error object will be serialized to the log.data property. Also the error.message and error.stack properties will be logged to the log.errorMessage and log.errorStack respectively.

If you cancel a job calling next(error) and populate the error.cancelJob property, the value you assign to error.cancelJob will be logged under log.message.

See the Queue.process document for more detail.

Manual Logging

If you wish to you may add a log entry against a job by using Job.addLog.

Job with Log Entries

For an example of what a job looks like with log history, here is a job created during the Queue.process integration tests:

{
  "dateCreated": Mon Nov 21 2016 00:42:22 GMT+00:00 ,
  "dateEnable": Mon Nov 21 2016 00:42:33 GMT+00:00 ,
  "dateFinished": Mon Nov 21 2016 00:42:29 GMT+00:00 ,
  "dateStarted": Mon Nov 21 2016 00:42:28 GMT+00:00 ,
  "id":  "31221159-e74f-408e-88cf-418b1e02e863" ,
  "log": [
    {
      "data": null ,
      "date": Mon Nov 21 2016 00:42:22 GMT+00:00 ,
      "message":  "Job added to the queue" ,
      "processCount": 0 ,
      "queueId":  "WebDev:rjqJobQueueTests:rjqJobQueueTestJobs:1484:8c45eaee-156f-47f7-8a85-7ae9e0ac4e8e" ,
      "retryCount": 0 ,
      "status":  "waiting" ,
      "type":  "information"
    } ,
    {
      "date": Mon Nov 21 2016 00:42:23 GMT+00:00 ,
      "message":  "Job retrieved and active" ,
      "processCount": 0 ,
      "queueId":  "WebDev:rjqJobQueueTests:rjqJobQueueTestJobs:1484:8c45eaee-156f-47f7-8a85-7ae9e0ac4e8e" ,
      "retryCount": 0 ,
      "status":  "active" ,
      "type":  "information"
    } ,
    {
      "data": {
        "message":  "Job timed out (run time > 1000 ms)" ,
        "name":  "Error" ,
        "stack":  "Error: Job timed out (run time > 1000 ms)
            at Timeout.timeoutHandler (/home/grant/node-rethinkdb-job-queue/src/queue-process.js:112:17)
            at ontimeout (timers.js:365:14)
            at tryOnTimeout (timers.js:237:5)
            at Timer.listOnTimeout (timers.js:207:5)"
      } ,
      "date": Mon Nov 21 2016 00:42:24 GMT+00:00 ,
      "duration": 1033 ,
      "errorMessage":  "Job timed out (run time > 1000 ms)" ,
      "errorStack":  "Error: Job timed out (run time > 1000 ms)
          at Timeout.timeoutHandler (/home/grant/node-rethinkdb-job-queue/src/queue-process.js:112:17)
          at ontimeout (timers.js:365:14)
          at tryOnTimeout (timers.js:237:5)
          at Timer.listOnTimeout (timers.js:207:5)" ,
      "message":  "Job processing failed" ,
      "processCount": 1 ,
      "queueId":  "WebDev:rjqJobQueueTests:rjqJobQueueTestJobs:1484:8c45eaee-156f-47f7-8a85-7ae9e0ac4e8e" ,
      "retryCount": 1 ,
      "status":  "failed" ,
      "type":  "warning"
    } ,
    {
      "date": Mon Nov 21 2016 00:42:24 GMT+00:00 ,
      "message":  "Job retrieved and active" ,
      "processCount": 1 ,
      "queueId":  "WebDev:rjqJobQueueTests:rjqJobQueueTestJobs:1484:8c45eaee-156f-47f7-8a85-7ae9e0ac4e8e" ,
      "retryCount": 1 ,
      "status":  "active" ,
      "type":  "information"
    } ,
    {
      "data": {
        "message":  "Job timed out (run time > 1000 ms)" ,
        "name":  "Error" ,
        "stack":  "Error: Job timed out (run time > 1000 ms)
            at Timeout.timeoutHandler (/home/grant/node-rethinkdb-job-queue/src/queue-process.js:112:17)
            at ontimeout (timers.js:365:14)
            at tryOnTimeout (timers.js:237:5)
            at Timer.listOnTimeout (timers.js:207:5)"
      } ,
      "date": Mon Nov 21 2016 00:42:25 GMT+00:00 ,
      "duration": 1034 ,
      "errorMessage":  "Job timed out (run time > 1000 ms)" ,
      "errorStack":  "Error: Job timed out (run time > 1000 ms)
          at Timeout.timeoutHandler (/home/grant/node-rethinkdb-job-queue/src/queue-process.js:112:17)
          at ontimeout (timers.js:365:14)
          at tryOnTimeout (timers.js:237:5)
          at Timer.listOnTimeout (timers.js:207:5)" ,
      "message":  "Job processing failed" ,
      "processCount": 2 ,
      "queueId":  "WebDev:rjqJobQueueTests:rjqJobQueueTestJobs:1484:8c45eaee-156f-47f7-8a85-7ae9e0ac4e8e" ,
      "retryCount": 2 ,
      "status":  "failed" ,
      "type":  "warning"
    } ,
    {
      "date": Mon Nov 21 2016 00:42:28 GMT+00:00 ,
      "message":  "Job retrieved and active" ,
      "processCount": 2 ,
      "queueId":  "WebDev:rjqJobQueueTests:rjqJobQueueTestJobs:1484:8c45eaee-156f-47f7-8a85-7ae9e0ac4e8e" ,
      "retryCount": 2 ,
      "status":  "active" ,
      "type":  "information"
    } ,
    {
      "data": {
        "message":  "Job timed out (run time > 1000 ms)" ,
        "name":  "Error" ,
        "stack":  "Error: Job timed out (run time > 1000 ms)
            at Timeout.timeoutHandler (/home/grant/node-rethinkdb-job-queue/src/queue-process.js:112:17)
            at ontimeout (timers.js:365:14)
            at tryOnTimeout (timers.js:237:5)
            at Timer.listOnTimeout (timers.js:207:5)"
      } ,
      "date": Mon Nov 21 2016 00:42:29 GMT+00:00 ,
      "duration": 1034 ,
      "errorMessage":  "Job timed out (run time > 1000 ms)" ,
      "errorStack":  "Error: Job timed out (run time > 1000 ms)
          at Timeout.timeoutHandler (/home/grant/node-rethinkdb-job-queue/src/queue-process.js:112:17)
          at ontimeout (timers.js:365:14)
          at tryOnTimeout (timers.js:237:5)
          at Timer.listOnTimeout (timers.js:207:5)" ,
      "message":  "Job processing failed" ,
      "processCount": 3 ,
      "queueId":  "WebDev:rjqJobQueueTests:rjqJobQueueTestJobs:1484:8c45eaee-156f-47f7-8a85-7ae9e0ac4e8e" ,
      "retryCount": 3 ,
      "status":  "failed" ,
      "type":  "warning"
    }
  ] ,
  "priority": 40 ,
  "processCount": 3 ,
  "progress": 0 ,
  "queueId":  "WebDev:rjqJobQueueTests:rjqJobQueueTestJobs:1484:8c45eaee-156f-47f7-8a85-7ae9e0ac4e8e" ,
  "repeat": false ,
  "repeatDelay": 300000 ,
  "retryCount": 3 ,
  "retryDelay": 2000 ,
  "retryMax": 3 ,
  "status":  "failed" ,
  "timeout": 1000
}