Improve NNI manager logging (#3624)

Co-authored-by: liuzhe <zhe.liu@microsoft.com>

nni/tools/nnictl/launcher.py

@@ -368,7 +368,7 @@ def launch_experiment(args, experiment_config, mode, experiment_id, config_versi
         log_dir = experiment_config['logDir'] if experiment_config.get('logDir') else NNI_HOME_DIR
     else:
         log_dir = experiment_config['experimentWorkingDirectory'] if experiment_config.get('experimentWorkingDirectory') else NNI_HOME_DIR
-    log_level = experiment_config['logLevel'] if experiment_config.get('logLevel') else None
+    log_level = experiment_config['logLevel'] if experiment_config.get('logLevel') else 'info'
     #view experiment mode do not need debug function, when view an experiment, there will be no new logs created
     foreground = False
     if mode != 'view':

ts/nni_manager/common/log.ts

@@ -5,151 +5,135 @@
 
 import * as fs from 'fs';
 import { Writable } from 'stream';
-import { WritableStreamBuffer } from 'stream-buffers';
-import { format } from 'util';
-import * as component from '../common/component';
-import { getExperimentStartupInfo, isReadonly } from './experimentStartupInfo';
-
-const FATAL: number = 1;
-const ERROR: number = 2;
-const WARNING: number = 3;
-const INFO: number = 4;
-const DEBUG: number = 5;
-const TRACE: number = 6;
-
-const logLevelNameMap: Map<string, number> = new Map([
-    ['fatal', FATAL],
-    ['error', ERROR],
-    ['warning', WARNING],
-    ['info', INFO],
-    ['debug', DEBUG],
-    ['trace', TRACE]
+
+/* log level constants */
+
+export const DEBUG = 10;
+export const INFO = 20;
+export const WARNING = 30;
+export const ERROR = 40;
+export const CRITICAL = 50;
+
+export const TRACE = 1;
+export const FATAL = 50;
+
+const levelNames = new Map<number, string>([
+    [CRITICAL, 'CRITICAL'],
+    [ERROR, 'ERROR'],
+    [WARNING, 'WARNING'],
+    [INFO, 'INFO'],
+    [DEBUG, 'DEBUG'],
+    [TRACE, 'TRACE'],
 ]);
 
-class BufferSerialEmitter {
-    private buffer: Buffer;
-    private emitting: boolean;
-    private writable: Writable;
+/* global_ states */
 
-    constructor(writable: Writable) {
-        this.buffer = Buffer.alloc(0);
-        this.emitting = false;
-        this.writable = writable;
-    }
+let logFile: Writable | null = null;
+let logLevel: number = 0;
+const loggers = new Map<string, Logger>();
 
-    public feed(buffer: Buffer): void {
-        this.buffer = Buffer.concat([this.buffer, buffer]);
-        if (!this.emitting) {
-            this.emit();
-        }
-    }
+/* major api */
 
-    private emit(): void {
-        this.emitting = true;
-        this.writable.write(this.buffer, () => {
-            if (this.buffer.length === 0) {
-                this.emitting = false;
-            } else {
-                this.emit();
-            }
-        });
-        this.buffer = Buffer.alloc(0);
+export class Logger {
+    private name: string;
+
+    constructor(name: string = 'root') {
+        this.name = name;
     }
-}
 
-@component.Singleton
-class Logger {
-    private level: number = INFO;
-    private bufferSerialEmitter?: BufferSerialEmitter;
-    private writable?: Writable;
-    private readonly: boolean = false;
-
-    constructor(fileName?: string) {
-        const logFile: string | undefined = fileName;
-        if (logFile) {
-            this.writable = fs.createWriteStream(logFile, {
-                flags: 'a+',
-                encoding: 'utf8',
-                autoClose: true
-            });
-            this.bufferSerialEmitter = new BufferSerialEmitter(this.writable);
-        }
+    public trace(...args: any[]): void {
+        this.log(TRACE, args);
+    }
 
-        const logLevelName: string = getExperimentStartupInfo()
-                                    .getLogLevel();
-        const logLevel: number | undefined = logLevelNameMap.get(logLevelName);
-        if (logLevel !== undefined) {
-            this.level = logLevel;
-        }
+    public debug(...args: any[]): void {
+        this.log(DEBUG, args);
+    }
 
-        this.readonly = isReadonly();
+    public info(...args: any[]): void {
+        this.log(INFO, args);
     }
 
-    public close(): void {
-        if (this.writable) {
-            this.writable.destroy();
-        }
+    public warning(...args: any[]): void {
+        this.log(WARNING, args);
     }
 
-    public trace(...param: any[]): void {
-        if (this.level >= TRACE) {
-            this.log('TRACE', param);
-        }
+    public error(...args: any[]): void {
+        this.log(ERROR, args);
     }
 
-    public debug(...param: any[]): void {
-        if (this.level >= DEBUG) {
-            this.log('DEBUG', param);
-        }
+    public critical(...args: any[]): void {
+        this.log(CRITICAL, args);
     }
 
-    public info(...param: any[]): void {
-        if (this.level >= INFO) {
-            this.log('INFO', param);
-        }
+    public fatal(...args: any[]): void {
+        this.log(FATAL, args);
     }
 
-    public warning(...param: any[]): void {
-        if (this.level >= WARNING) {
-            this.log('WARNING', param);
+    private log(level: number, args: any[]): void {
+        if (level < logLevel || logFile === null) {
+            return;
         }
-    }
 
-    public error(...param: any[]): void {
-        if (this.level >= ERROR) {
-            this.log('ERROR', param);
+        // `time.toLocaleString('sv')` trick does not work for Windows
+        const isoTime = new Date(new Date().toLocaleString() + ' UTC').toISOString();
+        const time = isoTime.slice(0, 10) + ' ' + isoTime.slice(11, 19);
+
+        const levelName = levelNames.has(level) ? levelNames.get(level) : level.toString();
+
+        const words = [];
+        for (const arg of args) {
+            if (arg === undefined) {
+                words.push('undefined');
+            } else if (arg === null) {
+                words.push('null');
+            } else if (typeof arg === 'object') {
+                const json = JSON.stringify(arg);
+                words.push(json === undefined ? arg : json);
+            } else {
+                words.push(arg);
+            }
         }
+        const message = words.join(' ');
+        
+        const record = `[${time}] ${levelName} (${this.name}) ${message}\n`;
+        logFile.write(record);
     }
+}
 
-    public fatal(...param: any[]): void {
-        this.log('FATAL', param);
+export function getLogger(name: string = 'root'): Logger {
+    let logger = loggers.get(name);
+    if (logger === undefined) {
+        logger = new Logger(name);
+        loggers.set(name, logger);
     }
-    
-    /**
-     * if the experiment is not in readonly mode, write log content to stream
-     * @param level log level
-     * @param param the params to be written
-     */
-    private log(level: string, param: any[]): void {
-        if (!this.readonly) {
-            const time = new Date();
-            const localTime = new Date(time.getTime() - time.getTimezoneOffset() * 60000);
-            const timeStr = localTime.toISOString().slice(0, -5).replace('T', ' ');
-            const logContent = `[${timeStr}] ${level} ${format(param)}\n`;
-            if (this.writable && this.bufferSerialEmitter) {
-                const buffer: WritableStreamBuffer = new WritableStreamBuffer();
-                buffer.write(logContent);
-                buffer.end();
-                this.bufferSerialEmitter.feed(buffer.getContents());
-            } else {
-                console.log(logContent);
-            }
+    return logger;
+}
+
+/* management functions */
+
+export function setLogLevel(levelName: string): void {
+    if (levelName) {
+        const level = module.exports[levelName.toUpperCase()];
+        if (typeof level === 'number') {
+            logLevel = level;
+        } else {
+            console.log('[ERROR] Bad log level:', levelName);
+            getLogger('logging').error('Bad log level:', levelName);
         }
     }
 }
 
-function getLogger(): Logger {
-    return component.get(Logger);
+export function startLogging(logPath: string): void {
+    logFile = fs.createWriteStream(logPath, {
+        flags: 'a+',
+        encoding: 'utf8',
+        autoClose: true
+    });
 }
 
-export { Logger, getLogger, logLevelNameMap };
+export function stopLogging(): void {
+    if (logFile !== null) {
+        logFile.end();
+        logFile = null;
+    }
+}

ts/nni_manager/common/utils.ts

@@ -23,7 +23,6 @@ import { ExperimentStartupInfo, getExperimentStartupInfo, setExperimentStartupIn
 import { ExperimentConfig, Manager } from './manager';
 import { ExperimentManager } from './experimentManager';
 import { HyperParameters, TrainingService, TrialJobStatus } from './trainingService';
-import { logLevelNameMap } from './log';
 
 function getExperimentRootDir(): string {
     return getExperimentStartupInfo()
@@ -195,9 +194,6 @@ function prepareUnitTest(): void {
     Container.snapshot(ExperimentManager);
 
     const logLevel: string = parseArg(['--log_level', '-ll']);
-    if (logLevel.length > 0 && !logLevelNameMap.has(logLevel)) {
-        console.log(`FATAL: invalid log_level: ${logLevel}`);
-    }
 
     setExperimentStartupInfo(true, 'unittest', 8080, 'unittest', undefined, logLevel);
     mkDirPSync(getLogDir());

ts/nni_manager/core/nnimanager.ts

@@ -10,7 +10,7 @@ import * as component from '../common/component';
 import { DataStore, MetricDataRecord, MetricType, TrialJobInfo } from '../common/datastore';
 import { NNIError } from '../common/errors';
 import { getExperimentId, getDispatcherPipe } from '../common/experimentStartupInfo';
-import { getLogger, Logger } from '../common/log';
+import { Logger, getLogger, stopLogging } from '../common/log';
 import {
     ExperimentProfile, Manager, ExperimentStatus,
     NNIManagerStatus, ProfileUpdateType, TrialJobStatistics
@@ -362,7 +362,7 @@ class NNIManager implements Manager {
             hasError = true;
             this.log.error(`${err.stack}`);
         } finally {
-            this.log.close();
+            stopLogging();
             process.exit(hasError ? 1 : 0);
         }
     }

ts/nni_manager/main.ts

@@ -10,7 +10,7 @@ import * as path from 'path';
 import * as component from './common/component';
 import { Database, DataStore } from './common/datastore';
 import { setExperimentStartupInfo } from './common/experimentStartupInfo';
-import { getLogger, Logger, logLevelNameMap } from './common/log';
+import { getLogger, setLogLevel, startLogging } from './common/log';
 import { Manager, ExperimentStartUpMode } from './common/manager';
 import { ExperimentManager } from './common/experimentManager';
 import { TensorboardManager } from './common/tensorboardManager';
@@ -47,14 +47,15 @@ async function initContainer(foreground: boolean, platformMode: string, logFileN
         .to(NNITensorboardManager)
         .scope(Scope.Singleton);
     const DEFAULT_LOGFILE: string = path.join(getLogDir(), 'nnimanager.log');
-    if (foreground) {
-        logFileName = undefined;
-    } else if (logFileName === undefined) {
-        logFileName = DEFAULT_LOGFILE;
+    if (!foreground) {
+        if (logFileName === undefined) {
+            startLogging(DEFAULT_LOGFILE);
+        } else {
+            startLogging(logFileName);
+        }
+        // eslint-disable-next-line @typescript-eslint/no-use-before-define
+        setLogLevel(logLevel);
     }
-    Container.bind(Logger).provider({
-        get: (): Logger => new Logger(logFileName)
-    });
     const ds: DataStore = component.get(DataStore);
 
     await ds.init();
@@ -110,9 +111,6 @@ if (logDir.length > 0) {
 }
 
 const logLevel: string = parseArg(['--log_level', '-ll']);
-if (logLevel.length > 0 && !logLevelNameMap.has(logLevel)) {
-    console.log(`FATAL: invalid log_level: ${logLevel}`);
-}
 
 const readonlyArg: string = parseArg(['--readonly', '-r']);
 if (!('true' || 'false').includes(readonlyArg.toLowerCase())) {
@@ -132,11 +130,9 @@ mkDirP(getLogDir())
             await initContainer(foreground, mode);
             const restServer: NNIRestServer = component.get(NNIRestServer);
             await restServer.start();
-            const log: Logger = getLogger();
-            log.info(`Rest server listening on: ${restServer.endPoint}`);
+            getLogger('main').info(`Rest server listening on: ${restServer.endPoint}`);
         } catch (err) {
-            const log: Logger = getLogger();
-            log.error(`${err.stack}`);
+            getLogger('main').error(`${err.stack}`);
             throw err;
         }
     })