|
| 1 | +# Case Study: No HTTP Request/Response Logs in `--verbose` Mode (#227) |
| 2 | + |
| 3 | +## Issue |
| 4 | + |
| 5 | +When the agent CLI is used directly with `--verbose`, HTTP request/response logs appear correctly. However, when the agent is spawned by the `solve` command via the `command-stream` library, HTTP verbose logs are silently absent despite `--verbose` being passed. |
| 6 | + |
| 7 | +**Issue:** https://github.com/link-assistant/agent/issues/227 |
| 8 | + |
| 9 | +## Evidence |
| 10 | + |
| 11 | +### Working Case (Direct Invocation) |
| 12 | + |
| 13 | +- **Log:** [Gist](https://gist.githubusercontent.com/konard/6a7107ae7987ef5ed19653d4b3b707cb/raw/2763388eac850465dc1a5ec1bb31f5001e9528f0/agent-cli-log.txt) |
| 14 | +- **Command:** `echo "hi" | agent --verbose` |
| 15 | +- **Version:** 0.18.3 |
| 16 | +- **Key indicators:** |
| 17 | + - `"verboseAtCreation": true` — Flag was true when SDK was created |
| 18 | + - 35 debug-level log entries |
| 19 | + - HTTP request/response logs present (e.g., `"message": "HTTP request"`) |
| 20 | + - `"message": "verbose HTTP logging active"` confirmation |
| 21 | + |
| 22 | +### Broken Case (Subprocess via solve/command-stream) |
| 23 | + |
| 24 | +- **Log:** [Gist](https://gist.githubusercontent.com/konard/79a96bcdf4b1e91ba83ba7bced26976c/raw/6a7f3b01e5a94d5a4bd00e94d1e50aae13c65c0e/solution-draft-log-pr-1775044356765.txt) |
| 25 | +- **Command:** `cat prompt.txt | agent --model opencode/minimax-m2.5-free --verbose` |
| 26 | +- **Version:** 0.18.1 (same code, different runtime environment) |
| 27 | +- **Key indicators:** |
| 28 | + - `"verboseAtCreation": false` — Flag was false when SDK was created |
| 29 | + - 0 debug-level log entries |
| 30 | + - No HTTP request/response logs at all |
| 31 | + - `"globalVerboseFetchInstalled": true` — Middleware DID run |
| 32 | + - No `"message": "verbose HTTP logging active"` confirmation |
| 33 | + |
| 34 | +## Timeline / Sequence of Events |
| 35 | + |
| 36 | +1. **Solve command** spawns agent CLI as child process via command-stream |
| 37 | +2. **Agent CLI starts** — yargs parses arguments, `--verbose` is recognized |
| 38 | +3. **Middleware runs** — `Flag.setVerbose(true)` is called, `globalThis.fetch` is monkey-patched |
| 39 | +4. **BUT** — `Flag.VERBOSE` is still `false` at the time HTTP calls are made |
| 40 | +5. **Verbose-fetch wrapper** checks `Flag.VERBOSE` → finds it `false` → skips logging |
| 41 | +6. **All HTTP logs are silently discarded** |
| 42 | + |
| 43 | +## Root Cause Analysis |
| 44 | + |
| 45 | +The `Flag.VERBOSE` flag is stored as an in-memory `export let` variable in the `flag.ts` module. When `setVerbose(true)` is called in the yargs middleware, it sets this variable to `true`. However, there's evidence that this value can be lost or not propagated correctly in certain runtime environments: |
| 46 | + |
| 47 | +1. **Module re-evaluation:** Bun may re-evaluate modules in some circumstances, resetting the flag to its initial value (`false` from env var check) |
| 48 | +2. **Runtime timing:** The flag may be checked before the middleware has fully completed in some environments |
| 49 | +3. **No persistence mechanism:** The flag only exists in memory — if the module is reloaded, the flag reverts to its default |
| 50 | + |
| 51 | +The evidence strongly supports this diagnosis: |
| 52 | + |
| 53 | +- `globalVerboseFetchInstalled: true` proves the middleware ran |
| 54 | +- `verboseAtCreation: false` proves the flag was `false` at SDK creation time |
| 55 | +- 0 debug-level logs proves the flag was `false` during `Log.init()` |
| 56 | +- These three facts together indicate the flag was set to `true` in the middleware but was `false` when checked later |
| 57 | + |
| 58 | +## Solution |
| 59 | + |
| 60 | +### 1. Remove Legacy OPENCODE\_\* Environment Variables |
| 61 | + |
| 62 | +All `OPENCODE_*` environment variable support has been removed from the codebase. The codebase now uses exclusively `LINK_ASSISTANT_AGENT_*` prefixed environment variables. This is a clean break from the legacy naming. |
| 63 | + |
| 64 | +### 2. Clean Flag Names |
| 65 | + |
| 66 | +All `Flag.OPENCODE_*` export names have been renamed to clean names without the `OPENCODE_` prefix (e.g., `Flag.VERBOSE`, `Flag.DRY_RUN`, `Flag.CONFIG`), since they are already namespaced under `Flag`. |
| 67 | + |
| 68 | +### 3. Environment Variable Propagation (Verbose Fix) |
| 69 | + |
| 70 | +When `Flag.setVerbose(true)` is called, the environment variable `LINK_ASSISTANT_AGENT_VERBOSE=true` is now also set. This provides: |
| 71 | + |
| 72 | +- **Persistence across module re-evaluations** — env vars survive module reloads |
| 73 | +- **Child process inheritance** — subprocesses automatically inherit the flag |
| 74 | +- **Redundancy** — two independent sources of truth |
| 75 | + |
| 76 | +### 4. `Flag.isVerbose()` Method with Fallback (Resilience Fix) |
| 77 | + |
| 78 | +A `Flag.isVerbose()` method checks both: |
| 79 | + |
| 80 | +- The in-memory `VERBOSE` flag (fast path) |
| 81 | +- The environment variable `LINK_ASSISTANT_AGENT_VERBOSE` (fallback) |
| 82 | + |
| 83 | +All verbose checks across the codebase use `Flag.isVerbose()` instead of directly reading `Flag.VERBOSE`. |
| 84 | + |
| 85 | +### Files Changed |
| 86 | + |
| 87 | +| File | Change | |
| 88 | +| ------------------------------ | ------------------------------------------------------------------------------------------- | |
| 89 | +| `js/src/config/config.ts`| Centralized config with makeConfig(), removed Flag module, env var propagation | |
| 90 | +| `js/src/util/verbose-fetch.ts` | Use `Flag.isVerbose()` | |
| 91 | +| `js/src/provider/provider.ts` | Use `Flag.DRY_RUN`, `Flag.ENABLE_EXPERIMENTAL_MODELS` | |
| 92 | +| `js/src/config/config.ts` | Use `Flag.CONFIG`, `Flag.CONFIG_DIR`, `Flag.CONFIG_CONTENT` | |
| 93 | +| `js/src/bun/index.ts` | Use `Flag.DRY_RUN` | |
| 94 | +| `js/src/file/watcher.ts` | Use `Flag.EXPERIMENTAL_WATCHER` | |
| 95 | +| `js/src/session/compaction.ts` | Use `Flag.DISABLE_AUTOCOMPACT`, `Flag.DISABLE_PRUNE` | |
| 96 | +| `js/src/util/log.ts` | Use `Flag.isVerbose()` | |
| 97 | +| `js/src/util/log-lazy.ts` | Use `Flag.isVerbose()` | |
| 98 | +| `js/src/index.js` | Use `Flag.DRY_RUN`, `Flag.isVerbose()` | |
| 99 | +| `js/src/session/*.ts` | Use `Flag.isVerbose()` | |
| 100 | +| `js/tests/` | Updated all tests to use new flag names and env var names | |
| 101 | + |
| 102 | +## Testing |
| 103 | + |
| 104 | +### New Tests (`verbose-env-fallback.test.js`) |
| 105 | + |
| 106 | +1. **Baseline:** `--verbose` flag produces HTTP logs |
| 107 | +2. **Env var:** `LINK_ASSISTANT_AGENT_VERBOSE=true` enables HTTP logs without `--verbose` flag |
| 108 | +3. **Negative:** No HTTP logs without `--verbose` or env var |
| 109 | +4. **Propagation:** `verboseAtCreation: true` confirmed in subprocess |
| 110 | + |
| 111 | +### Existing Tests |
| 112 | + |
| 113 | +- `verbose-hi.test.js` — continues to pass (no regression) |
| 114 | +- All dry-run, provider, and verbose logging tests updated and passing |
| 115 | + |
| 116 | +## Evidence from Issue #229 |
| 117 | + |
| 118 | +Issue [#229](https://github.com/link-assistant/agent/issues/229) independently confirmed the same root cause with additional detail: |
| 119 | + |
| 120 | +### Key Findings from #229 |
| 121 | + |
| 122 | +- **Working:** `OPENCODE_VERBOSE=true echo "hi" | agent --model opencode/minimax-m2.5-free` → `verboseAtCreation: true`, 18+ HTTP logs |
| 123 | +- **Broken:** `echo "hi" | agent --model opencode/minimax-m2.5-free --verbose` (via command-stream) → `verboseAtCreation: false`, 0 HTTP logs |
| 124 | +- **Critical observation:** `globalVerboseFetchInstalled: true` but `verboseAtCreation: false` — the interceptor was installed but the flag was not true when checked |
| 125 | + |
| 126 | +### #229 Workaround (confirms root cause) |
| 127 | + |
| 128 | +Setting both env vars AND CLI flag works: |
| 129 | + |
| 130 | +```bash |
| 131 | +OPENCODE_VERBOSE=true LINK_ASSISTANT_AGENT_VERBOSE=true echo "hi" | agent --verbose |
| 132 | +``` |
| 133 | + |
| 134 | +This workaround was adopted in hive-mind's solve command ([link-assistant/hive-mind#1521](https://github.com/link-assistant/hive-mind/issues/1521)). |
| 135 | + |
| 136 | +The fact that setting the env var fixes the problem while `--verbose` alone doesn't (in subprocess context) confirms that the in-memory flag set by yargs middleware is being lost, while the env var persists. This is the exact behavior our fix addresses: `setVerbose(true)` now also sets `LINK_ASSISTANT_AGENT_VERBOSE=true` in `process.env`, and `isVerbose()` checks the env var as fallback. |
| 137 | + |
| 138 | +### Why yargs options alone are insufficient |
| 139 | + |
| 140 | +The `--verbose` flag is processed by yargs middleware in `index.js`, which calls `Flag.setVerbose(true)`. However: |
| 141 | + |
| 142 | +1. `Flag.VERBOSE` is an `export let` variable — a single in-memory binding |
| 143 | +2. Many modules (`verbose-fetch.ts`, `log.ts`, `provider.ts`, etc.) import and check this flag independently at call time |
| 144 | +3. In Bun's runtime, when modules are re-evaluated (e.g., during subprocess execution), the `export let` binding resets to its initial value |
| 145 | +4. The initial value comes from `truthyEnv('LINK_ASSISTANT_AGENT_VERBOSE')` — if the env var isn't set, it defaults to `false` |
| 146 | +5. Yargs options are only available in the CLI entry point (`index.js`), not in the deeper modules that check the flag |
| 147 | + |
| 148 | +The env var propagation ensures the verbose state is available globally via `process.env`, which survives module re-evaluation and is accessible from any module without needing to thread yargs options through the entire call chain. |
| 149 | + |
| 150 | +## Env Var Consistency |
| 151 | + |
| 152 | +As part of this fix, all project-owned environment variables have been standardized to use the `LINK_ASSISTANT_AGENT_` prefix exclusively: |
| 153 | + |
| 154 | +| Old Name | New Name | |
| 155 | +| ------------------------------- | ---------------------------------------------------- | |
| 156 | +| `OPENCODE_VERBOSE` | `LINK_ASSISTANT_AGENT_VERBOSE` | |
| 157 | +| `OPENCODE_DRY_RUN` | `LINK_ASSISTANT_AGENT_DRY_RUN` | |
| 158 | +| `OPENCODE_CONFIG` | `LINK_ASSISTANT_AGENT_CONFIG` | |
| 159 | +| `VERIFY_IMAGES_AT_READ_TOOL` | `LINK_ASSISTANT_AGENT_VERIFY_IMAGES_AT_READ_TOOL` | |
| 160 | +| `MCP_DEFAULT_TOOL_CALL_TIMEOUT` | `LINK_ASSISTANT_AGENT_MCP_DEFAULT_TOOL_CALL_TIMEOUT` | |
| 161 | +| `MCP_MAX_TOOL_CALL_TIMEOUT` | `LINK_ASSISTANT_AGENT_MCP_MAX_TOOL_CALL_TIMEOUT` | |
| 162 | +| `AGENT_CLI_COMPACT` | `LINK_ASSISTANT_AGENT_COMPACT_JSON` | |
| 163 | +| `AGENT_STREAM_CHUNK_TIMEOUT_MS` | `LINK_ASSISTANT_AGENT_STREAM_CHUNK_TIMEOUT_MS` | |
| 164 | +| `AGENT_STREAM_STEP_TIMEOUT_MS` | `LINK_ASSISTANT_AGENT_STREAM_STEP_TIMEOUT_MS` | |
| 165 | + |
| 166 | +**Note:** Third-party env vars (`CLAUDE_CODE_OAUTH_TOKEN`, `AWS_*`, `GOOGLE_CLOUD_*`, `GEMINI_API_KEY`, etc.) are kept as-is since they are external interfaces defined by other tools/platforms. |
| 167 | + |
| 168 | +## Architectural Improvement: Centralized Config with lino-arguments |
| 169 | + |
| 170 | +### Problem |
| 171 | + |
| 172 | +Before this fix, environment variables were read in multiple scattered locations: |
| 173 | + |
| 174 | +- `flag.ts` — 15+ direct `process.env` reads with manual `truthyEnv()` helpers |
| 175 | +- `mcp/index.ts` — 2 direct `process.env` reads for MCP timeouts |
| 176 | +- `tool/read.ts` — 1 direct `process.env` read for image verification |
| 177 | +- `index.js` — yargs middleware manually syncing CLI args to Flag module |
| 178 | + |
| 179 | +This fragmentation made it hard to: |
| 180 | + |
| 181 | +1. Know what configuration was resolved at startup |
| 182 | +2. Debug configuration issues (no central log) |
| 183 | +3. Support `.lenv` files or case-insensitive env vars |
| 184 | + |
| 185 | +### Solution: lino-arguments |
| 186 | + |
| 187 | +Adopted [lino-arguments](https://github.com/link-foundation/lino-arguments) to centralize env var resolution: |
| 188 | + |
| 189 | +1. **`config.ts`** — Single source of truth for all configuration. Uses `getenv()` from lino-arguments which provides case-insensitive lookups, type-preserving defaults, and `.lenv` file support. |
| 190 | +2. **`flag.ts`** — Thin wrapper that reads from AgentConfig when initialized, falls back to env vars for backward compatibility. |
| 191 | +3. **`index.js` middleware** — Calls `initAgentConfig(argv)` once after yargs parsing, merging CLI args and env vars in one place. |
| 192 | +4. **Configuration logging** — Always logs the full resolved config as JSON at `info` level, critical for debugging. |
| 193 | + |
| 194 | +### Configuration priority (highest to lowest) |
| 195 | + |
| 196 | +1. CLI arguments (`--verbose`, `--dry-run`, etc.) |
| 197 | +2. Environment variables (`LINK_ASSISTANT_AGENT_VERBOSE=true`) |
| 198 | +3. `.lenv` file values (via lino-arguments) |
| 199 | +4. Code defaults |
| 200 | + |
| 201 | +### Key files |
| 202 | + |
| 203 | +| File | Role | |
| 204 | +| ----------------------------- | ---------------------------------------------------- | |
| 205 | +| `js/src/config/config.ts` | Centralized config with getenv() from lino-arguments | |
| 206 | +| `js/src/index.js` | Calls initAgentConfig(argv) in middleware | |
| 207 | +| `js/src/mcp/index.ts` | Uses Flag.MCP\_\*() instead of direct process.env | |
| 208 | +| `js/src/tool/read.ts` | Uses Flag.VERIFY_IMAGES_AT_READ_TOOL() | |
| 209 | + |
| 210 | +## Related Issues |
| 211 | + |
| 212 | +- #229 — HTTP request/response logs missing when using `--verbose` CLI flag (env var works) |
| 213 | +- #215 — Verbose HTTP logging infrastructure |
| 214 | +- #217 — Provider-level HTTP logging |
| 215 | +- #221 — Dual HTTP logging (global + provider) |
| 216 | +- #206 — Call-time verbose flag checking |
0 commit comments