The legacy engine logs before it settles a timed-out, closed or lost call, so a logger that throws leaves the call pending #651

// Probe (Imogen-2490): the legacy engine logs before it settles a call, in its
// request watchdog and in close(), so a host logger that throws leaves the
// call unsettled. Run with tsx from the agent-framework checkout's root.
import { McplServerConnection } from '../src/mcpl/server-connection.js';
import type { McplHostCapabilities, McplServerConfig } from '../src/mcpl/types.js';

console.log(`node ${process.version}, ${process.platform}`);

// Answers initialize and tools/list, never tools/call (as test/mcpl-request-timeout.test.ts's server).
const HUNG_SERVER = `
let buf = '';
process.stdin.on('data', (c) => {
  buf += c.toString('utf8');
  let i;
  while ((i = buf.indexOf('\\n')) >= 0) {
    const line = buf.slice(0, i); buf = buf.slice(i + 1);
    if (!line.trim()) continue;
    let m; try { m = JSON.parse(line); } catch { continue; }
    const reply = (result) => process.stdout.write(JSON.stringify({ jsonrpc: '2.0', id: m.id, result }) + '\\n');
    if (m.method === 'initialize') reply({ protocolVersion: '2024-11-05', capabilities: {} });
    else if (m.method === 'tools/list') reply({ tools: [{ name: 'stuck', description: 's', inputSchema: { type: 'object' } }] });
  }
});
setInterval(() => {}, 1 << 30);
`;
const HOST_CAPS: McplHostCapabilities = { version: '0.4', pushEvents: true, contextHooks: { beforeInference: true }, featureSets: true };
const config: McplServerConfig = { id: 'hung', command: process.execPath, args: ['-e', HUNG_SERVER], requestTimeoutMs: 250 };

const escaped: string[] = [];
process.on('uncaughtException', (err) => { escaped.push(String((err as Error).message ?? err)); });

const realError = console.error;
const throwingLogger = () => { throw new Error('host logger failed'); };

/** How a promise stands after `ms`: settled (and how) or still pending. */
async function standing(p: Promise<unknown>, ms: number): Promise<string> {
  let state = 'pending';
  p.then(() => { state = 'resolved'; }, (e) => { state = `rejected: ${String((e as Error).message).slice(0, 80)}`; });
  await new Promise((r) => setTimeout(r, ms));
  return state;
}

// 1. The watchdog: the call times out at 250 ms while the logger throws.
{
  const c = await McplServerConnection.connect(config, HOST_CAPS);
  c.ready();
  console.error = throwingLogger;
  const call = c.sendToolsCall('stuck', {});
  const s = await standing(call, 1500);
  console.error = realError;
  console.log(`watchdog, logger throwing: the call is ${s} 1.5 s after a 250 ms timeout`);
  console.log(`  escaped from the timer: ${JSON.stringify(escaped)}`);
  // With the logger working again, nothing later settles it.
  console.log(`  logger restored: the call is ${await standing(call, 3000)} 3 s later`);
  // Control: the same with a logger that works.
  const call2 = c.sendToolsCall('stuck', {});
  console.error = () => {};
  const s2 = await standing(call2, 1500);
  console.error = realError;
  console.log(`watchdog, logger working: the call is ${s2}`);
  await c.close();
}

// 2. close(): a call in flight when this host closes the connection.
{
  escaped.length = 0;
  const c = await McplServerConnection.connect({ ...config, requestTimeoutMs: 0 }, HOST_CAPS);
  c.ready();
  const call = c.sendToolsCall('stuck', {});
  await new Promise((r) => setTimeout(r, 100));
  console.error = throwingLogger;
  let closeThrew = 'no';
  try { void c.close().catch(() => {}); } catch (e) { closeThrew = `yes: ${(e as Error).message}`; }
  const s = await standing(call, 1000);
  console.error = realError;
  console.log(`close(), logger throwing: close() threw ${closeThrew}; the call is ${s} 1 s later`);
  // With the logger working again, a second close() doesn't settle it either.
  console.error = () => {};
  let again = 'resolved';
  try { await c.close(); } catch (e) { again = `threw: ${(e as Error).message}`; }
  console.error = realError;
  console.log(`  logger restored, close() again (${again}): the call is ${await standing(call, 1000)} 1 s later`);
}
// 3. The transport-close handler (`lost`): the server exits while a call is in flight.
{
  escaped.length = 0;
  const EXITS = HUNG_SERVER.replace(
    "else if (m.method === 'tools/list')",
    "else if (m.method === 'tools/call') setTimeout(() => process.exit(1), 100);\n    else if (m.method === 'tools/list')",
  );
  const c = await McplServerConnection.connect({ ...config, id: 'exits', args: ['-e', EXITS], requestTimeoutMs: 0 }, HOST_CAPS);
  c.ready();
  console.error = throwingLogger;
  const call = c.sendToolsCall('stuck', {});
  const s = await standing(call, 1500);
  console.error = realError;
  console.log(`lost, logger throwing: the server exited 100 ms into the call; the call is ${s} 1.5 s later`);
  console.log(`  escaped from the close handler: ${JSON.stringify(escaped)}`);
  // With the logger working again, nothing later settles it, and closing doesn't either.
  console.error = () => {};
  const later = await standing(call, 3000);
  try { await c.close(); } catch { /* closed */ }
  const afterClose = await standing(call, 500);
  console.error = realError;
  console.log(`  logger restored: the call is ${later} 3 s later, and ${afterClose} after close()`);
}
setTimeout(() => process.exit(0), 200);