diff --git a/packages/ssh/src/command.ts b/packages/ssh/src/command.ts index 29a1ad232ef..27b3b5164dd 100644 --- a/packages/ssh/src/command.ts +++ b/packages/ssh/src/command.ts @@ -350,7 +350,10 @@ export const resolveSshTarget = Effect.fn("ssh/command.resolveSshTarget")(functi Effect.logDebug("ssh.target.resolve.succeeded", sshTargetLogFields(target)), ), Effect.catch((cause) => - Effect.logDebug("ssh.target.resolve.fallback", { alias: trimmedAlias, cause }).pipe( + Effect.logDebug("ssh.target.resolve.fallback", { + alias: trimmedAlias, + failureTag: cause._tag, + }).pipe( Effect.as({ alias: trimmedAlias, hostname: trimmedAlias, diff --git a/packages/ssh/src/tunnel.test.ts b/packages/ssh/src/tunnel.test.ts index 198de14ab0e..d64c9eddd11 100644 --- a/packages/ssh/src/tunnel.test.ts +++ b/packages/ssh/src/tunnel.test.ts @@ -5,12 +5,14 @@ import * as Duration from "effect/Duration"; import * as Effect from "effect/Effect"; import * as Fiber from "effect/Fiber"; import * as Layer from "effect/Layer"; +import * as Logger from "effect/Logger"; import * as PlatformError from "effect/PlatformError"; import * as Result from "effect/Result"; import * as Sink from "effect/Sink"; import * as Stream from "effect/Stream"; import * as TestClock from "effect/testing/TestClock"; import * as HttpClient from "effect/unstable/http/HttpClient"; +import * as HttpClientError from "effect/unstable/http/HttpClientError"; import * as HttpClientResponse from "effect/unstable/http/HttpClientResponse"; import * as ChildProcess from "effect/unstable/process/ChildProcess"; import * as ChildProcessSpawner from "effect/unstable/process/ChildProcessSpawner"; @@ -21,6 +23,7 @@ import { SshHttpBridgeMissingUrlError, SshHttpBridgeNonLoopbackUrlError, SshPairingOutputParseError, + SshReadinessProbeError, SshReadinessProbeTimeoutError, SshReadinessTimeoutError, } from "./errors.ts"; @@ -88,6 +91,14 @@ function commandArgs(command: ChildProcess.Command): ReadonlyArray { return command._tag === "StandardCommand" ? command.args : []; } +function flattenedLogText(value: unknown): string { + if (typeof value === "string") return value; + if (typeof value !== "object" || value === null) return String(value); + return Object.entries(value) + .flatMap(([key, nested]) => [key, flattenedLogText(nested)]) + .join("\n"); +} + describe("ssh tunnel scripts", () => { it("builds the remote t3 runner with npx and npm fallbacks", () => { const script = SshTunnel.buildRemoteT3RunnerScript({ nodeEngineRange: TEST_NODE_ENGINE_RANGE }); @@ -255,13 +266,22 @@ describe("ssh tunnel scripts", () => { assert.include(SshTunnel.REMOTE_PICK_PORT_SCRIPT, 'const filePath = process.argv[2] ?? "";'); }); - it.effect("bounds each HTTP readiness probe so retries cannot hang on one request", () => - Effect.gen(function* () { + it.effect("bounds each HTTP readiness probe so retries cannot hang on one request", () => { + const baseUrl = + "http://ssh-user:ssh-password@127.0.0.1:41773/private/base?token=base-secret#base-fragment"; + const path = "/ready/private?credential=request-secret#request-fragment"; + const requestUrl = new URL(path, baseUrl).toString(); + const capturedLogs: Array> = []; + const logger = Logger.make(({ message }) => { + capturedLogs.push(Array.isArray(message) ? message : [message]); + }); + + return Effect.gen(function* () { const fiber = yield* Effect.forkChild( Effect.result( SshTunnel.waitForHttpReady({ - baseUrl: "http://127.0.0.1:41773/?token=base-secret#fragment", - path: "/ready?credential=request-secret#fragment", + baseUrl, + path, timeoutMs: 1_000, intervalMs: 100, probeTimeoutMs: 250, @@ -281,8 +301,8 @@ describe("ssh tunnel scripts", () => { protocol: "http:", hostname: "127.0.0.1", port: "41773", - urlLength: 50, - pathnameLength: 1, + urlLength: baseUrl.length, + pathnameLength: new TextEncoder().encode(new URL(baseUrl).pathname).length, hasQuery: true, hasFragment: true, }); @@ -290,8 +310,8 @@ describe("ssh tunnel scripts", () => { protocol: "http:", hostname: "127.0.0.1", port: "41773", - urlLength: 63, - pathnameLength: 6, + urlLength: requestUrl.length, + pathnameLength: new TextEncoder().encode(new URL(requestUrl).pathname).length, hasQuery: true, hasFragment: true, }); @@ -311,13 +331,91 @@ describe("ssh tunnel scripts", () => { const probeTimeout = timeoutError.cause as SshReadinessProbeTimeoutError; assert.equal(probeTimeout.attempt, timeoutError.attempts); assert.isFalse("cause" in probeTimeout); + + const logText = flattenedLogText(capturedLogs); + assert.include(logText, "127.0.0.1"); + assert.notInclude(logText, "ssh-user"); + assert.notInclude(logText, "ssh-password"); + assert.notInclude(logText, "/private/base"); + assert.notInclude(logText, "base-secret"); + assert.notInclude(logText, "/ready/private"); + assert.notInclude(logText, "request-secret"); + assert.notInclude(logText, "base-fragment"); + assert.notInclude(logText, "request-fragment"); } }).pipe( Effect.provide( - Layer.merge(TestClock.layer(), Layer.succeed(HttpClient.HttpClient, hangingHttpClient)), + Layer.mergeAll( + TestClock.layer(), + Layer.succeed(HttpClient.HttpClient, hangingHttpClient), + Logger.layer([logger], { mergeWithExisting: false }), + ), ), - ), - ); + ); + }); + + it.effect("preserves the exact HTTP transport cause without logging request secrets", () => { + const baseUrl = + "http://transport-user:transport-password@127.0.0.1:41773/private?token=transport-secret#fragment"; + const transportCause = new Error("socket closed"); + const clientErrors: Array = []; + const failingHttpClient = HttpClient.make((request) => { + const error = new HttpClientError.HttpClientError({ + reason: new HttpClientError.TransportError({ request, cause: transportCause }), + }); + clientErrors.push(error); + return Effect.fail(error); + }); + const capturedLogs: Array> = []; + const logger = Logger.make(({ message }) => { + capturedLogs.push(Array.isArray(message) ? message : [message]); + }); + + return Effect.gen(function* () { + const fiber = yield* Effect.forkChild( + Effect.result( + SshTunnel.waitForHttpReady({ + baseUrl, + timeoutMs: 300, + intervalMs: 100, + probeTimeoutMs: 250, + }), + ), + ); + yield* Effect.yieldNow; + yield* TestClock.adjust(Duration.millis(300)); + + const result = yield* Fiber.join(fiber); + assert.isTrue(Result.isFailure(result)); + if (Result.isFailure(result)) { + assert.instanceOf(result.failure, SshReadinessTimeoutError); + const timeoutError = result.failure as SshReadinessTimeoutError; + assert.instanceOf(timeoutError.cause, SshReadinessProbeError); + const probeError = timeoutError.cause as SshReadinessProbeError; + assert.strictEqual(probeError.cause, clientErrors.at(-1)); + assert.strictEqual( + (probeError.cause as HttpClientError.HttpClientError).reason.cause, + transportCause, + ); + + const logText = flattenedLogText(capturedLogs); + assert.include(logText, "HttpClientError"); + assert.include(logText, "TransportError"); + assert.notInclude(logText, "transport-user"); + assert.notInclude(logText, "transport-password"); + assert.notInclude(logText, "/private"); + assert.notInclude(logText, "transport-secret"); + } + }).pipe( + Effect.provide( + Layer.mergeAll( + TestClock.layer(), + Layer.succeed(HttpClient.HttpClient, failingHttpClient), + Logger.layer([logger], { mergeWithExisting: false }), + ), + ), + ); + }); it.effect("preserves forwarded HTTP URL error messages", () => Effect.gen(function* () { @@ -363,6 +461,10 @@ describe("ssh tunnel scripts", () => { cause: { type: "string" }, }, ); + + const cyclicCause: { readonly _tag: string; cause?: unknown } = { _tag: "CyclicCause" }; + cyclicCause.cause = cyclicCause; + assert.include(flattenedLogText(SshTunnel.describeReadinessCause(cyclicCause)), "truncated"); }); it("preserves structured readiness attributes in diagnostic output", () => { @@ -542,6 +644,10 @@ describe("ssh tunnel scripts", () => { const spawnedCommands: Array> = []; let tunnelKillCount = 0; let stopCommandCount = 0; + const capturedLogs: Array> = []; + const logger = Logger.make(({ message }) => { + capturedLogs.push(Array.isArray(message) ? message : [message]); + }); const spawner = ChildProcessSpawner.make((command) => Effect.sync(() => { const args = commandArgs(command); @@ -568,6 +674,7 @@ describe("ssh tunnel scripts", () => { Layer.succeed(NetService.NetService, testNetService), SshAuth.disabledLayer, SshTunnel.layer(), + Logger.layer([logger], { mergeWithExisting: false }), ); const target = { alias: "devbox", @@ -590,6 +697,10 @@ describe("ssh tunnel scripts", () => { assert.equal(spawnedCommands.filter((args) => args.includes("-N")).length, 2); assert.equal(tunnelKillCount, 1); + + const logText = flattenedLogText(capturedLogs); + assert.include(logText, "httpBaseUrlDiagnostics"); + assert.notInclude(logText, "httpBaseUrl\nhttp://"); }).pipe(Effect.provide(layer), Effect.scoped); }); }); diff --git a/packages/ssh/src/tunnel.ts b/packages/ssh/src/tunnel.ts index 38e09c18b4d..119b4f417ad 100644 --- a/packages/ssh/src/tunnel.ts +++ b/packages/ssh/src/tunnel.ts @@ -5,6 +5,8 @@ import type { import * as NetService from "@t3tools/shared/Net"; import { extractJsonObject, fromLenientJson } from "@t3tools/shared/schemaJson"; import { satisfiesSemverRange } from "@t3tools/shared/semver"; +import { getUrlDiagnostics } from "@t3tools/shared/urlDiagnostics"; +import * as Cause from "effect/Cause"; import * as Context from "effect/Context"; import * as Deferred from "effect/Deferred"; import * as Duration from "effect/Duration"; @@ -243,7 +245,24 @@ function applyScriptPlaceholders( return result; } -export function describeReadinessCause(cause: unknown): unknown { +const SSH_FAILURE_DIAGNOSTIC_DEPTH = 6; + +function describeReadinessCauseAtDepth(cause: unknown, depth: number): unknown { + if (depth >= SSH_FAILURE_DIAGNOSTIC_DEPTH) return { truncated: true }; + const describeNested = (nested: unknown) => describeReadinessCauseAtDepth(nested, depth + 1); + if (Cause.isCause(cause)) { + return { + reasons: cause.reasons.map((reason) => { + if (Cause.isFailReason(reason)) { + return { _tag: reason._tag, error: describeNested(reason.error) }; + } + if (Cause.isDieReason(reason)) { + return { _tag: reason._tag, defect: describeNested(reason.defect) }; + } + return { _tag: reason._tag, fiberId: reason.fiberId }; + }), + }; + } if (isSshReadinessError(cause)) { const { cause: nestedCause, ...attributes } = cause as SshReadinessError & { readonly cause?: unknown; @@ -251,13 +270,15 @@ export function describeReadinessCause(cause: unknown): unknown { return { ...attributes, message: cause.message, - ...(nestedCause === undefined ? {} : { cause: describeReadinessCause(nestedCause) }), + ...(nestedCause === undefined ? {} : { cause: describeNested(nestedCause) }), }; } if (cause instanceof Error) { + const tagged = cause as Error & { readonly _tag?: unknown; readonly reason?: unknown }; return { - name: cause.name, - ...(cause.cause === undefined ? {} : { cause: describeReadinessCause(cause.cause) }), + ...(typeof tagged._tag === "string" ? { _tag: tagged._tag } : { name: cause.name }), + ...(tagged.reason === undefined ? {} : { reason: describeNested(tagged.reason) }), + ...(cause.cause === undefined ? {} : { cause: describeNested(cause.cause) }), }; } if (typeof cause !== "object" || cause === null) { @@ -267,17 +288,23 @@ export function describeReadinessCause(cause: unknown): unknown { const record = cause as Readonly>; return { ...(typeof record._tag === "string" ? { _tag: record._tag } : {}), - ...(record.reason === undefined ? {} : { reason: describeReadinessCause(record.reason) }), - ...(record.cause === undefined ? {} : { cause: describeReadinessCause(record.cause) }), + ...(record.reason === undefined ? {} : { reason: describeNested(record.reason) }), + ...(record.cause === undefined ? {} : { cause: describeNested(record.cause) }), }; } -function readinessUrlDiagnostics(url: URL, urlLength: number) { +export function describeReadinessCause(cause: unknown): unknown { + return describeReadinessCauseAtDepth(cause, 0); +} + +function readinessUrlDiagnostics(input: string) { + const url = new URL(input); + const diagnostics = getUrlDiagnostics(input); return { - protocol: url.protocol, - hostname: url.hostname, + protocol: diagnostics.protocol ?? url.protocol, + hostname: diagnostics.hostname ?? url.hostname, ...(url.port === "" ? {} : { port: url.port }), - urlLength, + urlLength: diagnostics.inputLength, pathnameLength: utf8ByteLength(url.pathname), hasQuery: url.search !== "", hasFragment: url.hash !== "", @@ -900,8 +927,8 @@ export const waitForHttpReady = Effect.fn("ssh/tunnel.waitForHttpReady")(functio const baseUrl = new URL(input.baseUrl); const request = new URL(input.path ?? "/", baseUrl); const requestUrl = request.toString(); - const base = readinessUrlDiagnostics(baseUrl, utf8ByteLength(input.baseUrl)); - const requestDiagnostics = readinessUrlDiagnostics(request, utf8ByteLength(requestUrl)); + const base = readinessUrlDiagnostics(input.baseUrl); + const requestDiagnostics = readinessUrlDiagnostics(requestUrl); const client = yield* HttpClient.HttpClient; const lastProbeFailure = yield* Ref.make(null); let attempt = 0; @@ -1088,6 +1115,7 @@ const startSshTunnel = Effect.fn("ssh/tunnel.startSshTunnel")(function* (input: const sshCommand = yield* resolveSshCommand; const spawner = yield* ChildProcessSpawner.ChildProcessSpawner; const scope = yield* Scope.Scope; + const httpBaseUrlDiagnostics = getUrlDiagnostics(input.httpBaseUrl); yield* Effect.logDebug("ssh.tunnel.spawn.start", { ...sshTargetLogFields(input.resolvedTarget), command: sshCommand, @@ -1095,7 +1123,7 @@ const startSshTunnel = Effect.fn("ssh/tunnel.startSshTunnel")(function* (input: localPort: input.localPort, remotePort: input.remotePort, remoteServerKind: input.remoteServerKind, - httpBaseUrl: input.httpBaseUrl, + httpBaseUrlDiagnostics, }); const child = yield* spawner .spawn( @@ -1128,7 +1156,7 @@ const startSshTunnel = Effect.fn("ssh/tunnel.startSshTunnel")(function* (input: pid: child.pid, localPort: input.localPort, remotePort: input.remotePort, - httpBaseUrl: input.httpBaseUrl, + httpBaseUrlDiagnostics, }); const tunnelEntry: SshTunnelEntry = { key: input.key, @@ -1171,7 +1199,7 @@ const startSshTunnel = Effect.fn("ssh/tunnel.startSshTunnel")(function* (input: pid: child.pid, localPort: input.localPort, remotePort: input.remotePort, - httpBaseUrl: input.httpBaseUrl, + httpBaseUrlDiagnostics, exitCode, stderrBytes: utf8ByteLength(stderr), }).pipe(Effect.andThen(Effect.fail(error))); @@ -1192,7 +1220,7 @@ const startSshTunnel = Effect.fn("ssh/tunnel.startSshTunnel")(function* (input: pid: child.pid, localPort: input.localPort, remotePort: input.remotePort, - httpBaseUrl: input.httpBaseUrl, + httpBaseUrlDiagnostics, }), ), Effect.tapError((cause) => @@ -1220,19 +1248,19 @@ const startSshTunnel = Effect.fn("ssh/tunnel.startSshTunnel")(function* (input: processRunning, ...(Exit.isSuccess(processRunningExit) ? {} - : { processRunningError: processRunningExit.cause }), + : { processRunningFailure: describeReadinessCause(processRunningExit.cause) }), localPort: input.localPort, localPortListening: localPortAvailable === null ? null : !localPortAvailable, remotePort: input.remotePort, - httpBaseUrl: input.httpBaseUrl, + httpBaseUrlDiagnostics, ...(Exit.isSuccess(localPortAvailableExit) ? {} - : { localPortProbeError: localPortAvailableExit.cause }), + : { localPortProbeFailure: describeReadinessCause(localPortAvailableExit.cause) }), ...(remoteLogTail === null ? {} : { remoteLogTailBytes: utf8ByteLength(remoteLogTail) }), ...(Exit.isSuccess(remoteLogTailExit) ? {} - : { remoteLogTailError: remoteLogTailExit.cause }), - cause, + : { remoteLogTailFailure: describeReadinessCause(remoteLogTailExit.cause) }), + failure: describeReadinessCause(cause), }); }), ), @@ -1370,7 +1398,7 @@ export const make = Effect.fn("ssh/tunnel.SshEnvironmentManager.make")(function* ...sshTargetLogFields(input.target), key: input.key, promptCount: input.promptCount, - cause: input.error, + failure: describeReadinessCause(input.error), }); const promptService = yield* SshAuth.SshPasswordPrompt; if (!promptService.isAvailable) { @@ -1569,7 +1597,7 @@ export const make = Effect.fn("ssh/tunnel.SshEnvironmentManager.make")(function* key, localPort: entry.localPort, remotePort: entry.remotePort, - cause: readinessExit.cause, + failure: describeReadinessCause(readinessExit.cause), }); yield* closeTunnelEntry(entry); yield* cancelPendingTunnelEntry(key, resolvedTarget); @@ -1597,7 +1625,7 @@ export const make = Effect.fn("ssh/tunnel.SshEnvironmentManager.make")(function* Effect.logWarning("ssh.environment.tunnel.create.failed", { ...sshTargetLogFields(resolvedTarget), key, - cause, + failure: describeReadinessCause(cause), }), ), Effect.onExit((exit) =>