[worker] Mask secrets in every field of uploaded log records

.changeset/worker-mask-logged-errors.md

@@ -0,0 +1,5 @@
+---
+'@expo/worker': patch
+---
+
+Mask secrets in every field of uploaded job log records, such as logged errors, not only in log messages.

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

@@ -185,6 +185,100 @@ describe('logger', () => {
     expect(logs.map(log => log.msg)).toEqual(['token: ***************, prefix: ***']);
   });
 
+  describe('structured fields', () => {
+    async function logWithSecretAsync(
+      log: (
+        logger: Awaited<ReturnType<typeof createBuildLoggerWithSecretsFilter>>['logger']
+      ) => void
+    ): Promise<any[]> {
+      const { logger, outputStream } = await createBuildLoggerWithSecretsFilter({
+        environmentSecrets: [
+          { name: 'TOKEN', value: 'secret-token', type: EnvironmentSecretType.STRING },
+          { name: 'PIN', value: '123456789', type: EnvironmentSecretType.STRING },
+        ],
+      });
+      const logs: any[] = [];
+      outputStream.pipe(
+        new Writable({
+          objectMode: true,
+          write(chunk: any, _encoding: BufferEncoding, callback: TransformCallback) {
+            logs.push(chunk);
+            callback(null, chunk);
+          },
+        })
+      );
+      log(logger);
+      await waitForStreamFlush();
+      // The upload streams send JSON.stringify(record).
+      for (const record of logs) {
+        expect(JSON.stringify(record)).not.toContain('secret-token');
+        expect(JSON.stringify(record)).not.toContain('123456789');
+      }
+      return logs;
+    }
+
+    it('masks errors, including when the message is empty', async () => {
+      const err = new Error('git clone https://secret-token@github.com/acme/app failed');
+      const logs = await logWithSecretAsync(logger => {
+        logger.error({ err }, '');
+        logger.error({ err });
+      });
+
+      expect(logs).toHaveLength(2);
+      for (const log of logs) {
+        expect(log.err.message).toBe('git clone https://************@github.com/acme/app failed');
+        expect(log.err.stack).toContain(
+          'git clone https://************@github.com/acme/app failed'
+        );
+      }
+      expect(logs[0].msg).toBe('');
+      expect(logs[1].msg).toBe('git clone https://************@github.com/acme/app failed');
+    });
+
+    it('masks other fields, keys and numbers, and keeps metadata fields', async () => {
+      const job = { env: { TOKEN_COPY: 'secret-token', 'secret-token': 'key', PIN: 123456789 } };
+      const logs = await logWithSecretAsync(logger => {
+        logger.info({ job, source: 'stdout', buildStepId: 'step-1' }, 'Builder is ready');
+      });
+
+      expect(logs[0].job).toEqual({
+        env: { TOKEN_COPY: '************', '************': 'key', PIN: '*********' },
+      });
+      expect(logs[0].source).toBe('stdout');
+      expect(logs[0].buildStepId).toBe('step-1');
+      // The caller's object, which bunyan also hands to other streams, is not changed.
+      expect(job.env.TOKEN_COPY).toBe('secret-token');
+    });
+
+    it('masks what a toJSON method returns', async () => {
+      const logs = await logWithSecretAsync(logger => {
+        logger.error(
+          {
+            err: {
+              token: 'secret-token',
+              toJSON: () => ({ token: 'secret-token', at: new Date(0) }),
+            },
+          },
+          'failed'
+        );
+      });
+
+      expect(logs[0].err).toEqual({ token: '************', at: '1970-01-01T00:00:00.000Z' });
+    });
+
+    it('truncates deeply nested values instead of uploading them unmasked', async () => {
+      let nested: any = { token: 'secret-token' };
+      for (let index = 0; index < 30; index++) {
+        nested = { nested };
+      }
+      const logs = await logWithSecretAsync(logger => {
+        logger.error({ err: nested }, 'failed');
+      });
+
+      expect(JSON.stringify(logs[0].err)).toContain('[Truncated]');
+    });
+  });
+
   it('adds logId to each log', async () => {
     const { logger, outputStream } = await createBuildLoggerWithSecretsFilter({});
 

packages/worker/src/logger.ts

@@ -59,30 +59,45 @@ export class WorkerLogBuffer extends Writable implements LogBuffer {
   }
 }
 
+// Bunyan's own fields and fields that identify a log line, which never hold user data.
+const UNMASKED_FIELDS = new Set([
+  'name',
+  'pid',
+  'level',
+  'time',
+  'v',
+  'phase',
+  'source',
+  'marker',
+  'result',
+  'buildStepId',
+  'buildStepInternalId',
+]);
+const MAX_MASKED_DEPTH = 20;
+
 function createTransformStream(secretPatterns: ReadonlySet<string>): Transform {
   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') {
+        callback(null, _chunk);
+        return;
       }
-
-      if (chunk && typeof chunk === 'object' && chunk.msg) {
-        callback(null, {
-          ...chunk,
-          msg: maskSecrets(chunk.msg as string, secretPatterns),
-        });
-      } else {
-        callback(null, chunk);
+      // Remove hostname from logs since we don't need it. Bunyan shares the record with other
+      // streams, so build a copy instead of changing it.
+      const { hostname: _hostname, ...rest } = _chunk;
+      const chunk: Record<string, unknown> = {};
+      for (const [key, value] of Object.entries(rest)) {
+        // Secrets can be in any field, such as a serialized error's message and stack.
+        chunk[key] =
+          secretPatterns.size === 0 || UNMASKED_FIELDS.has(key)
+            ? value
+            : maskSecretsInValue(value, secretPatterns);
       }
+      // Add logId to each log.
+      chunk.logId = uuidv7();
+      callback(null, chunk);
     },
   });
 }
@@ -101,6 +116,48 @@ function maskSecrets(message: string, secrets: Iterable<string>): string {
   return characters.join('');
 }
 
+function maskSecretsInValue(value: unknown, secrets: ReadonlySet<string>): unknown {
+  if (value === null || typeof value !== 'object') {
+    return maskSecretsInJsonValue(value, secrets, 0);
+  }
+  // Mask what the upload streams will serialize, so a toJSON method can't bring back the original.
+  let json: unknown;
+  try {
+    json = JSON.parse(JSON.stringify(value));
+  } catch {
+    return '[Unserializable]';
+  }
+  return maskSecretsInJsonValue(json, secrets, 0);
+}
+
+function maskSecretsInJsonValue(
+  value: unknown,
+  secrets: ReadonlySet<string>,
+  depth: number
+): unknown {
+  if (typeof value === 'string') {
+    return maskSecrets(value, secrets);
+  }
+  if (typeof value === 'number') {
+    return secrets.has(String(value)) ? maskSecrets(String(value), secrets) : value;
+  }
+  if (value === null || typeof value !== 'object') {
+    return value;
+  }
+  if (depth >= MAX_MASKED_DEPTH) {
+    return '[Truncated]';
+  }
+  if (Array.isArray(value)) {
+    return value.map(item => maskSecretsInJsonValue(item, secrets, depth + 1));
+  }
+  return Object.fromEntries(
+    Object.entries(value).map(([key, item]) => [
+      maskSecrets(key, secrets),
+      maskSecretsInJsonValue(item, secrets, depth + 1),
+    ])
+  );
+}
+
 function createDiscardStream(): Writable {
   return new Writable({
     objectMode: true,