diff --git a/.changeset/mask-worker-stdout.md b/.changeset/mask-worker-stdout.md new file mode 100644 index 0000000000..11b7bda97d --- /dev/null +++ b/.changeset/mask-worker-stdout.md @@ -0,0 +1,5 @@ +--- +'@expo/worker': patch +--- + +Mask build secrets in every build log field, worker stdout and the build error log buffer. diff --git a/packages/worker/src/__unit__/logger.test.ts b/packages/worker/src/__unit__/logger.test.ts index 9c9e14759d..f98513c04a 100644 --- a/packages/worker/src/__unit__/logger.test.ts +++ b/packages/worker/src/__unit__/logger.test.ts @@ -71,6 +71,16 @@ async function waitForStreamFlush(): Promise { await new Promise(resolve => setImmediate(resolve)); } +function captureStdout(): { output: string[]; write: jest.SpyInstance } { + const output: string[] = []; + // Never call the write callback, like a stdout that has not flushed yet. + const write = jest.spyOn(process.stdout, 'write').mockImplementation(chunk => { + output.push(String(chunk)); + return true; + }); + return { output, write }; +} + const { HttpLogStream, RemoteLoggerStream } = jest.requireMock('@expo/build-tools') as { HttpLogStream: { instances: Array<{ @@ -135,6 +145,107 @@ describe('logger', () => { expect(logs[1].msg).toBe('another ****** in base64 is ********************'); }); + it('masks stdout and stderr messages before writing process output and the log buffer', async () => { + const { logger, logBuffer } = await createBuildLoggerWithSecretsFilter({ + environmentSecrets: [ + { name: 'TOKEN', value: 'fake-provider-token', type: EnvironmentSecretType.STRING }, + ], + }); + const { output, write } = captureStdout(); + try { + logger.child({ source: 'stdout' }).info('stdout: fake-provider-token'); + logger.child({ source: 'stderr' }).error('stderr: fake-provider-token'); + await waitForStreamFlush(); + + expect(output.map(line => JSON.parse(line).msg)).toEqual([ + 'stdout: *******************', + 'stderr: *******************', + ]); + expect(logBuffer.getLogs()).toEqual([ + 'stdout: *******************', + 'stderr: *******************', + ]); + } finally { + write.mockRestore(); + } + }); + + it('masks secrets in every field except logger metadata', async () => { + const { logger, outputStream } = await createBuildLoggerWithSecretsFilter({ + environmentSecrets: [ + { name: 'TOKEN', value: 'fake-provider-token', type: EnvironmentSecretType.STRING }, + { name: 'SOURCE', value: 'stdout', type: EnvironmentSecretType.STRING }, + ], + }); + const logs: any[] = []; + outputStream.on('data', log => logs.push(log)); + + const err = new Error('request with fake-provider-token failed'); + logger + .child({ source: 'stdout', buildStepDisplayName: 'Use fake-provider-token' }) + .error({ err, request: { headers: ['Bearer fake-provider-token'] } }, 'failed'); + await waitForStreamFlush(); + + expect(logs).toHaveLength(1); + expect(JSON.stringify(logs[0])).not.toContain('fake-provider-token'); + expect(logs[0].err.message).toBe('request with ******************* failed'); + expect(logs[0].err.stack).toContain('request with ******************* failed'); + expect(logs[0].request.headers).toEqual(['Bearer *******************']); + expect(logs[0].buildStepDisplayName).toBe('Use *******************'); + expect(logs[0].source).toBe('stdout'); + expect(typeof logs[0].time).toBe('string'); + }); + + it('writes records JSON.stringify would reject instead of throwing', async () => { + const { logger, logBuffer } = await createBuildLoggerWithSecretsFilter({ + environmentSecrets: [ + { name: 'TOKEN', value: 'fake-provider-token', type: EnvironmentSecretType.STRING }, + ], + }); + const { output, write } = captureStdout(); + try { + const circular: Record = { token: 'fake-provider-token' }; + circular.self = circular; + const throwing = { + toJSON() { + throw new Error('nope'); + }, + }; + + expect(() => { + logger.child({ source: 'stdout' }).info({ circular, count: 1n }, 'circular'); + logger.child({ source: 'stdout' }).info({ throwing }, 'throwing fake-provider-token'); + }).not.toThrow(); + await waitForStreamFlush(); + + const records = output.map(line => JSON.parse(line)); + expect(records).toHaveLength(2); + expect(records[0].circular).toEqual({ token: '*******************', self: '[Circular]' }); + expect(records[0].count).toBe('1'); + expect(records[1].msg).toBe('throwing *******************'); + expect(records[1].throwing).toBeUndefined(); + expect(logBuffer.getLogs()).toEqual(['circular', 'throwing *******************']); + } finally { + write.mockRestore(); + } + }); + + it('does not hold other destinations back while stdout flushes', async () => { + const { logger, logBuffer } = await createBuildLoggerWithSecretsFilter({}); + const write = jest.spyOn(process.stdout, 'write').mockImplementation(() => true); + try { + await waitForStreamFlush(); + const stdoutLogger = logger.child({ source: 'stdout' }); + for (let i = 0; i < 100; i++) { + stdoutLogger.info(`line ${i}`); + } + + expect(logBuffer.getLogs()).toHaveLength(100); + } finally { + write.mockRestore(); + } + }); + it('adds logId to each log', async () => { const { logger, outputStream } = await createBuildLoggerWithSecretsFilter({}); diff --git a/packages/worker/src/logger.ts b/packages/worker/src/logger.ts index 70b70209be..a822b61e14 100644 --- a/packages/worker/src/logger.ts +++ b/packages/worker/src/logger.ts @@ -62,43 +62,108 @@ function createTransformStream(secrets: EnvironmentSecret[]): Transform { ...secretValues, ...secretValues.map(maybeStringBase64Decode).filter((i): i is string => !!i), ].filter(i => i.length > 1 && !simpleSecretsWhitelist.includes(i)); + const maskSecrets = (value: string): string => + secretList.reduce((acc: string, pattern: string): string => { + return acc.replaceAll(pattern, '*'.repeat(pattern.length)); + }, value); return new Transform({ readableObjectMode: true, writableObjectMode: true, - transform(_chunk: any, _encoding: BufferEncoding, callback: TransformCallback) { - let chunk = _chunk; - if (chunk && typeof chunk === 'object') { - // Remove hostname from logs since we don't need it. - const { hostname: _hostname, ...rest } = chunk; - chunk = { - ...rest, - // Add logId to each log. - logId: uuidv7(), - }; - } - - if (chunk && typeof chunk === 'object' && chunk.msg) { - const msgWithoutSecrets = secretList.reduce((acc: string, pattern: string): string => { - return acc.replaceAll(pattern, '*'.repeat(pattern.length)); - }, chunk.msg as string); - - callback(null, { - ...chunk, - msg: msgWithoutSecrets, - }); - } else { + transform(chunk: any, _encoding: BufferEncoding, callback: TransformCallback) { + if (!chunk || typeof chunk !== 'object') { callback(null, chunk); + return; } + // Remove hostname from logs since we don't need it. + const { hostname: _hostname, ...rest } = chunk; + callback( + null, + toMaskedJsonRecord( + { + ...rest, + // Add logId to each log. + logId: uuidv7(), + }, + maskSecrets + ) + ); }, }); } -function createDiscardStream(): Writable { +// Set by the logger and build tooling rather than by build output. Masking them could +// break grouping and filtering, e.g. a secret equal to "stdout" or part of a timestamp. +const UNMASKED_RECORD_FIELDS = new Set([ + 'name', + 'pid', + 'level', + 'time', + 'v', + 'logId', + 'phase', + 'source', + 'buildStepId', + 'buildStepInternalId', + 'marker', + 'result', +]); + +// Every destination writes records as JSON, so return a plain JSON value with secrets +// masked in every string, not only in `msg`. Like bunyan's own stdout stream, tolerate +// values JSON.stringify rejects instead of throwing into the code that logged. +function toMaskedJsonRecord( + record: Record, + maskSecrets: (value: string) => string +): Record { + const createReplacer = (seen?: WeakSet) => + function (this: unknown, key: string, value: unknown): unknown { + if (typeof value === 'bigint') { + value = value.toString(); + } + if (this === record && UNMASKED_RECORD_FIELDS.has(key)) { + return value; + } + if (typeof value === 'string') { + return maskSecrets(value); + } + if (seen && value && typeof value === 'object') { + if (seen.has(value)) { + return '[Circular]'; + } + seen.add(value); + } + return value; + }; + + try { + return JSON.parse(JSON.stringify(record, createReplacer())); + } catch {} + try { + return JSON.parse(JSON.stringify(record, createReplacer(new WeakSet()))); + } catch {} + // Something like a throwing toJSON(); keep the top-level values that are safe to log. + const fallback: Record = {}; + for (const [key, value] of Object.entries(record)) { + if (typeof value === 'string') { + fallback[key] = UNMASKED_RECORD_FIELDS.has(key) ? value : maskSecrets(value); + } else if (typeof value === 'number' || typeof value === 'boolean' || value === null) { + fallback[key] = value; + } else if (value instanceof Date && !Number.isNaN(value.getTime())) { + fallback[key] = value.toISOString(); + } + } + return fallback; +} + +function createStdoutStream(): Writable { return new Writable({ objectMode: true, - write(_chunk: any, _encoding: BufferEncoding, callback: (error?: Error | null) => void) { - callback(null); + write(chunk: any, _encoding: BufferEncoding, callback: (error?: Error | null) => void) { + // Like bunyan's stdout stream, do not wait for stdout to flush. The other + // destinations are piped from the same source and would wait with it. + process.stdout.write(`${JSON.stringify(chunk)}\n`); + callback(); }, }); } @@ -109,17 +174,16 @@ export async function createBuildLoggerWithSecretsFilter(secrets: Job['secrets'] logBuffer: WorkerLogBuffer; outputStream: Readable; }> { - const buildLogger = defaultLogger.child({ phase: BuildPhase.UNKNOWN }); - const transformStream = createTransformStream(secrets?.environmentSecrets ?? []); - const discardStream = createDiscardStream(); - transformStream.pipe(discardStream); - - buildLogger.addStream({ - type: 'raw', - stream: transformStream, - reemitErrorEvents: true, - level: buildLogger.level(), + transformStream.pipe(createStdoutStream()); + + // Do not inherit defaultLogger's stdout stream: every build-log destination must + // receive the filtered record. + const buildLogger = createLogger({ + name: config.loggers.base.name, + phase: BuildPhase.UNKNOWN, + level: defaultLogger.level(), + streams: [{ type: 'raw', stream: transformStream, reemitErrorEvents: true }], }); let remoteLoggerStream: RemoteLoggerStream | null = null; @@ -137,12 +201,7 @@ export async function createBuildLoggerWithSecretsFilter(secrets: Job['secrets'] } const logBuffer = new WorkerLogBuffer(MAX_LINES_IN_BUFFER); - buildLogger.addStream({ - type: 'raw', - stream: logBuffer, - reemitErrorEvents: true, - level: buildLogger.level(), - }); + transformStream.pipe(logBuffer); let httpLogStream: HttpLogStream | null = null; if (config.loggers.http.baseUrl && secrets?.robotAccessToken) {