Switch implicit server.log behavior with tmpl to logWithMetadata (#29002

) * Changing the optimizer's use to logWithMetadata * Switching ensureEsVersion to logWithMetadata * Changing pid logging to use logWithMetadata * Changing server/plugins to use logWithMetadata * Changing saved objects onBeforeWrite to logWithMetata * Changing server/status to server.logWithMetadata * Changing ui settings to use logWithMetadata * Removing _.template's usage from within log_format * Fixing initializing plugin log message * Fixing ensureEsVersion tests * Fixing health check tests * Fixing a few more forgotten tests
elastic · Jan 23, 2019 · ece86f6 · ece86f6
1 parent e7c28fd
commit ece86f6
Show file tree

Hide file tree

Showing 23 changed files with 112 additions and 120 deletions.
diff --git a/src/legacy/core_plugins/elasticsearch/lib/__tests__/ensure_es_version.js b/src/legacy/core_plugins/elasticsearch/lib/__tests__/ensure_es_version.js
@@ -34,6 +34,7 @@ describe('plugins/elasticsearch', () => {
     beforeEach(function () {
       server = {
         log: sinon.stub(),
+        logWithMetadata: sinon.stub(),
         plugins: {
           elasticsearch: {
             getCluster: sinon.stub().withArgs('admin').returns({ callWithInternalUser: sinon.stub() }),
@@ -120,17 +121,17 @@ describe('plugins/elasticsearch', () => {
     it('warns if a node is only off by a patch version', async () => {
       setNodes('5.1.1');
       await ensureEsVersion(server, KIBANA_VERSION);
-      sinon.assert.callCount(server.log, 2);
-      expect(server.log.getCall(0).args[0]).to.contain('debug');
-      expect(server.log.getCall(1).args[0]).to.contain('warning');
+      sinon.assert.callCount(server.logWithMetadata, 2);
+      expect(server.logWithMetadata.getCall(0).args[0]).to.contain('debug');
+      expect(server.logWithMetadata.getCall(1).args[0]).to.contain('warning');
     });
 
     it('warns if a node is off by a patch version and without http publish address', async () => {
       setNodeWithoutHTTP('5.1.1');
       await ensureEsVersion(server, KIBANA_VERSION);
-      sinon.assert.callCount(server.log, 2);
-      expect(server.log.getCall(0).args[0]).to.contain('debug');
-      expect(server.log.getCall(1).args[0]).to.contain('warning');
+      sinon.assert.callCount(server.logWithMetadata, 2);
+      expect(server.logWithMetadata.getCall(0).args[0]).to.contain('debug');
+      expect(server.logWithMetadata.getCall(1).args[0]).to.contain('warning');
     });
 
     it('errors if a node incompatible and without http publish address', async () => {
@@ -147,28 +148,28 @@ describe('plugins/elasticsearch', () => {
       setNodes('5.1.1');
 
       await ensureEsVersion(server, KIBANA_VERSION);
-      sinon.assert.callCount(server.log, 2);
-      expect(server.log.getCall(0).args[0]).to.contain('debug');
-      expect(server.log.getCall(1).args[0]).to.contain('warning');
+      sinon.assert.callCount(server.logWithMetadata, 2);
+      expect(server.logWithMetadata.getCall(0).args[0]).to.contain('debug');
+      expect(server.logWithMetadata.getCall(1).args[0]).to.contain('warning');
 
       await ensureEsVersion(server, KIBANA_VERSION);
-      sinon.assert.callCount(server.log, 3);
-      expect(server.log.getCall(2).args[0]).to.contain('debug');
+      sinon.assert.callCount(server.logWithMetadata, 3);
+      expect(server.logWithMetadata.getCall(2).args[0]).to.contain('debug');
     });
 
     it('warns again if the node list changes', async () => {
       setNodes('5.1.1');
 
       await ensureEsVersion(server, KIBANA_VERSION);
-      sinon.assert.callCount(server.log, 2);
-      expect(server.log.getCall(0).args[0]).to.contain('debug');
-      expect(server.log.getCall(1).args[0]).to.contain('warning');
+      sinon.assert.callCount(server.logWithMetadata, 2);
+      expect(server.logWithMetadata.getCall(0).args[0]).to.contain('debug');
+      expect(server.logWithMetadata.getCall(1).args[0]).to.contain('warning');
 
       setNodes('5.1.2');
       await ensureEsVersion(server, KIBANA_VERSION);
-      sinon.assert.callCount(server.log, 4);
-      expect(server.log.getCall(2).args[0]).to.contain('debug');
-      expect(server.log.getCall(3).args[0]).to.contain('warning');
+      sinon.assert.callCount(server.logWithMetadata, 4);
+      expect(server.logWithMetadata.getCall(2).args[0]).to.contain('debug');
+      expect(server.logWithMetadata.getCall(3).args[0]).to.contain('warning');
     });
   });
 });
diff --git a/src/legacy/core_plugins/elasticsearch/lib/__tests__/health_check.js b/src/legacy/core_plugins/elasticsearch/lib/__tests__/health_check.js
@@ -85,7 +85,7 @@ describe('plugins/elasticsearch', () => {
 
       // Setup the server mock
       server = {
-        log: sinon.stub(),
+        logWithMetadata: sinon.stub(),
         info: { port: 5601 },
         config: function () { return { get, set }; },
         plugins: {

diff --git a/src/legacy/core_plugins/elasticsearch/lib/ensure_es_version.js b/src/legacy/core_plugins/elasticsearch/lib/ensure_es_version.js
@@ -40,7 +40,7 @@ export function ensureEsVersion(server, kibanaVersion) {
   const { callWithInternalUser } = server.plugins.elasticsearch.getCluster('admin');
   const isProd = server.config().get('env.prod');
 
-  server.log(['plugin', 'debug'], 'Checking Elasticsearch version');
+  server.logWithMetadata(['plugin', 'debug'], 'Checking Elasticsearch version');
   return callWithInternalUser('nodes.info', {
     filterPath: [
       'nodes.*.version',
@@ -92,15 +92,14 @@ export function ensureEsVersion(server, kibanaVersion) {
         const warningNodeNames = getHumanizedNodeNames(simplifiedNodes).join(', ');
         if (lastWarnedNodesForServer.get(server) !== warningNodeNames) {
           lastWarnedNodesForServer.set(server, warningNodeNames);
-          server.log(['warning'], {
-            tmpl: (
-              `You're running Kibana ${kibanaVersion} with some different versions of ` +
+          server.logWithMetadata(['warning'],
+            `You're running Kibana ${kibanaVersion} with some different versions of ` +
             'Elasticsearch. Update Kibana or Elasticsearch to the same ' +
-            `version to prevent compatibility issues: ${warningNodeNames}`
-            ),
-            kibanaVersion,
-            nodes: simplifiedNodes,
-          });
+            `version to prevent compatibility issues: ${warningNodeNames}`,
+            {
+              kibanaVersion,
+              nodes: simplifiedNodes,
+            });
         }
       }
 

diff --git a/src/optimize/base_optimizer.js b/src/optimize/base_optimizer.js
@@ -46,7 +46,7 @@ const STATS_WARNINGS_FILTER = new RegExp([
 
 export default class BaseOptimizer {
   constructor(opts) {
-    this.log = opts.log || (() => null);
+    this.logWithMetadata = opts.logWithMetadata || (() => null);
     this.uiBundles = opts.uiBundles;
     this.profile = opts.profile || false;
 
@@ -270,7 +270,7 @@ export default class BaseOptimizer {
         new DynamicDllPlugin({
           uiBundles: this.uiBundles,
           threadLoaderPoolConfig: this.getThreadLoaderPoolConfig(),
-          log: this.log
+          logWithMetadata: this.logWithMetadata
         }),
 
         new MiniCssExtractPlugin({

diff --git a/src/optimize/dynamic_dll_plugin/dll_compiler.js b/src/optimize/dynamic_dll_plugin/dll_compiler.js
@@ -51,13 +51,13 @@ export class DllCompiler {
     };
   }
 
-  constructor(uiBundles, threadLoaderPoolConfig, log) {
+  constructor(uiBundles, threadLoaderPoolConfig, logWithMetadata) {
     this.rawDllConfig = DllCompiler.getRawDllConfig(
       uiBundles,
       uiBundles.getCacheDirectory('babel'),
       threadLoaderPoolConfig
     );
-    this.log = log || (() => null);
+    this.logWithMetadata = logWithMetadata || (() => null);
   }
 
   async init() {
@@ -182,7 +182,7 @@ export class DllCompiler {
 
   async runWebpack(config) {
     return new Promise((resolve, reject) => {
-      this.log(['info', 'optimize:dynamic_dll_plugin'], 'Client vendors dll compilation started');
+      this.logWithMetadata(['info', 'optimize:dynamic_dll_plugin'], 'Client vendors dll compilation started');
 
       webpack(config, (err, stats) => {
         // If a critical error occurs or we have
@@ -197,15 +197,15 @@ export class DllCompiler {
         }));
 
         if (webpackErrors) {
-          this.log(
+          this.logWithMetadata(
             ['fatal', 'optimize:dynamic_dll_plugin'],
             `Client vendors dll compilation failed`
           );
           return reject(webpackErrors);
         }
 
         // Otherwise let it proceed
-        this.log(
+        this.logWithMetadata(
           ['info', 'optimize:dynamic_dll_plugin'],
           `Client vendors dll compilation finished with success`
         );

diff --git a/src/optimize/dynamic_dll_plugin/dynamic_dll_plugin.js b/src/optimize/dynamic_dll_plugin/dynamic_dll_plugin.js
@@ -40,9 +40,9 @@ function inPluginNodeModules(checkPath) {
 }
 
 export class DynamicDllPlugin {
-  constructor({ uiBundles, threadLoaderPoolConfig, log, maxCompilations = 1 }) {
-    this.log = log || (() => null);
-    this.dllCompiler = new DllCompiler(uiBundles, threadLoaderPoolConfig, log);
+  constructor({ uiBundles, threadLoaderPoolConfig, logWithMetadata, maxCompilations = 1 }) {
+    this.logWithMetadata = logWithMetadata || (() => null);
+    this.dllCompiler = new DllCompiler(uiBundles, threadLoaderPoolConfig, logWithMetadata);
     this.entryPaths = '';
     this.afterCompilationEntryPaths = '';
     this.maxCompilations = maxCompilations;
@@ -92,7 +92,7 @@ export class DynamicDllPlugin {
   }
 
   registerTasksHooks(compiler) {
-    this.log(['info', 'optimize:dynamic_dll_plugin'], 'Started dynamic dll plugin tasks');
+    this.logWithMetadata(['info', 'optimize:dynamic_dll_plugin'], 'Started dynamic dll plugin tasks');
     this.registerBeforeCompileHook(compiler);
     this.registerCompilationHook(compiler);
     this.registerDoneHook(compiler);
@@ -231,7 +231,7 @@ export class DynamicDllPlugin {
         // Only run this info log in the first performed dll compilation
         // per each execution run
         if (this.performedCompilations === 0) {
-          this.log(
+          this.logWithMetadata(
             ['info', 'optimize:dynamic_dll_plugin'],
             compilation.needsDLLCompilation
               ? 'Need to compile the client vendors dll'
@@ -269,7 +269,7 @@ export class DynamicDllPlugin {
       if (this.forceDLLCreationFlag) {
         this.forceDLLCreationFlag = false;
       }
-      this.log(['info', 'optimize:dynamic_dll_plugin'], 'Finished all dynamic dll plugin tasks');
+      this.logWithMetadata(['info', 'optimize:dynamic_dll_plugin'], 'Finished all dynamic dll plugin tasks');
     });
   }
 

diff --git a/src/optimize/index.js b/src/optimize/index.js
@@ -62,7 +62,7 @@ export default async (kbnServer, server, config) => {
 
   // only require the FsOptimizer when we need to
   const optimizer = new FsOptimizer({
-    log: (tags, data) => server.log(tags, data),
+    logWithMetadata: (tags, message, metadata) => server.logWithMetadata(tags, message, metadata),
     uiBundles,
     profile: config.get('optimize.profile'),
     sourceMaps: config.get('optimize.sourceMaps'),

diff --git a/src/optimize/watch/optmzr_role.js b/src/optimize/watch/optmzr_role.js
@@ -25,16 +25,16 @@ import { DllCompiler } from '../dynamic_dll_plugin';
 import { WatchCache } from './watch_cache';
 
 export default async (kbnServer, kibanaHapiServer, config) => {
-  const log = (tags, data) => kibanaHapiServer.log(tags, data);
+  const logWithMetadata = (tags, message, metadata) => kibanaHapiServer.logWithMetadata(tags, message, metadata);
 
   const watchOptimizer = new WatchOptimizer({
-    log,
+    logWithMetadata,
     uiBundles: kbnServer.uiBundles,
     profile: config.get('optimize.profile'),
     sourceMaps: config.get('optimize.sourceMaps'),
     prebuild: config.get('optimize.watchPrebuild'),
     watchCache: new WatchCache({
-      log,
+      logWithMetadata,
       outputPath: config.get('path.data'),
       dllsPath: DllCompiler.getRawDllConfig().outputPath,
       cachePath: resolve(kbnServer.uiBundles.getCacheDirectory(), '../'),

diff --git a/src/optimize/watch/watch_cache.ts b/src/optimize/watch/watch_cache.ts
@@ -31,7 +31,7 @@ const readAsync = promisify(readFile);
 const writeAsync = promisify(writeFile);
 
 interface Params {
-  log: (tags: string[], data: string) => void;
+  logWithMetadata: (tags: string[], message: string, metadata?: { [key: string]: any }) => void;
   outputPath: string;
   dllsPath: string;
   cachePath: string;
@@ -43,7 +43,7 @@ interface WatchCacheStateContent {
 }
 
 export class WatchCache {
-  private readonly log: Params['log'];
+  private readonly logWithMetadata: Params['logWithMetadata'];
   private readonly outputPath: Params['outputPath'];
   private readonly dllsPath: Params['dllsPath'];
   private readonly cachePath: Params['cachePath'];
@@ -53,7 +53,7 @@ export class WatchCache {
   private isInitialized: boolean;
 
   constructor(params: Params) {
-    this.log = params.log;
+    this.logWithMetadata = params.logWithMetadata;
     this.outputPath = params.outputPath;
     this.dllsPath = params.dllsPath;
     this.cachePath = params.cachePath;
@@ -87,7 +87,7 @@ export class WatchCache {
   }
 
   public async reset() {
-    this.log(['info', 'optimize:watch_cache'], 'The optimizer watch cache will reset');
+    this.logWithMetadata(['info', 'optimize:watch_cache'], 'The optimizer watch cache will reset');
 
     // start by deleting the state file to lower the
     // amount of time that another process might be able to
@@ -116,7 +116,7 @@ export class WatchCache {
     // re-write new cache state file
     await this.write();
 
-    this.log(['info', 'optimize:watch_cache'], 'The optimizer watch cache has reset');
+    this.logWithMetadata(['info', 'optimize:watch_cache'], 'The optimizer watch cache has reset');
   }
 
   private async buildShaWithMultipleFiles(filePaths: string[]) {

diff --git a/src/optimize/watch/watch_optimizer.js b/src/optimize/watch/watch_optimizer.js
@@ -156,16 +156,14 @@ export default class WatchOptimizer extends BaseOptimizer {
     switch (type) {
       case STATUS.RUNNING:
         if (!this.initialBuildComplete) {
-          this.log(['info', 'optimize'], {
-            tmpl: 'Optimization started',
+          this.logWithMetadata(['info', 'optimize'], `Optimization started`, {
             bundles: this.uiBundles.getIds()
           });
         }
         break;
 
       case STATUS.SUCCESS:
-        this.log(['info', 'optimize'], {
-          tmpl: 'Optimization <%= status %> in <%= seconds %> seconds',
+        this.logWithMetadata(['info', 'optimize'], `Optimization success in ${seconds} seconds`, {
           bundles: this.uiBundles.getIds(),
           status: 'success',
           seconds
@@ -176,8 +174,7 @@ export default class WatchOptimizer extends BaseOptimizer {
         // errors during initialization to the server, unlike the rest of the
         // errors produced here. Lets not muddy the console with extra errors
         if (!this.initializing) {
-          this.log(['fatal', 'optimize'], {
-            tmpl: 'Optimization <%= status %> in <%= seconds %> seconds<%= err %>',
+          this.logWithMetadata(['fatal', 'optimize'], `Optimization failed in ${seconds} seconds${error}`, {
             bundles: this.uiBundles.getIds(),
             status: 'failed',
             seconds,
@@ -187,7 +184,7 @@ export default class WatchOptimizer extends BaseOptimizer {
         break;
 
       case STATUS.FATAL:
-        this.log('fatal', error);
+        this.logWithMetadata('fatal', error);
         process.exit(1);
         break;
     }

diff --git a/src/server/logging/log_format.js b/src/server/logging/log_format.js
@@ -162,11 +162,6 @@ export default class TransformObjStream extends Stream.Transform {
     else if (logWithMetadata.isLogEvent(event.data)) {
       _.assign(data, logWithMetadata.getLogEventData(event.data));
     }
-    else if (_.isPlainObject(event.data) && event.data.tmpl) {
-      _.assign(data, event.data);
-      data.tmpl = undefined;
-      data.message = _.template(event.data.tmpl)(event.data);
-    }
     else {
       data.message = _.isString(event.data) ? event.data : inspect(event.data);
     }

diff --git a/src/server/pid/index.js b/src/server/pid/index.js
@@ -33,24 +33,23 @@ export default Promise.method(function (kbnServer, server, config) {
     .catch(function (err) {
       if (err.code !== 'EEXIST') throw err;
 
-      const log = {
-        tmpl: 'pid file already exists at <%= path %>',
+      const message = `pid file already exists at ${path}`;
+      const metadata = {
         path: path,
         pid: pid
       };
 
       if (config.get('pid.exclusive')) {
-        throw Boom.internal(_.template(log.tmpl)(log), log);
+        throw Boom.internal(message, { message, ...metadata });
       } else {
-        server.log(['pid', 'warning'], log);
+        server.log(['pid', 'warning'], message, metadata);
       }
 
       return writeFile(path, pid);
     })
     .then(function () {
 
-      server.log(['pid', 'debug'], {
-        tmpl: 'wrote pid file to <%= path %>',
+      server.logWithMetadata(['pid', 'debug'], `wrote pid file to ${path}`, {
         path: path,
         pid: pid
       });

diff --git a/src/server/plugins/lib/plugin.js b/src/server/plugins/lib/plugin.js
@@ -66,8 +66,7 @@ export class Plugin {
       this._server = server;
       this._options = options;
 
-      server.log(['plugins', 'debug'], {
-        tmpl: 'Initializing plugin <%= plugin.toString() %>',
+      server.logWithMetadata(['plugins', 'debug'], `Initializing plugin ${this.toString()}`, {
         plugin: this
       });