Skip to content

fix(server): log canceled relay requests at debug level - #32215

Open
Sidreyas wants to merge 1 commit into
pingdotgg:mainfrom
Sidreyas:sidreyas/fix-17765-relay-cancel-logs
Open

Sidreyas wants to merge 1 commit into
pingdotgg:mainfrom
Sidreyas:sidreyas/fix-17765-relay-cancel-logs

Conversation

@Sidreyas

@Sidreyas Sidreyas commented Nov 6, 2026

Copy link
Copy Markdown
Contributor

Problem

Cloudflared 2026.10.4 reports a downstream HTTP request cancellation with Incoming request ended abruptly: context canceled. The relay classifier currently turns that routine disconnect into Relay client reported a transport warning, contributing to the noise reported in #17765.

Change

Classify the two known cloudflared ERR cancellation formats as debug. Deadline failures, other tunnel cancellation errors, and fatal/panic output retain warning severity. Extend the existing classifier test with those cases.

Scope and approval

Addresses #17765's cancellation-log defect only. The snapshot timeout and request-concurrency concerns remain open. This is a small, reproducible correction to an existing log classifier under CONTRIBUTING.md's focused bug-fix exception; it introduces no configuration or client behavior.

Verification

Windows, Node 26.12.1, pnpm 12.14.0; frozen-lockfile install in the isolated checkout. Commands below use that checkout's local node_modules/.bin/vp.ps1.

  • Baseline from apps/server: vp test run src/cloud/ManagedEndpointRuntime.test.ts -t "classifies Cloudflare connection and warning output" failed with expected 'warning' to be 'debug' (1 failed, 22 skipped).
  • Fixed from apps/server: vp test run src/cloud/ManagedEndpointRuntime.test.ts src/provider/AgentContextBudget.test.ts passed all 25 tests across 2 files.

Runtime commands: node issue-17765-runtime.mjs <checkout> baseline before the production edit, then node issue-17765-runtime.mjs <checkout> fixed. The external fixture and harness are included below for reproduction.

Runtime verification used the actual ManagedEndpointRuntime layer, Node child-process spawner, secret store, HTTP readiness client, output observer, and rotating relay log in isolated temporary state. A deterministic connector process opened a loopback HTTP server; aborting an in-flight request caused it to emit cloudflared's two cancellation frames, followed by four error controls. This exercised the production process/network/logging path without a live Cloudflare account or client UI.

baseline child 30008: HTTP request arrived -> aborted
  cancellation frames: WARN, WARN (also persisted as WARN)
fixed child 21924: HTTP request arrived -> aborted
  cancellation frames: DEBUG, DEBUG (also persisted as DEBUG)
  deadline / tunnel-serving / FTL / PNC controls: WARN, WARN, WARN, WARN
  inspectConnector: readyConnections=1, protocol=quic
  applyConfig(null): child stopped; inspectConnector=null

No live tunnel, browser, desktop, or mobile pass is claimed; the changed behavior is server logging only. No paid provider turns or live userdata were used.

Runtime reproduction fixture (save both files together outside the checkout)

issue-17765-connector-fixture.mjs

import { createServer } from 'node:http';
import { once } from 'node:events';

// A real loopback HTTP cancellation drives the recorded cloudflared protocol lines.
let markArrived;
const arrived = new Promise((resolve) => { markArrived = resolve; });
let markCancelled;
const cancelled = new Promise((resolve) => { markCancelled = resolve; });
const line = (text) => process.stderr.write(`2026-11-07T00:00:00Z ${text}\n`);
const server = createServer(async (request, response) => {
  if (request.url === '/ready') {
    response.setHeader('content-type', 'application/json');
    response.end(JSON.stringify({ status: 200, readyConnections: 1 }));
  } else if (request.url === '/hold') {
    request.once('close', () => {
      line('ERR error="Incoming request ended abruptly: context canceled" connIndex=0');
      line('ERR Request failed error="Incoming request ended abruptly: context canceled" connIndex=0');
      markCancelled();
    });
    markArrived();
  } else if (request.url === '/arrived') {
    await arrived;
    response.end('request arrived');
  } else if (request.url === '/controls') {
    await cancelled;
    line('ERR error="Incoming request ended abruptly: context deadline exceeded" connIndex=0');
    line('ERR Failed to serve tunnel connection error="context canceled"');
    line('FTL error="Incoming request ended abruptly: context canceled"');
    line('PNC error="Incoming request ended abruptly: context canceled"');
    line('INF Registered tunnel connection connIndex=1 protocol=quic');
    response.end('control lines emitted');
  } else {
    response.writeHead(404).end();
  }
});
server.listen(0, '127.0.0.1');
await once(server, 'listening');
line(`INF Starting metrics server on 127.0.0.1:${server.address().port}/metrics`);
line('INF Registered tunnel connection connIndex=0 protocol=quic');
// This module is preloaded by the production process spawner; do not load its CLI placeholder.
await new Promise(() => {});

