fix: parse structured logs, and handle ANSI escape codes in logs (#620)

`firebase-functions/logger` writes structured logs to stdout and stderr by default, and makes these pretty with ANSI color codes.

When functions-framework intercepts these messages to assign execution IDs, it handles them incorrectly in two ways.

First, when the log emitted on stdout or stderr is already a structured log, we override (ignore) the severity set by the logger. This commit avoids changing severity if it's already set.

Second, when parsing the message and attempting to determine if it's already a json object/structured log, it doesn't handle ANSI escape codes (https://en.wikipedia.org/wiki/ANSI_escape_code) used to control color, so parsing these will fail. This means that severity handling falls back to just looking at whether the message came from stdout or stderr, so debug-level and warn-level logs aren't handled correctly. This commit strips all ANSI escape codes that control terminal color. This is a minor bummer because it's a whole lot less pretty, but color-coding and smarter color coding generally seems less important than correct log-level handling.

Fixes #617.

.eslintrc.json

@@ -1,3 +1,6 @@
 {
-    "extends": "./node_modules/gts"
+    "extends": "./node_modules/gts",
+    "rules": {
+        "no-control-regex": 0
+    }
 }

src/logger.ts

@@ -127,14 +127,24 @@ export function getModifiedData(
     return data;
   }
   const {isJSON, processedData} = processData(data, encoding);
-  let dataWithContext;
+
+  let dataWithContext: {
+    message: string | Uint8Array;
+    'logging.googleapis.com/labels': {execution_id: string | undefined};
+    'logging.googleapis.com/trace': string | undefined;
+    'logging.googleapis.com/spanId': string | undefined;
+    severity?: string | undefined;
+  };
   if (isJSON) {
     dataWithContext = getJSONWithContext(processedData, currentContext);
+    if (stderr && !(SEVERITY in dataWithContext)) {
+      dataWithContext[SEVERITY] = 'ERROR';
+    }
   } else {
     dataWithContext = getTextWithContext(processedData, currentContext);
-  }
-  if (stderr) {
-    dataWithContext[SEVERITY] = 'ERROR';
+    if (stderr) {
+      dataWithContext[SEVERITY] = 'ERROR';
+    }
   }
 
   return JSON.stringify(dataWithContext) + '\n';
@@ -178,6 +188,9 @@ function processData(data: Uint8Array | string, encoding?: BufferEncoding) {
     return {isJSON: false, processedData: data};
   }
 
+  // strip any leading ANSI color codes from the decoded data
+  // to parse colored JSON objects correctly
+  decodedData = decodedData.replace(/\x1b[[(?);]{0,2}(;?\d)*./g, '');
   try {
     return {isJSON: true, processedData: JSON.parse(decodedData)};
   } catch (e) {

test/logger.ts

@@ -148,4 +148,34 @@ describe('getModifiedData', () => {
       ) + '\n';
     assert.equal(modifiedData, expectedOutput);
   });
+
+  it('parses firebase warning severity and message', () => {
+    const modifiedData = <string>(
+      getModifiedData(
+        '\u001b[33m{"severity":"WARNING","message":"testing warning log level"}\u001b[39m\n',
+        undefined,
+        true
+      )
+    );
+    assert.equal('WARNING', JSON.parse(modifiedData)['severity']);
+    assert.equal(
+      'testing warning log level',
+      JSON.parse(modifiedData)['message']
+    );
+  });
+
+  it('parses firebase error severity and message', () => {
+    const modifiedData = <string>(
+      getModifiedData(
+        '\u001b[31m{"severity":"ERROR","message":"testing error log level"}\u001b[39m\n',
+        undefined,
+        true
+      )
+    );
+    assert.equal('ERROR', JSON.parse(modifiedData)['severity']);
+    assert.equal(
+      'testing error log level',
+      JSON.parse(modifiedData)['message']
+    );
+  });
 });