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

Edited Oct 11, 2021 by Marek Ištok