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