- {"dt": "2025-03-25T10:56:55.482369", "lvl": "info", "msg": "lava-dispatcher, installed at version: 2024.09.dev0100"}
- {"dt": "2025-03-25T10:56:55.482457", "lvl": "info", "msg": "start: 0 validate"}
- {"dt": "2025-03-25T10:56:55.482532", "lvl": "info", "msg": "Start time: 2025-03-25 10:56:55.482525+00:00 (UTC)"}
- {"dt": "2025-03-25T10:56:55.483308", "lvl": "debug", "msg": "Validating that https://storage.tuxsuite.com/public/linaro/anders/builds/2tmCo2a0FpKFsv4rCtTeLbgkG9C/Image.gz exists"}
- {"dt": "2025-03-25T10:56:55.917883", "lvl": "debug", "msg": "Using GET because HEAD is not supported properly"}
- {"dt": "2025-03-25T10:56:56.754549", "lvl": "debug", "msg": "Validating that file:///home/anders/.cache/tuxrun/assets/https___storage.tuxboot.com_debian_trixie_arm64_rootfs.ext4.xz exists"}
- {"dt": "2025-03-25T10:56:56.754774", "lvl": "debug", "msg": "Validating that https://storage.tuxsuite.com/public/linaro/anders/builds/2tmCo2a0FpKFsv4rCtTeLbgkG9C/modules.tar.xz exists"}
- {"dt": "2025-03-25T10:56:56.880289", "lvl": "debug", "msg": "Using GET because HEAD is not supported properly"}
- {"dt": "2025-03-25T10:56:57.433035", "lvl": "debug", "msg": "Validating that https://storage.tuxboot.com/overlays/debian/trixie/arm64/rt-tests/rt-2.8.y/rt-tests.tar.xz exists"}
- {"dt": "2025-03-25T10:56:57.609434", "lvl": "info", "msg": "qemu-system-arm, installed at version: 1:9.2.0+ds-2, host architecture: amd64"}
- {"dt": "2025-03-25T10:56:57.609663", "lvl": "warning", "msg": "Missing image arg for rootfs.modules"}
- {"dt": "2025-03-25T10:56:57.609751", "lvl": "warning", "msg": "Missing image arg for rootfs.overlay-00"}
- {"dt": "2025-03-25T10:56:57.609912", "lvl": "info", "msg": "validate duration: 2.13"}
- {"dt": "2025-03-25T10:56:57.609985", "lvl": "results", "msg": {"definition": "lava", "case": "validate", "result": "pass"}}
- {"dt": "2025-03-25T10:56:57.610113", "lvl": "info", "msg": "start: 1 deployimages (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:56:57.610203", "lvl": "debug", "msg": "start: 1.1 lava-overlay (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:56:57.610440", "lvl": "debug", "msg": "[common] Preparing overlay tarball in /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz"}
- {"dt": "2025-03-25T10:56:57.610592", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin"}
- {"dt": "2025-03-25T10:56:57.610691", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/tests"}
- {"dt": "2025-03-25T10:56:57.610789", "lvl": "debug", "msg": "makedir: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/results"}
- {"dt": "2025-03-25T10:56:57.610864", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-add-keys"}
- {"dt": "2025-03-25T10:56:57.610990", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-add-sources"}
- {"dt": "2025-03-25T10:56:57.611109", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-background-process-start"}
- {"dt": "2025-03-25T10:56:57.611226", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-background-process-stop"}
- {"dt": "2025-03-25T10:56:57.611344", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-common-functions"}
- {"dt": "2025-03-25T10:56:57.611457", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-echo-ipv4"}
- {"dt": "2025-03-25T10:56:57.611569", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-install-packages"}
- {"dt": "2025-03-25T10:56:57.611680", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-installed-packages"}
- {"dt": "2025-03-25T10:56:57.611790", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-os-build"}
- {"dt": "2025-03-25T10:56:57.611900", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-probe-channel"}
- {"dt": "2025-03-25T10:56:57.612009", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-probe-ip"}
- {"dt": "2025-03-25T10:56:57.612120", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-target-ip"}
- {"dt": "2025-03-25T10:56:57.612230", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-target-mac"}
- {"dt": "2025-03-25T10:56:57.612341", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-target-storage"}
- {"dt": "2025-03-25T10:56:57.612459", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-test-case"}
- {"dt": "2025-03-25T10:56:57.612571", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-test-event"}
- {"dt": "2025-03-25T10:56:57.612685", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-test-feedback"}
- {"dt": "2025-03-25T10:56:57.612797", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-test-raise"}
- {"dt": "2025-03-25T10:56:57.613019", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-test-reference"}
- {"dt": "2025-03-25T10:56:57.613212", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-test-runner"}
- {"dt": "2025-03-25T10:56:57.613461", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-test-set"}
- {"dt": "2025-03-25T10:56:57.613657", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-test-shell"}
- {"dt": "2025-03-25T10:56:57.613812", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-install-packages (oe)"}
- {"dt": "2025-03-25T10:56:57.614005", "lvl": "debug", "msg": "Updating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/bin/lava-installed-packages (oe)"}
- {"dt": "2025-03-25T10:56:57.614128", "lvl": "debug", "msg": "Creating /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/environment"}
- {"dt": "2025-03-25T10:56:57.614227", "lvl": "debug", "msg": "LAVA metadata"}
- {"dt": "2025-03-25T10:56:57.614286", "lvl": "debug", "msg": "- LAVA_JOB_ID=1"}
- {"dt": "2025-03-25T10:56:57.614333", "lvl": "debug", "msg": "- LAVA_DISPATCHER_IP=192.168.32.138"}
- {"dt": "2025-03-25T10:56:57.614419", "lvl": "debug", "msg": "start: 1.1.1 lava-vland-overlay (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:56:57.614467", "lvl": "debug", "msg": "skipped lava-vland-overlay"}
- {"dt": "2025-03-25T10:56:57.614522", "lvl": "debug", "msg": "end: 1.1.1 lava-vland-overlay (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:56:57.614580", "lvl": "debug", "msg": "start: 1.1.2 lava-multinode-overlay (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:56:57.614622", "lvl": "debug", "msg": "skipped lava-multinode-overlay"}
- {"dt": "2025-03-25T10:56:57.614671", "lvl": "debug", "msg": "end: 1.1.2 lava-multinode-overlay (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:56:57.614725", "lvl": "debug", "msg": "start: 1.1.3 test-definition (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:56:57.614774", "lvl": "info", "msg": "Loading test definitions"}
- {"dt": "2025-03-25T10:56:57.614833", "lvl": "debug", "msg": "start: 1.1.3.1 git-repo-action (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:56:57.614880", "lvl": "debug", "msg": "Using /lava-1 at stage 0"}
- {"dt": "2025-03-25T10:56:57.614951", "lvl": "info", "msg": "Fetching tests from https://github.com/roxell/test-definitions.git"}
- {"dt": "2025-03-25T10:56:57.615013", "lvl": "debug", "msg": "Running '/usr/bin/git clone -b test-rt-tests-add-iterations --depth=1 https://github.com/roxell/test-definitions.git /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/0/tests/0_rt-tests-pmqtest'"}
- {"dt": "2025-03-25T10:57:07.407660", "lvl": "debug", "msg": "Tests stored (tmp) in /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/0/tests/0_rt-tests-pmqtest/automated/linux/pmqtest/pmqtest.yaml"}
- {"dt": "2025-03-25T10:57:07.408131", "lvl": "debug", "msg": "uuid=1_1.1.3.1 testdef=None"}
- {"dt": "2025-03-25T10:57:07.408251", "lvl": "debug", "msg": "end: 1.1.3.1 git-repo-action (duration 00:00:10) [common]"}
- {"dt": "2025-03-25T10:57:07.408339", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "git-repo-action", "level": "1.1.3.1", "duration": "9.79", "result": "pass", "extra": {"commit": "de2bf15049f1ff53c926defa0e75f675813e9c22", "repository": "https://github.com/roxell/test-definitions.git", "path": "automated/linux/pmqtest/pmqtest.yaml"}}}
- {"dt": "2025-03-25T10:57:07.408507", "lvl": "debug", "msg": "start: 1.1.3.2 test-overlay (timeout 00:14:50) [common]"}
- {"dt": "2025-03-25T10:57:07.409265", "lvl": "debug", "msg": "end: 1.1.3.2 test-overlay (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:07.409319", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "test-overlay", "level": "1.1.3.2", "duration": "0.00", "result": "pass", "extra": {"uuid": "1_1.1.3.1", "name": "rt-tests-pmqtest", "path": "automated/linux/pmqtest/pmqtest.yaml", "from": "git", "repository": "https://github.com/roxell/test-definitions.git"}}}
- {"dt": "2025-03-25T10:57:07.409437", "lvl": "debug", "msg": "start: 1.1.3.3 test-install-overlay (timeout 00:14:50) [common]"}
- {"dt": "2025-03-25T10:57:07.410266", "lvl": "debug", "msg": "end: 1.1.3.3 test-install-overlay (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:07.410323", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "test-install-overlay", "level": "1.1.3.3", "duration": "0.00", "result": "pass", "extra": {"uuid": "1_1.1.3.1", "name": "rt-tests-pmqtest", "path": "automated/linux/pmqtest/pmqtest.yaml", "from": "git", "repository": "https://github.com/roxell/test-definitions.git", "skipped test-install-overlay": "1_1.1.3.1"}}}
- {"dt": "2025-03-25T10:57:07.410442", "lvl": "debug", "msg": "start: 1.1.3.4 test-runscript-overlay (timeout 00:14:50) [common]"}
- {"dt": "2025-03-25T10:57:07.418663", "lvl": "debug", "msg": "runner path: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/0/tests/0_rt-tests-pmqtest test_uuid 1_1.1.3.1"}
- {"dt": "2025-03-25T10:57:07.418743", "lvl": "debug", "msg": "DURATION='1m'"}
- {"dt": "2025-03-25T10:57:07.418801", "lvl": "debug", "msg": "BACKGROUND_CMD=''"}
- {"dt": "2025-03-25T10:57:07.418853", "lvl": "debug", "msg": "ITERATIONS='2'"}
- {"dt": "2025-03-25T10:57:07.419025", "lvl": "debug", "msg": "end: 1.1.3.4 test-runscript-overlay (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:07.419096", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "test-runscript-overlay", "level": "1.1.3.4", "duration": "0.01", "result": "pass", "extra": {"uuid": "1_1.1.3.1", "name": "rt-tests-pmqtest", "path": "automated/linux/pmqtest/pmqtest.yaml", "from": "git", "repository": "https://github.com/roxell/test-definitions.git", "filename": "/var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/0/tests/0_rt-tests-pmqtest/run.sh"}}}
- {"dt": "2025-03-25T10:57:07.419219", "lvl": "info", "msg": "Creating lava-test-runner.conf files"}
- {"dt": "2025-03-25T10:57:07.419269", "lvl": "debug", "msg": "Using lava-test-runner path: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/lava-overlay-w4zfg0wz/lava-1/0 for stage 0"}
- {"dt": "2025-03-25T10:57:07.419364", "lvl": "debug", "msg": "- 0_rt-tests-pmqtest"}
- {"dt": "2025-03-25T10:57:07.419463", "lvl": "debug", "msg": "end: 1.1.3 test-definition (duration 00:00:10) [common]"}
- {"dt": "2025-03-25T10:57:07.419540", "lvl": "debug", "msg": "start: 1.1.4 compress-overlay (timeout 00:14:50) [common]"}
- {"dt": "2025-03-25T10:57:13.437915", "lvl": "debug", "msg": "end: 1.1.4 compress-overlay (duration 00:00:06) [common]"}
- {"dt": "2025-03-25T10:57:13.438046", "lvl": "debug", "msg": "end: 1.1 lava-overlay (duration 00:00:16) [common]"}
- {"dt": "2025-03-25T10:57:13.438109", "lvl": "debug", "msg": "start: 1.2 apply-overlay-guest (timeout 00:14:44) [common]"}
- {"dt": "2025-03-25T10:57:13.438156", "lvl": "debug", "msg": "Overlay already applied"}
- {"dt": "2025-03-25T10:57:13.438204", "lvl": "debug", "msg": "end: 1.2 apply-overlay-guest (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:13.438268", "lvl": "debug", "msg": "start: 1.3 deploy-device-env (timeout 00:14:44) [common]"}
- {"dt": "2025-03-25T10:57:13.438315", "lvl": "debug", "msg": "end: 1.3 deploy-device-env (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:13.438364", "lvl": "debug", "msg": "start: 1.4 download-retry (timeout 00:14:44) [common]"}
- {"dt": "2025-03-25T10:57:13.438414", "lvl": "debug", "msg": "start: 1.4.1 http-download (timeout 00:05:00) [common]"}
- {"dt": "2025-03-25T10:57:13.438588", "lvl": "info", "msg": "downloading https://storage.tuxsuite.com/public/linaro/anders/builds/2tmCo2a0FpKFsv4rCtTeLbgkG9C/Image.gz"}
- {"dt": "2025-03-25T10:57:13.438641", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/kernel/Image"}
- {"dt": "2025-03-25T10:57:13.438680", "lvl": "debug", "msg": "total size: 13963222 (13\u202FMB)"}
- {"dt": "2025-03-25T10:57:13.438720", "lvl": "info", "msg": "Using gunzip to decompress gz"}
- {"dt": "2025-03-25T10:57:14.103879", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2025-03-25T10:57:14.424653", "lvl": "debug", "msg": "progress   5\u202F% (0\u202FMB)"}
- {"dt": "2025-03-25T10:57:14.536707", "lvl": "debug", "msg": "progress  10\u202F% (1\u202FMB)"}
- {"dt": "2025-03-25T10:57:14.638188", "lvl": "debug", "msg": "progress  16\u202F% (2\u202FMB)"}
- {"dt": "2025-03-25T10:57:14.740488", "lvl": "debug", "msg": "progress  24\u202F% (3\u202FMB)"}
- {"dt": "2025-03-25T10:57:14.951026", "lvl": "debug", "msg": "progress  29\u202F% (3\u202FMB)"}
- {"dt": "2025-03-25T10:57:15.080928", "lvl": "debug", "msg": "progress  48\u202F% (6\u202FMB)"}
- {"dt": "2025-03-25T10:57:15.181629", "lvl": "debug", "msg": "progress  59\u202F% (7\u202FMB)"}
- {"dt": "2025-03-25T10:57:15.414905", "lvl": "debug", "msg": "progress  64\u202F% (8\u202FMB)"}
- {"dt": "2025-03-25T10:57:15.516585", "lvl": "debug", "msg": "progress  79\u202F% (10\u202FMB)"}
- {"dt": "2025-03-25T10:57:15.713514", "lvl": "debug", "msg": "progress  93\u202F% (12\u202FMB)"}
- {"dt": "2025-03-25T10:57:15.776768", "lvl": "info", "msg": "13\u202FMB downloaded in 2.34\u202Fs (5.70\u202FMB/s)"}
- {"dt": "2025-03-25T10:57:15.776926", "lvl": "debug", "msg": "end: 1.4.1 http-download (duration 00:00:02) [common]"}
- {"dt": "2025-03-25T10:57:15.776986", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "http-download", "level": "1.4.1", "duration": "2.34", "result": "pass", "extra": {"label": "kernel", "size": ! "13963222", "sha256sum": "6a338800fd4d442201a2911a6d755165a0daaa8d85e1984c1d442be9e4cea894"}}}
- {"dt": "2025-03-25T10:57:15.777095", "lvl": "debug", "msg": "end: 1.4 download-retry (duration 00:00:02) [common]"}
- {"dt": "2025-03-25T10:57:15.777155", "lvl": "debug", "msg": "start: 1.5 download-retry (timeout 00:14:42) [common]"}
- {"dt": "2025-03-25T10:57:15.777215", "lvl": "debug", "msg": "start: 1.5.1 file-download (timeout 00:05:00) [common]"}
- {"dt": "2025-03-25T10:57:15.777395", "lvl": "info", "msg": "downloading file:///home/anders/.cache/tuxrun/assets/https___storage.tuxboot.com_debian_trixie_arm64_rootfs.ext4.xz"}
- {"dt": "2025-03-25T10:57:15.777450", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs/https___storage.tuxboot.com_debian_trixie_arm64_rootfs.ext4"}
- {"dt": "2025-03-25T10:57:15.777492", "lvl": "debug", "msg": "total size: 111407012 (106\u202FMB)"}
- {"dt": "2025-03-25T10:57:15.777533", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2025-03-25T10:57:15.877600", "lvl": "debug", "msg": "progress   2\u202F% (2\u202FMB)"}
- {"dt": "2025-03-25T10:57:16.038883", "lvl": "debug", "msg": "progress   7\u202F% (7\u202FMB)"}
- {"dt": "2025-03-25T10:57:16.209166", "lvl": "debug", "msg": "progress  12\u202F% (12\u202FMB)"}
- {"dt": "2025-03-25T10:57:16.369164", "lvl": "debug", "msg": "progress  17\u202F% (18\u202FMB)"}
- {"dt": "2025-03-25T10:57:16.529068", "lvl": "debug", "msg": "progress  22\u202F% (23\u202FMB)"}
- {"dt": "2025-03-25T10:57:16.702009", "lvl": "debug", "msg": "progress  27\u202F% (28\u202FMB)"}
- {"dt": "2025-03-25T10:57:16.837499", "lvl": "debug", "msg": "progress  32\u202F% (34\u202FMB)"}
- {"dt": "2025-03-25T10:57:16.993727", "lvl": "debug", "msg": "progress  37\u202F% (39\u202FMB)"}
- {"dt": "2025-03-25T10:57:17.160911", "lvl": "debug", "msg": "progress  42\u202F% (44\u202FMB)"}
- {"dt": "2025-03-25T10:57:17.322274", "lvl": "debug", "msg": "progress  47\u202F% (49\u202FMB)"}
- {"dt": "2025-03-25T10:57:17.487000", "lvl": "debug", "msg": "progress  52\u202F% (55\u202FMB)"}
- {"dt": "2025-03-25T10:57:17.657056", "lvl": "debug", "msg": "progress  57\u202F% (60\u202FMB)"}
- {"dt": "2025-03-25T10:57:17.841956", "lvl": "debug", "msg": "progress  62\u202F% (65\u202FMB)"}
- {"dt": "2025-03-25T10:57:18.004569", "lvl": "debug", "msg": "progress  67\u202F% (71\u202FMB)"}
- {"dt": "2025-03-25T10:57:18.151433", "lvl": "debug", "msg": "progress  72\u202F% (76\u202FMB)"}
- {"dt": "2025-03-25T10:57:18.312769", "lvl": "debug", "msg": "progress  77\u202F% (81\u202FMB)"}
- {"dt": "2025-03-25T10:57:18.476222", "lvl": "debug", "msg": "progress  82\u202F% (87\u202FMB)"}
- {"dt": "2025-03-25T10:57:18.640675", "lvl": "debug", "msg": "progress  87\u202F% (92\u202FMB)"}
- {"dt": "2025-03-25T10:57:18.741094", "lvl": "debug", "msg": "progress  92\u202F% (97\u202FMB)"}
- {"dt": "2025-03-25T10:57:18.860111", "lvl": "debug", "msg": "progress  97\u202F% (103\u202FMB)"}
- {"dt": "2025-03-25T10:57:22.124863", "lvl": "info", "msg": "106\u202FMB downloaded in 6.35\u202Fs (16.74\u202FMB/s)"}
- {"dt": "2025-03-25T10:57:22.125105", "lvl": "debug", "msg": "end: 1.5.1 file-download (duration 00:00:06) [common]"}
- {"dt": "2025-03-25T10:57:22.125187", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "file-download", "level": "1.5.1", "duration": "6.35", "result": "pass", "extra": {"label": "rootfs", "size": ! "111407012", "sha256sum": "71bcc7bc8dbd4ac7d02d52aed8886662999d6e6c790f9b9e5220beaf580ccfc1"}}}
- {"dt": "2025-03-25T10:57:22.125340", "lvl": "debug", "msg": "start: 1.5.2 download-retry (timeout 00:05:00) [common]"}
- {"dt": "2025-03-25T10:57:22.125425", "lvl": "debug", "msg": "start: 1.5.2.1 http-download (timeout 00:01:40) [common]"}
- {"dt": "2025-03-25T10:57:22.125665", "lvl": "info", "msg": "downloading https://storage.tuxsuite.com/public/linaro/anders/builds/2tmCo2a0FpKFsv4rCtTeLbgkG9C/modules.tar.xz"}
- {"dt": "2025-03-25T10:57:22.125733", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs.modules/modules.tar"}
- {"dt": "2025-03-25T10:57:22.125788", "lvl": "debug", "msg": "total size: 11573004 (11\u202FMB)"}
- {"dt": "2025-03-25T10:57:22.125831", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2025-03-25T10:57:22.721910", "lvl": "debug", "msg": "progress   0\u202F% (0\u202FMB)"}
- {"dt": "2025-03-25T10:57:23.018290", "lvl": "debug", "msg": "progress   5\u202F% (0\u202FMB)"}
- {"dt": "2025-03-25T10:57:23.133383", "lvl": "debug", "msg": "progress  10\u202F% (1\u202FMB)"}
- {"dt": "2025-03-25T10:57:23.234429", "lvl": "debug", "msg": "progress  17\u202F% (1\u202FMB)"}
- {"dt": "2025-03-25T10:57:23.334487", "lvl": "debug", "msg": "progress  26\u202F% (2\u202FMB)"}
- {"dt": "2025-03-25T10:57:23.612017", "lvl": "debug", "msg": "progress  31\u202F% (3\u202FMB)"}
- {"dt": "2025-03-25T10:57:23.714314", "lvl": "debug", "msg": "progress  51\u202F% (5\u202FMB)"}
- {"dt": "2025-03-25T10:57:23.814757", "lvl": "debug", "msg": "progress  66\u202F% (7\u202FMB)"}
- {"dt": "2025-03-25T10:57:23.993076", "lvl": "debug", "msg": "progress  71\u202F% (7\u202FMB)"}
- {"dt": "2025-03-25T10:57:24.140739", "lvl": "debug", "msg": "progress  76\u202F% (8\u202FMB)"}
- {"dt": "2025-03-25T10:57:24.222089", "lvl": "info", "msg": "11\u202FMB downloaded in 2.10\u202Fs (5.26\u202FMB/s)"}
- {"dt": "2025-03-25T10:57:24.222297", "lvl": "debug", "msg": "end: 1.5.2.1 http-download (duration 00:00:02) [common]"}
- {"dt": "2025-03-25T10:57:24.222354", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "http-download", "level": "1.5.2.1", "duration": "2.10", "result": "pass", "extra": {"label": "rootfs.modules", "size": ! "11573004", "sha256sum": "61d4d6ad2fe66b3500d797a98a5b6a4faec7d44c6740e3084ceeac06cc5b6805"}}}
- {"dt": "2025-03-25T10:57:24.222457", "lvl": "debug", "msg": "end: 1.5.2 download-retry (duration 00:00:02) [common]"}
- {"dt": "2025-03-25T10:57:24.222516", "lvl": "debug", "msg": "start: 1.5.3 download-retry (timeout 00:05:00) [common]"}
- {"dt": "2025-03-25T10:57:24.222571", "lvl": "debug", "msg": "start: 1.5.3.1 http-download (timeout 00:01:40) [common]"}
- {"dt": "2025-03-25T10:57:24.222753", "lvl": "info", "msg": "downloading https://storage.tuxboot.com/overlays/debian/trixie/arm64/rt-tests/rt-2.8.y/rt-tests.tar.xz"}
- {"dt": "2025-03-25T10:57:24.222806", "lvl": "debug", "msg": "saving as /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs.overlay-00/rt-tests.tar"}
- {"dt": "2025-03-25T10:57:24.222846", "lvl": "debug", "msg": "total size: 339980 (0\u202FMB)"}
- {"dt": "2025-03-25T10:57:24.222885", "lvl": "info", "msg": "Using unxz to decompress xz"}
- {"dt": "2025-03-25T10:57:25.142622", "lvl": "debug", "msg": "progress   9\u202F% (0\u202FMB)"}
- {"dt": "2025-03-25T10:57:25.325315", "lvl": "debug", "msg": "progress  48\u202F% (0\u202FMB)"}
- {"dt": "2025-03-25T10:57:25.376921", "lvl": "info", "msg": "0\u202FMB downloaded in 1.15\u202Fs (0.28\u202FMB/s)"}
- {"dt": "2025-03-25T10:57:25.377041", "lvl": "debug", "msg": "end: 1.5.3.1 http-download (duration 00:00:01) [common]"}
- {"dt": "2025-03-25T10:57:25.377103", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "http-download", "level": "1.5.3.1", "duration": "1.15", "result": "pass", "extra": {"label": "rootfs.overlay-00", "size": ! "339980", "sha256sum": "683eeaa88fa7f35780743a8928084dac31c643b23c9a6a6187cc01084074acda"}}}
- {"dt": "2025-03-25T10:57:25.377229", "lvl": "debug", "msg": "end: 1.5.3 download-retry (duration 00:00:01) [common]"}
- {"dt": "2025-03-25T10:57:25.377309", "lvl": "debug", "msg": "start: 1.5.4 append-overlays (timeout 00:05:00) [common]"}
- {"dt": "2025-03-25T10:57:25.377376", "lvl": "info", "msg": "Modifying '/var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs/https___storage.tuxboot.com_debian_trixie_arm64_rootfs.ext4'"}
- {"dt": "2025-03-25T10:57:26.940097", "lvl": "debug", "msg": "Overlays:"}
- {"dt": "2025-03-25T10:57:26.940917", "lvl": "debug", "msg": "- rootfs.lava: '/var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/compress-overlay-64w__fwy/overlay-1.1.4.tar.gz' to '/'"}
- {"dt": "2025-03-25T10:57:27.437147", "lvl": "debug", "msg": "- rootfs.modules: '/var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs.modules/modules.tar' to '/usr/'"}
- {"dt": "2025-03-25T10:57:27.627201", "lvl": "debug", "msg": "- rootfs.overlay-00: '/var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs.overlay-00/rt-tests.tar' to '/'"}
- {"dt": "2025-03-25T10:57:27.848652", "lvl": "debug", "msg": "end: 1.5.4 append-overlays (duration 00:00:02) [common]"}
- {"dt": "2025-03-25T10:57:27.849051", "lvl": "debug", "msg": "end: 1.5 download-retry (duration 00:00:12) [common]"}
- {"dt": "2025-03-25T10:57:27.849166", "lvl": "info", "msg": "end: 1 deployimages (duration 00:00:30) [common]"}
- {"dt": "2025-03-25T10:57:27.849294", "lvl": "info", "msg": "start: 2 boot-image-retry (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:57:27.849407", "lvl": "debug", "msg": "start: 2.1 boot-qemu-image (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:57:27.849497", "lvl": "debug", "msg": "start: 2.1.1 execute-qemu (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:57:27.849849", "lvl": "info", "msg": "Boot command: /usr/bin/qemu-system-aarch64 -cpu max,pauth-impdef=on -machine virt,virtualization=on,gic-version=3,mte=on -nographic -nic none -m 4G -monitor none -no-reboot -smp 2 -kernel /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/kernel/Image -append \"console=ttyAMA0,115200 rootwait root=/dev/vda debug verbose console_msg_format=syslog systemd.log_level=warning rw earlycon\" -drive file=/var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs/https___storage.tuxboot.com_debian_trixie_arm64_rootfs.ext4,format=raw,id=hd0,if=virtio"}
- {"dt": "2025-03-25T10:57:27.853059", "lvl": "debug", "msg": "started a shell command"}
- {"dt": "2025-03-25T10:57:27.853469", "lvl": "debug", "msg": "end: 2.1.1 execute-qemu (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:27.853563", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "execute-qemu", "level": "2.1.1", "duration": "0.00", "result": "pass", "extra": {"qemu_version": "1:9.2.0+ds-2", "host_arch": "amd64", "job_arch": "arm64"}}}
- {"dt": "2025-03-25T10:57:27.853740", "lvl": "debug", "msg": "end: 2.1 boot-qemu-image (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:27.853846", "lvl": "debug", "msg": "start: 2.2 auto-login-action (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:57:27.853920", "lvl": "debug", "msg": "Setting prompt string to ['Linux version [0-9]']"}
- {"dt": "2025-03-25T10:57:27.853974", "lvl": "debug", "msg": "auto-login-action: Wait for prompt ['Linux version [0-9]'] (timeout 00:15:00)"}
- {"dt": "2025-03-25T10:57:28.156158", "lvl": "target", "msg": "<6>[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x000f0510]"}
- {"dt": "2025-03-25T10:57:28.156563", "lvl": "debug", "msg": "start: 2.2.1 login-action (timeout 00:15:00) [common]"}
- {"dt": "2025-03-25T10:57:28.156661", "lvl": "debug", "msg": "Setting prompt string to []"}
- {"dt": "2025-03-25T10:57:28.156753", "lvl": "debug", "msg": "Setting prompt string to ['-\\\\[ cut here \\\\]', 'Unhandled fault', 'BUG: KCSAN:', 'BUG: KASAN:', 'BUG: KFENCE:', 'Oops(?: -|:)', 'WARNING:', '(kernel BUG at|BUG:)', 'invalid opcode:', 'Kernel panic - not syncing']"}
- {"dt": "2025-03-25T10:57:28.156837", "lvl": "debug", "msg": "Using line separator: #'\\n'#"}
- {"dt": "2025-03-25T10:57:28.156896", "lvl": "info", "msg": "Waiting for the login prompt"}
- {"dt": "2025-03-25T10:57:28.156954", "lvl": "info", "msg": "Parsing kernel messages"}
- {"dt": "2025-03-25T10:57:28.157004", "lvl": "debug", "msg": ["-\\[ cut here \\]", "Unhandled fault", "BUG: KCSAN:", "BUG: KASAN:", "BUG: KFENCE:", "Oops(?: -|:)", "WARNING:", "(kernel BUG at|BUG:)", "invalid opcode:", "Kernel panic - not syncing", "root@(.*):[/~]#", "login:", "Login incorrect"]}
- {"dt": "2025-03-25T10:57:28.157108", "lvl": "debug", "msg": "[login-action] Waiting for messages, (timeout 00:15:00)"}
- {"dt": "2025-03-25T10:57:28.157171", "lvl": "debug", "msg": "Waiting using forced prompt support (timeout 00:07:30)"}
- {"dt": "2025-03-25T10:57:28.157628", "lvl": "target", "msg": "<5>[    0.000000] Linux version 6.12.17-rc2 (tuxmake@tuxmake) (aarch64-linux-gnu-gcc (Debian 13.3.0-12) 13.3.0, GNU ld (GNU Binutils for Debian) 2.44) #1 SMP PREEMPT_RT @1740949090"}
- {"dt": "2025-03-25T10:57:28.157680", "lvl": "target", "msg": "<6>[    0.000000] KASLR enabled"}
- {"dt": "2025-03-25T10:57:28.157722", "lvl": "target", "msg": "<5>[    0.000000] random: crng init done"}
- {"dt": "2025-03-25T10:57:28.157769", "lvl": "target", "msg": "<6>[    0.000000] Machine model: linux,dummy-virt"}
- {"dt": "2025-03-25T10:57:28.157807", "lvl": "target", "msg": "<6>[    0.000000] efi: UEFI not found."}
- {"dt": "2025-03-25T10:57:28.157843", "lvl": "target", "msg": "<6>[    0.000000] earlycon: pl11 at MMIO 0x0000000009000000 (options '')"}
- {"dt": "2025-03-25T10:57:28.157877", "lvl": "target", "msg": "<6>[    0.000000] printk: legacy bootconsole [pl11] enabled"}
- {"dt": "2025-03-25T10:57:28.157910", "lvl": "target", "msg": "<6>[    0.000000] OF: reserved mem: Reserved memory: No reserved-memory node in the DT"}
- {"dt": "2025-03-25T10:57:28.157943", "lvl": "target", "msg": "<6>[    0.000000] NUMA: Faking a node at [mem 0x0000000040000000-0x000000013fffffff]"}
- {"dt": "2025-03-25T10:57:28.157975", "lvl": "target", "msg": "<6>[    0.000000] NODE_DATA(0) allocated [mem 0x13f7f92c0-0x13f7fb97f]"}
- {"dt": "2025-03-25T10:57:28.158009", "lvl": "target", "msg": "<6>[    0.000000] Zone ranges:"}
- {"dt": "2025-03-25T10:57:28.158041", "lvl": "target", "msg": "<6>[    0.000000]   DMA      [mem 0x0000000040000000-0x00000000ffffffff]"}
- {"dt": "2025-03-25T10:57:28.158089", "lvl": "target", "msg": "<6>[    0.000000]   DMA32    empty"}
- {"dt": "2025-03-25T10:57:28.158126", "lvl": "target", "msg": "<6>[    0.000000]   Normal   [mem 0x0000000100000000-0x000000013fffffff]"}
- {"dt": "2025-03-25T10:57:28.158160", "lvl": "target", "msg": "<6>[    0.000000] Movable zone start for each node"}
- {"dt": "2025-03-25T10:57:28.158192", "lvl": "target", "msg": "<6>[    0.000000] Early memory node ranges"}
- {"dt": "2025-03-25T10:57:28.158237", "lvl": "target", "msg": "<6>[    0.000000]   node   0: [mem 0x0000000040000000-0x000000013fffffff]"}
- {"dt": "2025-03-25T10:57:28.158430", "lvl": "target", "msg": "<6>[    0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x000000013fffffff]"}
- {"dt": "2025-03-25T10:57:28.158590", "lvl": "target", "msg": "<6>[    0.000000] cma: Reserved 32 MiB at 0x00000000fe000000 on node -1"}
- {"dt": "2025-03-25T10:57:28.158733", "lvl": "target", "msg": "<6>[    0.000000] psci: probing for conduit method from DT."}
- {"dt": "2025-03-25T10:57:28.159033", "lvl": "target", "msg": "<6>[    0.000000] psci: PSCIv1.1 detected in firmware."}
- {"dt": "2025-03-25T10:57:28.159187", "lvl": "target", "msg": "<6>[    0.000000] psci: Using standard PSCI v0.2 function IDs"}
- {"dt": "2025-03-25T10:57:28.159330", "lvl": "target", "msg": "<6>[    0.000000] psci: Trusted OS migration not required"}
- {"dt": "2025-03-25T10:57:28.159459", "lvl": "target", "msg": "<6>[    0.000000] psci: SMC Calling Convention v1.0"}
- {"dt": "2025-03-25T10:57:28.159658", "lvl": "target", "msg": "<6>[    0.000000] percpu: Embedded 25 pages/cpu s62256 r8192 d31952 u102400"}
- {"dt": "2025-03-25T10:57:28.159843", "lvl": "target", "msg": "<7>[    0.000000] pcpu-alloc: s62256 r8192 d31952 u102400 alloc=25*4096"}
- {"dt": "2025-03-25T10:57:28.159962", "lvl": "target", "msg": "<7>[    0.000000] pcpu-alloc: [0] 0 [0] 1 "}
- {"dt": "2025-03-25T10:57:28.160089", "lvl": "target", "msg": "<6>[    0.000000] Detected PIPT I-cache on CPU0"}
- {"dt": "2025-03-25T10:57:28.160294", "lvl": "target", "msg": "<6>[    0.000000] CPU features: detected: Address authentication (IMP DEF algorithm)"}
- {"dt": "2025-03-25T10:57:28.160483", "lvl": "target", "msg": "<6>[    0.000000] CPU features: detected: GIC system register CPU interface"}
- {"dt": "2025-03-25T10:57:28.160620", "lvl": "target", "msg": "<6>[    0.000000] CPU features: detected: HCRX_EL2 register"}
- {"dt": "2025-03-25T10:57:28.160820", "lvl": "target", "msg": "<6>[    0.000000] CPU features: detected: 52-bit Virtual Addressing (LPA2)"}
- {"dt": "2025-03-25T10:57:28.160997", "lvl": "target", "msg": "<6>[    0.000000] CPU features: detected: Virtualization Host Extensions"}
- {"dt": "2025-03-25T10:57:28.161154", "lvl": "target", "msg": "<6>[    0.000000] CPU features: detected: Memory Tagging Extension"}
- {"dt": "2025-03-25T10:57:28.161322", "lvl": "target", "msg": "<6>[    0.000000] CPU features: detected: Asymmetric MTE Tag Check Fault"}
- {"dt": "2025-03-25T10:57:28.161446", "lvl": "target", "msg": "<6>[    0.000000] CPU features: detected: Spectre-v4"}
- {"dt": "2025-03-25T10:57:28.161593", "lvl": "target", "msg": "<6>[    0.000000] alternatives: applying boot alternatives"}
- {"dt": "2025-03-25T10:57:28.162021", "lvl": "target", "msg": "<5>[    0.000000] Kernel command line: console=ttyAMA0,115200 rootwait root=/dev/vda debug verbose console_msg_format=syslog systemd.log_level=warning rw earlycon"}
- {"dt": "2025-03-25T10:57:28.162280", "lvl": "target", "msg": "<5>[    0.000000] Unknown kernel command line parameters \"verbose\", will be passed to user space."}
- {"dt": "2025-03-25T10:57:28.162499", "lvl": "target", "msg": "<6>[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.162722", "lvl": "target", "msg": "<6>[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.162842", "lvl": "target", "msg": "<6>[    0.000000] Fallback order for Node 0: 0 "}
- {"dt": "2025-03-25T10:57:28.163154", "lvl": "target", "msg": "<6>[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 1048576"}
- {"dt": "2025-03-25T10:57:28.163228", "lvl": "target", "msg": "<6>[    0.000000] Policy zone: Normal"}
- {"dt": "2025-03-25T10:57:28.163431", "lvl": "target", "msg": "<6>[    0.000000] mem auto-init: stack:all(zero), heap alloc:off, heap free:off"}
- {"dt": "2025-03-25T10:57:28.163550", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: area num 2."}
- {"dt": "2025-03-25T10:57:28.163755", "lvl": "target", "msg": "<6>[    0.000000] software IO TLB: mapped [mem 0x00000000fa000000-0x00000000fe000000] (64MB)"}
- {"dt": "2025-03-25T10:57:28.163943", "lvl": "target", "msg": "<6>[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1"}
- {"dt": "2025-03-25T10:57:28.164089", "lvl": "target", "msg": "<6>[    0.000000] rcu: Preemptible hierarchical RCU implementation."}
- {"dt": "2025-03-25T10:57:28.164208", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU event tracing is enabled."}
- {"dt": "2025-03-25T10:57:28.164394", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=2."}
- {"dt": "2025-03-25T10:57:28.164586", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU priority boosting: priority 1 delay 500 ms."}
- {"dt": "2025-03-25T10:57:28.164768", "lvl": "target", "msg": "<6>[    0.000000] rcu: \tRCU_SOFTIRQ processing moved to rcuc kthreads."}
- {"dt": "2025-03-25T10:57:28.164948", "lvl": "target", "msg": "<6>[    0.000000] \tNo expedited grace period (rcu_normal_after_boot)."}
- {"dt": "2025-03-25T10:57:28.165089", "lvl": "target", "msg": "<6>[    0.000000] \tTrampoline variant of Tasks RCU enabled."}
- {"dt": "2025-03-25T10:57:28.165214", "lvl": "target", "msg": "<6>[    0.000000] \tTracing variant of Tasks RCU enabled."}
- {"dt": "2025-03-25T10:57:28.165430", "lvl": "target", "msg": "<6>[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies."}
- {"dt": "2025-03-25T10:57:28.165627", "lvl": "target", "msg": "<6>[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2"}
- {"dt": "2025-03-25T10:57:28.165970", "lvl": "target", "msg": "<6>[    0.000000] RCU Tasks: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2."}
- {"dt": "2025-03-25T10:57:28.166154", "lvl": "target", "msg": "<6>[    0.000000] RCU Tasks Trace: Setting shift to 1 and lim to 1 rcu_task_cb_adjust=1 rcu_task_cpu_ids=2."}
- {"dt": "2025-03-25T10:57:28.166310", "lvl": "target", "msg": "<6>[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0"}
- {"dt": "2025-03-25T10:57:28.166469", "lvl": "target", "msg": "<6>[    0.000000] GICv3: GIC: Using split EOI/Deactivate mode"}
- {"dt": "2025-03-25T10:57:28.166594", "lvl": "target", "msg": "<6>[    0.000000] GICv3: 256 SPIs implemented"}
- {"dt": "2025-03-25T10:57:28.166735", "lvl": "target", "msg": "<6>[    0.000000] GICv3: 0 Extended SPIs implemented"}
- {"dt": "2025-03-25T10:57:28.166869", "lvl": "target", "msg": "<6>[    0.000000] Root IRQ handler: gic_handle_irq"}
- {"dt": "2025-03-25T10:57:28.166992", "lvl": "target", "msg": "<6>[    0.000000] GICv3: GICv3 features: 16 PPIs"}
- {"dt": "2025-03-25T10:57:28.167243", "lvl": "target", "msg": "<6>[    0.000000] GICv3: GICD_CTRL.DS=1, SCR_EL3.FIQ=0"}
- {"dt": "2025-03-25T10:57:28.167401", "lvl": "target", "msg": "<6>[    0.000000] GICv3: CPU0: found redistributor 0 region 0:0x00000000080a0000"}
- {"dt": "2025-03-25T10:57:28.167530", "lvl": "target", "msg": "<6>[    0.000000] ITS [mem 0x08080000-0x0809ffff]"}
- {"dt": "2025-03-25T10:57:28.167800", "lvl": "target", "msg": "<6>[    0.000000] ITS@0x0000000008080000: allocated 8192 Devices @100050000 (indirect, esz 8, psz 64K, shr 1)"}
- {"dt": "2025-03-25T10:57:28.168098", "lvl": "target", "msg": "<6>[    0.000000] ITS@0x0000000008080000: allocated 8192 Interrupt Collections @100060000 (flat, esz 8, psz 64K, shr 1)"}
- {"dt": "2025-03-25T10:57:28.168266", "lvl": "target", "msg": "<6>[    0.000000] GICv3: using LPI property table @0x0000000100070000"}
- {"dt": "2025-03-25T10:57:28.168469", "lvl": "target", "msg": "<6>[    0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000100080000"}
- {"dt": "2025-03-25T10:57:28.168681", "lvl": "target", "msg": "<6>[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention."}
- {"dt": "2025-03-25T10:57:28.168876", "lvl": "target", "msg": "<6>[    0.000000] arch_timer: cp15 timer(s) running at 1000.00MHz (phys)."}
- {"dt": "2025-03-25T10:57:28.169219", "lvl": "target", "msg": "<6>[    0.000000] clocksource: arch_sys_counter: mask: 0x1fffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns"}
- {"dt": "2025-03-25T10:57:28.169467", "lvl": "target", "msg": "<6>[    0.000051] sched_clock: 61 bits at 1000MHz, resolution 1ns, wraps every 4398046511103ns"}
- {"dt": "2025-03-25T10:57:28.169606", "lvl": "target", "msg": "<6>[    0.011079] Console: colour dummy device 80x25"}
- {"dt": "2025-03-25T10:57:28.169971", "lvl": "target", "msg": "<6>[    0.015059] Calibrating delay loop (skipped), value calculated using timer frequency.. 2000.00 BogoMIPS (lpj=4000000)"}
- {"dt": "2025-03-25T10:57:28.170070", "lvl": "target", "msg": "<6>[    0.015634] pid_max: default: 32768 minimum: 301"}
- {"dt": "2025-03-25T10:57:28.170218", "lvl": "target", "msg": "<6>[    0.017463] LSM: initializing lsm=capability"}
- {"dt": "2025-03-25T10:57:28.170425", "lvl": "target", "msg": "<6>[    0.020758] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.170639", "lvl": "target", "msg": "<6>[    0.020837] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.171020", "lvl": "target", "msg": "<4>[    0.044702] cacheinfo: Unable to detect cache hierarchy for CPU 0"}
- {"dt": "2025-03-25T10:57:28.171064", "lvl": "target", "msg": "<6>[    0.056857] rcu: Hierarchical SRCU implementation."}
- {"dt": "2025-03-25T10:57:28.171310", "lvl": "target", "msg": "<6>[    0.056887] rcu: \tMax phase no-delay instances is 1000."}
- {"dt": "2025-03-25T10:57:28.179330", "lvl": "target", "msg": "<6>[    0.080315] Timer migration: 1 hierarchy levels; 8 children per group; 1 crossnode level"}
- {"dt": "2025-03-25T10:57:28.184710", "lvl": "target", "msg": "<6>[    0.084169] fsl-mc MSI: its@8080000 domain created"}
- {"dt": "2025-03-25T10:57:28.184774", "lvl": "target", "msg": "<6>[    0.086171] EFI services will not be available."}
- {"dt": "2025-03-25T10:57:28.188416", "lvl": "target", "msg": "<6>[    0.088122] smp: Bringing up secondary CPUs ..."}
- {"dt": "2025-03-25T10:57:28.204509", "lvl": "target", "msg": "<6>[    0.102188] Detected PIPT I-cache on CPU1"}
- {"dt": "2025-03-25T10:57:28.204717", "lvl": "target", "msg": "<6>[    0.103482] GICv3: CPU1: found redistributor 1 region 0:0x00000000080c0000"}
- {"dt": "2025-03-25T10:57:28.204893", "lvl": "target", "msg": "<6>[    0.104192] GICv3: CPU1: using allocated LPI pending table @0x0000000100090000"}
- {"dt": "2025-03-25T10:57:28.205071", "lvl": "target", "msg": "<6>[    0.105745] CPU1: Booted secondary processor 0x0000000001 [0x000f0510]"}
- {"dt": "2025-03-25T10:57:28.216672", "lvl": "target", "msg": "<6>[    0.108728] smp: Brought up 1 node, 2 CPUs"}
- {"dt": "2025-03-25T10:57:28.226870", "lvl": "target", "msg": "<6>[    0.108756] SMP: Total of 2 processors activated."}
- {"dt": "2025-03-25T10:57:28.226956", "lvl": "target", "msg": "<6>[    0.108779] CPU: All CPU(s) started at EL2"}
- {"dt": "2025-03-25T10:57:28.227129", "lvl": "target", "msg": "<6>[    0.108980] CPU features: detected: Branch Target Identification"}
- {"dt": "2025-03-25T10:57:28.227257", "lvl": "target", "msg": "<6>[    0.109074] CPU features: detected: 32-bit EL0 Support"}
- {"dt": "2025-03-25T10:57:28.227390", "lvl": "target", "msg": "<6>[    0.109087] CPU features: detected: 32-bit EL1 Support"}
- {"dt": "2025-03-25T10:57:28.227549", "lvl": "target", "msg": "<6>[    0.109094] CPU features: detected: ARMv8.4 Translation Table Level"}
- {"dt": "2025-03-25T10:57:28.227841", "lvl": "target", "msg": "<6>[    0.109109] CPU features: detected: Instruction cache invalidation not required for I/D coherence"}
- {"dt": "2025-03-25T10:57:28.228100", "lvl": "target", "msg": "<6>[    0.109123] CPU features: detected: Data cache clean to the PoU not required for I/D coherence"}
- {"dt": "2025-03-25T10:57:28.228284", "lvl": "target", "msg": "<6>[    0.109157] CPU features: detected: Common not Private translations"}
- {"dt": "2025-03-25T10:57:28.228439", "lvl": "target", "msg": "<6>[    0.109164] CPU features: detected: CRC32 instructions"}
- {"dt": "2025-03-25T10:57:28.228653", "lvl": "target", "msg": "<6>[    0.109170] CPU features: detected: Data independent timing control (DIT)"}
- {"dt": "2025-03-25T10:57:28.228778", "lvl": "target", "msg": "<6>[    0.109176] CPU features: detected: E0PD"}
- {"dt": "2025-03-25T10:57:28.228971", "lvl": "target", "msg": "<6>[    0.109181] CPU features: detected: Enhanced Counter Virtualization"}
- {"dt": "2025-03-25T10:57:28.229186", "lvl": "target", "msg": "<6>[    0.109188] CPU features: detected: Enhanced Counter Virtualization (CNTPOFF)"}
- {"dt": "2025-03-25T10:57:28.229557", "lvl": "target", "msg": "<6>[    0.109194] CPU features: detected: Enhanced Privileged Access Never"}
- {"dt": "2025-03-25T10:57:28.229608", "lvl": "target", "msg": "<6>[    0.109200] CPU features: detected: Enhanced Virtualization Traps"}
- {"dt": "2025-03-25T10:57:28.229728", "lvl": "target", "msg": "<6>[    0.109206] CPU features: detected: Fine Grained Traps"}
- {"dt": "2025-03-25T10:57:28.229948", "lvl": "target", "msg": "<6>[    0.109260] CPU features: detected: Generic authentication (IMP DEF algorithm)"}
- {"dt": "2025-03-25T10:57:28.230128", "lvl": "target", "msg": "<6>[    0.109322] CPU features: detected: RCpc load-acquire (LDAPR)"}
- {"dt": "2025-03-25T10:57:28.230651", "lvl": "target", "msg": "<6>[    0.109356] CPU features: detected: 52-bit Virtual Addressing for KVM (LPA2)"}
- {"dt": "2025-03-25T10:57:28.230837", "lvl": "target", "msg": "<6>[    0.109363] CPU features: detected: LSE atomic instructions"}
- {"dt": "2025-03-25T10:57:28.231043", "lvl": "target", "msg": "<6>[    0.109369] CPU features: detected: Memory Copy and Memory Set instructions"}
- {"dt": "2025-03-25T10:57:28.231224", "lvl": "target", "msg": "<6>[    0.109375] CPU features: detected: Privileged Access Never"}
- {"dt": "2025-03-25T10:57:28.231384", "lvl": "target", "msg": "<6>[    0.109381] CPU features: detected: RAS Extension Support"}
- {"dt": "2025-03-25T10:57:28.231563", "lvl": "target", "msg": "<6>[    0.109387] CPU features: detected: Random Number Generator"}
- {"dt": "2025-03-25T10:57:28.231741", "lvl": "target", "msg": "<6>[    0.109393] CPU features: detected: Speculation barrier (SB)"}
- {"dt": "2025-03-25T10:57:28.231915", "lvl": "target", "msg": "<6>[    0.109399] CPU features: detected: Stage-2 Force Write-Back"}
- {"dt": "2025-03-25T10:57:28.232146", "lvl": "target", "msg": "<6>[    0.109405] CPU features: detected: Trap EL0 IMPLEMENTATION DEFINED functionality"}
- {"dt": "2025-03-25T10:57:28.232376", "lvl": "target", "msg": "<6>[    0.109412] CPU features: detected: TLB range maintenance instructions"}
- {"dt": "2025-03-25T10:57:28.232548", "lvl": "target", "msg": "<6>[    0.109418] CPU features: detected: WFx with timeout"}
- {"dt": "2025-03-25T10:57:28.232757", "lvl": "target", "msg": "<6>[    0.109445] CPU features: detected: Speculative Store Bypassing Safe (SSBS)"}
- {"dt": "2025-03-25T10:57:28.232929", "lvl": "target", "msg": "<6>[    0.109452] CPU features: detected: Scalable Vector Extension"}
- {"dt": "2025-03-25T10:57:28.233103", "lvl": "target", "msg": "<6>[    0.120466] alternatives: applying system-wide alternatives"}
- {"dt": "2025-03-25T10:57:28.239164", "lvl": "target", "msg": "<6>[    0.136604] CPU features: detected: Hardware dirty bit management on CPU0-1"}
- {"dt": "2025-03-25T10:57:28.239262", "lvl": "target", "msg": "<6>[    0.137319] SVE: maximum available vector length 256 bytes per vector"}
- {"dt": "2025-03-25T10:57:28.239376", "lvl": "target", "msg": "<6>[    0.137350] SVE: default vector length 64 bytes per vector"}
- {"dt": "2025-03-25T10:57:28.247763", "lvl": "target", "msg": "<6>[    0.148957] Memory: 3970300K/4194304K available (17536K kernel code, 4964K rwdata, 11964K rodata, 2944K init, 777K bss, 186808K reserved, 32768K cma-reserved)"}
- {"dt": "2025-03-25T10:57:28.275579", "lvl": "target", "msg": "<6>[    0.173833] devtmpfs: initialized"}
- {"dt": "2025-03-25T10:57:28.304188", "lvl": "target", "msg": "<6>[    0.205912] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns"}
- {"dt": "2025-03-25T10:57:28.304983", "lvl": "target", "msg": "<6>[    0.206488] futex hash table entries: 512 (order: 3, 32768 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.308125", "lvl": "target", "msg": "<6>[    0.208354] 2G module region forced by RANDOMIZE_MODULE_REGION_FULL"}
- {"dt": "2025-03-25T10:57:28.308343", "lvl": "target", "msg": "<6>[    0.208411] 0 pages in range for non-PLT usage"}
- {"dt": "2025-03-25T10:57:28.312117", "lvl": "target", "msg": "<6>[    0.208458] 514688 pages in range for PLT usage"}
- {"dt": "2025-03-25T10:57:28.312311", "lvl": "target", "msg": "<6>[    0.211242] pinctrl core: initialized pinctrl subsystem"}
- {"dt": "2025-03-25T10:57:28.320296", "lvl": "target", "msg": "<6>[    0.220245] DMI not present or invalid."}
- {"dt": "2025-03-25T10:57:28.336615", "lvl": "target", "msg": "<6>[    0.238273] NET: Registered PF_NETLINK/PF_ROUTE protocol family"}
- {"dt": "2025-03-25T10:57:28.348796", "lvl": "target", "msg": "<6>[    0.247222] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations"}
- {"dt": "2025-03-25T10:57:28.348916", "lvl": "target", "msg": "<6>[    0.247812] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations"}
- {"dt": "2025-03-25T10:57:28.349256", "lvl": "target", "msg": "<6>[    0.248494] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations"}
- {"dt": "2025-03-25T10:57:28.349390", "lvl": "target", "msg": "<6>[    0.248793] audit: initializing netlink subsys (disabled)"}
- {"dt": "2025-03-25T10:57:28.349524", "lvl": "target", "msg": "<5>[    0.250320] audit: type=2000 audit(0.228:1): state=initialized audit_enabled=0 res=1"}
- {"dt": "2025-03-25T10:57:28.359470", "lvl": "target", "msg": "<6>[    0.257822] thermal_sys: Registered thermal governor 'step_wise'"}
- {"dt": "2025-03-25T10:57:28.359930", "lvl": "target", "msg": "<6>[    0.257864] thermal_sys: Registered thermal governor 'power_allocator'"}
- {"dt": "2025-03-25T10:57:28.360019", "lvl": "target", "msg": "<6>[    0.258504] cpuidle: using governor menu"}
- {"dt": "2025-03-25T10:57:28.360147", "lvl": "target", "msg": "<6>[    0.259983] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers."}
- {"dt": "2025-03-25T10:57:28.360315", "lvl": "target", "msg": "<6>[    0.260519] ASID allocator initialised with 65536 entries"}
- {"dt": "2025-03-25T10:57:28.371590", "lvl": "target", "msg": "<6>[    0.271485] Serial: AMBA PL011 UART driver"}
- {"dt": "2025-03-25T10:57:28.431384", "lvl": "target", "msg": "<6>[    0.332626] 9000000.pl011: ttyAMA0 at MMIO 0x9000000 (irq = 15, base_baud = 0) is a PL011 rev1"}
- {"dt": "2025-03-25T10:57:28.432701", "lvl": "target", "msg": "<6>[    0.334048] printk: legacy console [ttyAMA0] enabled"}
- {"dt": "2025-03-25T10:57:28.432974", "lvl": "target", "msg": "<6>[    0.334048] printk: legacy console [ttyAMA0] enabled"}
- {"dt": "2025-03-25T10:57:28.433116", "lvl": "target", "msg": "<6>[    0.334114] printk: legacy bootconsole [pl11] disabled"}
- {"dt": "2025-03-25T10:57:28.433246", "lvl": "target", "msg": "<6>[    0.334114] printk: legacy bootconsole [pl11] disabled"}
- {"dt": "2025-03-25T10:57:28.457164", "lvl": "target", "msg": "<6>[    0.355976] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages"}
- {"dt": "2025-03-25T10:57:28.457325", "lvl": "target", "msg": "<6>[    0.356000] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page"}
- {"dt": "2025-03-25T10:57:28.457450", "lvl": "target", "msg": "<6>[    0.356035] HugeTLB: registered 32.0 MiB page size, pre-allocated 0 pages"}
- {"dt": "2025-03-25T10:57:28.457635", "lvl": "target", "msg": "<6>[    0.356044] HugeTLB: 0 KiB vmemmap can be freed for a 32.0 MiB page"}
- {"dt": "2025-03-25T10:57:28.457867", "lvl": "target", "msg": "<6>[    0.356056] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages"}
- {"dt": "2025-03-25T10:57:28.458206", "lvl": "target", "msg": "<6>[    0.356063] HugeTLB: 0 KiB vmemmap can be freed for a 2.00 MiB page"}
- {"dt": "2025-03-25T10:57:28.458291", "lvl": "target", "msg": "<6>[    0.356075] HugeTLB: registered 64.0 KiB page size, pre-allocated 0 pages"}
- {"dt": "2025-03-25T10:57:28.458775", "lvl": "target", "msg": "<6>[    0.356082] HugeTLB: 0 KiB vmemmap can be freed for a 64.0 KiB page"}
- {"dt": "2025-03-25T10:57:28.470970", "lvl": "target", "msg": "<6>[    0.369820] ACPI: Interpreter disabled."}
- {"dt": "2025-03-25T10:57:28.477301", "lvl": "target", "msg": "<6>[    0.379409] iommu: Default domain type: Translated"}
- {"dt": "2025-03-25T10:57:28.477382", "lvl": "target", "msg": "<6>[    0.379677] iommu: DMA domain TLB invalidation policy: strict mode"}
- {"dt": "2025-03-25T10:57:28.481238", "lvl": "target", "msg": "<5>[    0.381499] SCSI subsystem initialized"}
- {"dt": "2025-03-25T10:57:28.481312", "lvl": "target", "msg": "<7>[    0.382514] libata version 3.00 loaded."}
- {"dt": "2025-03-25T10:57:28.483152", "lvl": "target", "msg": "<6>[    0.384117] usbcore: registered new interface driver usbfs"}
- {"dt": "2025-03-25T10:57:28.483334", "lvl": "target", "msg": "<6>[    0.384331] usbcore: registered new interface driver hub"}
- {"dt": "2025-03-25T10:57:28.483566", "lvl": "target", "msg": "<6>[    0.384511] usbcore: registered new device driver usb"}
- {"dt": "2025-03-25T10:57:28.487315", "lvl": "target", "msg": "<6>[    0.387777] pps_core: LinuxPPS API ver. 1 registered"}
- {"dt": "2025-03-25T10:57:28.487635", "lvl": "target", "msg": "<6>[    0.387795] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>"}
- {"dt": "2025-03-25T10:57:28.487785", "lvl": "target", "msg": "<6>[    0.387877] PTP clock support registered"}
- {"dt": "2025-03-25T10:57:28.487938", "lvl": "target", "msg": "<6>[    0.388312] EDAC MC: Ver: 3.0.0"}
- {"dt": "2025-03-25T10:57:28.495452", "lvl": "target", "msg": "<6>[    0.394570] scmi_core: SCMI protocol bus registered"}
- {"dt": "2025-03-25T10:57:28.497491", "lvl": "target", "msg": "<6>[    0.398451] FPGA manager framework"}
- {"dt": "2025-03-25T10:57:28.497681", "lvl": "target", "msg": "<6>[    0.399190] Advanced Linux Sound Architecture Driver Initialized."}
- {"dt": "2025-03-25T10:57:28.511927", "lvl": "target", "msg": "<6>[    0.410443] vgaarb: loaded"}
- {"dt": "2025-03-25T10:57:28.512223", "lvl": "target", "msg": "<6>[    0.412609] clocksource: Switched to clocksource arch_sys_counter"}
- {"dt": "2025-03-25T10:57:28.512285", "lvl": "target", "msg": "<5>[    0.414073] VFS: Disk quotas dquot_6.6.0"}
- {"dt": "2025-03-25T10:57:28.512367", "lvl": "target", "msg": "<6>[    0.414169] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)"}
- {"dt": "2025-03-25T10:57:28.518197", "lvl": "target", "msg": "<6>[    0.416773] pnp: PnP ACPI: disabled"}
- {"dt": "2025-03-25T10:57:28.550141", "lvl": "target", "msg": "<6>[    0.451833] NET: Registered PF_INET protocol family"}
- {"dt": "2025-03-25T10:57:28.554192", "lvl": "target", "msg": "<6>[    0.453050] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.558214", "lvl": "target", "msg": "<6>[    0.458255] tcp_listen_portaddr_hash hash table entries: 2048 (order: 4, 81920 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.558560", "lvl": "target", "msg": "<6>[    0.458471] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.558928", "lvl": "target", "msg": "<6>[    0.458537] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.559218", "lvl": "target", "msg": "<6>[    0.459363] TCP bind hash table entries: 32768 (order: 9, 2621440 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.562198", "lvl": "target", "msg": "<6>[    0.462761] TCP: Hash tables configured (established 32768 bind 32768)"}
- {"dt": "2025-03-25T10:57:28.562474", "lvl": "target", "msg": "<6>[    0.463732] UDP hash table entries: 2048 (order: 5, 196608 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.562794", "lvl": "target", "msg": "<6>[    0.464038] UDP-Lite hash table entries: 2048 (order: 5, 196608 bytes, linear)"}
- {"dt": "2025-03-25T10:57:28.566061", "lvl": "target", "msg": "<6>[    0.465617] NET: Registered PF_UNIX/PF_LOCAL protocol family"}
- {"dt": "2025-03-25T10:57:28.570169", "lvl": "target", "msg": "<6>[    0.468921] RPC: Registered named UNIX socket transport module."}
- {"dt": "2025-03-25T10:57:28.570247", "lvl": "target", "msg": "<6>[    0.468957] RPC: Registered udp transport module."}
- {"dt": "2025-03-25T10:57:28.570356", "lvl": "target", "msg": "<6>[    0.468969] RPC: Registered tcp transport module."}
- {"dt": "2025-03-25T10:57:28.570494", "lvl": "target", "msg": "<6>[    0.468978] RPC: Registered tcp-with-tls transport module."}
- {"dt": "2025-03-25T10:57:28.570663", "lvl": "target", "msg": "<6>[    0.468987] RPC: Registered tcp NFSv4.1 backchannel transport module."}
- {"dt": "2025-03-25T10:57:28.570754", "lvl": "target", "msg": "<6>[    0.469069] PCI: CLS 0 bytes, default 64"}
- {"dt": "2025-03-25T10:57:28.582062", "lvl": "target", "msg": "<6>[    0.483479] kvm [1]: nv: 554 coarse grained trap handlers"}
- {"dt": "2025-03-25T10:57:28.586108", "lvl": "target", "msg": "<6>[    0.485091] kvm [1]: nv: 669 fine grained trap handlers"}
- {"dt": "2025-03-25T10:57:28.586185", "lvl": "target", "msg": "<6>[    0.486255] kvm [1]: IPA Size Limit: 52 bits"}
- {"dt": "2025-03-25T10:57:28.586276", "lvl": "target", "msg": "<6>[    0.486813] kvm [1]: GICv3: no GICV resource entry"}
- {"dt": "2025-03-25T10:57:28.586388", "lvl": "target", "msg": "<6>[    0.486905] kvm [1]: disabling GICv2 emulation"}
- {"dt": "2025-03-25T10:57:28.586571", "lvl": "target", "msg": "<6>[    0.487143] kvm [1]: GIC system register CPU interface enabled"}
- {"dt": "2025-03-25T10:57:28.586726", "lvl": "target", "msg": "<6>[    0.487815] kvm [1]: vgic interrupt IRQ9"}
- {"dt": "2025-03-25T10:57:28.586883", "lvl": "target", "msg": "<6>[    0.488246] kvm [1]: VHE mode initialized successfully"}
- {"dt": "2025-03-25T10:57:28.594062", "lvl": "target", "msg": "<5>[    0.494998] Initialise system trusted keyrings"}
- {"dt": "2025-03-25T10:57:28.594159", "lvl": "target", "msg": "<6>[    0.496229] workingset: timestamp_bits=42 max_order=20 bucket_order=0"}
- {"dt": "2025-03-25T10:57:28.598045", "lvl": "target", "msg": "<6>[    0.499106] squashfs: version 4.0 (2009/01/31) Phillip Lougher"}
- {"dt": "2025-03-25T10:57:28.602074", "lvl": "target", "msg": "<5>[    0.500853] NFS: Registering the id_resolver key type"}
- {"dt": "2025-03-25T10:57:28.602225", "lvl": "target", "msg": "<5>[    0.501108] Key type id_resolver registered"}
- {"dt": "2025-03-25T10:57:28.602334", "lvl": "target", "msg": "<5>[    0.501135] Key type id_legacy registered"}
- {"dt": "2025-03-25T10:57:28.602553", "lvl": "target", "msg": "<6>[    0.501375] nfs4filelayout_init: NFSv4 File Layout Driver Registering..."}
- {"dt": "2025-03-25T10:57:28.602758", "lvl": "target", "msg": "<6>[    0.501453] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering..."}
- {"dt": "2025-03-25T10:57:28.602924", "lvl": "target", "msg": "<6>[    0.502117] 9p: Installing v9fs 9p2000 file system support"}
- {"dt": "2025-03-25T10:57:28.670124", "lvl": "target", "msg": "<5>[    0.570434] Key type asymmetric registered"}
- {"dt": "2025-03-25T10:57:28.670292", "lvl": "target", "msg": "<5>[    0.570487] Asymmetric key parser 'x509' registered"}
- {"dt": "2025-03-25T10:57:28.670548", "lvl": "target", "msg": "<6>[    0.570732] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)"}
- {"dt": "2025-03-25T10:57:28.670685", "lvl": "target", "msg": "<6>[    0.570825] io scheduler mq-deadline registered"}
- {"dt": "2025-03-25T10:57:28.670826", "lvl": "target", "msg": "<6>[    0.570885] io scheduler kyber registered"}
- {"dt": "2025-03-25T10:57:28.670955", "lvl": "target", "msg": "<6>[    0.571150] io scheduler bfq registered"}
- {"dt": "2025-03-25T10:57:28.706161", "lvl": "target", "msg": "<6>[    0.607039] pl061_gpio 9030000.pl061: PL061 GPIO chip registered"}
- {"dt": "2025-03-25T10:57:28.714363", "lvl": "target", "msg": "<6>[    0.615618] pci-host-generic 4010000000.pcie: host bridge /pcie@10000000 ranges:"}
- {"dt": "2025-03-25T10:57:28.714520", "lvl": "target", "msg": "<6>[    0.616089] pci-host-generic 4010000000.pcie:       IO 0x003eff0000..0x003effffff -> 0x0000000000"}
- {"dt": "2025-03-25T10:57:28.718280", "lvl": "target", "msg": "<6>[    0.617405] pci-host-generic 4010000000.pcie:      MEM 0x0010000000..0x003efeffff -> 0x0010000000"}
- {"dt": "2025-03-25T10:57:28.718358", "lvl": "target", "msg": "<6>[    0.617460] pci-host-generic 4010000000.pcie:      MEM 0x8000000000..0xffffffffff -> 0x8000000000"}
- {"dt": "2025-03-25T10:57:28.718551", "lvl": "target", "msg": "<4>[    0.617862] pci-host-generic 4010000000.pcie: Memory resource size exceeds max for 32 bits"}
- {"dt": "2025-03-25T10:57:28.718817", "lvl": "target", "msg": "<6>[    0.618273] pci-host-generic 4010000000.pcie: ECAM at [mem 0x4010000000-0x401fffffff] for [bus 00-ff]"}
- {"dt": "2025-03-25T10:57:28.719015", "lvl": "target", "msg": "<6>[    0.619543] pci-host-generic 4010000000.pcie: PCI host bridge to bus 0000:00"}
- {"dt": "2025-03-25T10:57:28.719162", "lvl": "target", "msg": "<6>[    0.619753] pci_bus 0000:00: root bus resource [bus 00-ff]"}
- {"dt": "2025-03-25T10:57:28.719329", "lvl": "target", "msg": "<6>[    0.619813] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]"}
- {"dt": "2025-03-25T10:57:28.719541", "lvl": "target", "msg": "<6>[    0.619852] pci_bus 0000:00: root bus resource [mem 0x10000000-0x3efeffff]"}
- {"dt": "2025-03-25T10:57:28.719760", "lvl": "target", "msg": "<6>[    0.619867] pci_bus 0000:00: root bus resource [mem 0x8000000000-0xffffffffff]"}
- {"dt": "2025-03-25T10:57:28.722091", "lvl": "target", "msg": "<6>[    0.623102] pci 0000:00:00.0: [1b36:0008] type 00 class 0x060000 conventional PCI endpoint"}
- {"dt": "2025-03-25T10:57:28.726071", "lvl": "target", "msg": "<6>[    0.626634] pci 0000:00:01.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint"}
- {"dt": "2025-03-25T10:57:28.726226", "lvl": "target", "msg": "<6>[    0.626814] pci 0000:00:01.0: BAR 0 [io  0x0000-0x007f]"}
- {"dt": "2025-03-25T10:57:28.726374", "lvl": "target", "msg": "<6>[    0.626866] pci 0000:00:01.0: BAR 1 [mem 0x00000000-0x00000fff]"}
- {"dt": "2025-03-25T10:57:28.726573", "lvl": "target", "msg": "<6>[    0.626931] pci 0000:00:01.0: BAR 4 [mem 0x00000000-0x00003fff 64bit pref]"}
- {"dt": "2025-03-25T10:57:28.730086", "lvl": "target", "msg": "<6>[    0.630411] pci 0000:00:01.0: BAR 4 [mem 0x8000000000-0x8000003fff 64bit pref]: assigned"}
- {"dt": "2025-03-25T10:57:28.730466", "lvl": "target", "msg": "<6>[    0.630611] pci 0000:00:01.0: BAR 1 [mem 0x10000000-0x10000fff]: assigned"}
- {"dt": "2025-03-25T10:57:28.730571", "lvl": "target", "msg": "<6>[    0.630647] pci 0000:00:01.0: BAR 0 [io  0x1000-0x107f]: assigned"}
- {"dt": "2025-03-25T10:57:28.730653", "lvl": "target", "msg": "<6>[    0.630862] pci_bus 0000:00: resource 4 [io  0x0000-0xffff]"}
- {"dt": "2025-03-25T10:57:28.730785", "lvl": "target", "msg": "<6>[    0.630895] pci_bus 0000:00: resource 5 [mem 0x10000000-0x3efeffff]"}
- {"dt": "2025-03-25T10:57:28.730979", "lvl": "target", "msg": "<6>[    0.630911] pci_bus 0000:00: resource 6 [mem 0x8000000000-0xffffffffff]"}
- {"dt": "2025-03-25T10:57:28.810292", "lvl": "target", "msg": "<6>[    0.708957] virtio-pci 0000:00:01.0: enabling device (0000 -> 0003)"}
- {"dt": "2025-03-25T10:57:28.834404", "lvl": "target", "msg": "<6>[    0.733688] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled"}
- {"dt": "2025-03-25T10:57:28.846140", "lvl": "target", "msg": "<6>[    0.746132] msm_serial: driver initialized"}
- {"dt": "2025-03-25T10:57:28.846266", "lvl": "target", "msg": "<6>[    0.747096] SuperH (H)SCI(F) driver initialized"}
- {"dt": "2025-03-25T10:57:28.846450", "lvl": "target", "msg": "<6>[    0.747543] STM32 USART driver initialized"}
- {"dt": "2025-03-25T10:57:28.878117", "lvl": "target", "msg": "<6>[    0.778796] loop: module loaded"}
- {"dt": "2025-03-25T10:57:28.878466", "lvl": "target", "msg": "<6>[    0.779515] virtio_blk virtio0: 2/0/0 default/read/poll queues"}
- {"dt": "2025-03-25T10:57:28.890320", "lvl": "target", "msg": "<5>[    0.790250] virtio_blk virtio0: [vda] 5345376 512-byte logical blocks (2.74 GB/2.55 GiB)"}
- {"dt": "2025-03-25T10:57:28.902091", "lvl": "target", "msg": "<6>[    0.803591] megasas: 07.727.03.00-rc1"}
- {"dt": "2025-03-25T10:57:28.910816", "lvl": "target", "msg": "<5>[    0.809209] physmap-flash 0.flash: physmap platform flash device: [mem 0x00000000-0x03ffffff]"}
- {"dt": "2025-03-25T10:57:28.911094", "lvl": "target", "msg": "<6>[    0.810346] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000"}
- {"dt": "2025-03-25T10:57:28.911266", "lvl": "target", "msg": "<6>[    0.810695] Intel/Sharp Extended Query Table at 0x0031"}
- {"dt": "2025-03-25T10:57:28.911347", "lvl": "target", "msg": "<6>[    0.811379] Using buffer write method"}
- {"dt": "2025-03-25T10:57:28.911704", "lvl": "target", "msg": "<7>[    0.811632] erase region 0: offset=0x0,size=0x40000,blocks=256"}
- {"dt": "2025-03-25T10:57:28.911779", "lvl": "target", "msg": "<5>[    0.811805] physmap-flash 0.flash: physmap platform flash device: [mem 0x04000000-0x07ffffff]"}
- {"dt": "2025-03-25T10:57:28.912179", "lvl": "target", "msg": "<6>[    0.812501] 0.flash: Found 2 x16 devices at 0x0 in 32-bit bank. Manufacturer ID 0x000000 Chip ID 0x000000"}
- {"dt": "2025-03-25T10:57:28.912245", "lvl": "target", "msg": "<6>[    0.812546] Intel/Sharp Extended Query Table at 0x0031"}
- {"dt": "2025-03-25T10:57:28.912300", "lvl": "target", "msg": "<6>[    0.813230] Using buffer write method"}
- {"dt": "2025-03-25T10:57:28.913928", "lvl": "target", "msg": "<7>[    0.813273] erase region 0: offset=0x0,size=0x40000,blocks=256"}
- {"dt": "2025-03-25T10:57:28.914240", "lvl": "target", "msg": "<5>[    0.813362] Concatenating MTD devices:"}
- {"dt": "2025-03-25T10:57:28.914314", "lvl": "target", "msg": "<5>[    0.813387] (0): \"0.flash\""}
- {"dt": "2025-03-25T10:57:28.914569", "lvl": "target", "msg": "<5>[    0.813411] (1): \"0.flash\""}
- {"dt": "2025-03-25T10:57:28.914620", "lvl": "target", "msg": "<5>[    0.813422] into device \"0.flash\""}
- {"dt": "2025-03-25T10:57:28.946096", "lvl": "target", "msg": "<6>[    0.846305] tun: Universal TUN/TAP device driver, 1.6"}
- {"dt": "2025-03-25T10:57:28.950096", "lvl": "target", "msg": "<6>[    0.850080] thunder_xcv, ver 1.0"}
- {"dt": "2025-03-25T10:57:28.950169", "lvl": "target", "msg": "<6>[    0.850204] thunder_bgx, ver 1.0"}
- {"dt": "2025-03-25T10:57:28.950239", "lvl": "target", "msg": "<6>[    0.850324] nicpf, ver 1.0"}
- {"dt": "2025-03-25T10:57:28.954048", "lvl": "target", "msg": "<6>[    0.855019] hns3: Hisilicon Ethernet Network Driver for Hip08 Family - version"}
- {"dt": "2025-03-25T10:57:28.954159", "lvl": "target", "msg": "<6>[    0.855035] hns3: Copyright (c) 2017 Huawei Corporation."}
- {"dt": "2025-03-25T10:57:28.954251", "lvl": "target", "msg": "<6>[    0.855291] hclge is initializing"}
- {"dt": "2025-03-25T10:57:28.954409", "lvl": "target", "msg": "<6>[    0.855436] e1000: Intel(R) PRO/1000 Network Driver"}
- {"dt": "2025-03-25T10:57:28.954569", "lvl": "target", "msg": "<6>[    0.855449] e1000: Copyright (c) 1999-2006 Intel Corporation."}
- {"dt": "2025-03-25T10:57:28.954711", "lvl": "target", "msg": "<6>[    0.855581] e1000e: Intel(R) PRO/1000 Network Driver"}
- {"dt": "2025-03-25T10:57:28.954871", "lvl": "target", "msg": "<6>[    0.855592] e1000e: Copyright(c) 1999 - 2015 Intel Corporation."}
- {"dt": "2025-03-25T10:57:28.955040", "lvl": "target", "msg": "<6>[    0.855712] igb: Intel(R) Gigabit Ethernet Network Driver"}
- {"dt": "2025-03-25T10:57:28.955223", "lvl": "target", "msg": "<6>[    0.855725] igb: Copyright (c) 2007-2014 Intel Corporation."}
- {"dt": "2025-03-25T10:57:28.955423", "lvl": "target", "msg": "<6>[    0.855853] igbvf: Intel(R) Gigabit Virtual Function Network Driver"}
- {"dt": "2025-03-25T10:57:28.955588", "lvl": "target", "msg": "<6>[    0.855866] igbvf: Copyright (c) 2009 - 2012 Intel Corporation."}
- {"dt": "2025-03-25T10:57:28.960667", "lvl": "target", "msg": "<6>[    0.858758] sky2: driver version 1.30"}
- {"dt": "2025-03-25T10:57:28.962153", "lvl": "target", "msg": "<6>[    0.864274] VFIO - User Level meta-driver version: 0.3"}
- {"dt": "2025-03-25T10:57:28.974163", "lvl": "target", "msg": "<6>[    0.873965] usbcore: registered new interface driver usb-storage"}
- {"dt": "2025-03-25T10:57:28.986109", "lvl": "target", "msg": "<6>[    0.885843] rtc-pl031 9010000.pl031: registered as rtc0"}
- {"dt": "2025-03-25T10:57:28.986235", "lvl": "target", "msg": "<6>[    0.886352] rtc-pl031 9010000.pl031: setting system clock to 2025-03-25T10:57:28 UTC (1742900248)"}
- {"dt": "2025-03-25T10:57:28.990108", "lvl": "target", "msg": "<6>[    0.889488] i2c_dev: i2c /dev entries driver"}
- {"dt": "2025-03-25T10:57:29.010191", "lvl": "target", "msg": "<6>[    0.910794] sdhci: Secure Digital Host Controller Interface driver"}
- {"dt": "2025-03-25T10:57:29.010441", "lvl": "target", "msg": "<6>[    0.910808] sdhci: Copyright(c) Pierre Ossman"}
- {"dt": "2025-03-25T10:57:29.010874", "lvl": "target", "msg": "<6>[    0.913098] Synopsys Designware Multimedia Card Interface Driver"}
- {"dt": "2025-03-25T10:57:29.014083", "lvl": "target", "msg": "<6>[    0.915543] sdhci-pltfm: SDHCI platform and OF driver helper"}
- {"dt": "2025-03-25T10:57:29.026065", "lvl": "target", "msg": "<6>[    0.926265] usbcore: registered new interface driver usbhid"}
- {"dt": "2025-03-25T10:57:29.026248", "lvl": "target", "msg": "<6>[    0.926285] usbhid: USB HID core driver"}
- {"dt": "2025-03-25T10:57:29.038115", "lvl": "target", "msg": "<6>[    0.937313] hw perfevents: enabled with armv8_pmuv3 PMU driver, 7 (0,8000003f) counters available"}
- {"dt": "2025-03-25T10:57:29.054098", "lvl": "target", "msg": "<6>[    0.952312] NET: Registered PF_PACKET protocol family"}
- {"dt": "2025-03-25T10:57:29.054264", "lvl": "target", "msg": "<6>[    0.953859] 9pnet: Installing 9P2000 support"}
- {"dt": "2025-03-25T10:57:29.054429", "lvl": "target", "msg": "<5>[    0.954111] Key type dns_resolver registered"}
- {"dt": "2025-03-25T10:57:29.102660", "lvl": "target", "msg": "<6>[    1.003233] registered taskstats version 1"}
- {"dt": "2025-03-25T10:57:29.102801", "lvl": "target", "msg": "<5>[    1.005160] Loading compiled-in X.509 certificates"}
- {"dt": "2025-03-25T10:57:29.150177", "lvl": "target", "msg": "<6>[    1.049043] Demotion targets for Node 0: null"}
- {"dt": "2025-03-25T10:57:29.158128", "lvl": "target", "msg": "<6>[    1.057533] input: gpio-keys as /devices/platform/gpio-keys/input/input0"}
- {"dt": "2025-03-25T10:57:29.166161", "lvl": "target", "msg": "<6>[    1.064616] clk: Disabling unused clocks"}
- {"dt": "2025-03-25T10:57:29.166249", "lvl": "target", "msg": "<6>[    1.064794] PM: genpd: Disabling unused power domains"}
- {"dt": "2025-03-25T10:57:29.166313", "lvl": "target", "msg": "<6>[    1.065000] ALSA device list:"}
- {"dt": "2025-03-25T10:57:29.166381", "lvl": "target", "msg": "<6>[    1.065051]   No soundcards found."}
- {"dt": "2025-03-25T10:57:29.194210", "lvl": "target", "msg": "<6>[    1.095423] EXT4-fs (vda): mounted filesystem db78a389-4e12-4f05-bb8b-e7b25b5f99d9 r/w with ordered data mode. Quota mode: none."}
- {"dt": "2025-03-25T10:57:29.194365", "lvl": "target", "msg": "<6>[    1.095745] VFS: Mounted root (ext4 filesystem) on device 254:0."}
- {"dt": "2025-03-25T10:57:29.198145", "lvl": "target", "msg": "<6>[    1.098313] devtmpfs: mounted"}
- {"dt": "2025-03-25T10:57:29.238283", "lvl": "target", "msg": "<6>[    1.138837] Freeing unused kernel memory: 2944K"}
- {"dt": "2025-03-25T10:57:29.238659", "lvl": "target", "msg": "<6>[    1.139412] Run /sbin/init as init process"}
- {"dt": "2025-03-25T10:57:29.238728", "lvl": "target", "msg": "<7>[    1.139432]   with arguments:"}
- {"dt": "2025-03-25T10:57:29.238787", "lvl": "target", "msg": "<7>[    1.139444]     /sbin/init"}
- {"dt": "2025-03-25T10:57:29.238842", "lvl": "target", "msg": "<7>[    1.139455]     verbose"}
- {"dt": "2025-03-25T10:57:29.238965", "lvl": "target", "msg": "<7>[    1.139463]   with environment:"}
- {"dt": "2025-03-25T10:57:29.239091", "lvl": "target", "msg": "<7>[    1.139473]     HOME=/"}
- {"dt": "2025-03-25T10:57:29.239240", "lvl": "target", "msg": "<7>[    1.139484]     TERM=linux"}
- {"dt": "2025-03-25T10:57:29.574220", "lvl": "target", "msg": "<6>[    1.472300] NET: Registered PF_INET6 protocol family"}
- {"dt": "2025-03-25T10:57:29.582198", "lvl": "target", "msg": "<6>[    1.480497] Segment Routing with IPv6"}
- {"dt": "2025-03-25T10:57:29.582294", "lvl": "target", "msg": "<6>[    1.480724] In-situ OAM (IOAM) with IPv6"}
- {"dt": "2025-03-25T10:57:29.687414", "lvl": "target", "msg": "[!p]104\a[?7h"}
- {"dt": "2025-03-25T10:57:29.687792", "lvl": "target", "msg": "[0;1;39mWelcome to [0m[1mDebian GNU/Linux trixie/sid[0m[0;1;39m![0m"}
- {"dt": "2025-03-25T10:57:29.687867", "lvl": "target", "msg": "\r"}
- {"dt": "2025-03-25T10:57:31.772865", "lvl": "target", "msg": "[[0;32m  OK  [0m] Created slice [0;1;39msystem-getty.slice[0m - Slice /system/getty.\r"}
- {"dt": "2025-03-25T10:57:31.780043", "lvl": "target", "msg": "[[0;32m  OK  [0m] Created slice [0;1;39msystem-modprobe.slice[0m - Slice /system/modprobe.\r"}
- {"dt": "2025-03-25T10:57:31.786727", "lvl": "target", "msg": "[[0;32m  OK  [0m] Created slice [0;1;39msystem-serial\\x2dget\u2026slice[0m - Slice /system/serial-getty.\r"}
- {"dt": "2025-03-25T10:57:31.793310", "lvl": "target", "msg": "[[0;32m  OK  [0m] Created slice [0;1;39msystem-xfs_scrub.sli\u2026[0mxfs_scrub background service slice.\r"}
- {"dt": "2025-03-25T10:57:31.798945", "lvl": "target", "msg": "[[0;32m  OK  [0m] Created slice [0;1;39muser.slice[0m - User and Session Slice.\r"}
- {"dt": "2025-03-25T10:57:31.801457", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39msystemd-ask-password-conso\u2026[0mequests to Console Directory Watch.\r"}
- {"dt": "2025-03-25T10:57:31.803258", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39msystemd-ask-password-wall.\u2026[0md Requests to Wall Directory Watch.\r"}
- {"dt": "2025-03-25T10:57:31.805474", "lvl": "target", "msg": "         Expecting device [0;1;39mdev-ttyAMA0.device[0m - /dev/ttyAMA0...\r"}
- {"dt": "2025-03-25T10:57:31.806683", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mpaths.target[0m - Path Units.\r"}
- {"dt": "2025-03-25T10:57:31.807631", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mremote-fs.target[0m - Remote File Systems.\r"}
- {"dt": "2025-03-25T10:57:31.808538", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mslices.target[0m - Slice Units.\r"}
- {"dt": "2025-03-25T10:57:31.809406", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mswap.target[0m - Swaps.\r"}
- {"dt": "2025-03-25T10:57:31.823822", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39msystemd-creds.socket[0m - Credential Encryption/Decryption.\r"}
- {"dt": "2025-03-25T10:57:31.826880", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39msystemd-initctl.socke\u2026[0m- initctl Compatibility Named Pipe.\r"}
- {"dt": "2025-03-25T10:57:31.829202", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39msystemd-journald-dev-\u2026socket[0m - Journal Socket (/dev/log).\r"}
- {"dt": "2025-03-25T10:57:31.831522", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39msystemd-journald.socket[0m - Journal Sockets.\r"}
- {"dt": "2025-03-25T10:57:31.834348", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39msystemd-udevd-control.socket[0m - udev Control Socket.\r"}
- {"dt": "2025-03-25T10:57:31.835955", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39msystemd-udevd-kernel.socket[0m - udev Kernel Socket.\r"}
- {"dt": "2025-03-25T10:57:31.860973", "lvl": "target", "msg": "         Mounting [0;1;39mdev-hugepages.mount[0m - Huge Pages File System...\r"}
- {"dt": "2025-03-25T10:57:31.875214", "lvl": "target", "msg": "         Mounting [0;1;39mdev-mqueue.mount[0m - POSIX Message Queue File System...\r"}
- {"dt": "2025-03-25T10:57:31.890927", "lvl": "target", "msg": "         Mounting [0;1;39mrun-lock.mount[0m - Legacy Locks Directory /run/lock...\r"}
- {"dt": "2025-03-25T10:57:31.914121", "lvl": "target", "msg": "         Mounting [0;1;39msys-kernel-debug.mount[0m - Kernel Debug File System...\r"}
- {"dt": "2025-03-25T10:57:31.951427", "lvl": "target", "msg": "         Mounting [0;1;39mtmp.mount[0m - Temporary Directory /tmp...\r"}
- {"dt": "2025-03-25T10:57:31.989006", "lvl": "target", "msg": "         Starting [0;1;39mkmod-static-nodes.service[0m\u2026eate List of Static Device Nodes...\r"}
- {"dt": "2025-03-25T10:57:32.020712", "lvl": "target", "msg": "         Starting [0;1;39mmodprobe@configfs.service[0m - Load Kernel Module configfs...\r"}
- {"dt": "2025-03-25T10:57:32.115191", "lvl": "target", "msg": "         Starting [0;1;39mmodprobe@drm.service[0m - Load Kernel Module drm...\r"}
- {"dt": "2025-03-25T10:57:32.147216", "lvl": "target", "msg": "         Starting [0;1;39mmodprobe@efi_pstore.servi\u2026[0m - Load Kernel Module efi_pstore...\r"}
- {"dt": "2025-03-25T10:57:32.190319", "lvl": "target", "msg": "         Starting [0;1;39mmodprobe@fuse.service[0m - Load Kernel Module fuse...\r"}
- {"dt": "2025-03-25T10:57:32.263452", "lvl": "target", "msg": "         Starting [0;1;39msystemd-journald.service[0m - Journal Service...\r"}
- {"dt": "2025-03-25T10:57:32.285162", "lvl": "target", "msg": "         Starting [0;1;39msystemd-modules-load.service[0m - Load Kernel Modules...\r"}
- {"dt": "2025-03-25T10:57:32.312564", "lvl": "target", "msg": "         Starting [0;1;39msystemd-remount-fs.servic\u2026[0munt Root and Kernel File Systems...\r"}
- {"dt": "2025-03-25T10:57:32.333003", "lvl": "target", "msg": "         Starting [0;1;39msystemd-udev-load-credent\u2026[0mLoad udev Rules from Credentials...\r"}
- {"dt": "2025-03-25T10:57:32.357089", "lvl": "target", "msg": "         Starting [0;1;39msystemd-udev-trigger.service[0m - Coldplug All udev Devices...\r"}
- {"dt": "2025-03-25T10:57:32.396327", "lvl": "target", "msg": "[[0;32m  OK  [0m] Mounted [0;1;39mdev-hugepages.mount[0m - Huge Pages File System.\r"}
- {"dt": "2025-03-25T10:57:32.399181", "lvl": "target", "msg": "[[0;32m  OK  [0m] Mounted [0;1;39mdev-mqueue.mount[0m - POSIX Message Queue File System.\r"}
- {"dt": "2025-03-25T10:57:32.401312", "lvl": "target", "msg": "[[0;32m  OK  [0m] Mounted [0;1;39mrun-lock.mount[0m - Legacy Locks Directory /run/lock.\r"}
- {"dt": "2025-03-25T10:57:32.404164", "lvl": "target", "msg": "[[0;32m  OK  [0m] Mounted [0;1;39msys-kernel-debug.mount[0m - Kernel Debug File System.\r"}
- {"dt": "2025-03-25T10:57:32.406394", "lvl": "target", "msg": "[[0;32m  OK  [0m] Mounted [0;1;39mtmp.mount[0m - Temporary Directory /tmp.\r"}
- {"dt": "2025-03-25T10:57:32.418292", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39mkmod-static-nodes.service[0m\u2026Create List of Static Device Nodes.\r"}
- {"dt": "2025-03-25T10:57:32.442675", "lvl": "target", "msg": "         Starting [0;1;39msystemd-tmpfiles-setup-de\u2026[0m Device Nodes in /dev gracefully...\r"}
- {"dt": "2025-03-25T10:57:32.596249", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39mmodprobe@efi_pstore.service[0m - Load Kernel Module efi_pstore.\r"}
- {"dt": "2025-03-25T10:57:32.659426", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-modules-load.service[0m - Load Kernel Modules.\r"}
- {"dt": "2025-03-25T10:57:32.683319", "lvl": "target", "msg": "         Starting [0;1;39msystemd-sysctl.service[0m - Apply Kernel Variables...\r"}
- {"dt": "2025-03-25T10:57:32.742670", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-remount-fs.servic\u2026[0mmount Root and Kernel File Systems.\r"}
- {"dt": "2025-03-25T10:57:32.772840", "lvl": "target", "msg": "         Starting [0;1;39msystemd-random-seed.service[0m - Load/Save OS Random Seed...\r"}
- {"dt": "2025-03-25T10:57:32.874199", "lvl": "target", "msg": "<6>[    4.771587] fuse: init (API version 7.41)"}
- {"dt": "2025-03-25T10:57:32.879737", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39mmodprobe@drm.service[0m - Load Kernel Module drm.\r"}
- {"dt": "2025-03-25T10:57:32.892408", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39mmodprobe@configfs.service[0m - Load Kernel Module configfs.\r"}
- {"dt": "2025-03-25T10:57:32.918594", "lvl": "target", "msg": "         Mounting [0;1;39msys-kernel-config.mount[0m - Kernel Configuration File System...\r"}
- {"dt": "2025-03-25T10:57:32.952981", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39mmodprobe@fuse.service[0m - Load Kernel Module fuse.\r"}
- {"dt": "2025-03-25T10:57:32.992461", "lvl": "target", "msg": "         Mounting [0;1;39msys-fs-fuse-connections.mount[0m - FUSE Control File System...\r"}
- {"dt": "2025-03-25T10:57:33.121293", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-udev-load-credent\u2026[0m- Load udev Rules from Credentials.\r"}
- {"dt": "2025-03-25T10:57:33.144292", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-tmpfiles-setup-de\u2026[0mic Device Nodes in /dev gracefully.\r"}
- {"dt": "2025-03-25T10:57:33.160582", "lvl": "target", "msg": "[[0;32m  OK  [0m] Mounted [0;1;39msys-kernel-config.mount[0m - Kernel Configuration File System.\r"}
- {"dt": "2025-03-25T10:57:33.163169", "lvl": "target", "msg": "[[0;32m  OK  [0m] Mounted [0;1;39msys-fs-fuse-connections.mount[0m - FUSE Control File System.\r"}
- {"dt": "2025-03-25T10:57:33.188576", "lvl": "target", "msg": "         Starting [0;1;39msystemd-sysusers.service[0m - Create System Users...\r"}
- {"dt": "2025-03-25T10:57:33.226669", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-random-seed.service[0m - Load/Save OS Random Seed.\r"}
- {"dt": "2025-03-25T10:57:33.267853", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-sysctl.service[0m - Apply Kernel Variables.\r"}
- {"dt": "2025-03-25T10:57:33.551470", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-sysusers.service[0m - Create System Users.\r"}
- {"dt": "2025-03-25T10:57:33.580794", "lvl": "target", "msg": "         Starting [0;1;39msystemd-tmpfiles-setup-de\u2026[0meate Static Device Nodes in /dev...\r"}
- {"dt": "2025-03-25T10:57:33.607774", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39msystemd-journald.service[0m - Journal Service.\r"}
- {"dt": "2025-03-25T10:57:33.632018", "lvl": "target", "msg": "         Starting [0;1;39msystemd-journal-flush.ser\u2026[0msh Journal to Persistent Storage...\r"}
- {"dt": "2025-03-25T10:57:34.011882", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-tmpfiles-setup-de\u2026[0mCreate Static Device Nodes in /dev.\r"}
- {"dt": "2025-03-25T10:57:34.025206", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mlocal-fs-pre.target[0m\u2026Preparation for Local File Systems.\r"}
- {"dt": "2025-03-25T10:57:34.027097", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mlocal-fs.target[0m - Local File Systems.\r"}
- {"dt": "2025-03-25T10:57:34.047944", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39msystemd-sysext.socket[0m\u2026 System Extension Image Management.\r"}
- {"dt": "2025-03-25T10:57:34.076921", "lvl": "target", "msg": "         Starting [0;1;39msystemd-udevd.service[0m - R\u2026ager for Device Events and Files...\r"}
- {"dt": "2025-03-25T10:57:34.159035", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-journal-flush.ser\u2026[0mlush Journal to Persistent Storage.\r"}
- {"dt": "2025-03-25T10:57:34.192743", "lvl": "target", "msg": "         Starting [0;1;39msystemd-tmpfiles-setup.se\u2026[0mate System Files and Directories...\r"}
- {"dt": "2025-03-25T10:57:34.664166", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-tmpfiles-setup.se\u2026[0mreate System Files and Directories.\r"}
- {"dt": "2025-03-25T10:57:34.701475", "lvl": "target", "msg": "         Starting [0;1;39mldconfig.service[0m - Rebuild Dynamic Linker Cache...\r"}
- {"dt": "2025-03-25T10:57:34.719760", "lvl": "target", "msg": "         Starting [0;1;39msystemd-journal-catalog-u\u2026ervice[0m - Rebuild Journal Catalog...\r"}
- {"dt": "2025-03-25T10:57:34.880043", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39msystemd-udevd.service[0m - Ru\u2026anager for Device Events and Files.\r"}
- {"dt": "2025-03-25T10:57:35.298958", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-journal-catalog-u\u2026.service[0m - Rebuild Journal Catalog.\r"}
- {"dt": "2025-03-25T10:57:35.484689", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39mldconfig.service[0m - Rebuild Dynamic Linker Cache.\r"}
- {"dt": "2025-03-25T10:57:35.508054", "lvl": "target", "msg": "         Starting [0;1;39msystemd-update-done.service[0m - Update is Completed...\r"}
- {"dt": "2025-03-25T10:57:35.645034", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-update-done.service[0m - Update is Completed.\r"}
- {"dt": "2025-03-25T10:57:37.254429", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-udev-trigger.service[0m - Coldplug All udev Devices.\r"}
- {"dt": "2025-03-25T10:57:37.262708", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39msysinit.target[0m - System Initialization.\r"}
- {"dt": "2025-03-25T10:57:37.271320", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mapt-daily.timer[0m - Daily apt download activities.\r"}
- {"dt": "2025-03-25T10:57:37.275754", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mapt-daily-upgrade.timer[0m - \u2026y apt upgrade and clean activities.\r"}
- {"dt": "2025-03-25T10:57:37.277455", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mdpkg-db-backup.timer[0m - Daily dpkg database backup timer.\r"}
- {"dt": "2025-03-25T10:57:37.280362", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39me2scrub_all.timer[0m - Period\u2026Metadata Check for All Filesystems.\r"}
- {"dt": "2025-03-25T10:57:37.283796", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mfstrim.timer[0m - Discard unused filesystem blocks once a week.\r"}
- {"dt": "2025-03-25T10:57:37.286191", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mlogrotate.timer[0m - Daily rotation of log files.\r"}
- {"dt": "2025-03-25T10:57:37.291386", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39msystemd-tmpfiles-clean.tim\u2026[0my Cleanup of Temporary Directories.\r"}
- {"dt": "2025-03-25T10:57:37.293640", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mxfs_scrub_all.timer[0m - Peri\u2026Metadata Check for All Filesystems.\r"}
- {"dt": "2025-03-25T10:57:37.294687", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mtimers.target[0m - Timer Units.\r"}
- {"dt": "2025-03-25T10:57:37.296841", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39mdbus.socket[0m - D-Bus System Message Bus Socket.\r"}
- {"dt": "2025-03-25T10:57:37.298934", "lvl": "target", "msg": "[[0;32m  OK  [0m] Listening on [0;1;39msystemd-hostnamed.socket[0m - Hostname Service Socket.\r"}
- {"dt": "2025-03-25T10:57:37.299720", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39msockets.target[0m - Socket Units.\r"}
- {"dt": "2025-03-25T10:57:37.301107", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mbasic.target[0m - Basic System.\r"}
- {"dt": "2025-03-25T10:57:37.324755", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mcron.service[0m - Regular background program processing daemon.\r"}
- {"dt": "2025-03-25T10:57:37.342389", "lvl": "target", "msg": "         Starting [0;1;39mdbus.service[0m - D-Bus System Message Bus...\r"}
- {"dt": "2025-03-25T10:57:37.369511", "lvl": "target", "msg": "         Starting [0;1;39me2scrub_reap.service[0m - Re\u2026ne ext4 Metadata Check Snapshots...\r"}
- {"dt": "2025-03-25T10:57:37.428739", "lvl": "target", "msg": "         Starting [0;1;39msystemd-logind.service[0m - User Login Management...\r"}
- {"dt": "2025-03-25T10:57:37.452658", "lvl": "target", "msg": "         Starting [0;1;39msystemd-user-sessions.service[0m - Permit User Sessions...\r"}
- {"dt": "2025-03-25T10:57:37.741109", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39msystemd-user-sessions.service[0m - Permit User Sessions.\r"}
- {"dt": "2025-03-25T10:57:37.760403", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mgetty@tty1.service[0m - Getty on tty1.\r"}
- {"dt": "2025-03-25T10:57:37.808141", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mdbus.service[0m - D-Bus System Message Bus.\r"}
- {"dt": "2025-03-25T10:57:38.175008", "lvl": "target", "msg": "[[0;32m  OK  [0m] Found device [0;1;39mdev-ttyAMA0.device[0m - /dev/ttyAMA0.\r"}
- {"dt": "2025-03-25T10:57:38.193505", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39mserial-getty@ttyAMA0.service[0m - Serial Getty on ttyAMA0.\r"}
- {"dt": "2025-03-25T10:57:38.194990", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mgetty.target[0m - Login Prompts.\r"}
- {"dt": "2025-03-25T10:57:38.275461", "lvl": "target", "msg": "[[0;32m  OK  [0m] Finished [0;1;39me2scrub_reap.service[0m - Re\u2026line ext4 Metadata Check Snapshots.\r"}
- {"dt": "2025-03-25T10:57:38.570551", "lvl": "target", "msg": "[[0;32m  OK  [0m] Started [0;1;39msystemd-logind.service[0m - User Login Management.\r"}
- {"dt": "2025-03-25T10:57:38.575413", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mmulti-user.target[0m - Multi-User System.\r"}
- {"dt": "2025-03-25T10:57:38.576535", "lvl": "target", "msg": "[[0;32m  OK  [0m] Reached target [0;1;39mgraphical.target[0m - Graphical Interface.\r"}
- {"dt": "2025-03-25T10:57:40.407056", "lvl": "target", "msg": "[!p]104\a[?7h[6n[32766;32766H[6n[!p]104\a[?7h[6n[32766;32766H[6n\r"}
- {"dt": "2025-03-25T10:57:40.407214", "lvl": "target", "msg": "Debian GNU/Linux trixie/sid runner-ykxhnyexq-project-40964107-concurrent-0 ttyAMA0"}
- {"dt": "2025-03-25T10:57:40.407296", "lvl": "target", "msg": ""}
- {"dt": "2025-03-25T10:57:40.407882", "lvl": "debug", "msg": "Matched prompt #11: login:"}
- {"dt": "2025-03-25T10:57:40.407943", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "kernel-messages", "level": "2.2.1", "duration": "12.25", "result": "pass", "extra": {"extra": []}}}
- {"dt": "2025-03-25T10:57:40.408045", "lvl": "debug", "msg": "Sending username root"}
- {"dt": "2025-03-25T10:57:40.408111", "lvl": "debug", "msg": "Sending line: 'root'"}
- {"dt": "2025-03-25T10:57:40.508333", "lvl": "input", "msg": "root"}
- {"dt": "2025-03-25T10:57:40.508505", "lvl": "debug", "msg": "Setting prompt string to ['root@(.*):[/~]#']"}
- {"dt": "2025-03-25T10:57:40.508602", "lvl": "debug", "msg": "login-action: Wait for prompt ['root@(.*):[/~]#', 'Login incorrect', 'Login timed out'] (timeout 00:14:47)"}
- {"dt": "2025-03-25T10:57:40.508680", "lvl": "debug", "msg": "Waiting using forced prompt support (timeout 00:07:24)"}
- {"dt": "2025-03-25T10:57:40.509012", "lvl": "target", "msg": "runner-ykxhnyexq-project-40964107-concurrent-0 login: root\r"}
- {"dt": "2025-03-25T10:57:40.761652", "lvl": "target", "msg": "Linux runner-ykxhnyexq-project-40964107-concurrent-0 6.12.17-rc2 #1 SMP PREEMPT_RT @1740949090 aarch64"}
- {"dt": "2025-03-25T10:57:40.763447", "lvl": "target", "msg": ""}
- {"dt": "2025-03-25T10:57:40.763782", "lvl": "target", "msg": "The programs included with the Debian GNU/Linux system are free software;"}
- {"dt": "2025-03-25T10:57:40.763869", "lvl": "target", "msg": "the exact distribution terms for each program are described in the"}
- {"dt": "2025-03-25T10:57:40.763967", "lvl": "target", "msg": "individual files in /usr/share/doc/*/copyright."}
- {"dt": "2025-03-25T10:57:40.764042", "lvl": "target", "msg": ""}
- {"dt": "2025-03-25T10:57:40.764182", "lvl": "target", "msg": "Debian GNU/Linux comes with ABSOLUTELY NO WARRANTY, to the extent"}
- {"dt": "2025-03-25T10:57:40.764277", "lvl": "target", "msg": "permitted by applicable law."}
- {"dt": "2025-03-25T10:57:43.278961", "lvl": "debug", "msg": "Setting prompt string to ['root@(.*):[/~]#']"}
- {"dt": "2025-03-25T10:57:43.279138", "lvl": "debug", "msg": "end: 2.2.1 login-action (duration 00:00:15) [common]"}
- {"dt": "2025-03-25T10:57:43.279223", "lvl": "results", "msg": {"definition": "lava", "namespace": "common", "case": "login-action", "level": "2.2.1", "duration": "15.12", "result": "pass", "extra": {"success": "No kernel warnings or errors detected."}}}
- {"dt": "2025-03-25T10:57:43.279360", "lvl": "debug", "msg": "end: 2.2 auto-login-action (duration 00:00:15) [common]"}
- {"dt": "2025-03-25T10:57:43.279446", "lvl": "debug", "msg": "start: 2.3 expect-shell-connection (timeout 00:14:45) [common]"}
- {"dt": "2025-03-25T10:57:43.279515", "lvl": "debug", "msg": "Setting prompt string to ['root@(.*):[/~]#']"}
- {"dt": "2025-03-25T10:57:43.279575", "lvl": "debug", "msg": "Forcing a shell prompt, looking for ['root@(.*):[/~]#']"}
- {"dt": "2025-03-25T10:57:43.279633", "lvl": "debug", "msg": "Sending line: ''"}
- {"dt": "2025-03-25T10:57:43.329786", "lvl": "input", "msg": ""}
- {"dt": "2025-03-25T10:57:43.329987", "lvl": "debug", "msg": "expect-shell-connection: Wait for prompt ['root@(.*):[/~]#'] (timeout 00:15:00)"}
- {"dt": "2025-03-25T10:57:43.330059", "lvl": "debug", "msg": "Waiting using forced prompt support (timeout 00:07:30)"}
- {"dt": "2025-03-25T10:57:43.331154", "lvl": "target", "msg": "[?2004hroot@runner-ykxhnyexq-project-40964107-concurrent-0:~# "}
- {"dt": "2025-03-25T10:57:43.332786", "lvl": "debug", "msg": "end: 2.3 expect-shell-connection (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:43.332906", "lvl": "debug", "msg": "start: 2.4 export-device-env (timeout 00:14:45) [common]"}
- {"dt": "2025-03-25T10:57:43.333008", "lvl": "debug", "msg": "end: 2.4 export-device-env (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:57:43.333099", "lvl": "info", "msg": "end: 2 boot-image-retry (duration 00:00:15) [common]"}
- {"dt": "2025-03-25T10:57:43.333184", "lvl": "info", "msg": "start: 3 lava-test-retry (timeout 00:10:00) [common]"}
- {"dt": "2025-03-25T10:57:43.333268", "lvl": "debug", "msg": "start: 3.1 lava-test-shell (timeout 00:10:00) [common]"}
- {"dt": "2025-03-25T10:57:43.333335", "lvl": "debug", "msg": "Using namespace: common"}
- {"dt": "2025-03-25T10:57:43.333405", "lvl": "debug", "msg": "Sending line: '#'"}
- {"dt": "2025-03-25T10:57:43.433640", "lvl": "input", "msg": "#"}
- {"dt": "2025-03-25T10:57:43.433774", "lvl": "debug", "msg": "lava-test-shell: Wait for prompt ['root@(.*):[/~]#'] (timeout 00:10:00)"}
- {"dt": "2025-03-25T10:57:43.434314", "lvl": "target", "msg": "[?2004l\r[?2004hroot@runner-ykxhnyexq-project-40964107-concurrent-0:~# #"}
- {"dt": "2025-03-25T10:57:43.435942", "lvl": "debug", "msg": "Using /lava-1"}
- {"dt": "2025-03-25T10:57:43.436001", "lvl": "debug", "msg": "Sending line: 'export SHELL=/bin/sh'"}
- {"dt": "2025-03-25T10:57:43.536202", "lvl": "input", "msg": "export SHELL=/bin/sh"}
- {"dt": "2025-03-25T10:57:43.536765", "lvl": "target", "msg": "[?2004l\r[?2004hroot@runner-ykxhnyexq-project-40964107-concurrent-0:~# export SHELL=/bin/sh"}
- {"dt": "2025-03-25T10:57:43.538700", "lvl": "debug", "msg": "Sending line: '. /lava-1/environment'"}
- {"dt": "2025-03-25T10:57:43.638947", "lvl": "input", "msg": ". /lava-1/environment"}
- {"dt": "2025-03-25T10:57:43.639840", "lvl": "target", "msg": "[?2004l\r[?2004hroot@runner-ykxhnyexq-project-40964107-concurrent-0:~# . /lava-1/environment"}
- {"dt": "2025-03-25T10:57:43.643178", "lvl": "debug", "msg": "Sending line: '/lava-1/bin/lava-test-runner /lava-1/0'"}
- {"dt": "2025-03-25T10:57:43.743713", "lvl": "input", "msg": "/lava-1/bin/lava-test-runner /lava-1/0"}
- {"dt": "2025-03-25T10:57:43.743900", "lvl": "info", "msg": "Test shell timeout: 10s (minimum of the action and connection timeout)"}
- {"dt": "2025-03-25T10:57:43.744898", "lvl": "target", "msg": "[?2004l\r[?2004hroot@runner-ykxhnyexq-project-40964107-concurrent-0:~# /lava-1/bin/lava-test-runn\rner /lava-1/0"}
- {"dt": "2025-03-25T10:57:43.880680", "lvl": "target", "msg": "[?2004l\r+ export TESTRUN_ID=0_rt-tests-pmqtest"}
- {"dt": "2025-03-25T10:57:43.880841", "lvl": "target", "msg": "+ cd /lava-1/0/tests/0_rt-tests-pmqtest"}
- {"dt": "2025-03-25T10:57:43.883537", "lvl": "target", "msg": "+ cat uuid"}
- {"dt": "2025-03-25T10:57:43.890851", "lvl": "target", "msg": "+ UUID=1_1.1.3.1"}
- {"dt": "2025-03-25T10:57:43.891129", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2025-03-25T10:57:43.892104", "lvl": "target", "msg": "+ cd ./automated/linux/pmqtest/"}
- {"dt": "2025-03-25T10:57:43.894371", "lvl": "target", "msg": "<8>[   15.794405] <LAVA_SIGNAL_STARTRUN 0_rt-tests-pmqtest 1_1.1.3.1>"}
- {"dt": "2025-03-25T10:57:43.894640", "lvl": "debug", "msg": "Received signal: <STARTRUN> 0_rt-tests-pmqtest 1_1.1.3.1"}
- {"dt": "2025-03-25T10:57:43.894724", "lvl": "info", "msg": "Starting test lava.0_rt-tests-pmqtest (1_1.1.3.1)"}
- {"dt": "2025-03-25T10:57:43.894867", "lvl": "info", "msg": "Skipping test definition patterns."}
- {"dt": "2025-03-25T10:57:43.897652", "lvl": "target", "msg": "+ ./pmqtest.sh -D 1m -i 2 -w "}
- {"dt": "2025-03-25T10:58:43.999002", "lvl": "target", "msg": "#0: ID237, P98, CPU0, I1000; #1: ID238, P98, CPU0, TO 0, Cycles 49096"}
- {"dt": "2025-03-25T10:58:43.999130", "lvl": "target", "msg": "#2: ID239, P98, CPU1, I1500; #3: ID240, P98, CPU1, TO 0, Cycles 34369"}
- {"dt": "2025-03-25T10:58:43.999190", "lvl": "target", "msg": "#1 -> #0, Min   26, Cur   44, Avg   35, Max  760"}
- {"dt": "2025-03-25T10:58:43.999300", "lvl": "target", "msg": "#3 -> #2, Min   26, Cur   33, Avg   40, Max  289"}
- {"dt": "2025-03-25T10:59:44.114306", "lvl": "target", "msg": "#0: ID242, P98, CPU0, I1000; #1: ID243, P98, CPU0, TO 0, Cycles 48998"}
- {"dt": "2025-03-25T10:59:44.114456", "lvl": "target", "msg": "#2: ID244, P98, CPU1, I1500; #3: ID245, P98, CPU1, TO 0, Cycles 34423"}
- {"dt": "2025-03-25T10:59:44.115156", "lvl": "target", "msg": "#1 -> #0, Min   27, Cur   33, Avg   35, Max  427"}
- {"dt": "2025-03-25T10:59:44.115394", "lvl": "target", "msg": "#3 -> #2, Min   27, Cur   31, Avg   39, Max  434"}
- {"dt": "2025-03-25T10:59:44.706231", "lvl": "target", "msg": "t0-min-latency pass 26 us"}
- {"dt": "2025-03-25T10:59:44.706404", "lvl": "target", "msg": "t0-avg-latency pass 34.99 us"}
- {"dt": "2025-03-25T10:59:44.706477", "lvl": "target", "msg": "t0-max-latency pass 760 us"}
- {"dt": "2025-03-25T10:59:44.706546", "lvl": "target", "msg": "t1-min-latency pass 26 us"}
- {"dt": "2025-03-25T10:59:44.706810", "lvl": "target", "msg": "t1-avg-latency pass 39.64 us"}
- {"dt": "2025-03-25T10:59:44.706883", "lvl": "target", "msg": "t1-max-latency pass 289 us"}
- {"dt": "2025-03-25T10:59:44.706944", "lvl": "target", "msg": "pmqtest pass"}
- {"dt": "2025-03-25T10:59:44.776724", "lvl": "target", "msg": "iteration-1-t0-min-latency pass 26 us"}
- {"dt": "2025-03-25T10:59:44.776885", "lvl": "target", "msg": "iteration-1-t0-avg-latency pass 34.99 us"}
- {"dt": "2025-03-25T10:59:44.776966", "lvl": "target", "msg": "iteration-1-t0-max-latency pass 760 us"}
- {"dt": "2025-03-25T10:59:44.777263", "lvl": "target", "msg": "iteration-1-t1-min-latency pass 26 us"}
- {"dt": "2025-03-25T10:59:44.777331", "lvl": "target", "msg": "iteration-1-t1-avg-latency pass 39.64 us"}
- {"dt": "2025-03-25T10:59:44.777407", "lvl": "target", "msg": "iteration-1-t1-max-latency pass 289 us"}
- {"dt": "2025-03-25T10:59:44.777481", "lvl": "target", "msg": "iteration-1-pmqtest pass"}
- {"dt": "2025-03-25T10:59:44.979581", "lvl": "target", "msg": "t0-min-latency pass 27 us"}
- {"dt": "2025-03-25T10:59:44.979744", "lvl": "target", "msg": "t0-avg-latency pass 35.14 us"}
- {"dt": "2025-03-25T10:59:44.979829", "lvl": "target", "msg": "t0-max-latency pass 427 us"}
- {"dt": "2025-03-25T10:59:44.979893", "lvl": "target", "msg": "t1-min-latency pass 27 us"}
- {"dt": "2025-03-25T10:59:44.979961", "lvl": "target", "msg": "t1-avg-latency pass 39.25 us"}
- {"dt": "2025-03-25T10:59:44.980030", "lvl": "target", "msg": "t1-max-latency pass 434 us"}
- {"dt": "2025-03-25T10:59:44.980085", "lvl": "target", "msg": "pmqtest pass"}
- {"dt": "2025-03-25T10:59:45.031645", "lvl": "target", "msg": "iteration-2-t0-min-latency pass 27 us"}
- {"dt": "2025-03-25T10:59:45.031763", "lvl": "target", "msg": "iteration-2-t0-avg-latency pass 35.14 us"}
- {"dt": "2025-03-25T10:59:45.032048", "lvl": "target", "msg": "iteration-2-t0-max-latency pass 427 us"}
- {"dt": "2025-03-25T10:59:45.032124", "lvl": "target", "msg": "iteration-2-t1-min-latency pass 27 us"}
- {"dt": "2025-03-25T10:59:45.032199", "lvl": "target", "msg": "iteration-2-t1-avg-latency pass 39.25 us"}
- {"dt": "2025-03-25T10:59:45.032486", "lvl": "target", "msg": "iteration-2-t1-max-latency pass 434 us"}
- {"dt": "2025-03-25T10:59:45.032557", "lvl": "target", "msg": "iteration-2-pmqtest pass"}
- {"dt": "2025-03-25T10:59:45.036527", "lvl": "target", "msg": "+ ../../utils/upload-to-artifactorial.sh -a output/pmqtest.json -u https://archive.validation.linaro.org/artifacts/team/qa/ -t "}
- {"dt": "2025-03-25T10:59:45.089071", "lvl": "target", "msg": "WARNING: ARTIFACTORIAL_TOKEN is empty! File uploading skipped."}
- {"dt": "2025-03-25T10:59:45.089199", "lvl": "target", "msg": "test-attachment skip"}
- {"dt": "2025-03-25T10:59:45.110469", "lvl": "target", "msg": "<8>[  137.011075] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=test-attachment RESULT=skip>"}
- {"dt": "2025-03-25T10:59:45.110743", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=test-attachment RESULT=skip"}
- {"dt": "2025-03-25T10:59:45.110857", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "test-attachment", "result": "skip", "starttc": ! "739", "endtc": ! "739"}}
- {"dt": "2025-03-25T10:59:45.112143", "lvl": "target", "msg": "+ ../../utils/send-to-lava.sh ./output/result.txt"}
- {"dt": "2025-03-25T10:59:45.290242", "lvl": "target", "msg": "<8>[  137.191074] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-1-t0-min-latency RESULT=pass UNITS=us MEASUREMENT=26>"}
- {"dt": "2025-03-25T10:59:45.290581", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-1-t0-min-latency RESULT=pass UNITS=us MEASUREMENT=26"}
- {"dt": "2025-03-25T10:59:45.290718", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-1-t0-min-latency", "result": "pass", "measurement": ! "26.0", "units": "us", "starttc": ! "743", "endtc": ! "743"}}
- {"dt": "2025-03-25T10:59:45.434310", "lvl": "target", "msg": "<8>[  137.334861] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-1-t0-avg-latency RESULT=pass UNITS=us MEASUREMENT=34.99>"}
- {"dt": "2025-03-25T10:59:45.434606", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-1-t0-avg-latency RESULT=pass UNITS=us MEASUREMENT=34.99"}
- {"dt": "2025-03-25T10:59:45.434736", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-1-t0-avg-latency", "result": "pass", "measurement": ! "34.99", "units": "us", "starttc": ! "746", "endtc": ! "746"}}
- {"dt": "2025-03-25T10:59:45.574295", "lvl": "target", "msg": "<8>[  137.476308] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-1-t0-max-latency RESULT=pass UNITS=us MEASUREMENT=760>"}
- {"dt": "2025-03-25T10:59:45.574663", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-1-t0-max-latency RESULT=pass UNITS=us MEASUREMENT=760"}
- {"dt": "2025-03-25T10:59:45.574811", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-1-t0-max-latency", "result": "pass", "measurement": ! "760.0", "units": "us", "starttc": ! "749", "endtc": ! "749"}}
- {"dt": "2025-03-25T10:59:45.718342", "lvl": "target", "msg": "<8>[  137.618648] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-1-t1-min-latency RESULT=pass UNITS=us MEASUREMENT=26>"}
- {"dt": "2025-03-25T10:59:45.718634", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-1-t1-min-latency RESULT=pass UNITS=us MEASUREMENT=26"}
- {"dt": "2025-03-25T10:59:45.718742", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-1-t1-min-latency", "result": "pass", "measurement": ! "26.0", "units": "us", "starttc": ! "752", "endtc": ! "752"}}
- {"dt": "2025-03-25T10:59:45.862274", "lvl": "target", "msg": "<8>[  137.763906] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-1-t1-avg-latency RESULT=pass UNITS=us MEASUREMENT=39.64>"}
- {"dt": "2025-03-25T10:59:45.862640", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-1-t1-avg-latency RESULT=pass UNITS=us MEASUREMENT=39.64"}
- {"dt": "2025-03-25T10:59:45.862766", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-1-t1-avg-latency", "result": "pass", "measurement": ! "39.64", "units": "us", "starttc": ! "755", "endtc": ! "755"}}
- {"dt": "2025-03-25T10:59:46.010282", "lvl": "target", "msg": "<8>[  137.909261] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-1-t1-max-latency RESULT=pass UNITS=us MEASUREMENT=289>"}
- {"dt": "2025-03-25T10:59:46.010591", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-1-t1-max-latency RESULT=pass UNITS=us MEASUREMENT=289"}
- {"dt": "2025-03-25T10:59:46.010700", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-1-t1-max-latency", "result": "pass", "measurement": ! "289.0", "units": "us", "starttc": ! "758", "endtc": ! "758"}}
- {"dt": "2025-03-25T10:59:46.042232", "lvl": "target", "msg": "<8>[  137.943435] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-1-pmqtest RESULT=pass>"}
- {"dt": "2025-03-25T10:59:46.042536", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-1-pmqtest RESULT=pass"}
- {"dt": "2025-03-25T10:59:46.042667", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-1-pmqtest", "result": "pass", "starttc": ! "761", "endtc": ! "761"}}
- {"dt": "2025-03-25T10:59:46.186164", "lvl": "target", "msg": "<8>[  138.086741] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-2-t0-min-latency RESULT=pass UNITS=us MEASUREMENT=27>"}
- {"dt": "2025-03-25T10:59:46.186444", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-2-t0-min-latency RESULT=pass UNITS=us MEASUREMENT=27"}
- {"dt": "2025-03-25T10:59:46.186543", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-2-t0-min-latency", "result": "pass", "measurement": ! "27.0", "units": "us", "starttc": ! "764", "endtc": ! "764"}}
- {"dt": "2025-03-25T10:59:46.330263", "lvl": "target", "msg": "<8>[  138.231476] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-2-t0-avg-latency RESULT=pass UNITS=us MEASUREMENT=35.14>"}
- {"dt": "2025-03-25T10:59:46.330602", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-2-t0-avg-latency RESULT=pass UNITS=us MEASUREMENT=35.14"}
- {"dt": "2025-03-25T10:59:46.330718", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-2-t0-avg-latency", "result": "pass", "measurement": ! "35.14", "units": "us", "starttc": ! "767", "endtc": ! "767"}}
- {"dt": "2025-03-25T10:59:46.482249", "lvl": "target", "msg": "<8>[  138.382424] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-2-t0-max-latency RESULT=pass UNITS=us MEASUREMENT=427>"}
- {"dt": "2025-03-25T10:59:46.482595", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-2-t0-max-latency RESULT=pass UNITS=us MEASUREMENT=427"}
- {"dt": "2025-03-25T10:59:46.482694", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-2-t0-max-latency", "result": "pass", "measurement": ! "427.0", "units": "us", "starttc": ! "770", "endtc": ! "770"}}
- {"dt": "2025-03-25T10:59:46.630481", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-2-t1-min-latency RESULT=pass UNITS=us MEASUREMENT=27"}
- {"dt": "2025-03-25T10:59:46.630648", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-2-t1-min-latency", "result": "pass", "measurement": ! "27.0", "units": "us", "starttc": ! "772", "endtc": ! "772"}}
- {"dt": "2025-03-25T10:59:46.630821", "lvl": "target", "msg": "<8>[  138.531079] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-2-t1-min-latency RESULT=pass UNITS=us MEASUREMENT=27>"}
- {"dt": "2025-03-25T10:59:46.774385", "lvl": "target", "msg": "<8>[  138.676135] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-2-t1-avg-latency RESULT=pass UNITS=us MEASUREMENT=39.25>"}
- {"dt": "2025-03-25T10:59:46.774690", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-2-t1-avg-latency RESULT=pass UNITS=us MEASUREMENT=39.25"}
- {"dt": "2025-03-25T10:59:46.774777", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-2-t1-avg-latency", "result": "pass", "measurement": ! "39.25", "units": "us", "starttc": ! "776", "endtc": ! "776"}}
- {"dt": "2025-03-25T10:59:46.918220", "lvl": "target", "msg": "<8>[  138.820298] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-2-t1-max-latency RESULT=pass UNITS=us MEASUREMENT=434>"}
- {"dt": "2025-03-25T10:59:46.918531", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-2-t1-max-latency RESULT=pass UNITS=us MEASUREMENT=434"}
- {"dt": "2025-03-25T10:59:46.918626", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-2-t1-max-latency", "result": "pass", "measurement": ! "434.0", "units": "us", "starttc": ! "779", "endtc": ! "779"}}
- {"dt": "2025-03-25T10:59:46.954408", "lvl": "target", "msg": "<8>[  138.854115] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=iteration-2-pmqtest RESULT=pass>"}
- {"dt": "2025-03-25T10:59:46.954708", "lvl": "debug", "msg": "Received signal: <TESTCASE> TEST_CASE_ID=iteration-2-pmqtest RESULT=pass"}
- {"dt": "2025-03-25T10:59:46.954779", "lvl": "results", "msg": {"definition": "0_rt-tests-pmqtest", "case": "iteration-2-pmqtest", "result": "pass", "starttc": ! "782", "endtc": ! "782"}}
- {"dt": "2025-03-25T10:59:46.955437", "lvl": "target", "msg": "+ set +x"}
- {"dt": "2025-03-25T10:59:46.958155", "lvl": "target", "msg": "<8>[  138.858416] <LAVA_SIGNAL_ENDRUN 0_rt-tests-pmqtest 1_1.1.3.1>"}
- {"dt": "2025-03-25T10:59:46.958409", "lvl": "debug", "msg": "Received signal: <ENDRUN> 0_rt-tests-pmqtest 1_1.1.3.1"}
- {"dt": "2025-03-25T10:59:46.958496", "lvl": "info", "msg": "Ending use of test pattern."}
- {"dt": "2025-03-25T10:59:46.958557", "lvl": "info", "msg": "Ending test lava.0_rt-tests-pmqtest (1_1.1.3.1), duration 123.06"}
- {"dt": "2025-03-25T10:59:46.958636", "lvl": "results", "msg": {"definition": "lava", "case": "0_rt-tests-pmqtest", "uuid": "1_1.1.3.1", "repository": "https://github.com/roxell/test-definitions.git", "path": "automated/linux/pmqtest/pmqtest.yaml", "duration": "123.06", "result": "pass", "revision": "unspecified", "namespace": "common", "commit_id": "de2bf15049f1ff53c926defa0e75f675813e9c22"}}
- {"dt": "2025-03-25T10:59:46.960122", "lvl": "target", "msg": "<LAVA_TEST_RUNNER EXIT>"}
- {"dt": "2025-03-25T10:59:46.960335", "lvl": "info", "msg": "ok: lava_test_shell seems to have completed"}
- {"dt": "2025-03-25T10:59:46.960446", "lvl": "debug", "msg": "test-attachment: skip\niteration-1-t0-min-latency: pass\niteration-1-t0-avg-latency: pass\niteration-1-t0-max-latency: pass\niteration-1-t1-min-latency: pass\niteration-1-t1-avg-latency: pass\niteration-1-t1-max-latency: pass\niteration-1-pmqtest: pass\niteration-2-t0-min-latency: pass\niteration-2-t0-avg-latency: pass\niteration-2-t0-max-latency: pass\niteration-2-t1-min-latency: pass\niteration-2-t1-avg-latency: pass\niteration-2-t1-max-latency: pass\niteration-2-pmqtest: pass\n"}
- {"dt": "2025-03-25T10:59:46.960552", "lvl": "debug", "msg": "end: 3.1 lava-test-shell (duration 00:02:04) [common]"}
- {"dt": "2025-03-25T10:59:46.960637", "lvl": "info", "msg": "end: 3 lava-test-retry (duration 00:02:04) [common]"}
- {"dt": "2025-03-25T10:59:46.960723", "lvl": "info", "msg": "start: 4 finalize (timeout 00:05:00) [common]"}
- {"dt": "2025-03-25T10:59:46.960810", "lvl": "debug", "msg": "start: 4.1 power-off (timeout 00:00:30) [common]"}
- {"dt": "2025-03-25T10:59:46.960894", "lvl": "debug", "msg": "end: 4.1 power-off (duration 00:00:00) [common]"}
- {"dt": "2025-03-25T10:59:46.960975", "lvl": "debug", "msg": "start: 4.2 read-feedback (timeout 00:05:00) [common]"}
- {"dt": "2025-03-25T10:59:46.961114", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2025-03-25T10:59:46.963917", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2025-03-25T10:59:46.964224", "lvl": "debug", "msg": "Listened to connection for namespace 'common' for up to 1s"}
- {"dt": "2025-03-25T10:59:47.962241", "lvl": "info", "msg": "Finalising connection for namespace 'common'"}
- {"dt": "2025-03-25T10:59:47.962412", "lvl": "debug", "msg": "Sending line: 'poweroff'"}
- {"dt": "2025-03-25T10:59:48.063231", "lvl": "input", "msg": "poweroff"}
- {"dt": "2025-03-25T10:59:48.063700", "lvl": "debug", "msg": "Already disconnected"}
- {"dt": "2025-03-25T10:59:48.063811", "lvl": "target", "msg": "[?2004hroot@runner-ykxhnyexq-project-40964107-concurrent-0:~# poweroff"}
- {"dt": "2025-03-25T10:59:48.164405", "lvl": "debug", "msg": "end: 4.2 read-feedback (duration 00:00:01) [common]"}
- {"dt": "2025-03-25T10:59:48.164563", "lvl": "debug", "msg": "Already disconnected"}
- {"dt": "2025-03-25T10:59:48.164646", "lvl": "info", "msg": "end: 4 finalize (duration 00:00:01) [common]"}
- {"dt": "2025-03-25T10:59:48.164748", "lvl": "info", "msg": "Cleaning after the job"}
- {"dt": "2025-03-25T10:59:48.164878", "lvl": "debug", "msg": "Cleaning up downloaded image: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/kernel/Image"}
- {"dt": "2025-03-25T10:59:48.169806", "lvl": "debug", "msg": "Cleaning up downloaded image: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs/https___storage.tuxboot.com_debian_trixie_arm64_rootfs.ext4"}
- {"dt": "2025-03-25T10:59:48.262370", "lvl": "debug", "msg": "Cleaning up downloaded image: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs.modules/modules.tar"}
- {"dt": "2025-03-25T10:59:48.272132", "lvl": "debug", "msg": "Cleaning up downloaded image: /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1/deployimages-dq0moq5y/rootfs.overlay-00/rt-tests.tar"}
- {"dt": "2025-03-25T10:59:48.272595", "lvl": "info", "msg": "Removing root tmp directory at /var/lib/lava/dispatcher/tmp/tuxrun-qv4_s7bb-1"}
- {"dt": "2025-03-25T10:59:48.315305", "lvl": "info", "msg": "Job finished correctly"}
- {"dt": "2025-03-25T10:59:48.315375", "lvl": "results", "msg": {"definition": "lava", "case": "job", "result": "pass"}}
