Skip to content
This repository has been archived by the owner on Jul 25, 2024. It is now read-only.

plugins/linux_log_parser: Add support for test name regex #1142

Merged
merged 3 commits into from
Jul 25, 2024
+141 −51
Merged

plugins/linux_log_parser: Add support for test name regex #1142

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
a66d5cd
plugins/linux_log_parser: Add support for test name regex
katieworton Jul 17, 2024
b8e385c
plugins/linux_log_parser: Move test name regex to higher level
katieworton Jul 24, 2024
98e3120
test/plugins/test_linux_log_parser: Add an extra test for SHAs
katieworton Jul 25, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
111 changes: 79 additions & 32 deletions squad/plugins/linux_log_parser.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,26 +4,28 @@
from collections import defaultdict
from squad.plugins import Plugin as BasePlugin
from squad.core.models import SuiteMetadata
from django.template.defaultfilters import slugify


logger = logging.getLogger()

REGEX_NAME = 0
REGEX_BODY = 1
REGEX_EXTRACT_NAME = 2

MULTILINERS = [
('check-kernel-exception', r'-+\[? cut here \]?-+.*?-+\[? end trace \w* \]?-+'),
('check-kernel-kasan', r'=+\n\[[\s\.\d]+\]\s+BUG: KASAN:.*?=+'),
('check-kernel-kfence', r'=+\n\[[\s\.\d]+\]\s+BUG: KFENCE:.*?=+'),
('check-kernel-exception', r'-+\[? cut here \]?-+.*?-+\[? end trace \w* \]?-+', r"\d][^\+\n]*"),
chaws marked this conversation as resolved.
Show resolved Hide resolved
('check-kernel-kasan', r'=+\n\[[\s\.\d]+\]\s+BUG: KASAN:.*?=+', r"BUG: KASAN:[^\+\n]*"),
('check-kernel-kfence', r'=+\n\[[\s\.\d]+\]\s+BUG: KFENCE:.*?=+', r"BUG: KFENCE:[^\+\n]*"),
]

ONELINERS = [
('check-kernel-oops', r'^[^\n]+Oops(?: -|:).*?$'),
('check-kernel-fault', r'^[^\n]+Unhandled fault.*?$'),
('check-kernel-warning', r'^[^\n]+WARNING:.*?$'),
('check-kernel-bug', r'^[^\n]+(?: kernel BUG at|BUG:).*?$'),
('check-kernel-invalid-opcode', r'^[^\n]+invalid opcode:.*?$'),
('check-kernel-panic', r'Kernel panic - not syncing.*?$'),
('check-kernel-oops', r'^[^\n]+Oops(?: -|:).*?$', r"Oops[^\+\n]*"),
('check-kernel-fault', r'^[^\n]+Unhandled fault.*?$', r"Unhandled [^\+\n]*"),
('check-kernel-warning', r'^[^\n]+WARNING:.*?$', r"WARNING: [^\+\n]*"),
('check-kernel-bug', r'^[^\n]+(?: kernel BUG at|BUG:).*?$', r"BUG[^\+\n]*"),
('check-kernel-invalid-opcode', r'^[^\n]+invalid opcode:.*?$', r"invalid opcode: [^\+\n]*"),
('check-kernel-panic', r'Kernel panic - not syncing.*?$', r"Kernel [^\+\n]*"),
]

# Tip: broader regexes should come first
Expand Down Expand Up @@ -70,33 +72,55 @@ def __join_matches(self, matches, regexes):
snippets[regex_id].append(match[regex_id])
return snippets

def __create_tests(self, testrun, suite, test_name, lines):
def __create_tests(self, testrun, suite, test_name, lines, test_regex=None):
"""
There will be at least one test per regex. If there were any match for a given
regex, then a new test will be generated using test_name + shasum. This helps
comparing kernel logs accross different builds
"""
metadata, _ = SuiteMetadata.objects.get_or_create(suite=suite.slug, name=test_name, kind='test')
testrun.tests.create(
suite=suite,
result=(len(lines) == 0),
log='\n'.join(lines),
metadata=metadata,
build=testrun.build,
environment=testrun.environment,
)

