loggers (#996)

* multiple loggers

* simplify routes parameters

* pass logger explicitly

* use specific loggers in CLI functions

* fix test compile error

* validate logger format setting

* override logger format from CLI parameter

* use logger on server start

* docs typo

* log errors with correct level and in one event

* change signature for readability

* fix tests

* reduce exports from logger.ts - logger should be passed directly, no global imports

* logger that redirects everything to stderr

* push loggers further

* utils for now in iso format

* cleaner Logger API and types

* rename to @timestamp

* add docs

* let commander.js validate logger format values

* util for logging js error objects

* refactor for brevity

* readiness error should be logged as warn

docs/configuration-cluster.md

@@ -38,6 +38,17 @@ The port that Turnilo should run on.
 
 Indicates that Turnilo should run in verbose mode. This will log all the queries done by Turnilo.
 
+**loggerFormat** *EXPERIMENTAL* (`plain` or `json`), default: `plain` 
+
+Format for logged message. 
+* `plain`: messages are logged as is.
+* `json`: messages are wrapped in object with additional metadata and logged as stringified JSON.
+
+Additional metadata for `json` format:
+* `@timestamp`: ISO 8601 timestamp of logged event
+* `level`: "INFO", "WARN", or "ERROR" string
+* `logger`: name of the logger
+
 **serverHost** (string), default: bind to all hosts
 
 The host that Turnilo will bind to.

docs/extending-turnilo.md

@@ -53,7 +53,7 @@ exports.druidRequestDecoratorFactory = function (logger, params) {
   return function () {
     return {
       headers: {
-        "X-I-Like": auth
+        "X-I-Like": like
       },
     };
   };

src/common/logger/logger.ts

@@ -14,41 +14,113 @@
  * limitations under the License.
  */
 
+import { LoggerFormat } from "../../server/models/server-settings/server-settings";
 import { noop, Unary } from "../utils/functional/functional";
+import { isNil } from "../utils/general/general";
+import { isoNow } from "../utils/time/time";
+
+type LogFn = (msg: string, extra?: Record<string, string>) => void;
+type LogLevel = "INFO" | "WARN" | "ERROR";
+
+export function errorToMessage(error: Error): string {
+  if (isNil(error.stack)) {
+    return error.message;
+  }
+  return `${error.message}\n${error.stack}`;
+}
 
 export interface Logger {
-  log: Function;
-  warn: Function;
-  error: Function;
-  addPrefix: Unary<String, Logger>;
+  log: LogFn;
+  warn: LogFn;
+  error: LogFn;
+  setLoggerId: Unary<String, Logger>;
+}
+
+class JSONLogger implements Logger {
+
+  constructor(private logger = "turnilo") {
+  }
+
+  private logMessage(level: LogLevel, message: string, extra: Record<string, string> = {}) {
+    console.log(JSON.stringify({
+      message,
+      level,
+      "@timestamp": isoNow(),
+      "logger": this.logger,
+      ...extra
+    }));
+  }
+
+  log(message: string, extra: Record<string, string> = {}) {
+    this.logMessage("INFO", message, extra);
+  }
+
+  error(message: string, extra: Record<string, string> = {}) {
+    this.logMessage("ERROR", message, extra);
+  }
+
+  warn(message: string, extra: Record<string, string> = {}) {
+    this.logMessage("WARN", message, extra);
+  }
+
+  setLoggerId(loggerId: string): Logger {
+    return new JSONLogger(loggerId);
+  }
 }
 
 class ConsoleLogger implements Logger {
-  constructor(private prefixes: string[] = []) {
+  constructor(private prefix = "") {
   }
 
-  error(...args: any[]) {
-    console.error(...this.prefixes, ...args);
+  error(message: string) {
+    console.error(this.prefix, message);
   }
 
-  warn(...args: any[]) {
-    console.warn(...this.prefixes, ...args);
+  warn(message: string) {
+    console.warn(this.prefix, message);
   }
 
-  log(...args: any[]) {
-    console.log(...this.prefixes, ...args);
+  log(message: string) {
+    console.log(this.prefix, message);
   }
 
-  addPrefix(prefix: string): Logger {
-    return new ConsoleLogger([...this.prefixes, prefix]);
+  setLoggerId(loggerId: string): Logger {
+    return new ConsoleLogger(loggerId);
   }
 }
 
-export const LOGGER: Logger = new ConsoleLogger();
+class AlwaysStdErrLogger implements Logger {
+  setLoggerId(): Logger {
+    return this;
+  }
+
+  error(message: string) {
+    console.error(message);
+  }
+
+  log(message: string) {
+    console.error(message);
+  }
+
+  warn(message: string) {
+    console.error(message);
+  }
+}
 
-export const NULL_LOGGER: Logger = {
+export const NOOP_LOGGER: Logger = {
   error: noop,
   warn: noop,
   log: noop,
-  addPrefix: noop
+  setLoggerId: () => NOOP_LOGGER
 };
+
+const LOGGERS: Record<LoggerFormat, Logger> = {
+  noop: NOOP_LOGGER,
+  json: new JSONLogger(),
+  plain: new ConsoleLogger(),
+  error: new AlwaysStdErrLogger()
+} as const;
+
+export function getLogger(format: LoggerFormat): Logger {
+  return LOGGERS[format];
+}

src/common/models/app-settings/app-settings.ts

@@ -16,6 +16,7 @@
  */
 
 import { Executor } from "plywood";
+import { Logger } from "../../logger/logger";
 import {
   ClientCustomization,
   Customization,
@@ -62,10 +63,10 @@ export interface ClientAppSettings {
   readonly oauth: Oauth;
 }
 
-export function fromConfig(config: AppSettingsJS): AppSettings {
+export function fromConfig(config: AppSettingsJS, logger: Logger): AppSettings {
   const clientTimeout = config.clientTimeout === undefined ? DEFAULT_CLIENT_TIMEOUT : config.clientTimeout;
   const version = config.version || 0;
-  const customization = customizationFromConfig(config.customization);
+  const customization = customizationFromConfig(config.customization, logger);
   const oauth = oauthFromConfig(config.oauth);
 
   return {
@@ -76,7 +77,7 @@ export function fromConfig(config: AppSettingsJS): AppSettings {
   };
 }
 
-export const EMPTY_APP_SETTINGS = fromConfig({});
+export const emptySettings = (logger: Logger) => fromConfig({}, logger);
 
 export function serialize({ oauth, clientTimeout, customization, version }: AppSettings): SerializedAppSettings {
   return {

src/common/models/cluster/cluster.fixtures.ts

@@ -14,6 +14,7 @@
  * limitations under the License.
  */
 
+import { NOOP_LOGGER } from "../../logger/logger";
 import { Cluster, ClusterJS, fromConfig } from "./cluster";
 
 export class ClusterFixtures {
@@ -33,7 +34,7 @@ export class ClusterFixtures {
   }
 
   static druidWikiCluster(): Cluster {
-    return fromConfig(ClusterFixtures.druidWikiClusterJS());
+    return fromConfig(ClusterFixtures.druidWikiClusterJS(), NOOP_LOGGER);
   }
 
   static druidTwitterClusterJS(): ClusterJS {
@@ -52,7 +53,7 @@ export class ClusterFixtures {
   }
 
   static druidTwitterCluster(): Cluster {
-    return fromConfig(ClusterFixtures.druidTwitterClusterJS());
+    return fromConfig(ClusterFixtures.druidTwitterClusterJS(), NOOP_LOGGER);
   }
 
   static druidTwitterClusterJSWithGuard(guardDataCubes = true): Cluster {
@@ -68,6 +69,6 @@ export class ClusterFixtures {
       guardDataCubes,
 
       introspectionStrategy: "segment-metadata-fallback"
-    });
+    }, NOOP_LOGGER);
   }
 }

src/common/models/cluster/cluster.mocha.ts

@@ -19,6 +19,7 @@ import { expect, use } from "chai";
 import equivalent from "../../../client/utils/test-utils/equivalent";
 import { RequestDecorator } from "../../../server/utils/request-decorator/request-decorator";
 import { RetryOptions } from "../../../server/utils/retry-options/retry-options";
+import { NOOP_LOGGER } from "../../logger/logger";
 import { ClusterAuthJS } from "../cluster-auth/cluster-auth";
 import { Cluster, ClusterJS, fromConfig } from "./cluster";
 
@@ -31,15 +32,15 @@ function buildCluster(options: Partial<ClusterJS> = {}): Cluster {
   return fromConfig({
     ...baseConfig,
     ...options
-  });
+  }, NOOP_LOGGER);
 }
 
 use(equivalent);
 
 describe("Cluster", () => {
   describe("fromConfig", () => {
     it("should load default values", () => {
-      const cluster = fromConfig(baseConfig);
+      const cluster = buildCluster();
 
       expect(cluster).to.be.deep.equal({
         name: "foobar",
@@ -64,19 +65,19 @@ describe("Cluster", () => {
     });
 
     it("should throw with incorrect name type", () => {
-      expect(() => fromConfig({ ...baseConfig, name: 1 } as unknown as ClusterJS)).to.throw("must be a string");
+      expect(() => buildCluster({ name: 1 } as unknown as ClusterJS)).to.throw("must be a string");
     });
 
     it("should throw with incorrect empty name", () => {
-      expect(() => fromConfig({ ...baseConfig, name: "" })).to.throw("empty name");
+      expect(() => buildCluster({ name: "" })).to.throw("empty name");
     });
 
     it("should throw with not url safe name", () => {
-      expect(() => fromConfig({ ...baseConfig, name: "foobar%bazz#" })).to.throw("is not a URL safe name");
+      expect(() => buildCluster({ name: "foobar%bazz#" })).to.throw("is not a URL safe name");
     });
 
     it("should throw with name equal to native", () => {
-      expect(() => fromConfig({ ...baseConfig, name: "native" })).to.throw("name can not be 'native'");
+      expect(() => buildCluster({ name: "native" })).to.throw("name can not be 'native'");
     });
 
     it("should read auth options", () => {
@@ -119,7 +120,7 @@ describe("Cluster", () => {
     });
 
     it("should read request decorator", () => {
-      const cluster = fromConfig({
+      const cluster = buildCluster({
         name: "foobar",
         url: "http://foobar",
         requestDecorator: {
@@ -141,8 +142,10 @@ describe("Cluster", () => {
     });
 
     it("should read old host and assume http protocol", () => {
-      const cluster = fromConfig({
+      const cluster = buildCluster({
         name: "old-host",
+        // Set url to undefined, to force old format handling
+        url: undefined,
         host: "broker-host.com"
       } as unknown as ClusterJS);
 

src/common/models/cluster/cluster.ts

@@ -20,6 +20,7 @@ import { External } from "plywood";
 import { URL } from "url";
 import { RequestDecorator, RequestDecoratorJS } from "../../../server/utils/request-decorator/request-decorator";
 import { RetryOptions, RetryOptionsJS } from "../../../server/utils/retry-options/retry-options";
+import { Logger } from "../../logger/logger";
 import { isNil, isTruthy, optionalEnsureOneOf, verifyUrlSafeName } from "../../utils/general/general";
 import { ClusterAuth, ClusterAuthJS, readClusterAuth } from "../cluster-auth/cluster-auth";
 
@@ -117,9 +118,9 @@ function readUrl(cluster: any): string {
   throw new Error("Cluster: missing url field");
 }
 
-function readRequestDecorator(cluster: any): RequestDecorator | null {
+function readRequestDecorator(cluster: any, logger: Logger): RequestDecorator | null {
   if (typeof cluster.requestDecorator === "string" || !isNil(cluster.decoratorOptions)) {
-    console.warn(`Cluster ${cluster.name} : requestDecorator as string and decoratorOptions fields are deprecated. Use object with path and options fields`);
+    logger.warn(`Cluster ${cluster.name} : requestDecorator as string and decoratorOptions fields are deprecated. Use object with path and options fields`);
     return RequestDecorator.fromJS({ path: cluster.requestDecorator, options: cluster.decoratorOptions });
   }
   if (isTruthy(cluster.requestDecorator)) return RequestDecorator.fromJS(cluster.requestDecorator);
@@ -145,7 +146,7 @@ function readInterval(value: number | string, defaultValue: number): number {
   return numberValue;
 }
 
-export function fromConfig(params: ClusterJS): Cluster {
+export function fromConfig(params: ClusterJS, logger: Logger): Cluster {
   const {
     name,
     sourceListScan = DEFAULT_SOURCE_LIST_SCAN,
@@ -167,7 +168,7 @@ export function fromConfig(params: ClusterJS): Cluster {
   const sourceListRefreshInterval = readInterval(params.sourceListRefreshInterval, DEFAULT_SOURCE_LIST_REFRESH_INTERVAL);
   const sourceTimeBoundaryRefreshInterval = readInterval(params.sourceTimeBoundaryRefreshInterval, DEFAULT_SOURCE_TIME_BOUNDARY_REFRESH_INTERVAL);
   const retry = RetryOptions.fromJS(params.retry);
-  const requestDecorator = readRequestDecorator(params);
+  const requestDecorator = readRequestDecorator(params, logger);
   const auth = readClusterAuth(params.auth);
 
   const url = readUrl(params);