feat(cli): add HTTP debug logging - #485
Conversation
| const REDACTED_HEADERS = new Set([ | ||
| 'authorization', | ||
| 'proxy-authorization', | ||
| 'x-api-key', | ||
| 'cookie', | ||
| 'set-cookie', | ||
| ]) |
There was a problem hiding this comment.
We'll need to validate this list by scanning each API codebase to ensure these are the only values with the potential to leak secrets.
| name: 'ELASTIC_DEBUG', | ||
| required: false, | ||
| description: 'Set to 1 to print HTTP request and response details to stderr', | ||
| }, |
There was a problem hiding this comment.
It would be good to also add a --verbose/-v flag so an env var isn't the only way to do this.
| function writeHeaders (prefix: string, headers: RequestInit['headers']): void { | ||
| for (const [name, value] of new Headers(headers)) { | ||
| const printableValue = REDACTED_HEADERS.has(name.toLowerCase()) ? '(redacted)' : value | ||
| process.stderr.write(`${prefix} ${name}: ${printableValue}\n`) |
There was a problem hiding this comment.
This will violate the requirement that all stdout/stderr output be able to be parsed as valid JSON when --json is enabled on any command. This should be wrapped in a function that checks that flag and, if --json is enabled, it should push all debug statements to an array and include them in the JSON response somehow.
| } | ||
|
|
||
| return response | ||
| } |
There was a problem hiding this comment.
On the whole, providing a single fetch wrapped implementation is correct for this use case, and may have other benefits besides debug logs in the future. This makes fetchWithHttpDebug a bit too specific of a function name. Rename the module src/lib/http.ts and the function apiFetch or sendRequest; something that differentiates it from the built-in fetch function. That function should take an options object that looks like:
interface FetchOptions {
debug?: boolean
}This gives us a place to add new options as we need them.
| const REDACTED_URL_FIELDS = new Set([...REDACTED_JSON_FIELDS, ...GENERIC_TOKEN_FIELDS, 'code', 'state']) | ||
|
|
||
| /** | ||
| * Per-request behavior for {@link apiFetch}. | ||
| */ | ||
| export interface FetchOptions { | ||
| debug?: boolean | ||
| } | ||
|
|
||
| let cliDebugEnabled = false | ||
| let jsonDebugMode = false | ||
| const bufferedDebugStatements: string[] = [] | ||
|
|
||
| /** | ||
| * Enables or disables HTTP debugging for the current CLI process. | ||
| */ | ||
| export function setHttpDebugEnabled (enabled: boolean): void { | ||
| cliDebugEnabled = enabled | ||
| } | ||
|
|
||
| /** | ||
| * Returns whether HTTP debug output is enabled by CLI flag or environment. | ||
| */ | ||
| export function isHttpDebugEnabled (): boolean { | ||
| return cliDebugEnabled || process.env['ELASTIC_DEBUG'] === '1' | ||
| } | ||
|
|
||
| /** | ||
| * Buffers HTTP diagnostics for structured output instead of writing to stderr. | ||
| */ | ||
| export function setHttpDebugJsonMode (enabled: boolean): void { | ||
| jsonDebugMode = enabled | ||
| bufferedDebugStatements.length = 0 | ||
| } | ||
|
|
||
| function writeDebugStatement (statement: string): void { | ||
| if (jsonDebugMode) { | ||
| bufferedDebugStatements.push(statement) | ||
| } else { | ||
| process.stderr.write(`${statement}\n`) | ||
| } | ||
| } | ||
|
|
||
| function writeHeaders (prefix: string, headers: RequestInit['headers']): void { | ||
| for (const [name, value] of new Headers(headers)) { | ||
| const printableValue = REDACTED_HEADERS.has(name.toLowerCase()) ? REDACTED_VALUE : value | ||
| writeDebugStatement(`${prefix} ${name}: ${printableValue}`) | ||
| } | ||
| } | ||
|
|
||
| function normalizedFieldName (name: string): string { | ||
| return name.replace(/[^a-z0-9]/gi, '').toLowerCase() | ||
| } | ||
|
|
||
| function redactJsonValue (value: unknown, redactGenericTokens: boolean): unknown { | ||
| if (Array.isArray(value)) { | ||
| return value.map(item => redactJsonValue(item, redactGenericTokens)) | ||
| } | ||
| if (value === null || typeof value !== 'object') { | ||
| return value | ||
| } | ||
|
|
||
| return Object.fromEntries( | ||
| Object.entries(value).map(([name, fieldValue]) => { | ||
| const normalizedName = normalizedFieldName(name) | ||
| const isSensitive = REDACTED_JSON_FIELDS.has(normalizedName) || | ||
| (redactGenericTokens && GENERIC_TOKEN_FIELDS.has(normalizedName)) | ||
| return [ | ||
| name, | ||
| isSensitive ? REDACTED_VALUE : redactJsonValue(fieldValue, redactGenericTokens), | ||
| ] | ||
| }) | ||
| ) | ||
| } | ||
|
|
||
| function urlCarriesCredentialTokens (url: string): boolean { | ||
| let normalizedUrl: string | ||
| try { | ||
| normalizedUrl = new URL(url).pathname.toLowerCase() | ||
| } catch { | ||
| normalizedUrl = url.toLowerCase() | ||
| } | ||
| return [ | ||
| '/credential', | ||
| '/enroll', | ||
| '/oauth', | ||
| '/oidc', | ||
| '/saml', | ||
| '/token', | ||
| '/tokens', | ||
| ].some(pathPart => normalizedUrl.includes(pathPart)) | ||
| } | ||
|
|
||
| function redactBody (body: string, url: string): string { | ||
| const redactGenericTokens = urlCarriesCredentialTokens(url) | ||
| try { | ||
| return JSON.stringify(redactJsonValue(JSON.parse(body), redactGenericTokens)) | ||
| } catch { | ||
| const lines = body.split('\n') | ||
| if (lines.length === 1) return body | ||
|
|
||
| try { | ||
| return lines | ||
| .map(line => line.trim().length === 0 | ||
| ? line | ||
| : JSON.stringify(redactJsonValue(JSON.parse(line), redactGenericTokens))) | ||
| .join('\n') | ||
| } catch { | ||
| return body | ||
| } | ||
| } | ||
| } | ||
|
|
||
| function redactUrl (url: string): string { | ||
| try { | ||
| const parsed = new URL(url) | ||
| let changed = false | ||
|
|
||
| if (parsed.username.length > 0 || parsed.password.length > 0) { | ||
| parsed.username = REDACTED_VALUE | ||
| parsed.password = REDACTED_VALUE | ||
| changed = true | ||
| } | ||
|
|
||
| const segments = parsed.pathname.split('/') | ||
| for (let index = 0; index < segments.length - 1; index += 1) { | ||
| if (segments[index]?.toLowerCase() === 'invitations') { | ||
| segments[index + 1] = REDACTED_VALUE | ||
| changed = true | ||
| } | ||
| } | ||
| parsed.pathname = segments.join('/') | ||
|
|
||
| for (const name of parsed.searchParams.keys()) { | ||
| if (REDACTED_URL_FIELDS.has(normalizedFieldName(name))) { | ||
| parsed.searchParams.set(name, REDACTED_VALUE) | ||
| changed = true | ||
| } | ||
| } | ||
|
|
||
| if (!changed) return url | ||
| return parsed.toString().replaceAll('%28redacted%29', REDACTED_VALUE) | ||
| } catch { | ||
| return url | ||
| } | ||
| } |
There was a problem hiding this comment.
The issue only asked for header redaction, and it says response bodies should be printed as-is.
There are two practical problems with keeping this:
- It doesn't add protection. When a response contains a secret, the CLI already prints that response to stdout as the normal command output. Hiding it in the debug output doesn't stop the user from seeing it.
- The field list has to be kept up to date by hand. Every time an API adds a new field that holds a secret, someone has to remember to add it to this list, or it silently stops being complete.
Please keep the header redaction (that part is exactly right) and remove REDACTED_JSON_FIELDS, redactJsonValue, urlCarriesCredentialTokens, redactBody, redactUrl, and their tests. If we decide we want body redaction later, it deserves its own PR where we can discuss the field list properly.
Alternatively a note to the --debug/ELASTIC_DEBUG help text like "output may contain sensitive data from request and response bodies; review before sharing." may be enough for now
| it('registers --debug as a boolean flag', () => { | ||
| const prog = makeProgram() | ||
| const opt = prog.options.find((o) => o.long === '--debug') | ||
| assert.ok(opt != null, 'expected --debug option') | ||
| assert.ok(!opt.required, '--debug should be a boolean flag (no required value)') | ||
| }) | ||
|
|
||
| it('registers --verbose with the -v alias', () => { | ||
| const prog = makeProgram() | ||
| const opt = prog.options.find((o) => o.long === '--verbose') | ||
| assert.ok(opt != null, 'expected --verbose option') | ||
| assert.equal(opt.short, '-v') | ||
| assert.ok(!opt.required, '--verbose should be a boolean flag (no required value)') | ||
| }) | ||
|
|
There was a problem hiding this comment.
These tests only check that commander can register a boolean flag, which commander's own test suite already covers.
They also run against makeProgram(), which is a local copy of the flag setup defined in this test file.... so if someone changed the real flags in src/cli.ts, these tests would still pass. The e2e test you added below (the one that runs the real CLI against a live server) is what actually proves the flag works. Please remove these two.
| it('parses --debug as true when provided', () => { | ||
| const prog = makeProgram() | ||
| prog.parse(['--debug'], { from: 'user' }) | ||
| assert.equal(prog.opts()['debug'], true) | ||
| }) | ||
|
|
||
| it('parses -v as verbose mode', () => { | ||
| const prog = makeProgram() | ||
| prog.parse(['-v'], { from: 'user' }) | ||
| assert.equal(prog.opts()['verbose'], true) | ||
| }) | ||
|
|
There was a problem hiding this comment.
Same as above...this is commander's behavior. Covered by the e2e test. Please remove.
| it('exposes global --debug option on the root program', async () => { | ||
| const root = await buildCompletionTree([]) | ||
| const opt = root.options.find(o => o.long === '--debug') | ||
| assert.ok(opt != null, 'expected --debug global option') | ||
| }) | ||
|
|
||
| it('exposes global --verbose option with the -v alias', async () => { | ||
| const root = await buildCompletionTree([]) | ||
| const opt = root.options.find(o => o.long === '--verbose') | ||
| assert.ok(opt != null, 'expected --verbose global option') | ||
| assert.equal(opt.short, '-v') | ||
| }) | ||
|
|
There was a problem hiding this comment.
These duplicate the existing --json/--use-context completion tests pattern, but like those flags, the only thing being verified is that a root.option(...) call was made.
If we keep one flag per the other comment (-v, --debug), a single test here would be enough, or drop both and rely on the e2e test.
| process.stdout.write = ((chunk: string | Uint8Array) => { | ||
| stdoutChunks.push(String(chunk)) | ||
| return true | ||
| }) as typeof process.stdout.write | ||
| process.stderr.write = ((chunk: string | Uint8Array) => { | ||
| stderrChunks.push(String(chunk)) | ||
| return true | ||
| }) as typeof process.stderr.write |
There was a problem hiding this comment.
cool thing ...nodes test runner has this built in, so we don't need a custom helper. mock.method replaces the function, records every call, and restores it automatically when the test ends:
import { mock } from 'node:test'
const write = mock.method(process.stderr, 'write', () => true)
Please use that in the tests and delete this file.
| setHttpDebugEnabled(cliDebugEnabled) | ||
| setHttpDebugJsonMode(json === true) | ||
| } | ||
|
|
There was a problem hiding this comment.
i'm trying to understand the code here....
- the
await import(...)here looks like it avoids loading the module unless debugging is on, BUT you also added the same to the factory, so it's always loaded anyway. https://github.com/elastic/cli/pull/485/changes#diff-399d91c5730fe8c956a45beb380a60404c1fcea16640f3a5f58b82e052aebfda - The
ifalso repeats the ELASTIC_DEBUG check that already lives inisHttpDebugEnabled().
a regular import and two unconditional calls do the same thing in less code and allows for better readability and maintenance:
setHttpDebugEnabled(debug === true || verbose === true)
setHttpDebugJsonMode(json === true)
| if (options.debug !== true) { | ||
| return fetchImplementation(url, init) | ||
| } |
There was a problem hiding this comment.
All three clients call apiFetch with the exact same option:
// es-client.ts, kibana-client.ts, cloud-client.ts
const response = await apiFetch(this._fetch, url, init, { debug: isHttpDebugEnabled() })Since isHttpDebugEnabled lives in this module anyway, apiFetch can use it as the default when the caller doesn't say otherwise:
| if (options.debug !== true) { | |
| return fetchImplementation(url, init) | |
| } | |
| if ((options.debug ?? isHttpDebugEnabled()) !== true) { | |
| return fetchImplementation(url, init) | |
| } |
Then each call site shrinks to apiFetch(this._fetch, url, init) and no longer needs to import isHttpDebugEnabled. The explicit { debug: true } / { debug: false } option still works as an override, so the existing tests in test/lib/http.test.ts don't need to change.
TLDR - when every caller of a function passes the same argument, that argument isn't really a choice the callers are making...it's a default the function should own...now we dont need to repeat the same thing three times and have only one import
3 participants
Summary
--debugflag andELASTIC_DEBUG=1activationCloses #316
Testing
npm test(1,502 passed, 0 failed, 1 skipped; 100% line, branch, and function coverage)npm run test:lintAI assistance
This contribution was developed with Codex under my direction and reviewed and tested locally before submission.