Replace control characters before logging (opensearch-project#6402)

Signed-off-by: Miki <[email protected]>

CHANGELOG.md

@@ -87,6 +87,7 @@ Inspired from [Keep a Changelog](https://keepachangelog.com/en/1.0.0/)
 - [Workspace] Add APIs to support plugin state in request ([#6303](https://github.com/opensearch-project/OpenSearch-Dashboards/pull/6303))
 - [Workspace] Filter left nav menu items according to the current workspace ([#6234](https://github.com/opensearch-project/OpenSearch-Dashboards/pull/6234))
 - [Multiple Datasource] Refactor data source selector component to include placeholder and add tests ([#6372](https://github.com/opensearch-project/OpenSearch-Dashboards/pull/6372))
+- Replace control characters before logging ([#6402](https://github.com/opensearch-project/OpenSearch-Dashboards/pull/6402))
 - [Dynamic Configurations] Improve dynamic configurations by adding cache and simplifying client fetch ([#6364](https://github.com/opensearch-project/OpenSearch-Dashboards/pull/6364))
 - [MD] Add OpenSearch cluster group label to top of single selectable dropdown  ([#6400](https://github.com/opensearch-project/OpenSearch-Dashboards/pull/6400))
 - [Workspace] Support workspace in saved objects client in server side. ([#6365](https://github.com/opensearch-project/OpenSearch-Dashboards/pull/6365))

packages/osd-std/src/clean.test.ts

@@ -0,0 +1,31 @@
+/*
+ * Copyright OpenSearch Contributors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+import { cleanControlSequences } from './clean';
+
+describe('cleanControlSequences', () => {
+  it('does its job', () => {
+    // prettier-ignore
+    const controlSequences = [
+      '\x03', '\x04', '\x05', '\x07', '\x08',
+      '\x0B', '\x0C', '\x0D', '\x0E', '\x0F',
+      '\x10', '\x11', '\x12', '\x13', '\x14', '\x15', '\x16', '\x17', '\x18', '\x19',
+      '\x1A', '\x1B', '\x1C', '\x1D', '\x1E', '\x1F',
+      '\x7F',
+      '\x90', '\x9B', '\x9C'
+    ];
+    const input =
+      '0' + controlSequences.map((char, idx) => `${char}${(idx + 1).toString(36)}`).join('');
+    const expected =
+      '0(U+0003)1(U+0004)2(U+0005)3(U+0007)4(U+0008)' +
+      '5(U+000b)6(U+000c)7(U+000d)8(U+000e)9(U+000f)' +
+      'a(U+0010)b(U+0011)c(U+0012)d(U+0013)e(U+0014)f(U+0015)g(U+0016)h(U+0017)i(U+0018)j(U+0019)' +
+      'k(U+001a)l(U+001b)m(U+001c)n(U+001d)o(U+001e)p(U+001f)' +
+      'q(U+007f)' +
+      'r(U+0090)s(U+009b)t(U+009c)' +
+      'u';
+    expect(cleanControlSequences(input)).toEqual(expected);
+  });
+});

packages/osd-std/src/clean.ts

@@ -0,0 +1,45 @@
+/*
+ * Copyright OpenSearch Contributors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+/* Replaces a bunch of characters that should not be printed:
+ *    0x03  ETX: End of Text
+ *    0x04  EOT: End of Transmission
+ *    0x05  ENQ: Enquiry
+ *    0x07  BEL: Bell
+ *    0x08  BS:  Backspace
+ *    0x0B  VT:  Vertical Tabulation
+ *    0x0C  FF:  Form Feed
+ *    0x0D  CR:  Carriage Return
+ *    0x0E  SO:  Shift Out
+ *    0x0F  SI:  Shift In
+ *    0x10  DLE: Data Link Escape
+ *    0x11  DC1: Device Control One
+ *    0x12  DC2: Device Control Two
+ *    0x13  DC3: Device Control Three
+ *    0x14  DC4: Device Control Four
+ *    0x15  NAK: Negative Acknowledge
+ *    0x16  SYN: Synchronous Idle
+ *    0x17  ETB: End of Transmission Block
+ *    0x18  CAN: Cancel
+ *    0x19  EM:  End of Medium
+ *    0x1A  SUB: EoF on Windows
+ *    0x1B  ESC: Starts all the escape sequences
+ *    0x1C  FS:  File Separator
+ *    0x1D  GS:  Group Separator
+ *    0x1E  RS:  Record Separator
+ *    0x1F  US:  Unit Separator
+ *    0x7F  Del
+ *    0x90  DCS: Device Control String
+ *    0x9B  CSI: Control Sequence Introducer
+ *    0x9C  OSC: Operating System Command
+ *
+ * Ref: https://en.wikipedia.org/wiki/Control_character
+ */
+export const cleanControlSequences = (text: string): string => {
+  return text.replace(
+    /[\x03-\x05\x07\x08\x0B-\x1F\x7F\x90\x9B\x9C]/g,
+    (char) => `(U+${char.charCodeAt(0).toString(16).padStart(4, '0')})`
+  );
+};

packages/osd-std/src/index.ts

@@ -43,3 +43,4 @@ export { getFlattenedObject } from './get_flattened_object';
 export { validateObject } from './validate_object';
 export * from './rxjs_7';
 export { parse, stringify } from './json';
+export * from './clean';

src/core/server/legacy/logging/legacy_logging_server.test.ts

@@ -67,13 +67,23 @@ test('correctly forwards log records.', () => {
     meta: { tags: ['important', 'tags'], unknown: 2 },
   };
 
+  const controlSequenceLogRecord = {
+    timestamp: new Date(timestamp),
+    pid: 5355,
+    level: LogLevel.Trace,
+    context: 'some-context.sub-context',
+    message: 'some\u001b[33mCOLORED\u001b[0m',
+    meta: { tags: ['important', 'tags'], unknown: 2 },
+  };
+
   loggingServer.log(firstLogRecord);
   loggingServer.log(secondLogRecord);
   loggingServer.log(thirdLogRecord);
+  loggingServer.log(controlSequenceLogRecord);
 
-  expect(onLogMock).toHaveBeenCalledTimes(3);
+  expect(onLogMock).toHaveBeenCalledTimes(4);
 
-  const [[firstCall], [secondCall], [thirdCall]] = onLogMock.mock.calls;
+  const [[firstCall], [secondCall], [thirdCall], [controlSequenceCall]] = onLogMock.mock.calls;
   expect(firstCall).toMatchInlineSnapshot(`
 Object {
   "data": "some-message",
@@ -116,5 +126,26 @@ Object {
   ],
   "timestamp": 1554433221100,
 }
+`);
+
+  expect(controlSequenceCall).toMatchInlineSnapshot(`
+Object {
+  "data": Object {
+    Symbol(log message with metadata): Object {
+      "message": "some(U+001b)[33mCOLORED(U+001b)[0m",
+      "metadata": Object {
+        "unknown": 2,
+      },
+    },
+  },
+  "tags": Array [
+    "debug",
+    "some-context",
+    "sub-context",
+    "important",
+    "tags",
+  ],
+  "timestamp": 1554433221100,
+}
 `);
 });

src/core/server/legacy/logging/legacy_logging_server.ts

@@ -30,6 +30,7 @@
 
 import { ServerExtType } from '@hapi/hapi';
 import Podium from '@hapi/podium';
+import { cleanControlSequences } from '@osd/std';
 // @ts-expect-error: implicit any for JS file
 import { Config } from '../../../../legacy/server/config';
 // @ts-expect-error: implicit any for JS file
@@ -121,7 +122,7 @@ export class LegacyLoggingServer {
     const { tags = [], ...metadata } = meta;
 
     this.events.emit('log', {
-      data: getDataToLog(error, metadata, message),
+      data: getDataToLog(error, metadata, cleanControlSequences(message)),
       tags: [getLegacyLogLevel(level), ...context.split('.'), ...tags],
       timestamp: timestamp.getTime(),
     });

src/core/server/logging/layouts/conversions/message.ts

@@ -29,12 +29,14 @@
  */
 
 import { LogRecord } from '@osd/logging';
+import { cleanControlSequences } from '@osd/std';
 import { Conversion } from './type';
 
 export const MessageConversion: Conversion = {
   pattern: /%message/g,
   convert(record: LogRecord) {
     // Error stack is much more useful than just the message.
-    return (record.error && record.error.stack) || record.message;
+    const msg = (record.error && record.error.stack) || record.message;
+    return cleanControlSequences(msg);
   },
 };

src/core/server/logging/layouts/json_layout.test.ts

@@ -266,3 +266,43 @@ test('format() meta can override log level objects', () => {
     },
   });
 });
+
+test('format() correctly removes control sequences', () => {
+  const layout = new JsonLayout();
+  expect(
+    JSON.parse(
+      layout.format({
+        timestamp,
+        context: '123',
+        message: 'some\u001b[33mCOLORED\u001b[0m',
+        error: {
+          message: 'error \u001b[33mCOLORED\u001b[0m',
+          name: 'Some error name',
+          stack: 'stack \u001b[33mCOLORED\u001b[0m',
+        },
+        level: LogLevel.Error,
+        pid: 3,
+        meta: {
+          log: {
+            level: 'FATAL',
+          },
+        },
+      })
+    )
+  ).toStrictEqual({
+    '@timestamp': '2012-02-01T09:30:22.011-05:00',
+    error: {
+      message: 'error (U+001b)[33mCOLORED(U+001b)[0m',
+      stack_trace: 'stack (U+001b)[33mCOLORED(U+001b)[0m',
+      type: 'Some error name',
+    },
+    message: 'some(U+001b)[33mCOLORED(U+001b)[0m',
+    log: {
+      level: 'FATAL',
+      logger: '123',
+    },
+    process: {
+      pid: 3,
+    },
+  });
+});

src/core/server/logging/layouts/json_layout.ts

@@ -32,6 +32,7 @@ import moment from 'moment-timezone';
 import { merge } from 'lodash';
 import { schema } from '@osd/config-schema';
 import { LogRecord, Layout } from '@osd/logging';
+import { cleanControlSequences } from '@osd/std';
 
 const { literal, object } = schema;
 
@@ -57,9 +58,9 @@ export class JsonLayout implements Layout {
     }
 
     return {
-      message: error.message,
+      message: cleanControlSequences(error.message),
       type: error.name,
-      stack_trace: error.stack,
+      stack_trace: error.stack && cleanControlSequences(error.stack),
     };
   }
 
@@ -68,7 +69,7 @@ export class JsonLayout implements Layout {
       merge(
         {
           '@timestamp': moment(record.timestamp).format('YYYY-MM-DDTHH:mm:ss.SSSZ'),
-          message: record.message,
+          message: cleanControlSequences(record.message),
           error: JsonLayout.errorToSerializableObject(record.error),
           log: {
             level: record.level.id.toUpperCase(),

src/core/server/logging/layouts/pattern_layout.test.ts

@@ -129,6 +129,20 @@ test('`format()` correctly formats record with custom pattern.', () => {
   }
 });
 
+test('`format()` correctly removes control sequences.', () => {
+  const layout = new PatternLayout();
+
+  expect(
+    layout.format({
+      context: 'context-7',
+      level: LogLevel.Error,
+      message: 'some\u001b[33mCOLORED\u001b[0m',
+      timestamp,
+      pid: 5355,
+    })
+  ).toBe('[2012-02-01T14:30:22.011Z][ERROR][context-7] some(U+001b)[33mCOLORED(U+001b)[0m');
+});
+
 test('`format()` correctly formats record with meta data.', () => {
   const layout = new PatternLayout();