Merge pull request #2169 from github/dbartol/tee-logger

Use `TeeLogger` instead of `additionalLogLocation:` option

Author: Dave Bartolomeo

extensions/ql-vscode/src/common/logging/index.ts

@@ -1,3 +1,4 @@
 export * from "./logger";
+export * from "./tee-logger";
 export * from "./vscode/loggers";
 export * from "./vscode/output-channel-logger";

extensions/ql-vscode/src/common/logging/logger.ts

@@ -1,9 +1,6 @@
 export interface LogOptions {
   // If false, don't output a trailing newline for the log entry. Default true.
   trailingNewline?: boolean;
-
-  // If specified, add this log entry to the log file at the specified location.
-  additionalLogLocation?: string;
 }
 
 export interface Logger {
@@ -25,11 +22,4 @@ export interface Logger {
    * @param preserveFocus When `true` the channel will not take focus.
    */
   show(preserveFocus?: boolean): void;
-
-  /**
-   * Remove the log at the specified location.
-   *
-   * @param location log to remove
-   */
-  removeAdditionalLogLocation(location: string | undefined): void;
 }

extensions/ql-vscode/src/common/logging/tee-logger.ts

@@ -0,0 +1,68 @@
+import { appendFile, ensureFile } from "fs-extra";
+import { isAbsolute } from "path";
+import { getErrorMessage } from "../../pure/helpers-pure";
+import { Logger, LogOptions } from "./logger";
+
+/**
+ * An implementation of {@link Logger} that sends the output both to another {@link Logger}
+ * and to a file.
+ *
+ * The first time a message is written, an additional banner is written to the underlying logger
+ * pointing the user to the "side log" file.
+ */
+export class TeeLogger implements Logger {
+  private emittedRedirectMessage = false;
+  private error = false;
+
+  public constructor(
+    private readonly logger: Logger,
+    private readonly location: string,
+  ) {
+    if (!isAbsolute(location)) {
+      throw new Error(
+        `Additional Log Location must be an absolute path: ${location}`,
+      );
+    }
+  }
+
+  async log(message: string, options = {} as LogOptions): Promise<void> {
+    if (!this.emittedRedirectMessage) {
+      this.emittedRedirectMessage = true;
+      const msg = `| Log being saved to ${this.location} |`;
+      const separator = new Array(msg.length).fill("-").join("");
+      await this.logger.log(separator);
+      await this.logger.log(msg);
+      await this.logger.log(separator);
+    }
+
+    if (!this.error) {
+      try {
+        const trailingNewline = options.trailingNewline ?? true;
+        await ensureFile(this.location);
+
+        await appendFile(
+          this.location,
+          message + (trailingNewline ? "\n" : ""),
+          {
+            encoding: "utf8",
+          },
+        );
+      } catch (e) {
+        // Write an error message to the primary log, and stop trying to write to the side log.
+        this.error = true;
+        const errorMessage = getErrorMessage(e);
+        await this.logger.log(
+          `Error writing to additional log file: ${errorMessage}`,
+        );
+      }
+    }
+
+    if (!this.error) {
+      await this.logger.log(message, options);
+    }
+  }
+
+  show(preserveFocus?: boolean): void {
+    this.logger.show(preserveFocus);
+  }
+}

extensions/ql-vscode/src/common/logging/vscode/output-channel-logger.ts

@@ -1,6 +1,4 @@
 import { window as Window, OutputChannel, Progress } from "vscode";
-import { ensureFile, appendFile } from "fs-extra";
-import { isAbsolute } from "path";
 import { Logger, LogOptions } from "../logger";
 import { DisposableObject } from "../../../pure/disposable-object";
 
@@ -9,10 +7,6 @@ import { DisposableObject } from "../../../pure/disposable-object";
  */
 export class OutputChannelLogger extends DisposableObject implements Logger {
   public readonly outputChannel: OutputChannel;
-  private readonly additionalLocations = new Map<
-    string,
-    AdditionalLogLocation
-  >();
   isCustomLogDirectory: boolean;
 
   constructor(title: string) {
@@ -32,27 +26,6 @@ export class OutputChannelLogger extends DisposableObject implements Logger {
       } else {
         this.outputChannel.append(message);
       }
-
-      if (options.additionalLogLocation) {
-        if (!isAbsolute(options.additionalLogLocation)) {
-          throw new Error(
-            `Additional Log Location must be an absolute path: ${options.additionalLogLocation}`,
-          );
-        }
-        const logPath = options.additionalLogLocation;
-        let additional = this.additionalLocations.get(logPath);
-        if (!additional) {
-          const msg = `| Log being saved to ${logPath} |`;
-          const separator = new Array(msg.length).fill("-").join("");
-          this.outputChannel.appendLine(separator);
-          this.outputChannel.appendLine(msg);
-          this.outputChannel.appendLine(separator);
-          additional = new AdditionalLogLocation(logPath);
-          this.additionalLocations.set(logPath, additional);
-        }
-
-        await additional.log(message, options);
-      }
     } catch (e) {
       if (e instanceof Error && e.message === "Channel has been closed") {
         // Output channel is closed logging to console instead
@@ -69,31 +42,6 @@ export class OutputChannelLogger extends DisposableObject implements Logger {
   show(preserveFocus?: boolean): void {
     this.outputChannel.show(preserveFocus);
   }
-
-  removeAdditionalLogLocation(location: string | undefined): void {
-    if (location) {
-      this.additionalLocations.delete(location);
-    }
-  }
-}
-
-class AdditionalLogLocation {
-  constructor(private location: string) {}
-
-  async log(message: string, options = {} as LogOptions): Promise<void> {
-    if (options.trailingNewline === undefined) {
-      options.trailingNewline = true;
-    }
-    await ensureFile(this.location);
-
-    await appendFile(
-      this.location,
-      message + (options.trailingNewline ? "\n" : ""),
-      {
-        encoding: "utf8",
-      },
-    );
-  }
 }
 
 export type ProgressReporter = Progress<{ message: string }>;

extensions/ql-vscode/src/legacy-query-server/queryserver-client.ts

@@ -1,4 +1,3 @@
-import { dirname } from "path";
 import { ensureFile } from "fs-extra";
 
 import { DisposableObject } from "../pure/disposable-object";
@@ -13,10 +12,8 @@ import {
   progress,
   ProgressMessage,
   WithProgressId,
-  compileQuery,
 } from "../pure/legacy-messages";
 import { ProgressCallback, ProgressTask } from "../commandRunner";
-import { findQueryLogFile } from "../run-queries-shared";
 import { ServerProcess } from "../json-rpc-server";
 
 type WithProgressReporting = (
@@ -56,7 +53,7 @@ export class QueryServerClient extends DisposableObject {
     this.queryServerStartListeners.push(e);
   };
 
-  public activeQueryLogFile: string | undefined;
+  public activeQueryLogger: Logger;
 
   constructor(
     readonly config: QueryServerConfig,
@@ -65,6 +62,9 @@ export class QueryServerClient extends DisposableObject {
     withProgressReporting: WithProgressReporting,
   ) {
     super();
+    // Since no query is active when we initialize, just point the "active query logger" to the
+    // default logger.
+    this.activeQueryLogger = this.logger;
     // When the query server configuration changes, restart the query server.
     if (config.onDidChangeConfiguration !== undefined) {
       this.push(
@@ -177,9 +177,8 @@ export class QueryServerClient extends DisposableObject {
       args,
       this.logger,
       (data) =>
-        this.logger.log(data.toString(), {
+        this.activeQueryLogger.log(data.toString(), {
           trailingNewline: false,
-          additionalLogLocation: this.activeQueryLogFile,
         }),
       undefined, // no listener for stdout
       progressReporter,
@@ -240,8 +239,6 @@ export class QueryServerClient extends DisposableObject {
   ): Promise<R> {
     const id = this.nextProgress++;
     this.progressCallbacks[id] = progress;
-
-    this.updateActiveQuery(type.method, parameter);
     try {
       if (this.serverProcess === undefined) {
         throw new Error("No query server process found.");
@@ -255,18 +252,4 @@ export class QueryServerClient extends DisposableObject {
       delete this.progressCallbacks[id];
     }
   }
-
-  /**
-   * Updates the active query every time there is a new request to compile.
-   * The active query is used to specify the side log.
-   *
-   * This isn't ideal because in situations where there are queries running
-   * in parallel, each query's log messages are interleaved. Fixing this
-   * properly will require a change in the query server.
-   */
-  private updateActiveQuery(method: string, parameter: any): void {
-    if (method === compileQuery.method) {
-      this.activeQueryLogFile = findQueryLogFile(dirname(parameter.resultPath));
-    }
-  }
 }

extensions/ql-vscode/src/legacy-query-server/run-queries.ts

@@ -15,7 +15,7 @@ import {
 } from "../helpers";
 import { ProgressCallback } from "../commandRunner";
 import { QueryMetadata } from "../pure/interface-types";
-import { extLogger } from "../common";
+import { extLogger, Logger, TeeLogger } from "../common";
 import * as messages from "../pure/legacy-messages";
 import { InitialQueryInfo, LocalQueryInfo } from "../query-results";
 import * as qsClient from "./queryserver-client";
@@ -66,7 +66,8 @@ export class QueryInProgress {
     dbItem: DatabaseItem,
     progress: ProgressCallback,
     token: CancellationToken,
-    queryInfo?: LocalQueryInfo,
+    logger: Logger,
+    queryInfo: LocalQueryInfo | undefined,
   ): Promise<messages.EvaluationResult> {
     if (!dbItem.contents || dbItem.error) {
       throw new Error("Can't run query on invalid database.");
@@ -137,7 +138,7 @@ export class QueryInProgress {
           await this.queryEvalInfo.addQueryLogs(
             queryInfo,
             qs.cliServer,
-            qs.logger,
+            logger,
           );
         } else {
           void showAndLogWarningMessage(
@@ -162,6 +163,7 @@ export class QueryInProgress {
     program: messages.QlProgram,
     progress: ProgressCallback,
     token: CancellationToken,
+    logger: Logger,
   ): Promise<messages.CompilationMessage[]> {
     let compiled: messages.CheckQueryResult | undefined;
     try {
@@ -190,16 +192,19 @@ export class QueryInProgress {
         target,
       };
 
+      // Update the active query logger every time there is a new request to compile.
+      // This isn't ideal because in situations where there are queries running
+      // in parallel, each query's log messages are interleaved. Fixing this
+      // properly will require a change in the query server.
+      qs.activeQueryLogger = logger;
       compiled = await qs.sendRequest(
         messages.compileQuery,
         params,
         token,
         progress,
       );
     } finally {
-      void qs.logger.log(" - - - COMPILATION DONE - - - ", {
-        additionalLogLocation: this.queryEvalInfo.logPath,
-      });
+      void logger.log(" - - - COMPILATION DONE - - - ");
     }
     return (compiled?.messages || []).filter(
       (msg) => msg.severity === messages.Severity.ERROR,
@@ -386,6 +391,8 @@ export async function compileAndRunQueryAgainstDatabase(
     metadata,
     templates,
   );
+  const logger = new TeeLogger(qs.logger, query.queryEvalInfo.logPath);
+
   await query.queryEvalInfo.createTimestampFile();
 
   let upgradeDir: tmp.DirectoryResult | undefined;
@@ -402,7 +409,7 @@ export async function compileAndRunQueryAgainstDatabase(
     );
     let errors;
     try {
-      errors = await query.compile(qs, qlProgram, progress, token);
+      errors = await query.compile(qs, qlProgram, progress, token, logger);
     } catch (e) {
       if (
         e instanceof ResponseError &&
@@ -422,6 +429,7 @@ export async function compileAndRunQueryAgainstDatabase(
         dbItem,
         progress,
         token,
+        logger,
         queryInfo,
       );
       if (result.resultType !== messages.QueryResultType.SUCCESS) {
@@ -439,18 +447,14 @@ export async function compileAndRunQueryAgainstDatabase(
         result,
         successful: result.resultType === messages.QueryResultType.SUCCESS,
         logFileLocation: result.logFileLocation,
-        dispose: () => {
-          qs.logger.removeAdditionalLogLocation(result.logFileLocation);
-        },
       };
     } else {
       // Error dialogs are limited in size and scrollability,
       // so we include a general description of the problem,
       // and direct the user to the output window for the detailed compilation messages.
       // However we don't show quick eval errors there so we need to display them anyway.
-      void qs.logger.log(
+      void logger.log(
         `Failed to compile query ${initialInfo.queryPath} against database scheme ${qlProgram.dbschemePath}:`,
-        { additionalLogLocation: query.queryEvalInfo.logPath },
       );
 
       const formattedMessages: string[] = [];
@@ -459,9 +463,7 @@ export async function compileAndRunQueryAgainstDatabase(
         const message = error.message || "[no error message available]";
         const formatted = `ERROR: ${message} (${error.position.fileName}:${error.position.line}:${error.position.column}:${error.position.endLine}:${error.position.endColumn})`;
         formattedMessages.push(formatted);
-        void qs.logger.log(formatted, {
-          additionalLogLocation: query.queryEvalInfo.logPath,
-        });
+        void logger.log(formatted);
       }
       if (initialInfo.isQuickEval && formattedMessages.length <= 2) {
         // If there are more than 2 error messages, they will not be displayed well in a popup
@@ -484,9 +486,8 @@ export async function compileAndRunQueryAgainstDatabase(
     try {
       await upgradeDir?.cleanup();
     } catch (e) {
-      void qs.logger.log(
+      void logger.log(
         `Could not clean up the upgrades dir. Reason: ${getErrorMessage(e)}`,
-        { additionalLogLocation: query.queryEvalInfo.logPath },
       );
     }
   }
@@ -535,9 +536,6 @@ function createSyntheticResult(
       runId: 0,
     },
     successful: false,
-    dispose: () => {
-      /**/
-    },
   };
 }