TIMESTAMP_LOGS: regression: testport totally broken while bulk -tkC is fine.

[mandree]

Prerequisites

• Have you checked for an existing issue describing your problem?
• Are you running the latest version?
• Is your ports tree recent?
• Is your FreeBSD Host on a supported release?

Describe the bug

The last poudriere-devel upgrade has regressed and even simple "testport" runs fail:

...
[00:00:06] Sanity checking build queue
[00:00:06] Recording filesystem state for prepkg... done
[00:00:06] Committing packages to repository: /usr/local/poudriere/data/packages/140amd64-default/.real_1716041440 via .latest symli
nk
[00:00:07] Removing old packages
[00:00:07] Building with flags: 
[00:00:07] Removing existing /usr/local
[00:00:07] Error: /usr/local/share/poudriere/testport.sh:get_job_id:16:get_job_id: Failed to parse jobs -l output for pid 6845: [2] 
+ 6844 Running            $
      6845                    $
[140amd64-default] [2024-05-18_16h10m34s] [crashed] Time: 00:00:05
[00:00:07] Logs: /usr/local/poudriere/data/logs/bulk/140amd64-default/2024-05-18_16h10m34s

How to reproduce

Steps to reproduce the behavior:

1. Install poudriere-devel-3.4.99.20240424
2. Update ports tree in /usr/ports
3. Set up a 14.0-RELEASE jail called 140amd64
4. sudo poudriere testport -j 140amd64 mail/bogofilter-bdb
5. see error like the one pasted above

Expected behavior

testport should build and test install/uninstall the port.

Screenshots

As above

Environment

• Host OS [e.g. 12.2 amd64]: 14.0-RELEASE (fully patched) amd64
• Jail OS [e.g. 12.0 powerpc]: same
• Browser: [e.g. chrome, safari]: irrelevant
• Poudriere Version [e.g. 3.3.1 or git hash or port version]: poudriere-devel-3.4.99.20240424
• Ports branch and revision [e.g. 2020Q3 r550754]: HEAD

Additional context

The bogofilter-bdb poudriere log file has 0 size, and next to it still lies a named pipe of the same name with .pipe added:

-rw-r--r--  3 root wheel 0 18 Mai  16:10 /usr/local/poudriere/data/logs/bulk/140amd64-default/2024-05-18_16h10m34s/logs/bogofilter-b
db-1.2.5_4.log
prw-r--r--  1 root wheel 0 18 Mai  16:10 /usr/local/poudriere/data/logs/bulk/140amd64-default/2024-05-18_16h10m34s/logs/bogofilter-b
db-1.2.5_4.log.pipe

[bdrewery]

Is this still a problem? 20240424 in quarterly tree seems fine to me. I wasn't able to reproduce.

[mandree]

Hi Bryan,

thanks for checking back.

Seems to still be an issue for me anyways, with 3.4.99.20240709

$ sudo poudriere testport -b latest -j140amd64 -vv security/openvpn |& less
[...]
[00:00:25] Debug: Skipping ordering/inspection run job gettext-tools-0.22.5
=>> Debug: python311-3.11.9_1: provides: libasprintf.so.0 libffi.so.8 libhistory.so.8 libintl.so.8 libmpdec++.so.4 libmpdec.so.4 libreadline.so.8
=>> Debug: python311-3.11.9_1: required: libffi.so.8
libintl.so.8
libmpdec.so.4
libreadline.so.8
[00:00:25] [01] [00:00:00] Finished   lang/python311 | python311-3.11.9_1: Nothing to do
[00:00:25] Debug: Skipping ordering/inspection run job py311-wheel-0.44.0
[00:00:25] Debug: Skipping ordering/inspection run job py311-packaging-24.1
[00:00:25] Debug: Skipping ordering/inspection run job py311-flit-core-3.9.0
[00:00:25] Debug: Skipping ordering/inspection run job py311-installer-0.7.0
[00:00:25] Debug: Skipping ordering/inspection run job ninja-1.11.1,4
[00:00:25] Debug: Skipping ordering/inspection run job python311-3.11.9_1
[00:00:27] Debug: Skipping ordering/inspection run job py311-docutils-0.21.2,1
[00:00:27] Debug: Skipping ordering/inspection run job py311-setuptools-63.1.0_1
[00:00:27] Debug: Skipping ordering/inspection run job py311-pyproject_hooks-1.1.0
[00:00:27] Debug: Skipping ordering/inspection run job py311-build-1.2.1
[00:00:27] Debug: Skipping ordering/inspection run job meson-1.5.1
[00:00:27] Stopping 3 builders
[00:00:27] Committing packages to repository: /usr/local/poudriere/data/packages/140amd64-default/.real_1722936441 via .latest symlink
[00:00:27] Removing old packages
[00:00:27] Building with flags: 
[00:00:27] Removing existing /usr/local
[00:00:27] Error: /usr/local/share/poudriere/testport.sh:get_job_id:16:get_job_id: Failed to parse jobs -l output for pid 77727: [2] + 77726 Running           $
      77727                   $
[140amd64-default] [2024-08-06_11h26m54s] [crashed] Queued: 3  Built: 0  Failed: 0  Skipped: 0  Ignored: 2  Fetched: 0  Tobuild: 1   Time: 00:00:22
[00:00:27] Logs: /usr/local/poudriere/data/logs/bulk/140amd64-default/2024-08-06_11h26m54s
[00:00:27] Cleaning up
[00:00:27] Unmounting file systems
Error: (59062) jobid:_kill_job:1: No such job: %77727
Error: (59062) jobid:_kill_job:1: No such job: %%77727
err: Recursive error detected: kill_job: trying to kill unknown job %77727

[bdrewery]

I managed to repro this with TIMESTAMP_LOGS=yes set in poudriere.conf.

[bdrewery]

Do you have that set? If so unsetting it will unblock you for now.

[bdrewery]

This explains the .pipe file being there too as the code crashing is the line before it removes that file in log_start.

[bdrewery]

I have a fix that I will push out to the port tomorrow.

[mandree]

Do you have that set? If so unsetting it will unblock you for now.

Yes, I confirm I have that set, and bulk -tC has been my workaround for most purposes.
Thanks for identifying the cause!

$ grep TIMESTAMP /usr/local/etc/poudriere.conf
#TIMESTAMP_LOGS=no
TIMESTAMP_LOGS=yes
#PRESERVE_TIMESTAMP=yes

[mandree]

Confirmed fixed in latest release through ports, 3.4.99.20240811. Thank you very much!