1#!/usr/bin/env python3 2# 3# Copyright (C) 2022 Collabora Limited 4# Author: Guilherme Gallo <guilherme.gallo@collabora.com> 5# 6# SPDX-License-Identifier: MIT 7 8from datetime import datetime, timedelta 9 10import pytest 11from lava.exceptions import MesaCIKnownIssueException, MesaCITimeoutError 12from lava.utils import ( 13 GitlabSection, 14 LogFollower, 15 LogSectionType, 16 fix_lava_gitlab_section_log, 17 hide_sensitive_data, 18) 19from lava.utils.constants import KNOWN_ISSUE_R8152_MAX_CONSECUTIVE_COUNTER 20 21from ..lava.helpers import ( 22 create_lava_yaml_msg, 23 does_not_raise, 24 lava_yaml, 25 mock_lava_signal, 26 yaml_dump, 27) 28 29GITLAB_SECTION_SCENARIOS = { 30 "start collapsed": ( 31 "start", 32 True, 33 f"\x1b[0Ksection_start:mock_date:my_first_section[collapsed=true]\r\x1b[0K{GitlabSection.colour}my_header\x1b[0m", 34 ), 35 "start non_collapsed": ( 36 "start", 37 False, 38 f"\x1b[0Ksection_start:mock_date:my_first_section\r\x1b[0K{GitlabSection.colour}my_header\x1b[0m", 39 ), 40 "end collapsed": ( 41 "end", 42 True, 43 "\x1b[0Ksection_end:mock_date:my_first_section\r\x1b[0K", 44 ), 45 "end non_collapsed": ( 46 "end", 47 False, 48 "\x1b[0Ksection_end:mock_date:my_first_section\r\x1b[0K", 49 ), 50} 51 52@pytest.mark.parametrize( 53 "method, collapsed, expectation", 54 GITLAB_SECTION_SCENARIOS.values(), 55 ids=GITLAB_SECTION_SCENARIOS.keys(), 56) 57def test_gitlab_section(method, collapsed, expectation): 58 gs = GitlabSection( 59 id="my_first_section", 60 header="my_header", 61 type=LogSectionType.TEST_CASE, 62 start_collapsed=collapsed, 63 ) 64 gs.get_timestamp = lambda x: "mock_date" 65 gs.start() 66 result = getattr(gs, method)() 67 assert result == expectation 68 69 70def test_gl_sections(): 71 lines = [ 72 { 73 "dt": datetime.now(), 74 "lvl": "debug", 75 "msg": "Received signal: <STARTRUN> 0_setup-ssh-server 10145749_1.3.2.3.1", 76 }, 77 { 78 "dt": datetime.now(), 79 "lvl": "debug", 80 "msg": "Received signal: <STARTRUN> 0_mesa 5971831_1.3.2.3.1", 81 }, 82 # Redundant log message which triggers the same Gitlab Section, it 83 # should be ignored, unless the id is different 84 { 85 "dt": datetime.now(), 86 "lvl": "target", 87 "msg": "[ 7.778836] <LAVA_SIGNAL_STARTRUN 0_mesa 5971831_1.3.2.3.1>", 88 }, 89 { 90 "dt": datetime.now(), 91 "lvl": "debug", 92 "msg": "Received signal: <STARTTC> mesa-ci_iris-kbl-traces", 93 }, 94 # Another redundant log message 95 { 96 "dt": datetime.now(), 97 "lvl": "target", 98 "msg": "[ 16.997829] <LAVA_SIGNAL_STARTTC mesa-ci_iris-kbl-traces>", 99 }, 100 { 101 "dt": datetime.now(), 102 "lvl": "target", 103 "msg": "<LAVA_SIGNAL_ENDTC mesa-ci_iris-kbl-traces>", 104 }, 105 ] 106 lf = LogFollower() 107 with lf: 108 for line in lines: 109 lf.manage_gl_sections(line) 110 parsed_lines = lf.flush() 111 112 section_types = [s.type for s in lf.section_history] 113 114 assert "section_start" in parsed_lines[0] 115 assert "collapsed=true" not in parsed_lines[0] 116 assert "section_end" in parsed_lines[1] 117 assert "section_start" in parsed_lines[2] 118 assert "collapsed=true" not in parsed_lines[2] 119 assert "section_end" in parsed_lines[3] 120 assert "section_start" in parsed_lines[4] 121 assert "collapsed=true" not in parsed_lines[4] 122 assert "section_end" in parsed_lines[5] 123 assert "section_start" in parsed_lines[6] 124 assert "collapsed=true" in parsed_lines[6] 125 assert section_types == [ 126 # LogSectionType.LAVA_BOOT, True, if LogFollower started with Boot section 127 LogSectionType.TEST_DUT_SUITE, 128 LogSectionType.TEST_SUITE, 129 LogSectionType.TEST_CASE, 130 LogSectionType.LAVA_POST_PROCESSING, 131 ] 132 133 134def test_log_follower_flush(): 135 lines = [ 136 { 137 "dt": datetime.now(), 138 "lvl": "debug", 139 "msg": "Received signal: <STARTTC> mesa-ci_iris-kbl-traces", 140 }, 141 { 142 "dt": datetime.now(), 143 "lvl": "target", 144 "msg": "<LAVA_SIGNAL_ENDTC mesa-ci_iris-kbl-traces>", 145 }, 146 ] 147 lf = LogFollower() 148 lf.feed(lines) 149 parsed_lines = lf.flush() 150 empty = lf.flush() 151 lf.feed(lines) 152 repeated_parsed_lines = lf.flush() 153 154 assert parsed_lines 155 assert not empty 156 assert repeated_parsed_lines 157 158 159SENSITIVE_DATA_SCENARIOS = { 160 "no sensitive data tagged": ( 161 ["bla bla", "mytoken: asdkfjsde1341=="], 162 ["bla bla", "mytoken: asdkfjsde1341=="], 163 ["HIDEME"], 164 ), 165 "sensitive data tagged": ( 166 ["bla bla", "mytoken: asdkfjsde1341== # HIDEME"], 167 ["bla bla"], 168 ["HIDEME"], 169 ), 170 "sensitive data tagged with custom word": ( 171 ["bla bla", "mytoken: asdkfjsde1341== # DELETETHISLINE", "third line # NOTANYMORE"], 172 ["bla bla", "third line # NOTANYMORE"], 173 ["DELETETHISLINE", "NOTANYMORE"], 174 ), 175} 176 177 178@pytest.mark.parametrize( 179 "input, expectation, tags", 180 SENSITIVE_DATA_SCENARIOS.values(), 181 ids=SENSITIVE_DATA_SCENARIOS.keys(), 182) 183def test_hide_sensitive_data(input, expectation, tags): 184 yaml_data = yaml_dump(input) 185 yaml_result = hide_sensitive_data(yaml_data, *tags) 186 result = lava_yaml.load(yaml_result) 187 188 assert result == expectation 189 190 191GITLAB_SECTION_SPLIT_SCENARIOS = { 192 "Split section_start at target level": ( 193 "\x1b[0Ksection_start:1668454947:test_post_process[collapsed=true]\r\x1b[0Kpost-processing test results", 194 ( 195 "\x1b[0Ksection_start:1668454947:test_post_process[collapsed=true]", 196 "\x1b[0Kpost-processing test results", 197 ), 198 ), 199 "Split section_end at target level": ( 200 "\x1b[0Ksection_end:1666309222:test_post_process\r\x1b[0K", 201 ("\x1b[0Ksection_end:1666309222:test_post_process", "\x1b[0K"), 202 ), 203 "Second line is not split from the first": ( 204 ("\x1b[0Ksection_end:1666309222:test_post_process", "Any message"), 205 ("\x1b[0Ksection_end:1666309222:test_post_process", "Any message"), 206 ), 207} 208 209 210@pytest.mark.parametrize( 211 "expected_message, messages", 212 GITLAB_SECTION_SPLIT_SCENARIOS.values(), 213 ids=GITLAB_SECTION_SPLIT_SCENARIOS.keys(), 214) 215def test_fix_lava_gitlab_section_log(expected_message, messages): 216 fixed_messages = [] 217 gen = fix_lava_gitlab_section_log() 218 next(gen) 219 220 for message in messages: 221 lava_log = create_lava_yaml_msg(msg=message, lvl="target") 222 if recovered_line := gen.send(lava_log): 223 fixed_messages.append((recovered_line, lava_log["msg"])) 224 fixed_messages.append(lava_log["msg"]) 225 226 assert expected_message in fixed_messages 227 228 229@pytest.mark.parametrize( 230 "expected_message, messages", 231 GITLAB_SECTION_SPLIT_SCENARIOS.values(), 232 ids=GITLAB_SECTION_SPLIT_SCENARIOS.keys(), 233) 234def test_lava_gitlab_section_log_collabora(expected_message, messages, monkeypatch): 235 """Check if LogFollower does not change the message if we are running in Collabora farm.""" 236 monkeypatch.setenv("RUNNER_TAG", "mesa-ci-x86_64-lava-test") 237 lf = LogFollower() 238 for message in messages: 239 lf.feed([create_lava_yaml_msg(msg=message)]) 240 new_messages = lf.flush() 241 new_messages = tuple(new_messages) if len(new_messages) > 1 else new_messages[0] 242 assert new_messages == expected_message 243 244 245CARRIAGE_RETURN_SCENARIOS = { 246 "Carriage return at the end of the previous line": ( 247 ( 248 "\x1b[0Ksection_start:1677609903:test_setup[collapsed=true]\r\x1b[0K\x1b[0;36m[303:44] deqp: preparing test setup\x1b[0m", 249 ), 250 ( 251 "\x1b[0Ksection_start:1677609903:test_setup[collapsed=true]\r", 252 "\x1b[0K\x1b[0;36m[303:44] deqp: preparing test setup\x1b[0m\r\n", 253 ), 254 ), 255 "Newline at the end of the line": ( 256 ("\x1b[0K\x1b[0;36m[303:44] deqp: preparing test setup\x1b[0m", "log"), 257 ("\x1b[0K\x1b[0;36m[303:44] deqp: preparing test setup\x1b[0m\r\n", "log"), 258 ), 259} 260 261 262@pytest.mark.parametrize( 263 "expected_message, messages", 264 CARRIAGE_RETURN_SCENARIOS.values(), 265 ids=CARRIAGE_RETURN_SCENARIOS.keys(), 266) 267def test_lava_log_merge_carriage_return_lines(expected_message, messages): 268 lf = LogFollower() 269 for message in messages: 270 lf.feed([create_lava_yaml_msg(msg=message)]) 271 new_messages = tuple(lf.flush()) 272 assert new_messages == expected_message 273 274 275WATCHDOG_SCENARIOS = { 276 "1 second before timeout": ({"seconds": -1}, does_not_raise()), 277 "1 second after timeout": ({"seconds": 1}, pytest.raises(MesaCITimeoutError)), 278} 279 280 281@pytest.mark.parametrize( 282 "timedelta_kwargs, exception", 283 WATCHDOG_SCENARIOS.values(), 284 ids=WATCHDOG_SCENARIOS.keys(), 285) 286def test_log_follower_watchdog(frozen_time, timedelta_kwargs, exception): 287 lines = [ 288 { 289 "dt": datetime.now(), 290 "lvl": "debug", 291 "msg": "Received signal: <STARTTC> mesa-ci_iris-kbl-traces", 292 }, 293 ] 294 td = {LogSectionType.TEST_CASE: timedelta(minutes=1)} 295 lf = LogFollower(timeout_durations=td) 296 lf.feed(lines) 297 frozen_time.tick( 298 lf.timeout_durations[LogSectionType.TEST_CASE] + timedelta(**timedelta_kwargs) 299 ) 300 lines = [create_lava_yaml_msg()] 301 with exception: 302 lf.feed(lines) 303 304 305GITLAB_SECTION_ID_SCENARIOS = [ 306 ("a-good_name", "a-good_name"), 307 ("spaces are not welcome", "spaces-are-not-welcome"), 308 ("abc:amd64 1/3", "abc-amd64-1-3"), 309] 310 311 312@pytest.mark.parametrize("case_name, expected_id", GITLAB_SECTION_ID_SCENARIOS) 313def test_gitlab_section_id(case_name, expected_id): 314 gl = GitlabSection( 315 id=case_name, header=case_name, type=LogSectionType.LAVA_POST_PROCESSING 316 ) 317 318 assert gl.id == expected_id 319 320 321def a618_network_issue_logs(level: str = "target") -> list: 322 net_error = create_lava_yaml_msg( 323 msg="[ 1733.599402] r8152 2-1.3:1.0 eth0: Tx status -71", lvl=level) 324 325 nfs_error = create_lava_yaml_msg( 326 msg="[ 1733.604506] nfs: server 192.168.201.1 not responding, still trying", 327 lvl=level, 328 ) 329 330 return [ 331 *(KNOWN_ISSUE_R8152_MAX_CONSECUTIVE_COUNTER*[net_error]), 332 nfs_error 333 ] 334 335 336TEST_PHASE_LAVA_SIGNAL = mock_lava_signal(LogSectionType.TEST_CASE) 337A618_NET_ISSUE_BOOT = a618_network_issue_logs(level="feedback") 338A618_NET_ISSUE_TEST = [TEST_PHASE_LAVA_SIGNAL, *a618_network_issue_logs(level="target")] 339 340 341A618_NETWORK_ISSUE_SCENARIOS = { 342 "Fail - R8152 kmsg during boot phase": ( 343 A618_NET_ISSUE_BOOT, 344 pytest.raises(MesaCIKnownIssueException), 345 ), 346 "Fail - R8152 kmsg during test phase": ( 347 A618_NET_ISSUE_TEST, 348 pytest.raises(MesaCIKnownIssueException), 349 ), 350 "Pass - Partial (1) R8152 kmsg during test phase": ( 351 A618_NET_ISSUE_TEST[:1], 352 does_not_raise(), 353 ), 354 "Pass - Partial (2) R8152 kmsg during test phase": ( 355 A618_NET_ISSUE_TEST[:2], 356 does_not_raise(), 357 ), 358 "Pass - Partial (3) subsequent R8152 kmsg during test phase": ( 359 [ 360 TEST_PHASE_LAVA_SIGNAL, 361 A618_NET_ISSUE_TEST[1], 362 A618_NET_ISSUE_TEST[1], 363 ], 364 does_not_raise(), 365 ), 366 "Pass - Partial (4) subsequent nfs kmsg during test phase": ( 367 [ 368 TEST_PHASE_LAVA_SIGNAL, 369 A618_NET_ISSUE_TEST[-1], 370 A618_NET_ISSUE_TEST[-1], 371 ], 372 does_not_raise(), 373 ), 374} 375 376 377@pytest.mark.parametrize( 378 "messages, expectation", 379 A618_NETWORK_ISSUE_SCENARIOS.values(), 380 ids=A618_NETWORK_ISSUE_SCENARIOS.keys(), 381) 382def test_detect_failure(messages, expectation): 383 boot_section = GitlabSection( 384 id="lava_boot", 385 header="LAVA boot", 386 type=LogSectionType.LAVA_BOOT, 387 start_collapsed=True, 388 ) 389 boot_section.start() 390 lf = LogFollower(starting_section=boot_section) 391 with expectation: 392 lf.feed(messages) 393