diff --git a/squad/plugins/linux_log_parser.py b/squad/plugins/linux_log_parser.py index 6aa81d05..fe9ece12 100644 --- a/squad/plugins/linux_log_parser.py +++ b/squad/plugins/linux_log_parser.py @@ -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]*"), + ('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 @@ -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, @@ -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] + 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): @@ -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) diff --git a/test/plugins/test_linux_log_parser.py b/test/plugins/test_linux_log_parser.py index e0565044..bfe4fd94 100644 --- a/test/plugins/test_linux_log_parser.py +++ b/test/plugins/test_linux_log_parser.py @@ -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) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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') @@ -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) @@ -251,7 +251,7 @@ 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) @@ -259,8 +259,51 @@ def test_sha_name(self): 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') 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)