feat: prefix job logs with job identification

packages/djorm-cloud-jobs/models.js

@@ -1,3 +1,5 @@
+const logger = require('djorm/logger')
+
 const { publishMessage, resolveTopic } = require('./pubsub')
 const { getSettings } = require('djorm/config')
 const { RetryError, SpawnError } = require('./errors')
@@ -421,14 +423,28 @@ class JobBase extends DatabaseModel {
       return await this.spawn()
     }
     const err = new RetryError(
-      `${getModelName(this.constructor)}#${
-        this.pk
-      } has reached it's retry limit because it failed on: ${e.message}`,
+      `${this.ident} has reached it's retry limit because it failed on: ${e.message}`,
       [e]
     )
     err.stack = e.stack
     throw err
   }
+
+  get ident () {
+    return `${getModelName(this.constructor)}#${this.pk || this.type}`
+  }
+
+  get logger () {
+    if (!this.constructor.loggerInstance) {
+      this.constructor.loggerInstance = logger.child(
+        {},
+        {
+          msgPrefix: `[${this.ident}] `
+        }
+      )
+    }
+    return this.constructor.loggerInstance
+  }
 }
 
 /** Convenience class for people in hurry. Implements JobBase.

packages/djorm-cloud-jobs/runTask.js

@@ -1,6 +1,5 @@
 const { JobStatus, JobStatusHandler } = require('./models')
 const { RuntimeError, formatError } = require('./errors')
-const { debug, warn } = require('djorm/logger')
 const { getSettings } = require('djorm/config')
 
 const resolveHandler = (handlers, job, stage) => {
@@ -26,7 +25,7 @@ const closeupParent = async (job, stage) => {
         stats.stopped === 0 &&
         stats.waiting === 0
       ) {
-        debug(`Calling ${parent.id} a ${stage}`)
+        job.logger.debug(`status = ${stage}`)
         parent.status = stage
         await parent.save()
         await parent.spawn()
@@ -47,7 +46,7 @@ const closeupParent = async (job, stage) => {
  * @returns {Object}
  */
 async function runStage (handlers, job, stage, ...args) {
-  debug(`Running Job#${job.id}:${stage}`)
+  job.logger.debug(`run stage ${stage}`)
   const handler = resolveHandler(handlers, job, stage)
   const store = getSettings('cloudJobs.store', true)
   let outputs = null
@@ -116,7 +115,7 @@ async function runTask (handlers, job) {
         await runStage(handlers, job, status)
       }
     } catch (e) {
-      warn(`Caught error: ${formatError(e)}`)
+      job.logger.warn(`Caught error: ${formatError(e)}`)
       await runStage(handlers, job, JobStatus.failure, e)
       // This job will be recycled instead of fulfilling (rerun request stage)
       await job.retry(e)

packages/djorm-cloud-jobs/subscriptions.js

@@ -1,4 +1,4 @@
-const { error, info } = require('djorm/logger')
+const { warn } = require('djorm/logger')
 const { getModel } = require('djorm/models')
 const { getSettings, init, isUp, shutdown } = require('djorm/config')
 const { parseMessage } = require('./pubsub')
@@ -25,10 +25,10 @@ function createProcessWrapper (fn) {
       if (process.env.NODE_ENV === 'test') {
         throw processError
       } else {
-        error(processError)
+        job.logger.error(processError)
         if (processError.errors) {
           for (const e of processError.errors) {
-            error(e)
+            job.logger.error(e)
           }
         }
         if (getSettings('cloudJobs.exitOnFailure')) {
@@ -132,7 +132,7 @@ const createSubscription = ({ filename, tasks, topic }) => {
       const handlers = resolveJobHandlers(tasks, job.type)
       await runTask(handlers, job, topic)
     } else {
-      info(`No job resolved for message ${message}`)
+      warn(`No job resolved for message ${message}`)
     }
   }
 

packages/djorm/logger.js

@@ -1,6 +1,9 @@
 const noop = () => {}
 
 const defaultLogger = {
+  child () {
+    return this
+  },
   debug: noop,
   error: console.error,
   fatal: console.fatal,
@@ -24,6 +27,7 @@ const getLogger = () => logger
 const proxy = method => (...args) => getLogger()[method](...args)
 
 module.exports = {
+  child: proxy('child'),
   debug: proxy('debug'),
   error: proxy('error'),
   fatal: proxy('fatal'),