Fix a logging related bug (#3705)

microsoft · Jun 3, 2021 · 521f191 · 521f191
1 parent b7c91e7
commit 521f191
Show file tree

Hide file tree

Showing 34 changed files with 62 additions and 63 deletions.
diff --git a/ts/nni_manager/common/pythonScript.ts b/ts/nni_manager/common/pythonScript.ts
@@ -22,7 +22,7 @@ export async function runPythonScript(script: string, logger?: Logger): Promise<
 
     if (stderr) {
         if (logger === undefined) {
-            logger = getLogger();
+            logger = getLogger('pythonScript');
         }
         logger.warning('python script has stderr.');
         logger.warning('script:', script);

diff --git a/ts/nni_manager/common/restServer.ts b/ts/nni_manager/common/restServer.ts
@@ -25,7 +25,7 @@ export abstract class RestServer {
     protected hostName: string = '0.0.0.0';
     protected port?: number;
     protected app: express.Application = express();
-    protected log: Logger = getLogger();
+    protected log: Logger = getLogger('RestServer');
     protected basePort?: number;
 
     constructor() {

diff --git a/ts/nni_manager/core/ipcInterface.ts b/ts/nni_manager/core/ipcInterface.ts
@@ -56,7 +56,7 @@ class IpcInterface {
     private incomingStream: Readable;
     private eventEmitter: EventEmitter;
     private readBuffer: Buffer;
-    private logger: Logger = getLogger();
+    private logger: Logger = getLogger('IpcInterface');
 
     /**
      * Construct a IPC proxy

diff --git a/ts/nni_manager/core/nniDataStore.ts b/ts/nni_manager/core/nniDataStore.ts
@@ -19,7 +19,7 @@ import { getDefaultDatabaseDir, mkDirP } from '../common/utils';
 
 class NNIDataStore implements DataStore {
     private db: Database = component.get(Database);
-    private log: Logger = getLogger();
+    private log: Logger = getLogger('NNIDataStore');
     private initTask!: Deferred<void>;
 
     public init(): Promise<void> {
@@ -71,7 +71,6 @@ class NNIDataStore implements DataStore {
 
     public storeTrialJobEvent(
         event: TrialJobEvent, trialJobId: string, hyperParameter?: string, jobDetail?: TrialJobDetail): Promise<void> {
-        //this.log.debug(`storeTrialJobEvent: event: ${event}, data: ${hyperParameter}, jobDetail: ${JSON.stringify(jobDetail)}`);
 
         // Use the timestamp in jobDetail as TrialJobEvent timestamp for different events
         let timestamp: number | undefined;
@@ -243,7 +242,7 @@ class NNIDataStore implements DataStore {
         for (const metric of metrics) {
             const existMetrics: MetricDataRecord[] | undefined = map.get(metric.trialJobId);
             if (existMetrics !== undefined) {
-                this.log.error(`Found multiple FINAL results for trial job ${trialJobId}, metrics: ${JSON.stringify(metrics)}`);
+                this.log.error(`Found multiple FINAL results for trial job ${trialJobId}, metrics:`, metrics);
             } else {
                 map.set(metric.trialJobId, [metric]);
             }

diff --git a/ts/nni_manager/core/nniExperimentsManager.ts b/ts/nni_manager/core/nniExperimentsManager.ts
@@ -30,7 +30,7 @@ class NNIExperimentsManager implements ExperimentManager {
 
     constructor() {
         this.experimentsPath = getExperimentsInfoPath();
-        this.log = getLogger();
+        this.log = getLogger('NNIExperimentsManager');
         this.profileUpdateTimer = {};
     }
 

diff --git a/ts/nni_manager/core/nniTensorboardManager.ts b/ts/nni_manager/core/nniTensorboardManager.ts
@@ -37,7 +37,7 @@ class NNITensorboardManager implements TensorboardManager {
     private nniManager: Manager;
 
     constructor() {
-        this.log = getLogger();
+        this.log = getLogger('NNITensorboardManager');
         this.tensorboardTaskMap = new Map<string, TensorboardTaskDetail>();
         this.setTensorboardVersion();
         this.nniManager = component.get(Manager);

diff --git a/ts/nni_manager/core/nnimanager.ts b/ts/nni_manager/core/nnimanager.ts
@@ -61,7 +61,7 @@ class NNIManager implements Manager {
         this.trialDataForTuner = '';
         this.readonly = false;
 
-        this.log = getLogger();
+        this.log = getLogger('NNIManager');
         this.dataStore = component.get(DataStore);
         this.status = {
             status: 'INITIALIZED',
@@ -659,7 +659,7 @@ class NNIManager implements Manager {
                     }
                     const form = this.waitingTrials.shift() as TrialJobApplicationForm;
                     this.currSubmittedTrialNum++;
-                    this.log.info(`submitTrialJob: form: ${JSON.stringify(form)}`);
+                    this.log.info('submitTrialJob: form:', form);
                     const trialJobDetail: TrialJobDetail = await this.trainingService.submitTrialJob(form);
                     const Snapshot: TrialJobDetail = Object.assign({}, trialJobDetail);
                     await this.storeExperimentProfile();
@@ -732,15 +732,15 @@ class NNIManager implements Manager {
     }
 
     private async onTrialJobMetrics(metric: TrialJobMetric): Promise<void> {
-        this.log.debug(`NNIManager received trial job metrics: ${JSON.stringify(metric)}`);
+        this.log.debug('NNIManager received trial job metrics:', metric);
         if (this.trialJobs.has(metric.id)){
             await this.dataStore.storeMetricData(metric.id, metric.data);
             if (this.dispatcher === undefined) {
                 throw new Error('Error: tuner has not been setup');
             }
             this.dispatcher.sendCommand(REPORT_METRIC_DATA, metric.data);
         } else {
-            this.log.warning(`NNIManager received non-existent trial job metrics: ${metric}`);
+            this.log.warning('NNIManager received non-existent trial job metrics:', metric);
         }
     }
 
@@ -804,7 +804,7 @@ class NNIManager implements Manager {
                         index: tunerCommand.parameter_index
                     }
                 };
-                this.log.info(`updateTrialJob: job id: ${tunerCommand.trial_job_id}, form: ${JSON.stringify(trialJobForm)}`);
+                this.log.info('updateTrialJob: job id:', tunerCommand.trial_job_id, 'form:', trialJobForm);
                 await this.trainingService.updateTrialJob(tunerCommand.trial_job_id, trialJobForm);
                 if (tunerCommand['parameters'] !== null) {
                     // parameters field is set as empty string if no more hyper parameter can be generated by tuner.
@@ -820,7 +820,7 @@ class NNIManager implements Manager {
                 break;
             }
             case KILL_TRIAL_JOB: {
-                this.log.info(`cancelTrialJob: ${JSON.parse(content)}`);
+                this.log.info('cancelTrialJob:', content);
                 await this.trainingService.cancelTrialJob(JSON.parse(content), true);
                 break;
             }

diff --git a/ts/nni_manager/core/sqlDatabase.ts b/ts/nni_manager/core/sqlDatabase.ts
@@ -80,7 +80,7 @@ function loadMetricData(row: any): MetricDataRecord {
 
 class SqlDB implements Database {
     private db!: sqlite3.Database;
-    private log: Logger = getLogger();
+    private log: Logger = getLogger('SqlDB');
     private initTask!: Deferred<void>;
 
     public init(createNew: boolean, dbDir: string): Promise<void> {
@@ -130,7 +130,7 @@ class SqlDB implements Database {
             exp.nextSequenceId,
             exp.revision
         ];
-        this.log.trace(`storeExperimentProfile: SQL: ${sql}, args: ${JSON.stringify(args)}`);
+        this.log.trace(`storeExperimentProfile: SQL: ${sql}, args:`, args);
         const deferred: Deferred<void> = new Deferred<void>();
         this.db.run(sql, args, (err: Error | null) => { this.resolve(deferred, err); });
 
@@ -147,7 +147,7 @@ class SqlDB implements Database {
             sql = 'select * from ExperimentProfile where id=? and revision=?';
             args = [experimentId, revision];
         }
-        this.log.trace(`queryExperimentProfile: SQL: ${sql}, args: ${JSON.stringify(args)}`);
+        this.log.trace(`queryExperimentProfile: SQL: ${sql}, args:`, args);
         const deferred: Deferred<ExperimentProfile[]> = new Deferred<ExperimentProfile[]>();
         this.db.all(sql, args, (err: Error | null, rows: any[]) => {
             this.resolve(deferred, err, rows, loadExperimentProfile);
@@ -170,7 +170,7 @@ class SqlDB implements Database {
         const message: string | undefined = jobDetail === undefined ? undefined : jobDetail.message;
         const args: any[] = [timestamp, trialJobId, event, hyperParameter, logPath, sequenceId, message];
 
-        this.log.trace(`storeTrialJobEvent: SQL: ${sql}, args: ${JSON.stringify(args)}`);
+        this.log.trace(`storeTrialJobEvent: SQL: ${sql}, args:`, args);
         const deferred: Deferred<void> = new Deferred<void>();
         this.db.run(sql, args, (err: Error | null) => { this.resolve(deferred, err); });
 
@@ -193,7 +193,7 @@ class SqlDB implements Database {
             args = [trialJobId, event];
         }
 
-        this.log.trace(`queryTrialJobEvent: SQL: ${sql}, args: ${JSON.stringify(args)}`);
+        this.log.trace(`queryTrialJobEvent: SQL: ${sql}, args:`, args);
         const deferred: Deferred<TrialJobEventRecord[]> = new Deferred<TrialJobEventRecord[]>();
         this.db.all(sql, args, (err: Error | null, rows: any[]) => {
             this.resolve(deferred, err, rows, loadTrialJobEvent);
@@ -207,7 +207,7 @@ class SqlDB implements Database {
         const json: MetricDataRecord = JSON.parse(data);
         const args: any[] = [Date.now(), json.trialJobId, json.parameterId, json.type, json.sequence, JSON.stringify(json.data)];
 
-        this.log.trace(`storeMetricData: SQL: ${sql}, args: ${JSON.stringify(args)}`);
+        this.log.trace(`storeMetricData: SQL: ${sql}, args:`, args);
         const deferred: Deferred<void> = new Deferred<void>();
         this.db.run(sql, args, (err: Error | null) => { this.resolve(deferred, err); });
 
@@ -230,7 +230,7 @@ class SqlDB implements Database {
             args = [trialJobId, metricType];
         }
 
-        this.log.trace(`queryMetricData: SQL: ${sql}, args: ${JSON.stringify(args)}`);
+        this.log.trace(`queryMetricData: SQL: ${sql}, args:`, args);
         const deferred: Deferred<MetricDataRecord[]> = new Deferred<MetricDataRecord[]>();
         this.db.all(sql, args, (err: Error | null, rows: any[]) => {
             this.resolve(deferred, err, rows, loadMetricData);
@@ -259,7 +259,7 @@ class SqlDB implements Database {
             for (const row of (<any[]>rows)) {
                 data.push(rowLoader(row));
             }
-            this.log.trace(`sql query result: ${JSON.stringify(data)}`);
+            this.log.trace(`sql query result:`, data);
             (<Deferred<T[]>>deferred).resolve(data);
         }
     }

diff --git a/ts/nni_manager/rest_server/restHandler.ts b/ts/nni_manager/rest_server/restHandler.ts
@@ -32,14 +32,14 @@ class NNIRestHandler {
         this.experimentsManager = component.get(ExperimentManager);
         this.tensorboardManager = component.get(TensorboardManager);
         this.restServer = rs;
-        this.log = getLogger();
+        this.log = getLogger('NNIRestHandler');
     }
 
     public createRestHandler(): Router {
         const router: Router = Router();
 
         router.use((req: Request, res: Response, next) => {
-            this.log.debug(`${req.method}: ${req.url}: body:\n${JSON.stringify(req.body, undefined, 4)}`);
+            this.log.debug(`${req.method}: ${req.url}: body:`, req.body);
             res.header('Access-Control-Allow-Headers', 'Origin, X-Requested-With, Content-Type, Accept');
             res.header('Access-Control-Allow-Methods', 'PUT,POST,GET,DELETE,OPTIONS');
 

diff --git a/ts/nni_manager/training_service/common/clusterJobRestServer.ts b/ts/nni_manager/training_service/common/clusterJobRestServer.ts
@@ -76,7 +76,7 @@ export abstract class ClusterJobRestServer extends RestServer {
         const router: Router = Router();
 
         router.use((req: Request, res: Response, next: any) => {
-            this.log.info(`${req.method}: ${req.url}: body:\n${JSON.stringify(req.body, undefined, 4)}`);
+            this.log.info(`${req.method}: ${req.url}: body:`, req.body);
             res.setHeader('Content-Type', 'application/json');
             next();
         });
@@ -109,7 +109,7 @@ export abstract class ClusterJobRestServer extends RestServer {
         router.post(`/update-metrics/${this.expId}/:trialId`, (req: Request, res: Response) => {
             try {
                 this.log.info(`Get update-metrics request, trial job id is ${req.params.trialId}`);
-                this.log.info(`update-metrics body is ${JSON.stringify(req.body)}`);
+                this.log.info('update-metrics body is', req.body);
 
                 this.handleTrialMetrics(req.body.jobId, req.body.metrics);
 

diff --git a/ts/nni_manager/training_service/common/util.ts b/ts/nni_manager/training_service/common/util.ts
@@ -111,7 +111,7 @@ export async function execCopydir(source: string, destination: string): Promise<
                 await fs.promises.mkdir(destPath);
             }
         } else {
-            getLogger().debug(`Copying file from ${sourcePath} to ${destPath}`);
+            getLogger('execCopydir').debug(`Copying file from ${sourcePath} to ${destPath}`);
             await fs.promises.copyFile(sourcePath, destPath);
         }
     }

diff --git a/ts/nni_manager/training_service/kubernetes/azureStorageClientUtils.ts b/ts/nni_manager/training_service/kubernetes/azureStorageClientUtils.ts
@@ -22,7 +22,7 @@ export namespace AzureStorageClientUtility {
         const deferred: Deferred<boolean> = new Deferred<boolean>();
         fileServerClient.createShareIfNotExists(azureShare, (error: any, _result: any, _response: any) => {
             if (error) {
-                getLogger()
+                getLogger('AzureStorageClientUtility')
                   .error(`Create share failed:, ${error}`);
                 deferred.resolve(false);
             } else {
@@ -43,7 +43,7 @@ export namespace AzureStorageClientUtility {
         const deferred: Deferred<boolean> = new Deferred<boolean>();
         fileServerClient.createDirectoryIfNotExists(azureShare, azureFoler, (error: any, _result: any, _response: any) => {
             if (error) {
-                getLogger()
+                getLogger('AzureStorageClientUtility')
                   .error(`Create directory failed:, ${error}`);
                 deferred.resolve(false);
             } else {
@@ -91,7 +91,7 @@ export namespace AzureStorageClientUtility {
         await fileServerClient.createFileFromLocalFile(azureShare, azureDirectory, azureFileName, localFilePath,
                                                        (error: any, _result: any, _response: any) => {
             if (error) {
-                getLogger()
+                getLogger('AzureStorageClientUtility')
                   .error(`Upload file failed:, ${error}`);
                 deferred.resolve(false);
             } else {
@@ -116,7 +116,7 @@ export namespace AzureStorageClientUtility {
         await fileServerClient.getFileToStream(azureShare, azureDirectory, azureFileName, fs.createWriteStream(localFilePath),
                                                (error: any, _result: any, _response: any) => {
             if (error) {
-                getLogger()
+                getLogger('AzureStorageClientUtility')
                   .error(`Download file failed:, ${error}`);
                 deferred.resolve(false);
             } else {
@@ -185,19 +185,19 @@ export namespace AzureStorageClientUtility {
         fileServerClient.listFilesAndDirectoriesSegmented(azureShare, azureDirectory, 'null',
                                                           async (_error: any, result: any, _response: any) => {
             if (('entries' in result) === false) {
-                getLogger()
+                getLogger('AzureStorageClientUtility')
                   .error(`list files failed, can't get entries in result`);
                 throw new Error(`list files failed, can't get entries in result`);
             }
 
             if (('files' in result.entries) === false) {
-                getLogger()
+                getLogger('AzureStorageClientUtility')
                   .error(`list files failed, can't get files in result['entries']`);
                 throw new Error(`list files failed, can't get files in result['entries']`);
             }
 
             if (('directories' in result.directories) === false) {
-                getLogger()
+                getLogger('AzureStorageClientUtility')
                   .error(`list files failed, can't get directories in result['entries']`);
                 throw new Error(`list files failed, can't get directories in result['entries']`);
             }

diff --git a/ts/nni_manager/training_service/kubernetes/kubernetesApiClient.ts b/ts/nni_manager/training_service/kubernetes/kubernetesApiClient.ts
@@ -12,7 +12,7 @@ import {getLogger, Logger} from '../../common/log';
  */
 class GeneralK8sClient {
     protected readonly client: any;
-    protected readonly log: Logger = getLogger();
+    protected readonly log: Logger = getLogger('GeneralK8sClient');
     protected namespace: string = 'default';
 
     constructor() {
@@ -135,7 +135,7 @@ class GeneralK8sClient {
  */
 abstract class KubernetesCRDClient {
     protected readonly client: any;
-    protected readonly log: Logger = getLogger();
+    protected readonly log: Logger = getLogger('KubernetesCRDClient');
     protected crdSchema: any;
 
     constructor() {

diff --git a/ts/nni_manager/training_service/kubernetes/kubernetesJobInfoCollector.ts b/ts/nni_manager/training_service/kubernetes/kubernetesJobInfoCollector.ts
@@ -15,7 +15,7 @@ import { KubernetesTrialJobDetail } from './kubernetesData';
  */
 export class KubernetesJobInfoCollector {
     protected readonly trialJobsMap: Map<string, KubernetesTrialJobDetail>;
-    protected readonly log: Logger = getLogger();
+    protected readonly log: Logger = getLogger('KubernetesJobInfoCollector');
     protected readonly statusesNeedToCheck: TrialJobStatus[];
 
     constructor(jobMap: Map<string, KubernetesTrialJobDetail>) {

diff --git a/ts/nni_manager/training_service/kubernetes/kubernetesTrainingService.ts b/ts/nni_manager/training_service/kubernetes/kubernetesTrainingService.ts
@@ -54,7 +54,7 @@ abstract class KubernetesTrainingService {
     protected expContainerCodeFolder: string;
 
     constructor() {
-        this.log = getLogger();
+        this.log = getLogger('KubernetesTrainingService');
         this.metricsEmitter = new EventEmitter();
         this.trialJobsMap = new Map<string, KubernetesTrialJobDetail>();
         this.trialLocalTempFolder = path.join(getExperimentRootDir(), 'trials-nfs-tmp');

diff --git a/ts/nni_manager/training_service/local/gpuScheduler.ts b/ts/nni_manager/training_service/local/gpuScheduler.ts
@@ -24,7 +24,7 @@ class GPUScheduler {
 
     constructor() {
         this.stopping = false;
-        this.log = getLogger();
+        this.log = getLogger('GPUScheduler');
         this.gpuMetricCollectorScriptFolder = `${os.tmpdir()}/${os.userInfo().username}/nni/script`;
     }
 

diff --git a/ts/nni_manager/training_service/local/localTrainingService.ts b/ts/nni_manager/training_service/local/localTrainingService.ts
@@ -98,7 +98,7 @@ class LocalTrainingService implements TrainingService {
         this.jobMap = new Map<string, LocalTrialJobDetail>();
         this.jobQueue = [];
         this.stopping = false;
-        this.log = getLogger();
+        this.log = getLogger('LocalTrainingService');
         this.experimentId = getExperimentId();
         this.jobStreamMap = new Map<string, ts.Stream>();
         this.log.info('Construct local machine training service.');
@@ -204,7 +204,7 @@ class LocalTrainingService implements TrainingService {
         this.jobQueue.push(trialJobId);
         this.jobMap.set(trialJobId, trialJobDetail);
 
-        this.log.debug(`submitTrialJob: return: ${JSON.stringify(trialJobDetail)} `);
+        this.log.debug('submitTrialJob: return:',  trialJobDetail);
 
         return Promise.resolve(trialJobDetail);
     }

diff --git a/ts/nni_manager/training_service/pai/paiJobInfoCollector.ts b/ts/nni_manager/training_service/pai/paiJobInfoCollector.ts
@@ -18,7 +18,7 @@ interface FlattenOpenpaiConfig extends ExperimentConfig, OpenpaiConfig { }
  */
 export class PAIJobInfoCollector {
     private readonly trialJobsMap: Map<string, PAITrialJobDetail>;
-    private readonly log: Logger = getLogger();
+    private readonly log: Logger = getLogger('PAIJobInfoCollector');
     private readonly statusesNeedToCheck: TrialJobStatus[];
     private readonly finalStatuses: TrialJobStatus[];
 

diff --git a/ts/nni_manager/training_service/pai/paiJobRestServer.ts b/ts/nni_manager/training_service/pai/paiJobRestServer.ts
@@ -46,7 +46,7 @@ export class PAIJobRestServer extends ClusterJobRestServer {
 
         router.post(`/parameter-file-meta`, (req: Request, res: Response) => {
             try {
-                this.log.info(`POST /parameter-file-meta, body is ${JSON.stringify(req.body)}`);
+                this.log.info('POST /parameter-file-meta, body is', req.body);
                 this.parameterFileMetaList.push(req.body);
                 res.send();
             } catch (err) {

diff --git a/ts/nni_manager/training_service/pai/paiTrainingService.ts b/ts/nni_manager/training_service/pai/paiTrainingService.ts
@@ -63,7 +63,7 @@ class PAITrainingService implements TrainingService {
     private config: FlattenOpenpaiConfig;
 
     constructor(config: ExperimentConfig) {
-        this.log = getLogger();
+        this.log = getLogger('PAITrainingService');
         this.metricsEmitter = new EventEmitter();
         this.trialJobsMap = new Map<string, PAITrialJobDetail>();
         this.jobQueue = [];
@@ -308,7 +308,7 @@ class PAITrainingService implements TrainingService {
     }
 
     public async submitTrialJob(form: TrialJobApplicationForm): Promise<TrialJobDetail> {
-        this.log.info(`submitTrialJob: form: ${JSON.stringify(form)}`);
+        this.log.info('submitTrialJob: form:',  form);
 
         const trialJobId: string = uniqueString(5);
         //TODO: use HDFS working folder instead