Skip to content

Commit

Permalink
Fix wrong display of multiline messages in the log after filtering (#…
Browse files Browse the repository at this point in the history 
…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
  • Loading branch information
@jason810496
jason810496 authored Dec 3, 2024
1 parent 2e9b8b5 commit 294683a
Show file tree
Hide file tree
Showing 4 changed files with 140 additions and 67 deletions.
80 changes: 67 additions & 13 deletions airflow/www/static/js/dag/details/taskInstance/Logs/utils.test.tsx
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 <TaskInstance: test_ui_grid.section_1.get_entry_group scheduled__2022-06-03T00:00:00+00:00 [queued]>
[2022-06-04 00:00:01,906] {taskinstance.py:1132} INFO - Dependencies all met for <TaskInstance: test_ui_grid.section_1.get_entry_group scheduled__2022-06-03T00:00:00+00:00 [queued]>
[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 <Task(BashOperator): section_1.get_entry_group> 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 <TaskInstance: test_ui_grid.section_1.get_entry_group scheduled__2022-06-03T00:00:00+00:00 [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", () => {
Expand All @@ -65,20 +98,26 @@ 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",
({
logLevelFilters,
expectedNumberOfLines,
expectedNumberOfFileSources,
expectedLogs,
}) => {
const { parsedLogs, fileSources } = parseLogs(
mockTaskLog,
Expand All @@ -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]);
});
}
);

Expand All @@ -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 <TaskInstance: test_ui_grid.section_1.get_entry_group scheduled__2022-06-03T00:00:00+00:00 [queued]>
[2022-06-04 00:00:01,906] {taskinstance.py:1132} INFO - Dependencies all met for <TaskInstance: test_ui_grid.section_1.get_entry_group scheduled__2022-06-03T00:00:00+00:00 [queued]>
[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",
Expand All @@ -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", () => {
Expand Down Expand Up @@ -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(
'<a href="https://apple.com" target="_blank" rel="noopener noreferrer" style="color: blue; text-decoration: underline;">https://apple.com</a>'
);
Expand Down
115 changes: 63 additions & 52 deletions airflow/www/static/js/dag/details/taskInstance/Logs/utils.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -59,7 +59,7 @@ export const logGroupEnd = / INFO - (::|##\[])endgroup(::|\])/g;
export const parseLogs = (
data: string | undefined,
timezone: string | null,
logLevelFilters: Array<LogLevel>,
logLevelFilters: Array<string>,
fileSourceFilters: Array<string>,
unfoldedLogGroups: Array<string>
) => {
Expand All @@ -79,6 +79,8 @@ export const parseLogs = (

const parsedLines: Array<string> = [];
const fileSources: Set<string> = new Set();
const targetLogLevels: Set<string> = new Set(logLevelFilters);
const targetFileSources: Set<string> = new Set(fileSourceFilters);
const ansiUp = new AnsiUp();
ansiUp.url_allowlist = {};

Expand All @@ -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
Expand All @@ -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) =>
`<a href="${url}" target="_blank" rel="noopener noreferrer" style="color: blue; text-decoration: underline;">${url}</a>`
)
.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 = `<span id="${gId}${unfoldIdSuffix}" style="${ufDisplay}${logGroupStyle}"> &#9654; ${gName}</span>`;
const fDisplay = isFolded ? "display:none;" : "";
const fold = `<span style="${fDisplay}"><span id="${gId}${foldIdSuffix}" style="${logGroupStyle}"> &#9660; ${gName}</span>`;
return unfold + fold;
})
.replace(
logGroupEnd,
" <span style='color:#0060df;'>&#9650;&#9650;&#9650; Log group end</span></span>"
);
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) =>
`<a href="${url}" target="_blank" rel="noopener noreferrer" style="color: blue; text-decoration: underline;">${url}</a>`
)
.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 = `<span id="${gId}${unfoldIdSuffix}" style="${ufDisplay}${logGroupStyle}"> &#9654; ${gName}</span>`;
const fDisplay = isFolded ? "display:none;" : "";
const fold = `<span style="${fDisplay}"><span id="${gId}${foldIdSuffix}" style="${logGroupStyle}"> &#9660; ${gName}</span>`;
return unfold + fold;
})
.replace(
logGroupEnd,
" <span style='color:#0060df;'>&#9650;&#9650;&#9650; Log group end</span></span>"
);
parsedLines.push(lineWithHyperlinks);
});

return {
Expand Down
6 changes: 6 additions & 0 deletions airflow/www/static/js/utils/index.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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,
Expand All @@ -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,
Expand All @@ -198,6 +201,7 @@ describe("Test highlightByKeywords", () => {
const originalLine = " INFO - ::group::error";
const highlightedLine = highlightByKeywords(
originalLine,
"",
["error"],
["warn"],
logGroupStart,
Expand All @@ -209,6 +213,7 @@ describe("Test highlightByKeywords", () => {
const originalLine = " INFO - ::endgroup::";
const highlightedLine = highlightByKeywords(
originalLine,
"",
["endgroup"],
["warn"],
logGroupStart,
Expand All @@ -220,6 +225,7 @@ describe("Test highlightByKeywords", () => {
const originalLine = "sample line";
const highlightedLine = highlightByKeywords(
originalLine,
"",
["error"],
["warn"],
logGroupStart,
Expand Down
6 changes: 4 additions & 2 deletions airflow/www/static/js/utils/index.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -187,6 +188,7 @@ const toSentenceCase = (camelCase: string): string => {

const highlightByKeywords = (
parsedLine: string,
currentLogLevel: string,
errorKeywords: string[],
warningKeywords: string[],
logGroupStart: RegExp,
Expand All @@ -205,15 +207,15 @@ const highlightByKeywords = (
lowerParsedLine.includes(keyword)
);

if (containsError) {
if (containsError || currentLogLevel === (LogLevel.ERROR as string)) {
return red(parsedLine);
}

const containsWarning = warningKeywords.some((keyword) =>
lowerParsedLine.includes(keyword)
);

if (containsWarning) {
if (containsWarning || currentLogLevel === (LogLevel.WARNING as string)) {
return yellow(parsedLine);
}

Expand Down

0 comments on commit 294683a

Please sign in to comment.