Handle messageAs and legacy log calls

modules/@apostrophecms/util/index.js

@@ -541,11 +541,12 @@ module.exports = {
       // If the logger has no `log` method, the `info` method
       // is used. This allows an instance of `bole` or similar
       // to be used directly.
-      log(msg) {
+      log(...args) {
+        // kept for bc
         if (!self.logger.log) {
-          return self.logger.info.apply(self.logger.info, arguments);
+          return self.logger.info(...self.convertLegacyLogPayload(args));
         }
-        self.logger.log.apply(self.logger, arguments);
+        self.logger.log(...self.convertLegacyLogPayload(args));
       },
       // Log an informational message. The default
       // implementation wraps `console.info` and passes on
@@ -554,8 +555,8 @@ module.exports = {
       // Overrides should be written with support for
       // substitution strings in mind. See the
       // `console.log` documentation.
-      info(msg) {
-        self.logger.info.apply(self.logger, arguments);
+      info(...args) {
+        self.logger.info(...self.convertLegacyLogPayload(args));
       },
       // Log a debug message. The default implementation wraps
       // `console.debug` if available, otherwise `console.log`,
@@ -564,8 +565,8 @@ module.exports = {
       // Overrides should be written with support for
       // substitution strings in mind. See the
       // `console.warn` documentation.
-      debug(msg) {
-        self.logger.debug.apply(self.logger, arguments);
+      debug(...args) {
+        self.logger.debug(...self.convertLegacyLogPayload(args));
       },
       // Log a warning. The default implementation wraps
       // `console.warn` and passes on all arguments,
@@ -578,8 +579,8 @@ module.exports = {
       // The intention is that `apos.util.warn` should be
       // called for situations less dire than
       // `apos.util.error`.
-      warn(msg) {
-        self.logger.warn.apply(self.logger, arguments);
+      warn(...args) {
+        self.logger.warn(...self.convertLegacyLogPayload(args));
       },
 
       // Identical to `apos.util.warn`, except that the warning is
@@ -629,8 +630,8 @@ module.exports = {
       // Overrides should be written with support for
       // substitution strings in mind. See the
       // `console.error` documentation.
-      error(msg) {
-        self.logger.error.apply(self.logger, arguments);
+      error(...args) {
+        self.logger.error(...self.convertLegacyLogPayload(args));
       },
       // Performance profiling method. At the start of the operation you want
       // to profile, call with req (may be null or omitted entirely) and a
@@ -835,6 +836,46 @@ module.exports = {
       },
       omit(source, keys) {
         return _.omit(source, keys);
+      },
+
+      // Internal method. Attempt to convert the log payload to an object
+      // for legacy calls and when `@apostrophecms/log` has been configured
+      // with `messageAs: 'someKey'`.
+      // This change is backwards compatible with the previous behavior because
+      // `messageAs` is newly introduced option. Custom loggers should adapt
+      // to this change when using `messageAs`.
+      // `args` is the argument array passed to the any log method.
+      // The result (when required) is an array with a single object.
+      // First string argument (if available) is used as `message`.
+      // First object argument is used as result object.
+      // All other arguments are passed as `args` property of the result object.
+      convertLegacyLogPayload(args) {
+        const messageAs = self.apos.structuredLog.options.messageAs;
+        if (!messageAs || args.length === 0) {
+          return args;
+        }
+        // Already formatted by the structured log module. Nothing we can do if not.
+        if (args.length === 1 && _.isPlainObject(args[0])) {
+          return args;
+        }
+
+        // Should also handle apos.util.warnDev() calls.
+        const messageIndex = args
+          .findIndex(arg => typeof arg === 'string' && arg.trim() && arg !== '\n⚠️ ');
+        const firstObjectIndex = args.findIndex(arg => _.isPlainObject(arg));
+        const message = messageIndex !== -1 ? args[messageIndex] : null;
+        const firstObject = firstObjectIndex !== -1 ? { ...args[firstObjectIndex] } : {};
+
+        if (message) {
+          firstObject[messageAs] = message;
+        }
+        const rest = args
+          .filter((arg, index) => ![ messageIndex, firstObjectIndex ].includes(index));
+        if (rest.length) {
+          firstObject.args = rest;
+        }
+
+        return [ firstObject ];
       }
     };
   },

test/log.js

@@ -961,4 +961,280 @@ describe('structured logging', function () {
       });
     });
   });
+
+  describe('legacy logging with :messageAs"', function () {
+    before(async function () {
+      await t.destroy(apos);
+      apos = await t.create({
+        modules: {
+          '@apostrophecms/log': {
+            options: {
+              messageAs: 'msg'
+            }
+          }
+        }
+      });
+    });
+
+    after(async function () {
+      delete process.env.APOS_FILTER_LOGS;
+      await t.destroy(apos);
+      apos = null;
+    });
+
+    it('should log object: debug', function () {
+      let savedArgs = [];
+      const saved = apos.util.logger.debug;
+      apos.util.logger.debug = (...args) => {
+        savedArgs = args;
+      };
+
+      savedArgs = [];
+      apos.util.debug('some message');
+      assert.deepEqual(savedArgs, [ { msg: 'some message' } ]);
+
+      savedArgs = [];
+      apos.util.debug({ foo: 'bar' });
+      assert.deepEqual(savedArgs, [ { foo: 'bar' } ]);
+
+      savedArgs = [];
+      apos.util.debug('some message', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message'
+      } ]);
+
+      savedArgs = [];
+      apos.util.debug('some message', 'more', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      savedArgs = [];
+      apos.util.debug({ foo: 'bar' }, 'some message', 'more');
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      apos.util.logger.debug = saved;
+    });
+
+    it('should log object: log', function () {
+      let savedArgs = [];
+      const saved = apos.util.logger.log;
+      apos.util.logger.log = (...args) => {
+        savedArgs = args;
+      };
+
+      savedArgs = [];
+      apos.util.log('some message');
+      assert.deepEqual(savedArgs, [ { msg: 'some message' } ]);
+
+      savedArgs = [];
+      apos.util.log({ foo: 'bar' });
+      assert.deepEqual(savedArgs, [ { foo: 'bar' } ]);
+
+      savedArgs = [];
+      apos.util.log('some message', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message'
+      } ]);
+
+      savedArgs = [];
+      apos.util.log('some message', 'more', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      savedArgs = [];
+      apos.util.log({ foo: 'bar' }, 'some message', 'more');
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      apos.util.logger.log = saved;
+    });
+
+    it('should log object: info', function () {
+      let savedArgs = [];
+      const saved = apos.util.logger.info;
+      apos.util.logger.info = (...args) => {
+        savedArgs = args;
+      };
+
+      savedArgs = [];
+      apos.util.info('some message');
+      assert.deepEqual(savedArgs, [ { msg: 'some message' } ]);
+
+      savedArgs = [];
+      apos.util.info({ foo: 'bar' });
+      assert.deepEqual(savedArgs, [ { foo: 'bar' } ]);
+
+      savedArgs = [];
+      apos.util.info('some message', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message'
+      } ]);
+
+      savedArgs = [];
+      apos.util.info('some message', 'more', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      savedArgs = [];
+      apos.util.info({ foo: 'bar' }, 'some message', 'more');
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      apos.util.logger.info = saved;
+    });
+
+    it('should log object: warn', function () {
+      let savedArgs = [];
+      const saved = apos.util.logger.warn;
+      apos.util.logger.warn = (...args) => {
+        savedArgs = args;
+      };
+
+      savedArgs = [];
+      apos.util.warn('some message');
+      assert.deepEqual(savedArgs, [ { msg: 'some message' } ]);
+
+      savedArgs = [];
+      apos.util.warn({ foo: 'bar' });
+      assert.deepEqual(savedArgs, [ { foo: 'bar' } ]);
+
+      savedArgs = [];
+      apos.util.warn('some message', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message'
+      } ]);
+
+      savedArgs = [];
+      apos.util.warn('some message', 'more', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      savedArgs = [];
+      apos.util.warn({ foo: 'bar' }, 'some message', 'more');
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      apos.util.logger.warn = saved;
+    });
+
+    it('should log object: error', function () {
+      let savedArgs = [];
+      const saved = apos.util.logger.error;
+      apos.util.logger.error = (...args) => {
+        savedArgs = args;
+      };
+
+      savedArgs = [];
+      apos.util.error('some message');
+      assert.deepEqual(savedArgs, [ { msg: 'some message' } ]);
+
+      savedArgs = [];
+      apos.util.error({ foo: 'bar' });
+      assert.deepEqual(savedArgs, [ { foo: 'bar' } ]);
+
+      savedArgs = [];
+      apos.util.error('some message', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message'
+      } ]);
+
+      savedArgs = [];
+      apos.util.error('some message', 'more', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      savedArgs = [];
+      apos.util.error({ foo: 'bar' }, 'some message', 'more');
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ 'more' ]
+      } ]);
+
+      apos.util.logger.error = saved;
+    });
+
+    it('should log object: warnDev', function () {
+      let savedArgs = [];
+      const saved = apos.util.logger.warn;
+      apos.util.logger.warn = (...args) => {
+        savedArgs = args;
+      };
+
+      savedArgs = [];
+      apos.util.warnDev('some message');
+      assert.deepEqual(savedArgs, [ {
+        msg: 'some message',
+        args: [ '\n⚠️ ', '\n' ]
+      } ]);
+
+      savedArgs = [];
+      apos.util.warnDev({ foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        args: [ '\n⚠️ ', '\n' ]
+      }
+      ]);
+
+      savedArgs = [];
+      apos.util.warnDev('some message', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ '\n⚠️ ', '\n' ]
+      } ]);
+
+      savedArgs = [];
+      apos.util.warnDev('some message', 'more', { foo: 'bar' });
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ '\n⚠️ ', 'more', '\n' ]
+      } ]);
+
+      savedArgs = [];
+      apos.util.warnDev({ foo: 'bar' }, 'some message', 'more');
+      assert.deepEqual(savedArgs, [ {
+        foo: 'bar',
+        msg: 'some message',
+        args: [ '\n⚠️ ', 'more', '\n' ]
+      } ]);
+
+      apos.util.logger.warn = saved;
+    });
+
+  });
 });