Improve diagnostic logging for HostPort wait strategy (#397)

* Improve diagnostic logging for HostPort wait strategy * Cleanup * Improve test names
testcontainers · Sep 17, 2022 · 3dfc799 · 3dfc799
1 parent 7aca953
commit 3dfc799
Show file tree

Hide file tree

Showing 3 changed files with 163 additions and 2 deletions.
diff --git a/src/log-system-diagnostics.ts b/src/log-system-diagnostics.ts
@@ -33,7 +33,7 @@ const getDockerComposeInfo = async (): Promise<DockerComposeInfo | undefined> =>
       version: (await dockerComposeVersion()).data.version,
     };
   } catch (err) {
-    log.warn(`Unable to detect docker-compose version, is it installed? ${err}`);
+    log.info(`Unable to detect docker-compose version, is it installed? ${err}`);
     return undefined;
   }
 };
diff --git a/src/port-check.test.ts b/src/port-check.test.ts
@@ -0,0 +1,126 @@
+import { log } from "./logger";
+import { execContainer } from "./docker/functions/container/exec-container";
+import Dockerode from "dockerode";
+import { InternalPortCheck } from "./port-check";
+
+jest.mock("./logger");
+jest.mock("./docker/functions/container/exec-container");
+
+const mockLogger = jest.mocked(log, true);
+const mockExecContainer = jest.mocked(execContainer, true);
+
+describe("PortCheck", () => {
+  describe("InternalPortCheck", () => {
+    let mockContainer: Dockerode.Container;
+    let portCheck: InternalPortCheck;
+
+    beforeEach(() => {
+      jest.resetAllMocks();
+      mockContainer = { id: "containerId" } as Dockerode.Container;
+      portCheck = new InternalPortCheck(mockContainer);
+    });
+
+    it("should return true when at least one command returns exit code 0", async () => {
+      mockExecContainer
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "SUCCESS", exitCode: 0 }));
+
+      const result = await portCheck.isBound(8080);
+
+      expect(result).toBe(true);
+    });
+
+    it("should trace log unique error messages", async () => {
+      mockExecContainer
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 1 }));
+
+      await portCheck.isBound(8080);
+
+      expect(mockLogger.trace.mock.calls).toEqual([
+        ["Port check result for container containerId exit code 1: ERROR 1"],
+        ["Port check result for container containerId exit code 1: ERROR 2"],
+      ]);
+    });
+
+    it("should trace log unique error messages across multiple invocations", async () => {
+      mockExecContainer
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 1 }));
+
+      await portCheck.isBound(8080);
+      await portCheck.isBound(8080);
+
+      expect(mockLogger.trace.mock.calls).toEqual([
+        ["Port check result for container containerId exit code 1: ERROR 1"],
+        ["Port check result for container containerId exit code 1: ERROR 2"],
+      ]);
+    });
+
+    it("should not trace log error messages with empty output", async () => {
+      mockExecContainer
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "", exitCode: 1 }));
+
+      await portCheck.isBound(8080);
+
+      expect(mockLogger.trace.mock.calls).toEqual([
+        ["Port check result for container containerId exit code 1: ERROR 1"],
+      ]);
+    });
+
+    it("should not trace log error messages where the shell is missing if another shell exists", async () => {
+      mockExecContainer
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 1 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 126 }));
+
+      await portCheck.isBound(8080);
+
+      expect(mockLogger.trace.mock.calls).toEqual([
+        ["Port check result for container containerId exit code 1: ERROR 1"],
+      ]);
+    });
+
+    it("should error log when the port-check will fail due to missing shells (distroless)", async () => {
+      mockExecContainer
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 126 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 126 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 126 }));
+
+      await portCheck.isBound(8080);
+
+      expect(mockLogger.error.mock.calls).toEqual([
+        [
+          "The HostPortWaitStrategy will not work on a distroless image, use an alternate wait strategy for container containerId",
+        ],
+      ]);
+    });
+
+    it("should error log the distroless image once", async () => {
+      mockExecContainer
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 126 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 126 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 126 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 1", exitCode: 126 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 126 }))
+        .mockReturnValueOnce(Promise.resolve({ output: "ERROR 2", exitCode: 126 }));
+
+      await portCheck.isBound(8080);
+      await portCheck.isBound(8080);
+
+      expect(mockLogger.error.mock.calls).toEqual([
+        [
+          "The HostPortWaitStrategy will not work on a distroless image, use an alternate wait strategy for container containerId",
+        ],
+      ]);
+    });
+  });
+});
diff --git a/src/port-check.ts b/src/port-check.ts
@@ -2,6 +2,7 @@ import { Socket } from "net";
 import { Port } from "./port";
 import { Host } from "./docker/types";
 import { execContainer } from "./docker/functions/container/exec-container";
+import { log } from "./logger";
 import Dockerode from "dockerode";
 
 export interface PortCheck {
@@ -33,6 +34,9 @@ export class HostPortCheck implements PortCheck {
 }
 
 export class InternalPortCheck implements PortCheck {
+  private isDistroless = false;
+  private commandOutputs = new Set<string>();
+
   constructor(private readonly container: Dockerode.Container) {}
 
   public async isBound(port: Port): Promise<boolean> {
@@ -42,7 +46,38 @@ export class InternalPortCheck implements PortCheck {
       ["/bin/sh", "-c", `nc -vz -w 1 localhost ${port}`],
       ["/bin/bash", "-c", `</dev/tcp/localhost/${port}`],
     ];
+
     const commandResults = await Promise.all(commands.map((command) => execContainer(this.container, command)));
-    return commandResults.some((result) => result.exitCode === 0);
+    const isBound = commandResults.some((result) => result.exitCode === 0);
+
+    if (!isBound) {
+      const shellExists = commandResults.some((result) => result.exitCode !== 126);
+      if (!shellExists) {
+        if (!this.isDistroless) {
+          this.isDistroless = true;
+          log.error(
+            `The HostPortWaitStrategy will not work on a distroless image, use an alternate wait strategy for container ${this.container.id}`
+          );
+        }
+      } else {
+        commandResults
+          .map((result) => ({ ...result, output: result.output.trim() }))
+          .filter((result) => result.exitCode !== 126 && result.output.length > 0)
+          .forEach((result) => {
+            if (!this.commandOutputs.has(this.commandOutputsKey(result.output))) {
+              log.trace(
+                `Port check result for container ${this.container.id} exit code ${result.exitCode}: ${result.output}`
+              );
+              this.commandOutputs.add(this.commandOutputsKey(result.output));
+            }
+          });
+      }
+    }
+
+    return isBound;
+  }
+
+  private commandOutputsKey(output: string) {
+    return `${this.container.id}:${output}`;
   }
 }