issue-17765-runtime.mjs

import assert from 'node:assert/strict';
import { existsSync, mkdtempSync, readFileSync, writeFileSync } from 'node:fs';
import { createRequire } from 'node:module';
import { dirname, join } from 'node:path';
import { fileURLToPath, pathToFileURL } from 'node:url';

const checkout = process.argv[2];
const mode = process.argv[3];
assert.ok(checkout && ['baseline', 'fixed'].includes(mode));
assert.ok(existsSync(join(checkout, 'apps/server/node_modules/effect/package.json')), 'Local server dependencies are not linked; ancestor fallback is forbidden.');
const requireLocal = createRequire(join(checkout, 'apps/server/package.json'));
const pkg = (name) => import(pathToFileURL(requireLocal.resolve(name)).href);
const source = (path) => import(pathToFileURL(join(checkout, path)).href);
const [Effect, Layer, Logger, Deferred, Exit, References, ConfigProvider, NodeServices, NodeCrypto, FetchHttpClient, HostProcess, RelayClient, ServerConfig, ServerSecretStore, ManagedPolicy, ManagedEndpointRuntime] = await Promise.all([
  pkg('effect/Effect'), pkg('effect/Layer'), pkg('effect/Logger'), pkg('effect/Deferred'), pkg('effect/Exit'), pkg('effect/References'), pkg('effect/ConfigProvider'), pkg('@effect/platform-node/NodeServices'), pkg('@effect/platform-node/NodeCrypto'), pkg('effect/http/FetchHttpClient'), source('packages/shared/src/HostProcess.ts'), source('packages/shared/src/relayClient.ts'),
  source('apps/server/src/config.ts'), source('apps/server/src/auth/ServerSecretStore.ts'), source('apps/server/src/policy/ManagedPolicy.ts'), source('apps/server/src/cloud/ManagedEndpointRuntime.ts'),
]);
const scratch = dirname(fileURLToPath(import.meta.url));
const state = mkdtempSync(join(scratch, `issue-17765-${mode}-`));
const logs = [];
const address = Deferred.makeUnsafe();
const controlsSeen = Deferred.makeUnsafe();
const capturedPids = new Set();
const logger = Logger.make(({ logLevel, message }) => {
  if (!Array.isArray(message) || !String(message[0]).startsWith('Relay client')) return;
  const attributes = message[1] ?? {};
  logs.push({ level: logLevel, message: message[0], output: attributes.output });
  if (typeof attributes.pid === 'number') capturedPids.add(attributes.pid);
  const output = attributes.output ?? '';
  const match = /Starting metrics server on (127\.0\.0\.1:\d+)\/metrics/.exec(output);
  if (match) Deferred.doneUnsafe(address, Exit.succeed(`http://${match[1]}`));
  if (output.includes('Registered tunnel connection connIndex=1')) Deferred.doneUnsafe(controlsSeen, Exit.void);
});
const fixtureUrl = new URL('./issue-17765-connector-fixture.mjs', import.meta.url).href;
const env = { ...process.env, NODE_OPTIONS: `--import=${fixtureUrl}` };
delete env.VITE_HTTP_URL;
delete env.VITE_WS_URL;
const configuration = ServerConfig.layerTest(checkout, state).pipe(Layer.provide(NodeServices.layer));
const system = Layer.mergeAll(NodeServices.layer, NodeCrypto.layer, configuration);
const dependencies = Layer.mergeAll(
  ManagedPolicy.layerTest(),
  ServerSecretStore.layer.pipe(Layer.provide(system)),
  FetchHttpClient.layer,
  configuration,
  Layer.succeed(RelayClient.RelayClient, RelayClient.RelayClient.of({
    resolve: Effect.succeed({ status: 'available', executablePath: process.execPath, source: 'path', version: RelayClient.CLOUDFLARED_VERSION }),
    install: Effect.die('unexpected installer'),
    installWithProgress: () => Effect.die('unexpected installer'),
    pruneManagedVersions: Effect.void,
  })),
).pipe(Layer.provideMerge(system));
try {
  await Effect.runPromise(Effect.gen(function* () {
    const context = yield* Layer.build(ManagedEndpointRuntime.layer.pipe(Layer.provide(dependencies)));
    const runtime = yield* Effect.service(ManagedEndpointRuntime.CloudManagedEndpointRuntime).pipe(Effect.provide(context));
    yield* runtime.applyConfig({ providerKind: 'cloudflare_tunnel', connectorToken: 'fixture-only-no-cloud-access', tunnelId: 'fixture-17765' });
    const origin = yield* Deferred.await(address);
    yield* Effect.promise(async () => {
      const controller = new AbortController();
      const held = fetch(`${origin}/hold`, { signal: controller.signal }).catch((error) => error);
      assert.equal(await (await fetch(`${origin}/arrived`)).text(), 'request arrived');
      controller.abort();
      assert.equal((await held).name, 'AbortError');
      assert.equal(await (await fetch(`${origin}/controls`)).text(), 'control lines emitted');
    });
    yield* Deferred.await(controlsSeen);
    const output = logs.filter((entry) => entry.output);
    const cancellations = output.filter((entry) => / ERR .*error="Incoming request ended abruptly: context canceled"/.test(entry.output));
    assert.equal(cancellations.length, 2);
    assert.deepEqual(cancellations.map((entry) => entry.level), mode === 'baseline' ? ['Warn', 'Warn'] : ['Debug', 'Debug']);
    const controls = output.filter((entry) => /deadline exceeded|Failed to serve tunnel| FTL | PNC /.test(entry.output));
    assert.equal(controls.length, 4);
    assert.ok(controls.every((entry) => entry.level === 'Warn'));
    const facts = yield* runtime.inspectConnector;
    assert.equal(facts.readyConnections, 1);
    assert.equal(facts.protocol, 'quic');
    const persisted = readFileSync(join(state, 'userdata/logs/relay-client.ndjson'), 'utf8').trim().split('\n').map((line) => JSON.parse(line));
    const persistedCancellations = persisted.filter((entry) => / ERR .*error="Incoming request ended abruptly: context canceled"/.test(entry.message[1]?.output ?? ''));
    assert.deepEqual(persistedCancellations.map((entry) => entry.level), mode === 'baseline' ? ['WARN', 'WARN'] : ['DEBUG', 'DEBUG']);
    const persistedControls = persisted.filter((entry) => /deadline exceeded|Failed to serve tunnel| FTL | PNC /.test(entry.message[1]?.output ?? ''));
    assert.equal(persistedControls.length, 4);
    assert.ok(persistedControls.every((entry) => entry.level === 'WARN'));
    yield* runtime.applyConfig(null);
    assert.equal(yield* runtime.inspectConnector, null);
  }).pipe(
    Effect.scoped,
    Effect.withLogger(logger),
    Effect.provideService(References.MinimumLogLevel, 'Debug'),
    Effect.provideService(HostProcess.Environment, env),
    Effect.provide(ConfigProvider.layer(ConfigProvider.fromEnv({ env }))),
  ));
  console.log(JSON.stringify({ mode, state, capturedPids: [...capturedPids], observations: logs, result: 'passed', boundary: 'Real production connector service, OS child process, loopback HTTP abort, output observer and log sink; deterministic cloudflared protocol fixture, no live cloud tunnel or UI.' }, null, 2));
} finally {
  writeFileSync(join(state, 'transcript.json'), JSON.stringify({ mode, capturedPids: [...capturedPids], logs }, null, 2));
}

