[worker] Mask secrets before writing build logs to stdout

.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.

packages/worker/src/__unit__/logger.test.ts

@@ -71,6 +71,16 @@ async function waitForStreamFlush(): Promise<void> {
   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<string, unknown> = { 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({});
 

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<string, unknown>,
+  maskSecrets: (value: string) => string
+): Record<string, unknown> {
+  const createReplacer = (seen?: WeakSet<object>) =>
+    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<string, unknown> = {};
+  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) {