fix: remove unnecessary isLoggingEnabled() checks (#420)

It appears that use of `isLoggingEnabled()` was erroneously copypasta'd
in many places. This PR updates its docstring to clarify that should
only be used to avoid constructing a potentially expensive docstring.
With this change, the only function that merits/uses this check is
`execCommand()`.

---
[//]: # (BEGIN SAPLING FOOTER)
Stack created with [Sapling](https://sapling-scm.com). Best reviewed
with [ReviewStack](https://reviewstack.dev/openai/codex/pull/420).
* #423
* __->__ #420
* #419
This commit is contained in:
Michael Bolin
2025-04-20 09:58:06 -07:00
committed by GitHub
parent 81cf47e591
commit b554b522f7
10 changed files with 199 additions and 192 deletions

View File

@@ -1,4 +1,4 @@
import { log, isLoggingEnabled } from "../../utils/agent/log.js";
import { log } from "../../utils/agent/log.js";
import { Box, Text, useInput, useStdin } from "ink";
import React, { useState } from "react";
import { useInterval } from "use-interval";
@@ -40,11 +40,9 @@ export default function TerminalChatInputThinking({
const str = Buffer.isBuffer(data) ? data.toString("utf8") : data;
if (str === "\x1b\x1b") {
if (isLoggingEnabled()) {
log(
"raw stdin: received collapsed ESC ESC starting confirmation timer",
);
}
log(
"raw stdin: received collapsed ESC ESC starting confirmation timer",
);
setAwaitingConfirm(true);
setTimeout(() => setAwaitingConfirm(false), 1500);
}
@@ -65,15 +63,11 @@ export default function TerminalChatInputThinking({
}
if (awaitingConfirm) {
if (isLoggingEnabled()) {
log("useInput: second ESC detected triggering onInterrupt()");
}
log("useInput: second ESC detected triggering onInterrupt()");
onInterrupt();
setAwaitingConfirm(false);
} else {
if (isLoggingEnabled()) {
log("useInput: first ESC detected waiting for confirmation");
}
log("useInput: first ESC detected waiting for confirmation");
setAwaitingConfirm(true);
setTimeout(() => setAwaitingConfirm(false), 1500);
}

View File

@@ -8,7 +8,7 @@ import type {
import MultilineTextEditor from "./multiline-editor";
import { TerminalChatCommandReview } from "./terminal-chat-command-review.js";
import { log, isLoggingEnabled } from "../../utils/agent/log.js";
import { log } from "../../utils/agent/log.js";
import { loadConfig } from "../../utils/config.js";
import { createInputItem } from "../../utils/input-utils.js";
import { setSessionId } from "../../utils/session.js";
@@ -738,11 +738,9 @@ function TerminalChatInputThinking({
const str = Buffer.isBuffer(data) ? data.toString("utf8") : data;
if (str === "\x1b\x1b") {
// Treat as the first Escape press prompt the user for confirmation.
if (isLoggingEnabled()) {
log(
"raw stdin: received collapsed ESC ESC starting confirmation timer",
);
}
log(
"raw stdin: received collapsed ESC ESC starting confirmation timer",
);
setAwaitingConfirm(true);
setTimeout(() => setAwaitingConfirm(false), 1500);
}
@@ -767,15 +765,11 @@ function TerminalChatInputThinking({
}
if (awaitingConfirm) {
if (isLoggingEnabled()) {
log("useInput: second ESC detected triggering onInterrupt()");
}
log("useInput: second ESC detected triggering onInterrupt()");
onInterrupt();
setAwaitingConfirm(false);
} else {
if (isLoggingEnabled()) {
log("useInput: first ESC detected waiting for confirmation");
}
log("useInput: first ESC detected waiting for confirmation");
setAwaitingConfirm(true);
setTimeout(() => setAwaitingConfirm(false), 1500);
}

View File

@@ -8,7 +8,7 @@ import type {
import MultilineTextEditor from "./multiline-editor";
import { TerminalChatCommandReview } from "./terminal-chat-command-review.js";
import { log, isLoggingEnabled } from "../../utils/agent/log.js";
import { log } from "../../utils/agent/log.js";
import { loadConfig } from "../../utils/config.js";
import { createInputItem } from "../../utils/input-utils.js";
import { setSessionId } from "../../utils/session.js";
@@ -505,11 +505,9 @@ function TerminalChatInputThinking({
const str = Buffer.isBuffer(data) ? data.toString("utf8") : data;
if (str === "\x1b\x1b") {
// Treat as the first Escape press prompt the user for confirmation.
if (isLoggingEnabled()) {
log(
"raw stdin: received collapsed ESC ESC starting confirmation timer",
);
}
log(
"raw stdin: received collapsed ESC ESC starting confirmation timer",
);
setAwaitingConfirm(true);
setTimeout(() => setAwaitingConfirm(false), 1500);
}
@@ -531,15 +529,11 @@ function TerminalChatInputThinking({
}
if (awaitingConfirm) {
if (isLoggingEnabled()) {
log("useInput: second ESC detected triggering onInterrupt()");
}
log("useInput: second ESC detected triggering onInterrupt()");
onInterrupt();
setAwaitingConfirm(false);
} else {
if (isLoggingEnabled()) {
log("useInput: first ESC detected waiting for confirmation");
}
log("useInput: first ESC detected waiting for confirmation");
setAwaitingConfirm(true);
setTimeout(() => setAwaitingConfirm(false), 1500);
}

View File

@@ -15,7 +15,7 @@ import { formatCommandForDisplay } from "../../format-command.js";
import { useConfirmation } from "../../hooks/use-confirmation.js";
import { useTerminalSize } from "../../hooks/use-terminal-size.js";
import { AgentLoop } from "../../utils/agent/agent-loop.js";
import { isLoggingEnabled, log } from "../../utils/agent/log.js";
import { log } from "../../utils/agent/log.js";
import { ReviewDecision } from "../../utils/agent/review.js";
import { generateCompactSummary } from "../../utils/compact-summary.js";
import { OPENAI_BASE_URL } from "../../utils/config.js";
@@ -213,30 +213,25 @@ export default function TerminalChat({
// ────────────────────────────────────────────────────────────────
// DEBUG: log every render w/ key bits of state
// ────────────────────────────────────────────────────────────────
if (isLoggingEnabled()) {
log(
`render agent? ${Boolean(agentRef.current)} loading=${loading} items=${
items.length
}`,
);
}
log(
`render agent? ${Boolean(agentRef.current)} loading=${loading} items=${
items.length
}`,
);
useEffect(() => {
// Skip recreating the agent if awaiting a decision on a pending confirmation
if (confirmationPrompt != null) {
if (isLoggingEnabled()) {
log("skip AgentLoop recreation due to pending confirmationPrompt");
}
log("skip AgentLoop recreation due to pending confirmationPrompt");
return;
}
if (isLoggingEnabled()) {
log("creating NEW AgentLoop");
log(
`model=${model} instructions=${Boolean(
config.instructions,
)} approvalPolicy=${approvalPolicy}`,
);
}
log("creating NEW AgentLoop");
log(
`model=${model} instructions=${Boolean(
config.instructions,
)} approvalPolicy=${approvalPolicy}`,
);
// Tear down any existing loop before creating a new one
agentRef.current?.terminate();
@@ -304,14 +299,10 @@ export default function TerminalChat({
// force a render so JSX below can "see" the freshly created agent
forceUpdate();
if (isLoggingEnabled()) {
log(`AgentLoop created: ${inspect(agentRef.current, { depth: 1 })}`);
}
log(`AgentLoop created: ${inspect(agentRef.current, { depth: 1 })}`);
return () => {
if (isLoggingEnabled()) {
log("terminating AgentLoop");
}
log("terminating AgentLoop");
agentRef.current?.terminate();
agentRef.current = undefined;
forceUpdate(); // rerender after teardown too
@@ -393,9 +384,7 @@ export default function TerminalChat({
// Let's also track whenever the ref becomes available
const agent = agentRef.current;
useEffect(() => {
if (isLoggingEnabled()) {
log(`agentRef.current is now ${Boolean(agent)}`);
}
log(`agentRef.current is now ${Boolean(agent)}`);
}, [agent]);
// ---------------------------------------------------------------------
@@ -541,11 +530,9 @@ export default function TerminalChat({
if (!agent) {
return;
}
if (isLoggingEnabled()) {
log(
"TerminalChat: interruptAgent invoked calling agent.cancel()",
);
}
log(
"TerminalChat: interruptAgent invoked calling agent.cancel()",
);
agent.cancel();
setLoading(false);
@@ -581,13 +568,11 @@ export default function TerminalChat({
currentModel={model}
hasLastResponse={Boolean(lastResponseId)}
onSelect={(newModel) => {
if (isLoggingEnabled()) {
log(
"TerminalChat: interruptAgent invoked calling agent.cancel()",
);
if (!agent) {
log("TerminalChat: agent is not ready yet");
}
log(
"TerminalChat: interruptAgent invoked calling agent.cancel()",
);
if (!agent) {
log("TerminalChat: agent is not ready yet");
}
agent?.cancel();
setLoading(false);

View File

@@ -8,7 +8,7 @@ import type {
} from "openai/resources/responses/responses.mjs";
import type { Reasoning } from "openai/resources.mjs";
import { log, isLoggingEnabled } from "./log.js";
import { log } from "./log.js";
import { OPENAI_BASE_URL, OPENAI_TIMEOUT_MS } from "../config.js";
import { parseToolCallArguments } from "../parsers.js";
import {
@@ -116,15 +116,13 @@ export class AgentLoop {
// Reset the current stream to allow new requests
this.currentStream = null;
if (isLoggingEnabled()) {
log(
`AgentLoop.cancel() invoked currentStream=${Boolean(
this.currentStream,
)} execAbortController=${Boolean(
this.execAbortController,
)} generation=${this.generation}`,
);
}
log(
`AgentLoop.cancel() invoked currentStream=${Boolean(
this.currentStream,
)} execAbortController=${Boolean(this.execAbortController)} generation=${
this.generation
}`,
);
(
this.currentStream as { controller?: { abort?: () => void } } | null
)?.controller?.abort?.();
@@ -136,9 +134,7 @@ export class AgentLoop {
// Create a new abort controller for future tool calls
this.execAbortController = new AbortController();
if (isLoggingEnabled()) {
log("AgentLoop.cancel(): execAbortController.abort() called");
}
log("AgentLoop.cancel(): execAbortController.abort() called");
// NOTE: We intentionally do *not* clear `lastResponseId` here. If the
// stream produced a `function_call` before the user cancelled, OpenAI now
@@ -174,9 +170,7 @@ export class AgentLoop {
// this.onItem(cancelNotice);
this.generation += 1;
if (isLoggingEnabled()) {
log(`AgentLoop.cancel(): generation bumped to ${this.generation}`);
}
log(`AgentLoop.cancel(): generation bumped to ${this.generation}`);
}
/**
@@ -315,13 +309,11 @@ export class AgentLoop {
const callId: string = (item as any).call_id ?? (item as any).id;
const args = parseToolCallArguments(rawArguments ?? "{}");
if (isLoggingEnabled()) {
log(
`handleFunctionCall(): name=${
name ?? "undefined"
} callId=${callId} args=${rawArguments}`,
);
}
log(
`handleFunctionCall(): name=${
name ?? "undefined"
} callId=${callId} args=${rawArguments}`,
);
if (args == null) {
const outputItem: ResponseInputItem.FunctionCallOutput = {
@@ -407,11 +399,9 @@ export class AgentLoop {
// Create a fresh AbortController for this run so that tool calls from a
// previous run do not accidentally get signalled.
this.execAbortController = new AbortController();
if (isLoggingEnabled()) {
log(
`AgentLoop.run(): new execAbortController created (${this.execAbortController.signal}) for generation ${this.generation}`,
);
}
log(
`AgentLoop.run(): new execAbortController created (${this.execAbortController.signal}) for generation ${this.generation}`,
);
// NOTE: We no longer (re)attach an `abort` listener to `hardAbort` here.
// A single listener that forwards the `abort` to the current
// `execAbortController` is installed once in the constructor. Readding a
@@ -502,11 +492,9 @@ export class AgentLoop {
const mergedInstructions = [prefix, this.instructions]
.filter(Boolean)
.join("\n");
if (isLoggingEnabled()) {
log(
`instructions (length ${mergedInstructions.length}): ${mergedInstructions}`,
);
}
log(
`instructions (length ${mergedInstructions.length}): ${mergedInstructions}`,
);
// eslint-disable-next-line no-await-in-loop
stream = await this.oai.responses.create({
model: this.model,
@@ -733,9 +721,7 @@ export class AgentLoop {
try {
// eslint-disable-next-line no-await-in-loop
for await (const event of stream) {
if (isLoggingEnabled()) {
log(`AgentLoop.run(): response event ${event.type}`);
}
log(`AgentLoop.run(): response event ${event.type}`);
// process and surface each item (noop until we can depend on streaming events)
if (event.type === "response.output_item.done") {

View File

@@ -223,23 +223,22 @@ async function execCommand(
workdir = process.cwd();
}
}
if (isLoggingEnabled()) {
if (applyPatchCommand != null) {
log("EXEC running apply_patch command");
} else {
const { cmd, timeoutInMillis } = execInput;
// Seconds are a bit easier to read in log messages and most timeouts
// are specified as multiples of 1000, anyway.
const timeout =
timeoutInMillis != null
? Math.round(timeoutInMillis / 1000).toString()
: "undefined";
log(
`EXEC running \`${formatCommandForDisplay(
cmd,
)}\` in workdir=${workdir} with timeout=${timeout}s`,
);
}
if (applyPatchCommand != null) {
log("EXEC running apply_patch command");
} else if (isLoggingEnabled()) {
const { cmd, timeoutInMillis } = execInput;
// Seconds are a bit easier to read in log messages and most timeouts
// are specified as multiples of 1000, anyway.
const timeout =
timeoutInMillis != null
? Math.round(timeoutInMillis / 1000).toString()
: "undefined";
log(
`EXEC running \`${formatCommandForDisplay(
cmd,
)}\` in workdir=${workdir} with timeout=${timeout}s`,
);
}
// Note execApplyPatch() and exec() are coded defensively and should not

View File

@@ -124,6 +124,14 @@ export function log(message: string): void {
(logger ?? initLogger()).log(message);
}
/**
* USE SPARINGLY! This function should only be used to guard a call to log() if
* the log message is large and you want to avoid constructing it if logging is
* disabled.
*
* `log()` is already a no-op if DEBUG is not set, so an extra
* `isLoggingEnabled()` check is unnecessary.
*/
export function isLoggingEnabled(): boolean {
return (logger ?? initLogger()).isLoggingEnabled();
}

View File

@@ -2,7 +2,7 @@
* Utility functions for handling platform-specific commands
*/
import { log, isLoggingEnabled } from "./log.js";
import { log } from "./log.js";
/**
* Map of Unix commands to their Windows equivalents
@@ -59,9 +59,7 @@ export function adaptCommandForPlatform(command: Array<string>): Array<string> {
return command;
}
if (isLoggingEnabled()) {
log(`Adapting command '${cmd}' for Windows platform`);
}
log(`Adapting command '${cmd}' for Windows platform`);
// Create a new command array with the adapted command
const adaptedCommand = [...command];
@@ -78,9 +76,7 @@ export function adaptCommandForPlatform(command: Array<string>): Array<string> {
}
}
if (isLoggingEnabled()) {
log(`Adapted command: ${adaptedCommand.join(" ")}`);
}
log(`Adapted command: ${adaptedCommand.join(" ")}`);
return adaptedCommand;
}

View File

@@ -7,12 +7,15 @@ import type {
StdioPipe,
} from "child_process";
import { log, isLoggingEnabled } from "../log.js";
import { log } from "../log.js";
import { adaptCommandForPlatform } from "../platform-commands.js";
import { spawn } from "child_process";
import * as os from "os";
const MAX_BUFFER = 1024 * 100; // 100 KB
// Maximum output cap: either MAX_OUTPUT_LINES lines or MAX_OUTPUT_BYTES bytes,
// whichever limit is reached first.
const MAX_OUTPUT_BYTES = 1024 * 10; // 10 KB
const MAX_OUTPUT_LINES = 256;
/**
* This function should never return a rejected promise: errors should be
@@ -27,10 +30,7 @@ export function exec(
// Adapt command for the current platform (e.g., convert 'ls' to 'dir' on Windows)
const adaptedCommand = adaptCommandForPlatform(command);
if (
isLoggingEnabled() &&
JSON.stringify(adaptedCommand) !== JSON.stringify(command)
) {
if (JSON.stringify(adaptedCommand) !== JSON.stringify(command)) {
log(
`Command adapted for platform: ${command.join(
" ",
@@ -95,9 +95,7 @@ export function exec(
// timely fashion.
if (abortSignal) {
const abortHandler = () => {
if (isLoggingEnabled()) {
log(`raw-exec: abort signal received killing child ${child.pid}`);
}
log(`raw-exec: abort signal received killing child ${child.pid}`);
const killTarget = (signal: NodeJS.Signals) => {
if (!child.pid) {
return;
@@ -148,37 +146,14 @@ export function exec(
// resolve the promise and translate the failure into a regular
// ExecResult object so the rest of the agent loop can carry on gracefully.
const stdoutChunks: Array<Buffer> = [];
const stderrChunks: Array<Buffer> = [];
let numStdoutBytes = 0;
let numStderrBytes = 0;
let hitMaxStdout = false;
let hitMaxStderr = false;
return new Promise<ExecResult>((resolve) => {
child.stdout?.on("data", (data: Buffer) => {
if (!hitMaxStdout) {
numStdoutBytes += data.length;
if (numStdoutBytes <= MAX_BUFFER) {
stdoutChunks.push(data);
} else {
hitMaxStdout = true;
}
}
});
child.stderr?.on("data", (data: Buffer) => {
if (!hitMaxStderr) {
numStderrBytes += data.length;
if (numStderrBytes <= MAX_BUFFER) {
stderrChunks.push(data);
} else {
hitMaxStderr = true;
}
}
});
// Collect stdout and stderr up to configured limits.
const stdoutCollector = createTruncatingCollector(child.stdout!);
const stderrCollector = createTruncatingCollector(child.stderr!);
child.on("exit", (code, signal) => {
const stdout = Buffer.concat(stdoutChunks).toString("utf8");
const stderr = Buffer.concat(stderrChunks).toString("utf8");
const stdout = stdoutCollector.getString();
const stderr = stderrCollector.getString();
// Map (code, signal) to an exit code. We expect exactly one of the two
// values to be non-null, but we code defensively to handle the case where
@@ -194,24 +169,104 @@ export function exec(
exitCode = 1;
}
if (isLoggingEnabled()) {
log(
`raw-exec: child ${child.pid} exited code=${exitCode} signal=${signal}`,
);
}
resolve({
log(
`raw-exec: child ${child.pid} exited code=${exitCode} signal=${signal}`,
);
const execResult = {
stdout,
stderr,
exitCode,
});
};
resolve(
addTruncationWarningsIfNecessary(
execResult,
stdoutCollector.hit,
stderrCollector.hit,
),
);
});
child.on("error", (err) => {
resolve({
const execResult = {
stdout: "",
stderr: String(err),
exitCode: 1,
});
};
resolve(
addTruncationWarningsIfNecessary(
execResult,
stdoutCollector.hit,
stderrCollector.hit,
),
);
});
});
}
/**
* Creates a collector that accumulates data Buffers from a stream up to
* specified byte and line limits. After either limit is exceeded, further
* data is ignored.
*/
function createTruncatingCollector(
stream: NodeJS.ReadableStream,
byteLimit: number = MAX_OUTPUT_BYTES,
lineLimit: number = MAX_OUTPUT_LINES,
) {
const chunks: Array<Buffer> = [];
let totalBytes = 0;
let totalLines = 0;
let hitLimit = false;
stream?.on("data", (data: Buffer) => {
if (hitLimit) {
return;
}
totalBytes += data.length;
for (let i = 0; i < data.length; i++) {
if (data[i] === 0x0a) {
totalLines++;
}
}
if (totalBytes <= byteLimit && totalLines <= lineLimit) {
chunks.push(data);
} else {
hitLimit = true;
}
});
return {
getString() {
return Buffer.concat(chunks).toString("utf8");
},
/** True if either byte or line limit was exceeded */
get hit(): boolean {
return hitLimit;
},
};
}
/**
* Adds a truncation warnings to stdout and stderr, if appropriate.
*/
function addTruncationWarningsIfNecessary(
execResult: ExecResult,
hitMaxStdout: boolean,
hitMaxStderr: boolean,
): ExecResult {
if (!hitMaxStdout && !hitMaxStderr) {
return execResult;
} else {
const { stdout, stderr, exitCode } = execResult;
return {
stdout: hitMaxStdout
? stdout + "\n\n[Output truncated: too many lines or bytes]"
: stdout,
stderr: hitMaxStderr
? stderr + "\n\n[Output truncated: too many lines or bytes]"
: stderr,
exitCode,
};
}
}

View File

@@ -8,7 +8,7 @@
import type { FullAutoErrorMode } from "./auto-approval-mode.js";
import { log, isLoggingEnabled } from "./agent/log.js";
import { log } from "./agent/log.js";
import { AutoApprovalMode } from "./auto-approval-mode.js";
import { existsSync, mkdirSync, readFileSync, writeFileSync } from "fs";
import { load as loadYaml, dump as dumpYaml } from "js-yaml";
@@ -245,15 +245,11 @@ export const loadConfig = (
? resolvePath(cwd, options.projectDocPath)
: discoverProjectDocPath(cwd);
if (projectDocPath) {
if (isLoggingEnabled()) {
log(
`[codex] Loaded project doc from ${projectDocPath} (${projectDoc.length} bytes)`,
);
}
log(
`[codex] Loaded project doc from ${projectDocPath} (${projectDoc.length} bytes)`,
);
} else {
if (isLoggingEnabled()) {
log(`[codex] No project doc found in ${cwd}`);
}
log(`[codex] No project doc found in ${cwd}`);
}
}