From 294683aa708d0ca6e410cfd1448889a09c96a9f6 Mon Sep 17 00:00:00 2001 From: LIU ZHE YOU <68415893+jason810496@users.noreply.github.com> Date: Tue, 3 Dec 2024 21:35:19 +0800 Subject: [PATCH] Fix wrong display of multiline messages in the log after filtering (#44457) * Fix Logs/utils * Fix test for Logs/utils * Fix by Review Comment - Added red color styling to lines based on the `currentLevel` - Added comments for new regExp * Refactor Logs/utils test cases --- .../details/taskInstance/Logs/utils.test.tsx | 80 ++++++++++-- .../js/dag/details/taskInstance/Logs/utils.ts | 115 ++++++++++-------- airflow/www/static/js/utils/index.test.ts | 6 + airflow/www/static/js/utils/index.ts | 6 +- 4 files changed, 140 insertions(+), 67 deletions(-) diff --git a/airflow/www/static/js/dag/details/taskInstance/Logs/utils.test.tsx b/airflow/www/static/js/dag/details/taskInstance/Logs/utils.test.tsx index 8e577068d27e0..57cad4314f6ff 100644 --- a/airflow/www/static/js/dag/details/taskInstance/Logs/utils.test.tsx +++ b/airflow/www/static/js/dag/details/taskInstance/Logs/utils.test.tsx @@ -19,27 +19,60 @@ /* global describe, test, expect */ +import { AnsiUp } from "ansi_up"; import { LogLevel, parseLogs } from "./utils"; -const mockTaskLog = ` -5d28cfda3219 +const mockTaskLogInfoBegin = `5d28cfda3219 *** Reading local file: /root/airflow/logs/dag_id=test_ui_grid/run_id=scheduled__2022-06-03T00:00:00+00:00/task_id=section_1.get_entry_group/attempt=1.log [2022-06-04 00:00:01,901] {taskinstance.py:1132} INFO - Dependencies all met for [2022-06-04 00:00:01,906] {taskinstance.py:1132} INFO - Dependencies all met for [2022-06-04 00:00:01,906] {taskinstance.py:1329} INFO - --------------------------------------------------------------------------------- [2022-06-04 00:00:01,906] {taskinstance.py:1330} INFO - Starting attempt 1 of 1 [2022-06-04 00:00:01,906] {taskinstance.py:1331} INFO - --------------------------------------------------------------------------------- -[2022-06-04 00:00:01,916] {taskinstance.py:1350} INFO - Executing on 2022-06-03 00:00:00+00:00 +`; +const mockTaskLogErrorWithTraceback = `[2022-06-04 00:00:01,910] {taskinstance.py:3311} ERROR - Task failed with exception +Traceback (most recent call last): + File "/opt/airflow/airflow/models/taskinstance.py", line 767, in _execute_task + result = _execute_callable(context=context, **execute_callable_kwargs) + File "/opt/airflow/airflow/models/taskinstance.py", line 733, in _execute_callable + return ExecutionCallableRunner( + File "/opt/airflow/airflow/utils/operator_helpers.py", line 252, in run + return self.func(*args, **kwargs) + File "/opt/airflow/airflow/models/baseoperator.py", line 422, in wrapper + return func(self, *args, **kwargs) + File "/opt/airflow/airflow/operators/python.py", line 505, in execute + return super().execute(context=serializable_context) + File "/opt/airflow/airflow/models/baseoperator.py", line 422, in wrapper + return func(self, *args, **kwargs) + File "/opt/airflow/airflow/operators/python.py", line 238, in execute + return_value = self.execute_callable() + File "/opt/airflow/airflow/operators/python.py", line 870, in execute_callable + result = self._execute_python_callable_in_subprocess(python_path) + File "/opt/airflow/airflow/operators/python.py", line 588, in _execute_python_callable_in_subprocess + raise AirflowException(error_msg) from None +airflow.exceptions.AirflowException: Process returned non-zero exit status 1. +This is log line 1 +This is log line 2 +This is log line 3 +This is log line 4 +This is log line 5 +`; +const mockTaskLogWarning = `[2022-06-04 00:00:02,010] {taskinstance.py:1548} WARNING - Exporting env vars: AIRFLOW_CTX_DAG_OWNER=*** AIRFLOW_CTX_DAG_ID=test_ui_grid`; +const mockTaskLogInfoEndWithWarningAndUrl = `[2022-06-04 00:00:01,914] {taskinstance.py:1225} INFO - Marking task as FAILED. dag_id=reproduce_log_error_dag, task_id=reproduce_log_error_python_task2, run_id=manual__2024-11-30T02:18:22.203608+00:00, execution_date=20241130T021822, start_date=20241130T021842, end_date=20241130T021844 [2022-06-04 00:00:01,919] {standard_task_runner.py:52} INFO - Started process 41646 to run task [2022-06-04 00:00:01,920] {standard_task_runner.py:80} INFO - Running: ['***', 'tasks', 'run', 'test_ui_grid', 'section_1.get_entry_group', 'scheduled__2022-06-03T00:00:00+00:00', '--job-id', '1626', '--raw', '--subdir', 'DAGS_FOLDER/test_ui_grid.py', '--cfg-path', '/tmp/tmpte7k80ur'] [2022-06-04 00:00:01,921] {standard_task_runner.py:81} INFO - Job 1626: Subtask section_1.get_entry_group [2022-06-04 00:00:01,921] {dagbag.py:507} INFO - Filling up the DagBag from /files/dags/test_ui_grid.py [2022-06-04 00:00:01,964] {task_command.py:377} INFO - Running on host 5d28cfda3219 -[2022-06-04 00:00:02,010] {taskinstance.py:1548} WARNING - Exporting env vars: AIRFLOW_CTX_DAG_OWNER=*** AIRFLOW_CTX_DAG_ID=test_ui_grid -[2024-07-01 00:00:02,010] {taskinstance.py:1548} INFO - Url parsing test => "https://apple.com", "https://google.com", https://something.logs/_dashboard/?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-1d,to:now))&_a=(columns:!(_source),filters:!(('$state':(store:appState)))) -`; +${mockTaskLogWarning} +[2024-07-01 00:00:02,010] {taskinstance.py:1548} INFO - Url parsing test => "https://apple.com", "https://google.com", https://something.logs/_dashboard/?_g=(filters:!(),refreshInterval:(pause:!t,value:0),time:(from:now-1d,to:now))&_a=(columns:!(_source),filters:!(('$state':(store:appState))))`; + +const mockTaskLog = `${mockTaskLogInfoBegin}${mockTaskLogErrorWithTraceback}${mockTaskLogInfoEndWithWarningAndUrl}`; +const ansiUp = new AnsiUp(); +const parseExpectedLogs = (logs: string) => { + ansiUp.url_allowlist = {}; + return logs.split("\n").map((line) => ansiUp.ansi_to_html(line)); +}; describe("Test Logs Utils.", () => { test("parseLogs function replaces datetimes", () => { @@ -65,13 +98,18 @@ describe("Test Logs Utils.", () => { test.each([ { logLevelFilters: [LogLevel.INFO], - expectedNumberOfLines: 12, + expectedNumberOfLines: 14, expectedNumberOfFileSources: 4, + expectedLogs: `${mockTaskLogInfoBegin}${mockTaskLogInfoEndWithWarningAndUrl.replace( + mockTaskLogWarning, + "" + )}`, }, { logLevelFilters: [LogLevel.WARNING], expectedNumberOfLines: 1, expectedNumberOfFileSources: 1, + expectedLogs: mockTaskLogWarning, }, ])( "Filtering logs on $logLevelFilters level should return $expectedNumberOfLines lines and $expectedNumberOfFileSources file sources", @@ -79,6 +117,7 @@ describe("Test Logs Utils.", () => { logLevelFilters, expectedNumberOfLines, expectedNumberOfFileSources, + expectedLogs, }) => { const { parsedLogs, fileSources } = parseLogs( mockTaskLog, @@ -91,8 +130,11 @@ describe("Test Logs Utils.", () => { expect(fileSources).toHaveLength(expectedNumberOfFileSources); expect(parsedLogs).toBeDefined(); const lines = parsedLogs!.split("\n"); + const expectedLines = parseExpectedLogs(expectedLogs); expect(lines).toHaveLength(expectedNumberOfLines); - lines.forEach((line) => expect(line).toContain(logLevelFilters[0])); + lines.forEach((line, index) => { + expect(line).toContain(expectedLines[index]); + }); } ); @@ -104,6 +146,14 @@ describe("Test Logs Utils.", () => { ["taskinstance.py"], [] ); + const expectedLogs = `[2022-06-04 00:00:01,901] {taskinstance.py:1132} INFO - Dependencies all met for +[2022-06-04 00:00:01,906] {taskinstance.py:1132} INFO - Dependencies all met for +[2022-06-04 00:00:01,906] {taskinstance.py:1329} INFO - +[2022-06-04 00:00:01,906] {taskinstance.py:1330} INFO - Starting attempt 1 of 1 +[2022-06-04 00:00:01,906] {taskinstance.py:1331} INFO - +${mockTaskLogErrorWithTraceback} +${mockTaskLogWarning} +[2024-07-01 00:00:02,010] {taskinstance.py:1548} INFO -`; // Ignore matching for transformed hyperlinks; only verify that all the correct lines are returned. expect(fileSources).toEqual([ "dagbag.py", @@ -112,8 +162,11 @@ describe("Test Logs Utils.", () => { "taskinstance.py", ]); const lines = parsedLogs!.split("\n"); - expect(lines).toHaveLength(8); - lines.forEach((line) => expect(line).toContain("taskinstance.py")); + const expectedLines = parseExpectedLogs(expectedLogs); + expect(lines).toHaveLength(34); + lines.forEach((line, index) => { + expect(line).toContain(expectedLines[index]); + }); }); test("parseLogs function with filter on log level and file source", () => { @@ -145,7 +198,8 @@ describe("Test Logs Utils.", () => { [] ); - const lines = parsedLogs!.split("\n"); + // remove the last line which is empty + const lines = parsedLogs!.split("\n").filter((line) => line.length > 0); expect(lines[lines.length - 1]).toContain( 'https://apple.com' ); diff --git a/airflow/www/static/js/dag/details/taskInstance/Logs/utils.ts b/airflow/www/static/js/dag/details/taskInstance/Logs/utils.ts index f5340f0afb82a..b35a713484e14 100644 --- a/airflow/www/static/js/dag/details/taskInstance/Logs/utils.ts +++ b/airflow/www/static/js/dag/details/taskInstance/Logs/utils.ts @@ -59,7 +59,7 @@ export const logGroupEnd = / INFO - (::|##\[])endgroup(::|\])/g; export const parseLogs = ( data: string | undefined, timezone: string | null, - logLevelFilters: Array, + logLevelFilters: Array, fileSourceFilters: Array, unfoldedLogGroups: Array ) => { @@ -79,6 +79,8 @@ export const parseLogs = ( const parsedLines: Array = []; const fileSources: Set = new Set(); + const targetLogLevels: Set = new Set(logLevelFilters); + const targetFileSources: Set = new Set(fileSourceFilters); const ansiUp = new AnsiUp(); ansiUp.url_allowlist = {}; @@ -87,24 +89,20 @@ export const parseLogs = ( // Coloring (blue-60 as chakra style, is #0060df) and style such that log group appears like a link const logGroupStyle = "color:#0060df;cursor:pointer;font-weight:bold;"; + // Example Log Format: [2021-08-26 00:00:00,000] {filename.py:42} INFO - Log message + const regExp = /\[(.*?)\] \{(.*?)\} (.*?) -/; + let currentLevel: LogLevel = LogLevel.INFO; + let currentFileSource = ""; lines.forEach((line) => { let parsedLine = line; - - // Apply log level filter. - if ( - logLevelFilters.length > 0 && - logLevelFilters.every((level) => !line.includes(level)) - ) { - return; - } - - const regExp = /\[(.*?)\] \{(.*?)\}/; const matches = line.match(regExp); - let logGroup = ""; + let fileSource = ""; if (matches) { // Replace UTC with the local timezone. const dateTime = matches[1]; - [logGroup] = matches[2].split(":"); + [fileSource] = matches[2].split(":"); + const logLevel = matches[3]; + if (dateTime && timezone) { // @ts-ignore const localDateTime = moment @@ -115,50 +113,63 @@ export const parseLogs = ( parsedLine = line.replace(dateTime, localDateTime); } - fileSources.add(logGroup); + // The `currentLogLevel` and `currentFileSource` should remain same + // until a new `logLevel` or `fileSource` is encountered. + currentLevel = logLevel as LogLevel; + currentFileSource = fileSource; } + // Apply log level filter. + if (logLevelFilters.length > 0 && !targetLogLevels.has(currentLevel)) { + return; + } + if (fileSource) { + // Only add file source if it is not empty. + fileSources.add(fileSource); + } + // Apply file source filter. if ( - fileSourceFilters.length === 0 || - fileSourceFilters.some((fileSourceFilter) => - line.includes(fileSourceFilter) - ) + fileSourceFilters.length > 0 && + !targetFileSources.has(currentFileSource) ) { - parsedLine = highlightByKeywords( - parsedLine, - errorKeywords, - warningKeywords, - logGroupStart, - logGroupEnd - ); - // for lines with color convert to nice HTML - const coloredLine = ansiUp.ansi_to_html(parsedLine); - - // for lines with links, transform to hyperlinks - const lineWithHyperlinks = coloredLine - .replace( - urlRegex, - (url) => - `${url}` - ) - .replace(logGroupStart, (textLine) => { - const unfoldIdSuffix = "_unfold"; - const foldIdSuffix = "_fold"; - const gName = textLine.substring(17); - const gId = gName.replace(/\W+/g, "_").toLowerCase(); - const isFolded = unfoldedLogGroups.indexOf(gId) === -1; - const ufDisplay = isFolded ? "" : "display:none;"; - const unfold = ` ▶ ${gName}`; - const fDisplay = isFolded ? "display:none;" : ""; - const fold = ` ▼ ${gName}`; - return unfold + fold; - }) - .replace( - logGroupEnd, - " ▲▲▲ Log group end" - ); - parsedLines.push(lineWithHyperlinks); + return; } + + parsedLine = highlightByKeywords( + parsedLine, + currentLevel, + errorKeywords, + warningKeywords, + logGroupStart, + logGroupEnd + ); + // for lines with color convert to nice HTML + const coloredLine = ansiUp.ansi_to_html(parsedLine); + + // for lines with links, transform to hyperlinks + const lineWithHyperlinks = coloredLine + .replace( + urlRegex, + (url) => + `${url}` + ) + .replace(logGroupStart, (textLine) => { + const unfoldIdSuffix = "_unfold"; + const foldIdSuffix = "_fold"; + const gName = textLine.substring(17); + const gId = gName.replace(/\W+/g, "_").toLowerCase(); + const isFolded = unfoldedLogGroups.indexOf(gId) === -1; + const ufDisplay = isFolded ? "" : "display:none;"; + const unfold = ` ▶ ${gName}`; + const fDisplay = isFolded ? "display:none;" : ""; + const fold = ` ▼ ${gName}`; + return unfold + fold; + }) + .replace( + logGroupEnd, + " ▲▲▲ Log group end" + ); + parsedLines.push(lineWithHyperlinks); }); return { diff --git a/airflow/www/static/js/utils/index.test.ts b/airflow/www/static/js/utils/index.test.ts index 569d3af98b537..26b1fd6d84033 100644 --- a/airflow/www/static/js/utils/index.test.ts +++ b/airflow/www/static/js/utils/index.test.ts @@ -163,6 +163,7 @@ describe("Test highlightByKeywords", () => { const expected = `\x1b[1m\x1b[31mline with Error\x1b[39m\x1b[0m`; const highlightedLine = highlightByKeywords( originalLine, + "", ["error"], ["warn"], logGroupStart, @@ -175,6 +176,7 @@ describe("Test highlightByKeywords", () => { const expected = `\x1b[1m\x1b[33mline with Warning\x1b[39m\x1b[0m`; const highlightedLine = highlightByKeywords( originalLine, + "", ["error"], ["warn"], logGroupStart, @@ -187,6 +189,7 @@ describe("Test highlightByKeywords", () => { const expected = `\x1b[1m\x1b[31mline with error Warning\x1b[39m\x1b[0m`; const highlightedLine = highlightByKeywords( originalLine, + "", ["error"], ["warn"], logGroupStart, @@ -198,6 +201,7 @@ describe("Test highlightByKeywords", () => { const originalLine = " INFO - ::group::error"; const highlightedLine = highlightByKeywords( originalLine, + "", ["error"], ["warn"], logGroupStart, @@ -209,6 +213,7 @@ describe("Test highlightByKeywords", () => { const originalLine = " INFO - ::endgroup::"; const highlightedLine = highlightByKeywords( originalLine, + "", ["endgroup"], ["warn"], logGroupStart, @@ -220,6 +225,7 @@ describe("Test highlightByKeywords", () => { const originalLine = "sample line"; const highlightedLine = highlightByKeywords( originalLine, + "", ["error"], ["warn"], logGroupStart, diff --git a/airflow/www/static/js/utils/index.ts b/airflow/www/static/js/utils/index.ts index 8bef31a8582a9..2742612dc8a05 100644 --- a/airflow/www/static/js/utils/index.ts +++ b/airflow/www/static/js/utils/index.ts @@ -20,6 +20,7 @@ import Color from "color"; import type { DagRun, RunOrdering, Task, TaskInstance } from "src/types"; +import { LogLevel } from "src/dag/details/taskInstance/Logs/utils"; import useOffsetTop from "./useOffsetTop"; // Delay in ms for various hover actions @@ -187,6 +188,7 @@ const toSentenceCase = (camelCase: string): string => { const highlightByKeywords = ( parsedLine: string, + currentLogLevel: string, errorKeywords: string[], warningKeywords: string[], logGroupStart: RegExp, @@ -205,7 +207,7 @@ const highlightByKeywords = ( lowerParsedLine.includes(keyword) ); - if (containsError) { + if (containsError || currentLogLevel === (LogLevel.ERROR as string)) { return red(parsedLine); } @@ -213,7 +215,7 @@ const highlightByKeywords = ( lowerParsedLine.includes(keyword) ); - if (containsWarning) { + if (containsWarning || currentLogLevel === (LogLevel.WARNING as string)) { return yellow(parsedLine); }