fix(gateway): debug log floods with event-loop-health scheduler lines (#161895)

* fix(gateway): debug log floods with event-loop-health scheduler lines

Since event-loop sampling moved onto the Gateway scheduler as a 20 ms
cadence job, the scheduler's per-run "running <id>" debug line fires about
47 times a second. With logging.level "debug" that line is about 98% of
the file log, so the default rolling log keeps only about 8 hours.

Log repeating cadence runs at trace and keep one-shot runs at debug.
Run failures still log at error.

Closes #161891

* test(hooks): give the Gmail watcher's logger mock a trace method

The Gmail watcher renews through a Gateway scheduler cadence job, whose
per-run line is now logged at trace. The test's subsystem logger mock had
no trace method, so every renewal threw "log.trace is not a function".
This commit is contained in:
matthematics1137 2026-10-01 08:29:33 -04:00 • committed by GitHub
parent fbb4b36376
commit b2fc927ff4
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
3 changed files with 33 additions and 2 deletions

View file

@ -11,7 +11,7 @@ const mocks = vi.hoisted(() => ({
runCommandWithTimeout: vi.fn(),
killProcessTree: vi.fn(),
spawn: vi.fn(),
log: { debug: vi.fn(), error: vi.fn(), warn: vi.fn(), info: vi.fn() },
log: { debug: vi.fn(), trace: vi.fn(), error: vi.fn(), warn: vi.fn(), info: vi.fn() },
defaultRuntime: {
log: vi.fn(),
error: vi.fn(),

View file

@ -7,6 +7,11 @@ import {
createTestGatewayScheduler,
} from "../test-utils/gateway-scheduler-clock.js";
const schedulerLog = vi.hoisted(() => ({ debug: vi.fn(), trace: vi.fn(), error: vi.fn() }));
vi.mock("../logging/subsystem.js", () => ({
createSubsystemLogger: () => schedulerLog,
}));
function fixture() {
const time = createGatewaySchedulerClock(1_000);
const scheduler = createTestGatewayScheduler(time.clock);
@ -331,6 +336,26 @@ describe("Gateway timed work", () => {
await scheduler.stop();
});
it("logs one-shot runs at debug and repeating cadence runs only at trace", async () => {
const { time, scheduler } = fixture();
schedulerLog.debug.mockClear();
schedulerLog.trace.mockClear();
const sample = vi.fn();
scheduler.schedule({ id: "event-loop-health", delayMs: 20, everyMs: 20, run: sample });
scheduler.schedule({ id: "approval", delayMs: 30, run: () => {} });
await time.advanceBy(20);
await time.advanceBy(20);
await time.advanceBy(20);
expect(sample).toHaveBeenCalledTimes(3);
expect(schedulerLog.debug.mock.calls).toEqual([["running approval"]]);
expect(schedulerLog.trace.mock.calls).toEqual([
["running event-loop-health"],
["running event-loop-health"],
["running event-loop-health"],
]);
await scheduler.stop();
});
it("retains a distant deadline across the host timer delay ceiling", async () => {
const { time, scheduler } = fixture();
const run = vi.fn();

View file

@ -274,7 +274,13 @@ export class GatewayScheduler {
}
private run(job: ScheduledWork): Promise<void> {
log.debug(`running ${job.id}`);
// Cadence jobs can run every few milliseconds (event-loop sampling runs every 20ms),
// so only one-shot runs are worth a debug line.
if (job.everyMs === undefined) {
log.debug(`running ${job.id}`);
} else {
log.trace(`running ${job.id}`);
}
const done = createDeferredCore();
const work = new AsyncWorkScope();
job.running = done.promise;