The required vp run check:changed --concurrency 1 was attempted. It printed 2 files since 32a0531748c4 (origin/main), then stalled in the ignored-input git ls-files junction scan tracked by #32023. I stopped only that retained session and ran every selected equivalent stage serially, without changing check configuration or creating a check cache:

  • Format and lint: both changed files passed (vp fmt --check --no-error-on-unmatched-pattern <both files> and vp lint --no-error-on-unmatched-pattern <both files>).
  • vp exec knip --include files,dependencies --no-config-hints: passed.
  • Exports knip, with the unchanged knip:check:exports arguments below: passed (saved exit code 0).
  • vp run --filter ./apps/server generate --check: passed.
  • For each of t3, @t3tools/scripts, and @t3tools/evals: vp run --cache --parallel --concurrency-limit 1 --filter <package> typecheck: passed, exit 0. Earlier attempts encountered host memory-allocation failures; all three were rerun successfully with the same checker settings. Existing Effect suggestions were emitted, with no error diagnostics.
  • The two selected test files listed above passed from their owning package. No repo-wide test suite or model eval was run; this change contains no model-facing text.
  • git diff --check: passed.
Exact format, lint, and exports commands
vp fmt --check --no-error-on-unmatched-pattern apps/server/src/cloud/ManagedEndpointRuntime.ts apps/server/src/cloud/ManagedEndpointRuntime.test.ts
vp lint --no-error-on-unmatched-pattern apps/server/src/cloud/ManagedEndpointRuntime.ts apps/server/src/cloud/ManagedEndpointRuntime.test.ts
vp exec knip --workspace apps/server --workspace apps/desktop --workspace apps/web --workspace packages/client-runtime --workspace packages/contracts --workspace packages/effect-acp --workspace packages/effect-codex-app-server --workspace packages/shared --workspace packages/ssh --workspace packages/tailscale --workspace packages/provider-core --workspace packages/provider-acp --workspace packages/provider-acp-registry --workspace packages/provider-testing --workspace packages/provider-pi --workspace packages/provider-muse --workspace packages/provider-opencode --workspace packages/provider-cursor --workspace packages/provider-fx --workspace packages/provider-grok --workspace packages/provider-kiro --workspace packages/secret-provider-core --workspace packages/secret-provider-definitions --workspace packages/secret-provider-onepassword --workspace packages/source-control-core --workspace packages/source-control-definitions --workspace packages/source-control-azure-devops --workspace packages/source-control-bitbucket --workspace packages/source-control-forgejo --workspace packages/source-control-gitcafe --workspace packages/source-control-github --workspace packages/source-control-gitlab --workspace packages/source-control-testing --exports --preprocessor ./scripts/knip-schemas.ts --no-config-hints

