fix(logging): Log templates that don't have flow event data (#1618), r=@philbooth

lib/bounces.js

@@ -128,6 +128,8 @@ module.exports = function (log, error) {
           }
 
           log.flowEvent(flowEventInfo)
+        } else {
+          log.error({ op: 'handleBounce.flowEvent', templateName, flowId, flowBeginTime, currentTime })
         }
 
         log.info(logData)

test/local/bounce_tests.js

@@ -67,12 +67,12 @@ describe('bounce messages', () => {
         assert.equal(mockDB.deleteAccount.callCount, 2)
         assert.equal(mockDB.emailRecord.args[0][0], 'test@example.com')
         assert.equal(mockDB.emailRecord.args[1][0], 'foobar@example.com')
-        assert.equal(mockLog.messages.length, 6, 'messages logged')
-        assert.equal(mockLog.messages[1].level, 'increment')
-        assert.equal(mockLog.messages[1].args[0], 'account.email_bounced')
-        assert.equal(mockLog.messages[5].level, 'info')
-        assert.equal(mockLog.messages[5].args[0].op, 'accountDeleted')
-        assert.equal(mockLog.messages[5].args[0].email, 'foobar@example.com')
+        assert.equal(mockLog.messages.length, 8, 'messages logged')
+        assert.equal(mockLog.messages[2].level, 'increment')
+        assert.equal(mockLog.messages[2].args[0], 'account.email_bounced')
+        assert.equal(mockLog.messages[7].level, 'info')
+        assert.equal(mockLog.messages[7].args[0].op, 'accountDeleted')
+        assert.equal(mockLog.messages[7].args[0].email, 'foobar@example.com')
         assert.equal(mockMsg.del.callCount, 1)
       })
     }
@@ -107,7 +107,7 @@ describe('bounce messages', () => {
         assert.equal(mockDB.deleteAccount.callCount, 2)
         assert.equal(mockDB.emailRecord.args[0][0], 'test@example.com')
         assert.equal(mockDB.emailRecord.args[1][0], 'foobar@example.com')
-        assert.equal(mockLog.messages.length, 6)
+        assert.equal(mockLog.messages.length, 8)
       })
     }
   )
@@ -143,22 +143,22 @@ describe('bounce messages', () => {
         assert.equal(mockDB.emailRecord.args[1][0], 'verified@example.com')
         assert.equal(mockDB.deleteAccount.callCount, 1)
         assert.equal(mockDB.deleteAccount.args[0][0].email, 'test@example.com')
-        assert.equal(mockLog.messages.length, 6)
-        assert.equal(mockLog.messages[0].args[0].op, 'handleBounce')
-        assert.equal(mockLog.messages[0].args[0].email, 'test@example.com')
-        assert.equal(mockLog.messages[0].args[0].status, '5.0.0')
-        assert.equal(mockLog.messages[0].args[0].action, 'failed')
-        assert.equal(mockLog.messages[0].args[0].diagnosticCode, 'smtp; 550 user unknown')
-        assert.equal(mockLog.messages[1].args[0], 'account.email_bounced')
-        assert.equal(mockLog.messages[2].args[0].op, 'accountDeleted')
-        assert.equal(mockLog.messages[2].args[0].email, 'test@example.com')
-        assert.equal(mockLog.messages[3].args[0].op, 'handleBounce')
-        assert.equal(mockLog.messages[3].args[0].email, 'verified@example.com')
-        assert.equal(mockLog.messages[3].args[0].status, '4.0.0')
+        assert.equal(mockLog.messages.length, 8)
+        assert.equal(mockLog.messages[1].args[0].op, 'handleBounce')
+        assert.equal(mockLog.messages[1].args[0].email, 'test@example.com')
+        assert.equal(mockLog.messages[1].args[0].status, '5.0.0')
+        assert.equal(mockLog.messages[1].args[0].action, 'failed')
+        assert.equal(mockLog.messages[1].args[0].diagnosticCode, 'smtp; 550 user unknown')
+        assert.equal(mockLog.messages[2].args[0], 'account.email_bounced')
+        assert.equal(mockLog.messages[3].args[0].op, 'accountDeleted')
+        assert.equal(mockLog.messages[3].args[0].email, 'test@example.com')
+        assert.equal(mockLog.messages[5].args[0].op, 'handleBounce')
+        assert.equal(mockLog.messages[5].args[0].email, 'verified@example.com')
+        assert.equal(mockLog.messages[5].args[0].status, '4.0.0')
         assert(!mockLog.messages[3].args[0].diagnosticCode)
-        assert.equal(mockLog.messages[4].args[0], 'account.email_bounced')
-        assert.equal(mockLog.messages[5].level, 'increment')
-        assert.equal(mockLog.messages[5].args[0], 'account.email_bounced.already_verified')
+        assert.equal(mockLog.messages[6].args[0], 'account.email_bounced')
+        assert.equal(mockLog.messages[7].level, 'increment')
+        assert.equal(mockLog.messages[7].args[0], 'account.email_bounced.already_verified')
       })
     }
   )