# Some lines of the matched regex might be the same, and we don't want to create
# multiple tests like test1-sha1, test1-sha1, etc, so we'll create a set of sha1sums
# then create only new tests for unique sha's
# Run the REGEX_EXTRACT_NAME regex over the log lines to sort them by
# extracted name. If no name is extracted or the log parser did not
# have any output for a particular regex, just use the default name
# (for example "check-kernel-oops").
tests_to_create = defaultdict(set)
shas = defaultdict(set)
for line in lines:
sha = self.__create_shasum(line)
shas[sha].add(line)

for sha, lines in shas.items():
name = f'{test_name}-{sha}'
# If there are no lines, use the default name and create a passing
# test. For example "check-kernel-oops"
if not lines:
tests_to_create[test_name] = []

# If there are lines, then create the tests for these.
for line in lines:
extracted_name = self.__create_name(line, test_regex)
if extracted_name:
extended_test_name = f"{test_name}-{extracted_name}"
else:
extended_test_name = test_name
tests_to_create[extended_test_name].add(line)

for name, lines in tests_to_create.items():
metadata, _ = SuiteMetadata.objects.get_or_create(suite=suite.slug, name=name, kind='test')
testrun.tests.create(
suite=suite,
result=(len(lines) == 0),
log='\n'.join(lines),
metadata=metadata,
build=testrun.build,
environment=testrun.environment,
)

# Some lines of the matched regex might be the same, and we don't want to create
# multiple tests like test1-sha1, test1-sha1, etc, so we'll create a set of sha1sums
# then create only new tests for unique sha's

for line in lines:
sha = self.__create_shasum(line)
name_with_sha = f"{name}-{sha}"
shas[name_with_sha].add(line)

for name_with_sha, lines in shas.items():
metadata, _ = SuiteMetadata.objects.get_or_create(suite=suite.slug, name=name_with_sha, kind='test')
testrun.tests.create(
suite=suite,
result=False,
Expand All @@ -106,11 +130,30 @@ def __create_tests(self, testrun, suite, test_name, lines):
environment=testrun.environment,
)

def __remove_numbers_and_time(self, snippet):
without_numbers = re.sub(r"(0x[a-f0-9]+|[<\[][0-9a-f]+?[>\]]|\d+)", "", snippet)
without_time = re.sub(r"^\[[^\]]+\]", "", without_numbers)

return without_time

def __create_name(self, snippet, regex=None):
matches = None
if regex:
matches = regex.findall(snippet)
if not matches:
return None
snippet = matches[0]
without_numbers_and_time = self.__remove_numbers_and_time(snippet)

# Limit the name length to 191 characters, since the max name length
# for SuiteMetadata in SQUAD is 256 characters. The SHA and "-" take 65
# characters: 256-65=191
return slugify(without_numbers_and_time)[:191]
chaws marked this conversation as resolved.
Show resolved Hide resolved

def __create_shasum(self, snippet):
sha = hashlib.sha256()
without_numbers = re.sub(r'(0x[a-f0-9]+|[<\[][0-9a-f]+?[>\]]|\d+)', '', snippet)
without_time = re.sub(r'^\[[^\]]+\]', '', without_numbers)
sha.update(without_time.encode())
without_numbers_and_time = self.__remove_numbers_and_time(snippet)
sha.update(without_numbers_and_time.encode())
return sha.hexdigest()

def postprocess_testrun(self, testrun):
Expand All @@ -133,4 +176,8 @@ def postprocess_testrun(self, testrun):

for regex_id in range(len(REGEXES)):
test_name = REGEXES[regex_id][REGEX_NAME]
self.__create_tests(testrun, suite, test_name, snippets[regex_id])
regex_pattern = REGEXES[regex_id][REGEX_EXTRACT_NAME]
test_name_regex = None
if regex_pattern:
test_name_regex = re.compile(regex_pattern, re.S | re.M)
self.__create_tests(testrun, suite, test_name, snippets[regex_id], test_name_regex)
81 changes: 62 additions & 19 deletions test/plugins/test_linux_log_parser.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@ def test_detects_oops(self):
testrun = self.new_testrun('oops.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-oops')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-oops-oops-bug-preempt-smp')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Linux version 4.4.89-01529-gb29bace', test.log)
Expand All @@ -40,19 +40,19 @@ def test_detects_kernel_panic(self):
testrun = self.new_testrun('kernelpanic.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-panic')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-panic-kernel-panic-not-syncing-attempted-to-kill-the-idle-task')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Booting Linux', test.log)
self.assertIn('Kernel panic - not syncing', test.log)
self.assertIn('Attempted to kill init! exitcode=0x00000009', test.log)
self.assertNotIn('Attempted to kill init! exitcode=0x00000009', test.log)
self.assertNotIn('Internal error: Oops', test.log)

def test_detects_kernel_exception(self):
testrun = self.new_testrun('kernelexceptiontrace.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception-warning-cpu-pid-at-kernelsmpc-smp_call_function_many_cond')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Booting Linux', test.log)
Expand All @@ -64,7 +64,7 @@ def test_detects_kernel_exception_without_square_braces(self):
testrun = self.new_testrun('kernelexceptiontrace_without_squarebraces.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception-warning-cpu-pid-at-kernelsmpc-smp_call_function_many_cond')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Booting Linux', test.log)
Expand All @@ -76,7 +76,7 @@ def test_detects_kernel_kasan(self):
testrun = self.new_testrun('kasan.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-kasan')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-kasan-bug-kasan-slab-out-of-bounds-in-kmalloc_oob_right')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Booting Linux', test.log)
Expand All @@ -89,7 +89,7 @@ def test_detects_kernel_kfence(self):
testrun = self.new_testrun('kfence.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-kfence')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-kfence-bug-kfence-memory-corruption-in-kfree')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Booting Linux', test.log)
Expand All @@ -102,7 +102,7 @@ def test_detects_kernel_bug(self):
testrun = self.new_testrun('oops.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-bug')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-bug-bug-spinlock-lockup-suspected-on-cpu-gdbus')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Booting Linux', test.log)
Expand All @@ -112,7 +112,7 @@ def test_detects_kernel_bug(self):
testrun = self.new_testrun('kernel_bug_and_invalid_opcode.log', job_id='1000')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-bug')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception-kernel-bug-at-usrsrckernelarchxkvmmmummuc')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Booting Linux', test.log)
Expand All @@ -124,7 +124,7 @@ def test_detects_kernel_invalid_opcode(self):
testrun = self.new_testrun('kernel_bug_and_invalid_opcode.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-invalid-opcode')
test = testrun.tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-invalid-opcode-invalid-opcode-smp-pti')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Booting Linux', test.log)
Expand All @@ -137,11 +137,11 @@ def test_detects_multiple(self):
self.plugin.postprocess_testrun(testrun)

tests = testrun.tests
test_panic = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-panic')
test_exception = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception')
test_warning = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-warning')
test_oops = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-oops')
test_fault = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-fault')
test_panic = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-panic-kernel-panic-not-syncing-stack-protector-kernel-stack-is-corrupted-in-ffffffffcc')
test_exception = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception-warning-cpu-pid-at-driversgpudrmradeonradeon_objectc-radeon_ttm_bo_destroy')
test_warning = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-warning-warning-cpu-pid-at-driversregulatorcorec-_regulator_putpart')
test_oops = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-oops-oops-preempt-smp')
test_fault = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-fault-unhandled-fault-external-abort-on-non-linefetch-at')

self.assertFalse(test_panic.result)
self.assertNotIn('Boot CPU', test_panic.log)
Expand Down Expand Up @@ -208,7 +208,7 @@ def test_rcu_warning(self):
tests = testrun.tests
test_panic = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-panic')
test_exception = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception')
test_warning = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-warning')
test_warning = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-warning-warning-suspicious-rcu-usage')
test_oops = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-oops')
test_fault = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-fault')

Expand Down Expand Up @@ -240,7 +240,7 @@ def test_boot_log(self):
testrun = self.new_testrun('oops.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-boot', metadata__name='check-kernel-oops')
test = testrun.tests.get(suite__slug='log-parser-boot', metadata__name='check-kernel-oops-oops-bug-preempt-smp')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Linux version 4.4.89-01529-gb29bace', test.log)
Expand All @@ -251,16 +251,59 @@ def test_sha_name(self):
testrun = self.new_testrun('oops.log')
self.plugin.postprocess_testrun(testrun)