Implemented with OpenAI GPT-6 via the Codex harness.

Copilot AI balanced review requested due to automatic review settings November 6, 2026 22:22

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota. Try requesting a review at a lower effort level.

@github-actions github-actions Bot added vouch:unvouched PR author is not yet trusted in the VOUCHED list. size:XS 0-9 changed lines (additions + deletions). labels Nov 6, 2026
@macroscopeapp

macroscopeapp Bot commented Nov 6, 2026

Copy link
Copy Markdown
Contributor

Approvability

Verdict: Approved at b1cce47

Macroscope's review found this PR approvable — Canceled relay-request messages move from warning to debug logging. The change is narrowly scoped and leaves tunnel recovery and other error reporting unchanged.

You can add or adjust custom eligibility rules. Learn more.

@coderabbitai

coderabbitai Bot commented Nov 6, 2026

Copy link
Copy Markdown
Contributor

Explain Change →

No actionable comments were generated in the recent review.

Walkthrough

The relay output classifier now treats a specific canceled-request error as debug. Tests cover both accepted prefixes and confirm warning classifications for other error messages.

Changes: Relay output classification

Layer / File(s) Summary
Canceled-request classification
apps/server/src/cloud/ManagedEndpointRuntime.ts, apps/server/src/cloud/ManagedEndpointRuntime.test.ts
classifyRelayClientOutput classifies the specified context-canceled error as debug, with or without the Request failed prefix. Tests also verify warning classifications for deadline, connection-serving, fatal, and panic output.

Estimated code review effort: 2 (Simple) | ~10 minutes

Change: Bug fix · Severity of issue fixed: Low

Possibly related issues

  • Issue 17765: Canceled Cloudflared requests were logged as warnings. This change classifies the specified canceled-request output as debug.

Suggested reviewers: juliusmarminge

Merge Risk: Minimal · up to b1cce

The change lowers log severity for routine relay cancellations while retaining warnings for the reported control cases. No merge-blocking risk is established.

Pre-merge checks: Passed 4

Check name Status Explanation
Title check Passed The title clearly describes the main logging change.
Description check Passed The description covers the problem, change, scope, approval exception, and verification. It also states testing limits and identifies the model and harness.
Linked Issues check Passed Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check Passed Check skipped because no linked issues were found for this pull request.
Finishing Touches

Generate unit tests (beta)

  • Create a new PR
  • Autofix · Keep fixing CodeRabbit findings and required CI, and resolving merge conflicts
Recent review info

Run configuration

Commits

Reviewing files that changed from the base of the PR and between b90e554 and b1cce47.

Files selected for processing: 2

  • apps/server/src/cloud/ManagedEndpointRuntime.test.ts
  • apps/server/src/cloud/ManagedEndpointRuntime.ts

Included review availability: This review used your included allowance. Your plan provides up to 10 included reviews per hour; 8 remain after this review.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

size:XS 0-9 changed lines (additions + deletions). vouch:unvouched PR author is not yet trusted in the VOUCHED list.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants