chore(logging): Use bunyan for logging and add debug logs in checks. (mergeability#155)

* chore(logging): Use bunyan for logging and add debug logs in checks.

* test(logging): update tests to reflect changes to using log.child

Author: jusx

__fixtures__/helper.js

@@ -7,13 +7,14 @@ const throwNotFound = () => {
 }
 
 module.exports = {
-  mockContext: (options) => {
-    if (!options) options = {}
-
+  mockContext: (options = {}) => {
     return {
       repo: (properties) => { return Object.assign({ owner: 'owner', repo: 'repo' }, properties) },
       event: (options.event) ? options.event : 'pull_request',
       payload: {
+        repository: {
+          full_name: 'name'
+        },
         pull_request: {
           user: {
             login: 'creator'
@@ -36,9 +37,13 @@ module.exports = {
         }
       },
       log: {
-        debug: (s) => console.log(`TEST[debug] > ${JSON.stringify(s)}`),
-        info: (s) => console.log(`TEST[info] > ${JSON.stringify(s)}`),
-        warn: (s) => console.log(`TEST[warn] > ${JSON.stringify(s)}`)
+        child: (s) => {
+          return {
+            debug: (s) => console.log(`TEST[debug] > ${JSON.stringify(s)}`),
+            info: (s) => console.log(`TEST[info] > ${JSON.stringify(s)}`),
+            warn: (s) => console.log(`TEST[warn] > ${JSON.stringify(s)}`)
+          }
+        }
       },
       github: {
         repos: {

__tests__/mergeable.test.js

@@ -43,7 +43,11 @@ const startMergeable = (mode, version) => {
 const mockRobot = {
   on: jest.fn(),
   log: {
-    warn: jest.fn(),
-    info: jest.fn()
+    child: () => {
+      return {
+        debug: jest.fn(),
+        info: jest.fn()
+      }
+    }
   }
 }

lib/actions/checks.js

@@ -22,9 +22,11 @@ const createChecks = async (context, name, status, output) => {
   }
   status = !status ? 'in_progress' : status
 
-  return context.github.checks.create(
-    createParams({context, headBranch, headSha, name, status, output})
-  )
+  let log = context.log.child({name: 'mergeable'})
+  let params = createParams({context, headBranch, headSha, name, status, output})
+  log.debug(`Creating Check for ${context.payload.repository.full_name} - status=${status}`)
+  log.debug(params)
+  return context.github.checks.create(params)
 }
 
 const updateChecks = async (context, id, name, status, conclusion, output) => {
@@ -36,12 +38,13 @@ const updateChecks = async (context, id, name, status, conclusion, output) => {
   }
 
   status = !status ? 'completed' : status
-
   conclusion = !conclusion ? 'success' : conclusion
 
-  await context.github.checks.update(
-    updateParams({context, name, status, output, id, conclusion})
-  )
+  let log = context.log.child({name: 'mergeable'})
+  let params = updateParams({context, name, status, output, id, conclusion})
+  log.debug(`Updating Check for ${context.payload.repository.full_name} - status=${status}`)
+  log.debug(params)
+  await context.github.checks.update(params)
 }
 
 const createParams = ({context, headBranch, headSha, name, status, output}) => {

lib/mergeable.js

@@ -12,21 +12,23 @@ class Mergeable {
   }
 
   start (robot) {
+    let log = robot.log.child({name: 'mergeable'})
+    let intervalSecs = 2
     if (this.mode === 'development') {
-      robot.log.info('In DEVELOPMENT mode.')
-      robot.log.info('Starting scheduler at 2 second intervals.')
-      this.schedule(robot, { interval: 60 * 60 * 2 })
+      log.info('In DEVELOPMENT mode.')
     } else {
-      robot.log.info('In PRODUCTION mode.')
-      if (process.env.MERGEABLE_SCHEDULER === 'true') {
-        robot.log.info('Starting scheduler at 1 hour intervals')
-        this.schedule(robot, { interval: 60 * 60 * 1000 })
-      } else {
-        robot.log.info(`Scheduler: ${'off'.bold.white}!`)
-      }
+      log.info('In PRODUCTION mode.')
+      intervalSecs = 1000
+    }
+
+    if (process.env.MERGEABLE_SCHEDULER === 'true') {
+      log.info('Starting scheduler at 2 second intervals.')
+      this.schedule(robot, { interval: 60 * 60 * intervalSecs })
+    } else {
+      log.info(`Scheduler: ${'off'.bold.white}!`)
     }
 
-    robot.log.info(`Version: ${this.version.bold.white}`)
+    log.info(`Version: ${this.version.bold.white}`)
 
     if (this.version === 'flex') {
       this.flex(robot)
@@ -42,15 +44,16 @@ class Mergeable {
   // version 2 of mergeable WIP as we refactor the code base.
   flex (robot) {
     robot.on('*', async context => {
+      let log = context.log.child({name: 'mergeable'})
       if (_.isUndefined(context.payload.repository)) {
-        context.log.warn('Unable to log repository name. There is no repository in the payload:')
-        context.log.warn(context.payload)
+        log.warn('Unable to log repository name. There is no repository in the payload:')
+        log.warn(context.payload)
       } else {
-        context.log.info({Repo: context.payload.repository.full_name,
+        log.info({Repo: context.payload.repository.full_name,
           url: context.payload.repository.html_url,
           private: context.payload.repository.private})
       }
-      context.log.info({event: context.event, action: context.payload.action})
+      log.info({event: context.event, action: context.payload.action})
       flexExecutor(context)
     })
   }