refactor logger - brings back jobID and experienceName to android logs

bin/turtle.js

@@ -1,6 +1,15 @@
 #!/usr/bin/env node
 'use strict';
 
+const subcommand = process.argv[2];
+if (subcommand) {
+  const [, platform] = subcommand.split(':');
+  if (platform === 'ios' || platform === 'android') {
+    // so that logs have correct platform set
+    process.env.PLATFORM = platform;
+  }
+}
+
 require('source-map-support').install();
 require('../build/bin/env').initOfflineEnv();
 require('../build/bin/index').run('turtle');

src/bin/commands/setup.ts

@@ -6,7 +6,7 @@ import setup from 'turtle/bin/setup/setup';
 import { PLATFORMS } from 'turtle/constants';
 import logger from 'turtle/logger';
 
-const l = logger.withFields({ buildPhase: 'setting up environment' });
+const l = logger.child({ buildPhase: 'setting up environment' });
 
 function createSetupCommand(platform: string, os?: string) {
   return (program: any) => {

src/bin/setup/android/index.ts

@@ -41,7 +41,7 @@ const REQUIRED_TOOLS: IToolDefinition[] = [
   },
 ];
 const LOGGER_FIELDS = { buildPhase: 'setting up environment' };
-const l = logger.withFields(LOGGER_FIELDS);
+const l = logger.child(LOGGER_FIELDS);
 
 export default async function setup(sdkVersion?: string) {
   await checkSystem(REQUIRED_TOOLS);

src/bin/setup/android/ndk.ts

@@ -12,7 +12,7 @@ import logger from 'turtle/logger';
 const ANDROID_NDK_URL = `https://dl.google.com/android/repository/android-ndk-r10e-${os.platform()}-x86_64.zip`;
 
 const LOGGER_FIELDS = { buildPhase: 'setting up environment' };
-const l = logger.withFields(LOGGER_FIELDS);
+const l = logger.child(LOGGER_FIELDS);
 
 export default async function ensureAndroidNDKIsPresent() {
   const androidNdkDir = path.join(config.directories.androidDependenciesDir, 'ndk');

src/bin/setup/android/sdk.ts

@@ -13,7 +13,7 @@ import logger from 'turtle/logger';
 const ANDROID_SDK_URL = 'https://dl.google.com/android/repository/sdk-tools-linux-4333796.zip';
 
 const LOGGER_FIELDS = { buildPhase: 'setting up environment' };
-const l = logger.withFields(LOGGER_FIELDS);
+const l = logger.child(LOGGER_FIELDS);
 
 export default async function ensureAndroidSDKIsPresent() {
   const androidSdkDir = path.join(config.directories.androidDependenciesDir, 'sdk');

src/bin/setup/utils/common.ts

@@ -10,7 +10,7 @@ import { IShellAppDirectoryConfig } from 'turtle/builders/utils/workingdir';
 import config from 'turtle/config';
 import logger from 'turtle/logger';
 
-const l = logger.withFields({ buildPhase: 'setting up environment' });
+const l = logger.child({ buildPhase: 'setting up environment' });
 
 interface IShellAppFormaters {
   formatShellAppDirectory: (config: IShellAppDirectoryConfig) => string;

src/bin/setup/utils/toolsDetector.ts

@@ -4,7 +4,7 @@ import _which from 'which';
 import logger from 'turtle/logger';
 
 const which = util.promisify(_which);
-const l = logger.withFields({ buildPhase: 'setting up environment' });
+const l = logger.child({ buildPhase: 'setting up environment' });
 
 export interface IToolDefinition {
   command: string;

src/builders/ios/archive.ts

@@ -29,7 +29,7 @@ export default async function buildArchive(ctx: IContext, job: IJob) {
 }
 
 async function buildAndSignIPA(ctx: IContext, job: IJob, keychainPath: string, manifest: any) {
-  const l = logger.withFields({ buildPhase: 'building and signing IPA' });
+  const l = logger.child({ buildPhase: 'building and signing IPA' });
   l.info('building and signing IPA');
 
   const {

src/builders/ios/simulator.ts

@@ -4,7 +4,7 @@ import { IJob } from 'turtle/job';
 import logger from 'turtle/logger';
 
 export default async function buildSimulator(ctx: IContext, job: IJob) {
-  const l = logger.withFields({ buildPhase: 'running simulator builder' });
+  const l = logger.child({ buildPhase: 'running simulator builder' });
   l.info('running simulator build');
   await runShellAppBuilder(ctx, job);
   l.info('build complete');

src/builders/utils/android/credentials.ts

@@ -12,7 +12,7 @@ import { isOffline } from 'turtle/turtleContext';
 
 async function getOrCreateCredentials(jobData: IJob): Promise<IAndroidCredentials> {
   if (!jobData.credentials) {
-    const l = logger.withFields({ buildPhase: 'generating keystore' });
+    const l = logger.child({ buildPhase: 'generating keystore' });
     const credentials: any = {};
     l.info('Creating keystore');
     const keystoreFilename = `/tmp/keystore-${jobData.id}.tmp.jks`;

src/builders/utils/ios/keychain.ts

@@ -9,7 +9,7 @@ interface IKeychain {
 }
 
 export async function create(ctx: IContext): Promise<IKeychain> {
-  const l = logger.withFields({ buildPhase: 'creating keychain' });
+  const l = logger.child({ buildPhase: 'creating keychain' });
   try {
     l.info('creating keychain...');
     const keychainInfo = await IosKeychain.createKeychain(ctx.appUUID, false);
@@ -22,7 +22,7 @@ export async function create(ctx: IContext): Promise<IKeychain> {
 }
 
 export async function remove(ctx: IContext, keychainPath: string) {
-  const l = logger.withFields({ buildPhase: 'deleting keychain' });
+  const l = logger.child({ buildPhase: 'deleting keychain' });
   try {
     l.info('delete keychain...');
     const keychainInfo = await IosKeychain.deleteKeychain({
@@ -49,7 +49,7 @@ export async function importCert(
     certPassword,
   }: { keychainPath: string; certP12: string; certPassword: string },
 ) {
-  const l = logger.withFields({ buildPhase: 'importing certificate into keychain' });
+  const l = logger.child({ buildPhase: 'importing certificate into keychain' });
   try {
     l.info('importing distribution certificate into keychain...');
     const { tempCertPath: certPath } = ctx;

src/builders/utils/uploader.ts

@@ -12,14 +12,14 @@ interface IUploadCtx {
 
 export async function uploadBuildToS3(ctx: IUploadCtx) {
   if (config.builder.fakeUpload) {
-    const l = logger.withFields({ buildPhase: 'copying build artifact' });
+    const l = logger.child({ buildPhase: 'copying build artifact' });
     const { fakeUploadBuildPath, uploadPath } = ctx;
     l.info('copying build to fake upload directory');
     await fs.copy(uploadPath, fakeUploadBuildPath as string);
     l.info(`copied build to ${fakeUploadBuildPath}`);
     return fakeUploadBuildPath as string;
   } else {
-    const l = logger.withFields({ buildPhase: 'uploading to S3' });
+    const l = logger.child({ buildPhase: 'uploading to S3' });
     l.info('uploading build artifact to S3');
     const { Location: fileLocation } = await uploadFile({
       key: ctx.s3FileKey as string,

src/config.ts

@@ -43,7 +43,7 @@ export default {
   },
   logger: {
     level: env('LOGGER_LEVEL', 'info'),
-    interval: envNum('LOGGER_INTERVAL', 5),
+    intervalMs: envNum('LOGGER_INTERVAL_MS', 5000),
     client: {
       level: env('CLIENT_LOGGER_LEVEL', 'info'),
     },

src/jobManager.ts

@@ -121,7 +121,7 @@ function failAfterMaxJobTime(priority: string, receiptHandle: string, job: any)
 
 async function build(job: any) {
   const startTimestamp = Date.now();
-  const s3Url = await logger.init(job);
+  const s3Url = await logger.initForJob(job);
   const calculateBuildDuration = () => Math.ceil((Date.now() - startTimestamp) / 1000);
 
   try {
@@ -151,7 +151,7 @@ async function build(job: any) {
     });
     return false;
   } finally {
-    await logger.cleanup(job);
+    await logger.cleanup();
   }
 }
 

src/logger/gcloudStream.ts

@@ -1,58 +0,0 @@
-import EventEmitter from 'events';
-
-import { IJob } from 'turtle/job';
-
-// type error when using import
-// https://github.com/googleapis/nodejs-logging-bunyan/issues/241
-// tslint:disable-next-line:no-var-requires
-const { LoggingBunyan } = require('@google-cloud/logging-bunyan');
-
-export interface IGCloudConfig {
-  name: string;
-  resource: {
-    type: string;
-    labels: {
-      node_id: string;
-      location: string;
-      namespace: string;
-    };
-  };
-}
-
-interface IGCloudExtraFields {
-  jobID: string;
-  experienceName: string;
-}
-
-export default class GCloudStream extends EventEmitter {
-  private logsStream: any;
-  private extraFields: IGCloudExtraFields | null;
-
-   constructor(gcloudConfig: IGCloudConfig) {
-    super();
-
-    const { name, resource } = gcloudConfig;
-    this.logsStream = new LoggingBunyan({ name, resource });
-    this.extraFields = null;
-  }
-
-  public init(job: IJob) {
-    this.extraFields = {
-      jobID: job.id,
-      experienceName: job.experienceName,
-    };
-  }
-
-  public cleanup() {
-    this.extraFields = null;
-  }
-
-  public write(rec: any) {
-    const { msg: message, ...other } = rec;
-    this.logsStream.write({
-      message,
-      ...other,
-      data: this.extraFields || {},
-    });
-  }
-}

src/logger/index.ts

@@ -1,103 +1,75 @@
 import bunyan from 'bunyan';
-import bunyanDebugStream from 'bunyan-debug-stream';
-import { SentryStream } from 'bunyan-sentry-stream';
-import { Client as RavenClient } from 'raven';
 
 import config from 'turtle/config';
-import * as constants from 'turtle/constants/logger';
 import { IJob } from 'turtle/job';
-import GCloudStream from 'turtle/logger/gcloudStream';
-import S3Stream from 'turtle/logger/s3Stream';
-import { isOffline } from 'turtle/turtleContext';
+import streams from 'turtle/logger/streams';
 
-interface IStream {
-  stream: any;
-  type?: string;
-  level?: string;
-  reemitErrorEvents?: boolean;
+interface ILoggerFields {
+  [key: string]: string | number;
 }
 
-export const s3logger = new S3Stream();
-let gcloudStream: GCloudStream;
+class Logger {
+  private parentLogger: any;
+  private currentLogger: any;
 
-const streams: IStream[] = [];
-
-if (isOffline()) {
-  const prettyStdOut = new bunyanDebugStream({ forceColor: true });
-  streams.push({ stream: prettyStdOut, type: 'raw', level: config.logger.client.level });
-} else {
-  streams.push(
-    { stream: process.stdout },
-    {
-      type: 'raw',
-      stream: s3logger,
-      reemitErrorEvents: true,
-      level: config.logger.client.level,
-    },
-  );
-}
-
-if (config.sentry.dsn && config.deploymentEnv !== 'development') {
-  const raven = new RavenClient();
-  raven.config(config.sentry.dsn, { environment: config.deploymentEnv });
-  streams.push({
-    level: 'error',
-    type: 'raw', // Mandatory type for SentryStream
-    stream: new SentryStream(raven),
-  });
-}
-
-if (config.google.credentials) {
-  const gcloudConfig = {
-    name: 'turtle',
-    resource: {
-      type: 'generic_node',
-      labels: {
-        node_id: config.hostname,
-        location: '', // default value
-        namespace: '', // default value
-      },
-    },
-  };
-  gcloudStream = new GCloudStream(gcloudConfig);
-  streams.push({
-    level: 'info',
-    type: 'raw',
-    stream: gcloudStream,
-  });
-}
-
-const logger = bunyan.createLogger({
-  name: 'turtle',
-  level: config.logger.level,
-  platform: config.platform,
-  environment: config.deploymentEnv,
-  streams,
-});
-
-logger.withFields = (extraFields: any) => withFields(logger, extraFields);
-
-logger.init = async (job: IJob) => {
-  if (gcloudStream) {
-    gcloudStream.init(job);
+  constructor(parentLogger?: any) {
+    this.parentLogger = parentLogger || bunyan.createLogger({
+      name: 'turtle',
+      level: config.logger.level,
+      platform: config.platform,
+      ...config.deploymentEnv && { environment: config.deploymentEnv },
+      streams: Object.values(streams),
+    });
+    this.currentLogger = this.parentLogger;
   }
-  return await s3logger.init(job);
-};
 
-logger.cleanup = async () => {
-  // a little hacky, but works
-  logger.info({ lastBuildLog: true }, 'this is the last log from this build');
-  if (gcloudStream) {
-    gcloudStream.cleanup();
+  public async initForJob(job: IJob) {
+    this.currentLogger = this.parentLogger.child({
+      jobID: job.id,
+      experienceName: job.experienceName,
+    });
+    const s3Url = await streams.s3.stream.init(job);
+    return s3Url;
   }
-  await s3logger.waitForLogger();
-};
 
-export default logger;
+  public async cleanup() {
+    this.currentLogger = this.parentLogger;
+    await streams.s3.stream.cleanup();
+  }
 
-export function withFields(loggerObj: any, extraFields: any) {
-  return constants.LEVELS.reduce((obj, level) => {
-    obj[level] = (...args: any[]) => loggerObj[level](extraFields, ...args);
-    return obj;
-  }, {} as any);
+  public trace(...all: any[]) {
+    this.currentLogger.trace(...all);
+  }
+
+  public debug(...all: any[]) {
+    this.currentLogger.debug(...all);
+  }
+
+  public info(...all: any[]) {
+    this.currentLogger.info(...all);
+  }
+
+  public warn(...all: any[]) {
+    this.currentLogger.warn(...all);
+  }
+
+  public error(...all: any[]) {
+    this.currentLogger.error(...all);
+  }
+
+  public fatal(...all: any[]) {
+    this.currentLogger.fatal(...all);
+  }
+
+  public child(fields: ILoggerFields) {
+    const newLogger = this.currentLogger.child(fields);
+    return new Logger(newLogger);
+  }
+
+  // only for backward compatibility
+  public withFields(fields: ILoggerFields) {
+    return this.child(fields);
+  }
 }
+
+export default new Logger();

src/logger/s3Stream.ts

@@ -1,111 +0,0 @@
-
-import EventEmitter from 'events';
-import path from 'path';
-
-import fs from 'fs-extra';
-import _ from 'lodash';
-
-import { uploadFile } from 'turtle/aws/s3';
-import config from 'turtle/config';
-import * as constants from 'turtle/constants/logger';
-import { IJob } from 'turtle/job';
-
-export default class S3Stream extends EventEmitter {
-  private s3Url: string | null;
-  private lastFlush: number | null;
-  private filePath: string | null;
-  private fileHandle: number | null;
-  private finishedPromise: Promise<any> | null;
-  private finishedPromiseResolveFn: any;
-  private secrets: any;
-
-  constructor() {
-    super();
-    this.s3Url = null;
-    this.lastFlush = null;
-    this.filePath = null;
-    this.fileHandle = null;
-    this.finishedPromise = null;
-    this.finishedPromiseResolveFn = null;
-  }
-
-  public async init(job: IJob) {
-    this.s3Url = `logs/${job.experienceName}/${job.id}`;
-    const dir = config.directories.tempS3LogsDir;
-    const exists = await fs.pathExists(dir);
-    if (!exists) {
-      await fs.mkdir(dir);
-    }
-    this.filePath = path.join(dir, job.id);
-    this.fileHandle = await fs.open(this.filePath, 'w+', 0o660);
-    this.secrets = {};
-    this.finishedPromise = new Promise((resolveFn) => (this.finishedPromiseResolveFn = resolveFn));
-    const res = await this.flush() as any;
-    return res.Location;
-  }
-
-  public async cleanup() {
-    const res = this.finishedPromiseResolveFn;
-    try {
-      await this.flush(true);
-      await fs.close(this.fileHandle as number);
-      this.fileHandle = null;
-      this.lastFlush = null;
-      this.secrets = {};
-    } finally {
-      this.finishedPromise = null;
-      this.finishedPromiseResolveFn = null;
-      res();
-    }
-  }
-
-  public flush(force = false) {
-    if (force || !this.lastFlush) {
-      return this._flush();
-    }
-    const now = Date.now();
-    if (now - this.lastFlush > config.logger.interval) {
-      return this._flush();
-    }
-  }
-
-  public write(recRaw: any) {
-    if (this.fileHandle) {
-      const rec = JSON.stringify({
-        ...recRaw,
-        level: constants.LEVELS_MAPPING[recRaw.level].toLowerCase(),
-      });
-      if (recRaw.lastBuildLog) {
-        return this.cleanup();
-      }
-      const recSanitized = Object.keys(this.secrets).reduce(
-        (acc, secret) => acc.replace(new RegExp(secret, 'g'), this.secrets[secret]),
-        rec,
-      );
-      fs
-        .write(this.fileHandle as number, `${recSanitized}\n`)
-        .then(() => {
-          this.flush();
-        });
-    }
-  }
-
-  public addSecretsToFilter(secrets: any) {
-    const filteredSecrets = secrets.filter((i: any) => i !== undefined && i !== null);
-    const replacements = filteredSecrets.map((i: any) => 'X'.repeat(i.length));
-    const toAdd = _.zipObject(filteredSecrets, replacements);
-    this.secrets = Object.assign({}, this.secrets, toAdd);
-  }
-
-  public waitForLogger() {
-    return this.finishedPromise;
-  }
-
-  private _flush() {
-    this.lastFlush = Date.now();
-    return uploadFile({
-      srcPath: this.filePath as string,
-      key: this.s3Url as string,
-    });
-  }
-}

src/logger/streams/gcloud.ts

@@ -0,0 +1,29 @@
+import config from 'turtle/config';
+
+// type error when using import
+// https://github.com/googleapis/nodejs-logging-bunyan/issues/241
+// tslint:disable-next-line:no-var-requires
+const { LoggingBunyan } = require('@google-cloud/logging-bunyan');
+
+export default function create() {
+  if (!config.google.credentials) {
+    return null;
+  }
+
+  const gcloudStream = new LoggingBunyan({
+    name: 'turtle',
+    resource: {
+      type: 'generic_node',
+      labels: {
+        node_id: config.hostname,
+        location: '', // default value
+        namespace: '', // default value
+      },
+    },
+  });
+  return {
+    level: 'info',
+    type: 'raw',
+    stream: gcloudStream,
+  };
+}

src/logger/streams/index.ts

@@ -0,0 +1,38 @@
+import pickBy from 'lodash/pickBy';
+
+import createGCloudStream from 'turtle/logger/streams/gcloud';
+import createOfflineStream from 'turtle/logger/streams/offline';
+import createS3Stream from 'turtle/logger/streams/s3';
+import createSentryStream from 'turtle/logger/streams/sentry';
+import { isOffline } from 'turtle/turtleContext';
+
+interface IStream {
+  stream: any;
+  type?: string;
+  level?: string;
+  reemitErrorEvents?: boolean;
+}
+
+interface IStreamMap {
+  [key: string]: IStream;
+}
+
+function prepareStreams(): IStreamMap {
+  if (isOffline()) {
+    return {
+      stdout: createOfflineStream(),
+    };
+  } else {
+    const allStreams = {
+      stdout: { stream: process.stdout },
+      gcloud: createGCloudStream(),
+      s3: createS3Stream(),
+      sentry: createSentryStream(),
+    };
+    return pickBy(allStreams) as IStreamMap;
+  }
+}
+
+const streams = prepareStreams();
+
+export default streams;

src/logger/streams/offline.ts

@@ -0,0 +1,11 @@
+import bunyanDebugStream from 'bunyan-debug-stream';
+import config from 'turtle/config';
+
+export default function create() {
+  const prettyStdOut = new bunyanDebugStream({ forceColor: true });
+  return {
+    stream: prettyStdOut,
+    type: 'raw',
+    level: config.logger.client.level,
+  };
+}

src/logger/streams/s3.ts

@@ -0,0 +1,106 @@
+
+import EventEmitter from 'events';
+import path from 'path';
+
+import fs from 'fs-extra';
+import _ from 'lodash';
+
+import { uploadFile } from 'turtle/aws/s3';
+import config from 'turtle/config';
+import { IJob } from 'turtle/job';
+
+export default function create() {
+  const s3 = new S3Stream();
+  return {
+    type: 'raw',
+    stream: s3,
+    reemitErrorEvents: true,
+    level: config.logger.client.level,
+  };
+}
+
+class S3Stream extends EventEmitter {
+  private s3Url: string | null = null;
+  private lastFlush: number | null = null;
+  private filePath: string | null = null;
+  private fileHandle: number | null = null;
+  private uploadingPromise: Promise<void> | null = null;
+  private uploadingPromiseResolveFn: any;
+  private waitingOnPromise: boolean = false;
+
+  public async init(job: IJob) {
+    this.s3Url = `logs/${job.experienceName}/${job.id}`;
+    const dir = config.directories.tempS3LogsDir;
+    const exists = await fs.pathExists(dir);
+    if (!exists) {
+      await fs.mkdir(dir);
+    }
+    this.filePath = path.join(dir, job.id);
+    this.fileHandle = await fs.open(this.filePath, 'w+', 0o660);
+    this.lastFlush = null;
+
+    const res = await this.flush() as any;
+    return res.Location;
+  }
+
+  public async cleanup() {
+    await this.flush(true);
+    await fs.close(this.fileHandle as number);
+    this.fileHandle = null;
+    this.waitingOnPromise = false;
+  }
+
+  public flush(force = false) {
+    if (force || !this.lastFlush) {
+      return this.flushInternal();
+    }
+    const now = Date.now();
+    if (now - this.lastFlush > config.logger.intervalMs) {
+      return this.flushInternal();
+    }
+  }
+
+  public write(rec: any) {
+    if (!this.fileHandle) {
+      return;
+    }
+    fs
+      .write(this.fileHandle as number, `${JSON.stringify(rec)}\n`)
+      .then(() => {
+        this.flush();
+      });
+  }
+
+  private flushInternal(): any {
+    this.lastFlush = Date.now();
+    if (!this.uploadingPromise) {
+      this.uploadingPromise = new Promise((res) => {
+        this.uploadingPromiseResolveFn = res;
+      });
+      return this
+        .upload()
+        .then((result) => {
+          setTimeout(() => this.uploadingPromiseResolveFn(), 0);
+          return result;
+        });
+    } else {
+      if (this.waitingOnPromise) {
+        return;
+      }
+      this.waitingOnPromise = true;
+      return this.uploadingPromise
+        .then(() => {
+          this.waitingOnPromise = false;
+          this.uploadingPromise = null;
+          return this.flushInternal();
+        });
+    }
+  }
+
+  private upload() {
+    return uploadFile({
+      srcPath: this.filePath as string,
+      key: this.s3Url as string,
+    });
+  }
+}

src/logger/streams/sentry.ts

@@ -0,0 +1,18 @@
+import { SentryStream } from 'bunyan-sentry-stream';
+import { Client as RavenClient } from 'raven';
+
+import config from 'turtle/config';
+
+export default function create() {
+  if (!config.sentry.dsn || config.deploymentEnv === 'development') {
+    return null;
+  }
+
+  const raven = new RavenClient();
+  raven.config(config.sentry.dsn, { environment: config.deploymentEnv });
+  return {
+    level: 'error',
+    type: 'raw', // Mandatory type for SentryStream
+    stream: new SentryStream(raven),
+  };
+}