Use file handle in TeeLogger

This switches the `TeeLogger` from using the `appendFile` function to
manually opening and closing a file handle and calling `appendFile` on
the file handle. This results in a more efficient implementation as the
file handle is only opened once and closed once, instead of being
opened and closed for every log message. This should result in less
"too many open files" errors.

Author: koesie10

extensions/ql-vscode/src/common/disposable-object.ts

@@ -88,3 +88,7 @@ export class DisposableObject implements Disposable {
     }
   }
 }
+
+export function isDisposable(obj: unknown): obj is Disposable {
+  return obj !== undefined && typeof (obj as Disposable).dispose === "function";
+}

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

@@ -1,7 +1,10 @@
-import { appendFile, ensureFile } from "fs-extra";
+import { ensureFile } from "fs-extra";
+import { open } from "node:fs/promises";
+import type { FileHandle } from "node:fs/promises";
 import { isAbsolute } from "path";
 import { getErrorMessage } from "../helpers-pure";
 import type { Logger, LogOptions } from "./logger";
+import type { Disposable } from "../disposable-object";
 
 /**
  * An implementation of {@link Logger} that sends the output both to another {@link Logger}
@@ -10,9 +13,10 @@ import type { Logger, LogOptions } from "./logger";
  * 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 {
+export class TeeLogger implements Logger, Disposable {
   private emittedRedirectMessage = false;
   private error = false;
+  private fileHandle: FileHandle | undefined = undefined;
 
   public constructor(
     private readonly logger: Logger,
@@ -37,11 +41,15 @@ export class TeeLogger implements Logger {
 
     if (!this.error) {
       try {
+        if (!this.fileHandle) {
+          await ensureFile(this.location);
+
+          this.fileHandle = await open(this.location, "a");
+        }
+
         const trailingNewline = options.trailingNewline ?? true;
-        await ensureFile(this.location);
 
-        await appendFile(
-          this.location,
+        await this.fileHandle.appendFile(
           message + (trailingNewline ? "\n" : ""),
           {
             encoding: "utf8",
@@ -50,6 +58,7 @@ export class TeeLogger implements Logger {
       } catch (e) {
         // Write an error message to the primary log, and stop trying to write to the side log.
         this.error = true;
+        this.fileHandle = undefined;
         const errorMessage = getErrorMessage(e);
         await this.logger.log(
           `Error writing to additional log file: ${errorMessage}`,
@@ -65,4 +74,9 @@ export class TeeLogger implements Logger {
   show(preserveFocus?: boolean): void {
     this.logger.show(preserveFocus);
   }
+
+  dispose(): void {
+    void this.fileHandle?.close();
+    this.fileHandle = undefined;
+  }
 }

extensions/ql-vscode/src/language-support/contextual/query-resolver.ts

@@ -92,11 +92,12 @@ export async function runContextualQuery(
   void extLogger.log(
     `Running contextual query ${query}; results will be stored in ${queryRun.outputDir.querySaveDir}`,
   );
-  const results = await queryRun.evaluate(
-    progress,
-    token,
-    new TeeLogger(qs.logger, queryRun.outputDir.logPath),
-  );
-  await cleanup?.();
-  return results;
+  const teeLogger = new TeeLogger(qs.logger, queryRun.outputDir.logPath);
+
+  try {
+    return await queryRun.evaluate(progress, token, teeLogger);
+  } finally {
+    await cleanup?.();
+    teeLogger.dispose();
+  }
 }

extensions/ql-vscode/src/local-queries/local-query-run.ts

@@ -25,6 +25,7 @@ import { redactableError } from "../common/errors";
 import type { LocalQueries } from "./local-queries";
 import { tryGetQueryMetadata } from "../codeql-cli/query-metadata";
 import { telemetryListener } from "../common/vscode/telemetry";
+import { isDisposable } from "../common/disposable-object";
 
 function formatResultMessage(result: CoreQueryResults): string {
   switch (result.resultType) {
@@ -61,6 +62,10 @@ export class LocalQueryRun {
     private readonly localQueries: LocalQueries,
     private readonly queryInfo: LocalQueryInfo,
     private readonly dbItem: DatabaseItem,
+    /**
+     * The logger is only available while the query is running and will be disposed of when the
+     * query completes.
+     */
     public readonly logger: Logger, // Public so that other clients, like the debug adapter, know where to send log output
     private readonly queryHistoryManager: QueryHistoryManager,
     private readonly cliServer: CodeQLCliServer,
@@ -92,6 +97,10 @@ export class LocalQueryRun {
     // Note we must update the query history view after showing results as the
     // display and sorting might depend on the number of results
     await this.queryHistoryManager.refreshTreeView();
+
+    if (isDisposable(this.logger)) {
+      this.logger.dispose();
+    }
   }
 
   /**
@@ -110,6 +119,10 @@ export class LocalQueryRun {
     err.message = `Error running query: ${err.message}`;
     this.queryInfo.failureReason = err.message;
     await this.queryHistoryManager.refreshTreeView();
+
+    if (isDisposable(this.logger)) {
+      this.logger.dispose();
+    }
   }
 
   /**

extensions/ql-vscode/src/local-queries/run-query.ts

@@ -47,21 +47,27 @@ export async function runQuery({
     undefined,
   );
 
-  const completedQuery = await queryRun.evaluate(
-    progress,
-    token,
-    new TeeLogger(queryRunner.logger, queryRun.outputDir.logPath),
+  const teeLogger = new TeeLogger(
+    queryRunner.logger,
+    queryRun.outputDir.logPath,
   );
 
-  if (completedQuery.resultType !== QueryResultType.SUCCESS) {
-    void showAndLogExceptionWithTelemetry(
-      extLogger,
-      telemetryListener,
-      redactableError`Failed to run ${basename(queryPath)} query: ${
-        completedQuery.message ?? "No message"
-      }`,
-    );
-    return;
+  try {
+    const completedQuery = await queryRun.evaluate(progress, token, teeLogger);
+
+    if (completedQuery.resultType !== QueryResultType.SUCCESS) {
+      void showAndLogExceptionWithTelemetry(
+        extLogger,
+        telemetryListener,
+        redactableError`Failed to run ${basename(queryPath)} query: ${
+          completedQuery.message ?? "No message"
+        }`,
+      );
+      return;
+    }
+
+    return completedQuery;
+  } finally {
+    teeLogger.dispose();
   }
-  return completedQuery;
 }

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

@@ -5,6 +5,7 @@ import { dirSync } from "tmp";
 import type { BaseLogger, Logger } from "../../../src/common/logging";
 import { TeeLogger } from "../../../src/common/logging";
 import { OutputChannelLogger } from "../../../src/common/logging/vscode";
+import type { Disposable } from "../../../src/common/disposable-object";
 
 jest.setTimeout(999999);
 
@@ -66,6 +67,8 @@ describe("OutputChannelLogger tests", function () {
 
     // should have created 1 side log
     expect(readdirSync(tempFolders.storagePath.name)).toEqual(["hucairz"]);
+
+    hucairz.dispose();
   });
 
   it("should create a side log", async () => {
@@ -86,12 +89,15 @@ describe("OutputChannelLogger tests", function () {
     expect(
       readFileSync(join(tempFolders.storagePath.name, "second"), "utf8"),
     ).toBe("yyy\n");
+
+    first.dispose();
+    second.dispose();
   });
 
   function createSideLogger(
     logger: Logger,
     additionalLogLocation: string,
-  ): BaseLogger {
+  ): BaseLogger & Disposable {
     return new TeeLogger(
       logger,
       join(tempFolders.storagePath.name, additionalLogLocation),