test = testrun.tests.get(suite__slug='log-parser-boot', metadata__name='check-kernel-oops')
test = testrun.tests.get(suite__slug='log-parser-boot', metadata__name='check-kernel-oops-oops-bug-preempt-smp')
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertNotIn('Linux version 4.4.89-01529-gb29bace', test.log)
self.assertIn('Internal error: Oops - BUG: 0 [#0] PREEMPT SMP', test.log)
self.assertNotIn('Kernel panic', test.log)

# Now check if a test with sha digest in the name
test = testrun.tests.get(suite__slug='log-parser-boot', metadata__name='check-kernel-oops-a1acf2f0467782c9c2f6aeadb1d1d3cec136642b13d7231824a66ef63ee62220')
test = testrun.tests.get(suite__slug='log-parser-boot', metadata__name='check-kernel-oops-oops-bug-preempt-smp-a1acf2f0467782c9c2f6aeadb1d1d3cec136642b13d7231824a66ef63ee62220')
chaws marked this conversation as resolved.
Show resolved Hide resolved
self.assertFalse(test.result)
self.assertIsNotNone(test.log)
self.assertIn('Internal error: Oops - BUG: 0 [#0] PREEMPT SMP', test.log)
self.assertNotIn('Internal error: Oops - BUG: 99 [#1] PREEMPT SMP', test.log)

def test_sha_name_multiple(self):
testrun = self.new_testrun('multiple_issues_dmesg.log')
self.plugin.postprocess_testrun(testrun)

tests = testrun.tests
test_panic = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-panic-kernel-panic-not-syncing-stack-protector-kernel-stack-is-corrupted-in-ffffffffcc-ab2f1708a36efc4f90943d58fb240d435fcb3d05f7fac9b00163483fe77209eb')
test_exception = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-exception-warning-cpu-pid-at-driversgpudrmradeonradeon_objectc-radeon_ttm_bo_destroy-77251099bfa081e5c942070a569fe31163336e61a80bda7304cd59f0f4b82080')
test_warning = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-warning-warning-cpu-pid-at-driversregulatorcorec-_regulator_putpart-d44949024d5373185a7381cb9dd291b13c117d6b93feb576a431e5376025004f')
test_oops = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-oops-oops-preempt-smp-4e1ddddb2c142178a8977e7d973c2a13db2bb978aa471c0049ee39fe3fe4d74c')
test_fault = tests.get(suite__slug='log-parser-test', metadata__name='check-kernel-fault-unhandled-fault-external-abort-on-non-linefetch-at-6f9e3ab8f97e35c1e9167fed1e01c6149986819c54451064322b7d4208528e07')

self.assertFalse(test_panic.result)
self.assertNotIn('Boot CPU', test_panic.log)
self.assertIn('Kernel panic - not syncing', test_panic.log)

self.assertFalse(test_exception.result)
self.assertNotIn('Boot CPU', test_exception.log)
self.assertIn('------------[ cut here ]------------', test_exception.log)

self.assertFalse(test_warning.result)
self.assertNotIn('Boot CPU', test_warning.log)
self.assertNotIn('Kernel panic - not syncing', test_warning.log)
self.assertNotIn('------------[ cut here ]------------', test_warning.log)
self.assertNotIn('Unhandled fault:', test_warning.log)
self.assertNotIn('Oops', test_warning.log)
self.assertIn('WARNING: CPU', test_warning.log)

self.assertFalse(test_oops.result)
self.assertNotIn('Boot CPU', test_oops.log)
self.assertNotIn('Kernel panic - not syncing', test_oops.log)
self.assertNotIn('------------[ cut here ]------------', test_oops.log)
self.assertNotIn('WARNING: CPU', test_oops.log)
self.assertNotIn('Unhandled fault:', test_oops.log)
self.assertIn('Oops', test_oops.log)

self.assertFalse(test_fault.result)
self.assertNotIn('Boot CPU', test_fault.log)
self.assertNotIn('Kernel panic - not syncing', test_fault.log)
self.assertNotIn('------------[ cut here ]------------', test_fault.log)
self.assertNotIn('WARNING: CPU', test_fault.log)
self.assertNotIn('Oops', test_fault.log)
self.assertIn('Unhandled fault:', test_fault.log)
Loading