@@ -183,12 +183,12 @@ describe('bounce messages', () => {
       return mockedBounces(mockLog, mockDB).handleBounce(mockMsg).then(function () {
         assert.equal(mockDB.emailRecord.callCount, 1)
         assert.equal(mockDB.emailRecord.args[0][0], 'test@example.com')
-        assert.equal(mockLog.messages.length, 3)
-        assert.equal(mockLog.messages[0].args[0].op, 'handleBounce')
-        assert.equal(mockLog.messages[0].args[0].email, 'test@example.com')
-        assert.equal(mockLog.messages[1].args[0], 'account.email_bounced')
-        assert.equal(mockLog.messages[2].args[0].op, 'databaseError')
-        assert.equal(mockLog.messages[2].args[0].email, 'test@example.com')
+        assert.equal(mockLog.messages.length, 4)
+        assert.equal(mockLog.messages[1].args[0].op, 'handleBounce')
+        assert.equal(mockLog.messages[1].args[0].email, 'test@example.com')
+        assert.equal(mockLog.messages[2].args[0], 'account.email_bounced')
+        assert.equal(mockLog.messages[3].args[0].op, 'databaseError')
+        assert.equal(mockLog.messages[3].args[0].email, 'test@example.com')
         assert.equal(mockMsg.del.callCount, 1)
       })
     }
@@ -223,13 +223,13 @@ describe('bounce messages', () => {
         assert.equal(mockDB.emailRecord.args[0][0], 'test@example.com')
         assert.equal(mockDB.deleteAccount.callCount, 1)
         assert.equal(mockDB.deleteAccount.args[0][0].email, 'test@example.com')
-        assert.equal(mockLog.messages.length, 3)
-        assert.equal(mockLog.messages[0].args[0].op, 'handleBounce')
-        assert.equal(mockLog.messages[0].args[0].email, 'test@example.com')
-        assert.equal(mockLog.messages[1].args[0], 'account.email_bounced')
-        assert.equal(mockLog.messages[2].args[0].op, 'databaseError')
-        assert.equal(mockLog.messages[2].args[0].email, 'test@example.com')
-        assert.equal(mockLog.messages[2].args[0].err.errno, error.ERRNO.ACCOUNT_UNKNOWN)
+        assert.equal(mockLog.messages.length, 4)
+        assert.equal(mockLog.messages[1].args[0].op, 'handleBounce')
+        assert.equal(mockLog.messages[1].args[0].email, 'test@example.com')
+        assert.equal(mockLog.messages[2].args[0], 'account.email_bounced')
+        assert.equal(mockLog.messages[3].args[0].op, 'databaseError')
+        assert.equal(mockLog.messages[3].args[0].email, 'test@example.com')
+        assert.equal(mockLog.messages[3].args[0].err.errno, error.ERRNO.ACCOUNT_UNKNOWN)
         assert.equal(mockMsg.del.callCount, 1)
       })
     }
@@ -313,13 +313,13 @@ describe('bounce messages', () => {
         assert.equal(mockDB.emailRecord.args[0][0], 'test@example.com')
         assert.equal(mockDB.deleteAccount.callCount, 1)
         assert.equal(mockDB.deleteAccount.args[0][0].email, 'test@example.com')
-        assert.equal(mockLog.messages.length, 3)
-        assert.equal(mockLog.messages[0].args[0].op, 'handleBounce')
-        assert.equal(mockLog.messages[0].args[0].email, 'test@example.com')
-        assert.equal(mockLog.messages[0].args[0].template, 'verifyLoginEmail')
-        assert.equal(mockLog.messages[0].args[0].bounceType, 'Permanent')
-        assert.equal(mockLog.messages[0].args[0].bounceSubType, 'General')
-        assert.equal(mockLog.messages[1].args[0], 'account.email_bounced')
+        assert.equal(mockLog.messages.length, 4)
+        assert.equal(mockLog.messages[1].args[0].op, 'handleBounce')
+        assert.equal(mockLog.messages[1].args[0].email, 'test@example.com')
+        assert.equal(mockLog.messages[1].args[0].template, 'verifyLoginEmail')
+        assert.equal(mockLog.messages[1].args[0].bounceType, 'Permanent')
+        assert.equal(mockLog.messages[1].args[0].bounceSubType, 'General')
+        assert.equal(mockLog.messages[2].args[0], 'account.email_bounced')
       })
     }
   )
@@ -360,7 +360,7 @@ describe('bounce messages', () => {
             },
             {
               name: 'X-Flow-Begin-Time',
-              value: 1234
+              value: '1234'
             }
           ]
         }