ZMS-19: Improve gelf error logging

acme.js

@@ -7,6 +7,7 @@ const logger = require('restify-logger');
 const db = require('./lib/db');
 const Gelf = require('gelf');
 const os = require('os');
+const { normalizeLoggelfMessage } = require('./lib/loggelf-message');
 
 const acmeRoutes = require('./lib/api/acme');
 
@@ -78,6 +79,7 @@ module.exports = done => {
             };
         }
         message = message || {};
+        normalizeLoggelfMessage(message);
 
         if (!message.short_message || message.short_message.indexOf(component.toUpperCase()) !== 0) {
             message.short_message = component.toUpperCase() + ' ' + (message.short_message || '');

api.js

@@ -24,6 +24,7 @@ const tls = require('tls');
 const Lock = require('ioredfour');
 const Path = require('path');
 const errors = require('restify-errors');
+const { normalizeLoggelfMessage } = require('./lib/loggelf-message');
 
 const acmeRoutes = require('./lib/api/acme');
 const usersRoutes = require('./lib/api/users');
@@ -492,6 +493,7 @@ module.exports = done => {
             };
         }
         message = message || {};
+        normalizeLoggelfMessage(message);
 
         if (!message.short_message || message.short_message.indexOf(component.toUpperCase()) !== 0) {
             message.short_message = component.toUpperCase() + ' ' + (message.short_message || '');

imap.js

@@ -16,6 +16,7 @@ const certs = require('./lib/certs');
 const Gelf = require('gelf');
 const os = require('os');
 const Lock = require('ioredfour');
+const { normalizeLoggelfMessage } = require('./lib/loggelf-message');
 
 const onFetch = require('./lib/handlers/on-fetch');
 const onAuth = require('./lib/handlers/on-auth');
@@ -217,6 +218,7 @@ module.exports = done => {
         }
 
         message = message || {};
+        normalizeLoggelfMessage(message);
 
         if (!message.short_message || message.short_message.indexOf(component.toUpperCase()) !== 0) {
             message.short_message = component.toUpperCase() + ' ' + (message.short_message || '');

indexer.js

@@ -13,6 +13,7 @@ const { ObjectId } = require('mongodb');
 const libmime = require('libmime');
 const punycode = require('punycode.js');
 const { getClient } = require('./lib/elasticsearch');
+const { normalizeLoggelfMessage } = require('./lib/loggelf-message');
 
 let loggelf;
 let processlock;
@@ -589,6 +590,7 @@ module.exports.start = callback => {
         }
 
         message = message || {};
+        normalizeLoggelfMessage(message);
 
         if (!message.short_message || message.short_message.indexOf(component.toUpperCase()) !== 0) {
             message.short_message = component.toUpperCase() + ' ' + (message.short_message || '');

lib/errors.js

@@ -6,6 +6,7 @@ const log = require('npmlog');
 const Gelf = require('gelf');
 const os = require('os');
 const util = require('util');
+const { normalizeLoggelfMessage } = require('./loggelf-message');
 
 let loggelf;
 let component;
@@ -66,6 +67,7 @@ loggelf = (...args) => {
     message.host = hostname;
     message.timestamp = Date.now() / 1000;
     message._component = component;
+    normalizeLoggelfMessage(message);
 
     Object.keys(message).forEach(key => {
         if (!message[key]) {

lib/filter-handler.js

@@ -570,7 +570,7 @@ class FilterHandler {
             log.error('Filter', '%s AUTOREPLYFAIL from=%s to=%s error=%s', prepared.id.toString(), '<>', sender, err.message);
             this.loggelf({
                 short_message: '[AUTOREPLYFAIL] Failed to queue autoreply',
-                full_message: err && err.stack,
+                _stack: err && err.stack,
                 _queue_id: prepared.id && prepared.id.toString(),
                 _error: err && err.message,
                 _code: err && err.code,

lib/handlers/on-search.js

@@ -366,7 +366,7 @@ module.exports = server => (mailbox, options, session, callback) => {
                         if (typeof server.loggelf === 'function') {
                             server.loggelf({
                                 short_message: '[SEARCHFAIL] ' + (err && err.message ? err.message : 'Search failed'),
-                                full_message: err && err.stack,
+                                _stack: err && err.stack,
                                 _error: err && err.message,
                                 _code: err && err.code,
                                 _tnx: 'search',

lib/loggelf-message.js

@@ -0,0 +1,20 @@
+'use strict';
+
+const hasValue = value => (typeof value === 'string' ? value.trim().length > 0 : !!value);
+
+module.exports.normalizeLoggelfMessage = message => {
+    if (!message || typeof message !== 'object') {
+        return;
+    }
+
+    // Critical errors are represented by full_message + _error.
+    // For all non-critical errors, move _error to _failure_msg.
+    if (hasValue(message._error) && !hasValue(message.full_message)) {
+        if (!hasValue(message._failure_msg)) {
+            message._failure_msg = message._error;
+        }
+        delete message._error;
+    }
+
+    return;
+};

lib/user-handler.js

@@ -490,7 +490,7 @@ class UserHandler {
             err.code = 'InternalDatabaseError';
             this.loggelf({
                 short_message: '[AUTHFAIL] ' + username,
-                full_message: err.stack,
+                _stack: err.stack,
                 _error: err.message,
                 _code: err.code,
                 _auth_result: 'error',
@@ -564,7 +564,7 @@ class UserHandler {
             err.code = 'InternalDatabaseError';
             this.loggelf({
                 short_message: '[AUTHFAIL] ' + username,
-                full_message: err.stack,
+                _stack: err.stack,
                 _error: err.message,
                 _code: err.code,
                 _auth_result: 'error',
@@ -590,7 +590,7 @@ class UserHandler {
                 err.code = 'InternalDatabaseError';
                 this.loggelf({
                     short_message: '[AUTHFAIL] ' + username,
-                    full_message: err.stack,
+                    _stack: err.stack,
                     _error: err.message,
                     _code: err.code,
                     _auth_result: 'error',
@@ -644,7 +644,7 @@ class UserHandler {
             err.user = userData._id;
             this.loggelf({
                 short_message: '[AUTHFAIL] ' + username,
-                full_message: err.stack,
+                _stack: err.stack,
                 _error: err.message,
                 _code: err.code,
                 _auth_result: 'error',
@@ -1141,7 +1141,7 @@ class UserHandler {
         } catch (err) {
             this.loggelf({
                 short_message: '[AUTHFAIL] ' + username,
-                full_message: err.stack,
+                _stack: err.stack,
                 _error: err.message || 'Authentication failed',
                 _code: err.code,
                 _auth_result: 'fail',

lmtp.js

@@ -14,6 +14,7 @@ const db = require('./lib/db');
 const certs = require('./lib/certs');
 const Gelf = require('gelf');
 const os = require('os');
+const { normalizeLoggelfMessage } = require('./lib/loggelf-message');
 
 let messageHandler;
 let userHandler;
@@ -217,6 +218,7 @@ module.exports = done => {
             };
         }
         message = message || {};
+        normalizeLoggelfMessage(message);
 
         if (!message.short_message || message.short_message.indexOf(component.toUpperCase()) !== 0) {
             message.short_message = component.toUpperCase() + ' ' + (message.short_message || '');

pop3.js

@@ -13,6 +13,7 @@ const LimitedFetch = require('./lib/limited-fetch');
 const tools = require('./lib/tools');
 const Gelf = require('gelf');
 const os = require('os');
+const { normalizeLoggelfMessage } = require('./lib/loggelf-message');
 
 const MAX_MESSAGES = 250;
 
@@ -466,6 +467,7 @@ module.exports = done => {
             };
         }
         message = message || {};
+        normalizeLoggelfMessage(message);
 
         if (!message.short_message || message.short_message.indexOf(component.toUpperCase()) !== 0) {
             message.short_message = component.toUpperCase() + ' ' + (message.short_message || '');

tasks.js

@@ -30,6 +30,7 @@ const taskClearFolder = require('./lib/tasks/clear-folder');
 const taskSearchApply = require('./lib/tasks/search-apply');
 const taskUserIndexing = require('./lib/tasks/user-indexing');
 const taskRunMigrations = require('./lib/tasks/run-migrations');
+const { normalizeLoggelfMessage } = require('./lib/loggelf-message');
 
 let messageHandler;
 let mailboxHandler;
@@ -65,6 +66,7 @@ module.exports.start = callback => {
         }
 
         message = message || {};
+        normalizeLoggelfMessage(message);
 
         if (!message.short_message || message.short_message.indexOf(component.toUpperCase()) !== 0) {
             message.short_message = component.toUpperCase() + ' ' + (message.short_message || '');

webhooks.js

@@ -11,6 +11,7 @@ const { ObjectId } = require('mongodb');
 const axios = require('axios');
 const packageData = require('./package.json');
 const { MARKED_SPAM, MARKED_HAM } = require('./lib/events');
+const { normalizeLoggelfMessage } = require('./lib/loggelf-message');
 
 let loggelf;
 let queueWorkers = {};
@@ -97,6 +98,7 @@ module.exports.start = callback => {
         }
 
         message = message || {};
+        normalizeLoggelfMessage(message);
 
         if (!message.short_message || message.short_message.indexOf(component.toUpperCase()) !== 0) {
             message.short_message = component.toUpperCase() + ' ' + (message.short_message || '');