Logger test failing
Version, Distribution, Desktop Environment:
Version: master (pipewire-git 0.3.38.80.g336caa9d-1)
Arch Linux: Linux mia-arch 5.14.10-arch1-1 #1 SMP PREEMPT Thu, 07 Oct 2021 20:00:23 +0000 x86_64 GNU/Linux
DE: none (xorg+i3)
Description of Problem:
I'm using the Arch AUR package pipewire-git
to install & maintain PipeWire on my system, but recently I couldn't get it to build anymore, failing in the testing stage.
Till recently, the errors I always received were along the lines of what Patola mentioned on the pipewire-full-ffmpeg-git
AUR package:
- name: "logger_journal"
status: FAIL
log: |
FAILED COMPARISON: mark_line_found == true
Resolved to: false == true
in logger_journal() (../pipewire/test/test-logger.c:496)
- name: "logger_journal_chain"
status: FAIL
log: |
FAILED ERRNO CHECK: expected 0 (Success), got 74 (Bad message)
in logger_journal_chain() (../pipewire/test/test-logger.c:565)
So I pulled up the test-logger.c
file, found out that the command that is failing is likely test-logger.c#L564.
I know next to nothing about the sd_journal
functions, but I thought, that after some people mentioned that the package builds fine in a clean chroot, that it might be.. well that I'm not in one. My journal is old. Like over 2GB of data old. So I cleaned it:
Vacuuming done, freed 1.9G of archived journals from /var/log/journal/b2715d0aa1af42ffaccae284ff7d80aa.
And tried again - without success, a bit of a different.. and more confusing error this time.
Here is the new error log.. and yes, it looks exactly as I'm posting it here:
- name: "logger_journal"
status: FAIL
log: |
FAILED COMPARISON: mark_line_found == true
Resolved to: false == true
in logger_journal() (../pipewire/test/test-logger.c:496)
kkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk
- name: "logger_journal_chain"
status: PASS
- suite: "support"
tests:
- name: "pwtest_load_nonexisting"
status: PASS
- name: "pwtest_load_plugin"
status: PASS
――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――――
14/17 pw-test-protocol-native OK 0.12s
15/17 test pipewire utils OK 0.11s
16/17 test-fmt-ops OK 0.18s
17/17 test spa OK 0.21s
Summary of Failures:
13/17 test support FAIL 0.07s exit status 1
Ok: 16
Expected Fail: 0
Fail: 1
Unexpected Pass: 0
Skipped: 0
Timeout: 0
The large amount of character are always different, from run to run:
Resolved to: false == true
in logger_journal() (../pipewire/test/test-logger.c:496)
PPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPPP
etc ...
Here is the journal log from during the tests. But from just a quick glance at how the test sould work, I see the markers in the logs, so I've got no idea why the tests are failing.
Oct 11 01:25:45 mia-arch audit[124697]: ANOM_ABEND auid=1000 uid=1000 gid=1000 ses=1 pid=124697 comm="test-spa" exe="/home/niraami/.cache/yay/pipewire-git/src/build/test/test-spa" sig=6 res=1
Oct 11 01:25:45 mia-arch kernel: audit: type=1701 audit(1633908345.787:261): auid=1000 uid=1000 gid=1000 ses=1 pid=124697 comm="test-spa" exe="/home/niraami/.cache/yay/pipewire-git/src/build/test/test-spa" sig=6 res=1
Oct 11 01:25:45 mia-arch test-support[124704]: journal 0x56283ab9b9b0: initialized
Oct 11 01:25:45 mia-arch test-support[124704]: pwtest journal: MARK
Oct 11 01:25:45 mia-arch test-support[124705]: journal 0x56283ab9bad0: initialized
Oct 11 01:25:45 mia-arch test-support[124705]: pwtest journal: MARK
Oct 11 01:25:45 mia-arch audit: BPF prog-id=58 op=LOAD
Oct 11 01:25:45 mia-arch audit: BPF prog-id=59 op=LOAD
Oct 11 01:25:45 mia-arch audit: BPF prog-id=60 op=LOAD
Oct 11 01:25:45 mia-arch systemd[1]: Started Process Core Dump (PID 124698/UID 0).
Oct 11 01:25:45 mia-arch audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@9-124698-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 01:25:45 mia-arch kernel: audit: type=1334 audit(1633908345.820:262): prog-id=58 op=LOAD
Oct 11 01:25:45 mia-arch kernel: audit: type=1334 audit(1633908345.820:263): prog-id=59 op=LOAD
Oct 11 01:25:45 mia-arch kernel: audit: type=1334 audit(1633908345.820:264): prog-id=60 op=LOAD
Oct 11 01:25:45 mia-arch kernel: audit: type=1130 audit(1633908345.820:265): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@9-124698-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 01:25:45 mia-arch systemd-coredump[124708]: Resource limits disable core dumping for process 124697 (test-spa).
Oct 11 01:25:45 mia-arch systemd-coredump[124708]: [🡕] Process 124697 (test-spa) of user 1000 dumped core.
Oct 11 01:25:45 mia-arch audit[124714]: ANOM_ABEND auid=1000 uid=1000 gid=1000 ses=1 pid=124714 comm="test-spa" exe="/home/niraami/.cache/yay/pipewire-git/src/build/test/test-spa" sig=6 res=1
Oct 11 01:25:45 mia-arch kernel: audit: type=1701 audit(1633908345.857:266): auid=1000 uid=1000 gid=1000 ses=1 pid=124714 comm="test-spa" exe="/home/niraami/.cache/yay/pipewire-git/src/build/test/test-spa" sig=6 res=1
Oct 11 01:25:45 mia-arch kernel: audit: type=1131 audit(1633908345.857:267): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@9-124698-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 01:25:45 mia-arch audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@9-124698-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 01:25:45 mia-arch systemd[1]: systemd-coredump@9-124698-0.service: Deactivated successfully.
Oct 11 01:25:45 mia-arch audit: BPF prog-id=61 op=LOAD
Oct 11 01:25:45 mia-arch audit: BPF prog-id=62 op=LOAD
Oct 11 01:25:45 mia-arch audit: BPF prog-id=63 op=LOAD
Oct 11 01:25:45 mia-arch systemd[1]: Started Process Core Dump (PID 124717/UID 0).
Oct 11 01:25:45 mia-arch audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@10-124717-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 01:25:45 mia-arch kernel: audit: type=1334 audit(1633908345.864:268): prog-id=61 op=LOAD
Oct 11 01:25:45 mia-arch kernel: audit: type=1334 audit(1633908345.864:269): prog-id=62 op=LOAD
Oct 11 01:25:45 mia-arch kernel: audit: type=1334 audit(1633908345.864:270): prog-id=63 op=LOAD
Oct 11 01:25:45 mia-arch systemd-coredump[124721]: Resource limits disable core dumping for process 124714 (test-spa).
Oct 11 01:25:45 mia-arch systemd-coredump[124721]: [🡕] Process 124714 (test-spa) of user 1000 dumped core.
Oct 11 01:25:45 mia-arch audit[124724]: ANOM_ABEND auid=1000 uid=1000 gid=1000 ses=1 pid=124724 comm="test-spa" exe="/home/niraami/.cache/yay/pipewire-git/src/build/test/test-spa" sig=6 res=1
Oct 11 01:25:45 mia-arch audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@10-124717-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 01:25:45 mia-arch systemd[1]: systemd-coredump@10-124717-0.service: Deactivated successfully.
Oct 11 01:25:45 mia-arch audit: BPF prog-id=64 op=LOAD
Oct 11 01:25:45 mia-arch audit: BPF prog-id=65 op=LOAD
Oct 11 01:25:45 mia-arch audit: BPF prog-id=66 op=LOAD
Oct 11 01:25:45 mia-arch systemd[1]: Started Process Core Dump (PID 124725/UID 0).
Oct 11 01:25:45 mia-arch audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@11-124725-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 01:25:45 mia-arch systemd-coredump[124731]: Resource limits disable core dumping for process 124724 (test-spa).
Oct 11 01:25:45 mia-arch systemd-coredump[124731]: [🡕] Process 124724 (test-spa) of user 1000 dumped core.
Oct 11 01:25:45 mia-arch systemd[1]: systemd-coredump@11-124725-0.service: Deactivated successfully.
Oct 11 01:25:45 mia-arch audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-coredump@11-124725-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Oct 11 01:25:45 mia-arch audit: BPF prog-id=60 op=UNLOAD
Oct 11 01:25:45 mia-arch audit: BPF prog-id=59 op=UNLOAD
Oct 11 01:25:45 mia-arch audit: BPF prog-id=58 op=UNLOAD
I do believe that this is something that is special about my system, as I do believe the package built without issues on my nearly identical system at work. But after seeing at least one other user experience the exact same issue, I feel confident that this can be fixed and I'm willing to help in any way shape or form to investigate this issue.
How Reproducible
Every time I build the package, the same error occurs. So on my specific system, perfectly reproducible, not affected by reboots or other system upgrades, persisted for over 2 weeks now.
Steps to reproduce, actual results, expected results
All described in the issue description above.
pwdump
output:
pwdump
console build log: log.txt
testlog.txt
:
testlog.txt