Build failed. More information on how to proceed and troubleshoot errors available at https://fedoraproject.org/wiki/Zuul-based-ci
https://fedora.softwarefactory-project.io/zuul/buildset/212b5ddbbf3441eeb4236d62c52700a7

• validate : FAILURE in 12m 28s

Build failed. More information on how to proceed and troubleshoot errors available at https://fedoraproject.org/wiki/Zuul-based-ci
https://fedora.softwarefactory-project.io/zuul/buildset/e8116f56a7af496fadfddfcc9175e62b

• validate : FAILURE in 10m 18s

Waiting on https://bodhi.fedoraproject.org/updates/FEDORA-2024-95ba17d99d

/recheck

recheck

This one is going to fail too. add-determinism-0.3.3-1.fc41.x86_64 was installed, but 0.3.5 is needed. Maybe add a version guard?

Build failed. More information on how to proceed and troubleshoot errors available at https://fedoraproject.org/wiki/Zuul-based-ci
https://fedora.softwarefactory-project.io/zuul/buildset/a060c6c748f94dc59729e57033c74b35

• validate : FAILURE in 10m 21s

recheck

Build succeeded.
https://fedora.softwarefactory-project.io/zuul/buildset/804612d82d2246f693e390a4e95ac6aa

• validate : SUCCESS in 15m 04s

2024-07-21 11:26:00.494509 | vm | + add-determinism -j --handler pyc-zero-mtime /usr
2024-07-21 11:26:02.474021 | vm | /usr/share/gcc-14/python/libstdcxx/__pycache__/__init__.cpython-313.pyc: rewriting with normalized contents
...
2024-07-21 11:26:08.887636 | vm | /usr/lib64/python3.13/zoneinfo/__pycache__/_zoneinfo.cpython-313.pyc: rewriting with normalized contents
2024-07-21 11:26:09.027971 | vm | Scanned 9214 directories and 73077 files,
2024-07-21 11:26:09.276806 | vm |                processed 4859 inodes,
2024-07-21 11:26:09.276923 | vm |                4617 modified (4 replaced + 4613 rewritten),
2024-07-21 11:26:09.276938 | vm |                0 unsupported format, 0 errors

I'm surprised that is takes so much time: 9 s.

The logging is rather verbose, because it writes one line per each modified file. This makes sense in the usual case, because we usually only modify a handful of files. But here this doesn't work so well. Do you think it'd make sense to suppress the per-file output? This would likely also speed up the whole process.

This one is going to fail too. add-determinism-0.3.3-1.fc41.x86_64 was installed, but 0.3.5 is needed. Maybe add a version guard?

Ideally we would but there isn't a good way to do that right now. I'll only push this to branches where this is available.

Do you think it'd make sense to suppress the per-file output? This would likely also speed up the whole process.

Indeed, it would probably be nice to add a "--quiet" switch.

For us, 9s is negligible as the builds usually takes 20 to 40 minutes. But I'll take any improvement :).

https://github.com/keszybz/add-determinism/pull/32 makes the logging quieter for that handler.

20 to 40 minutes

Yikes!

Running the same test from https://pagure.io/workstation-ostree-config/pull-request/505#comment-201638 give me the same weird result on a freshly updated Rawhide system with this change in:

$ python3 -v -c 'import mailbox' 2>&1 | grep '# bytecode is stale for' -A2
# bytecode is stale for 'urllib'
# code object from /usr/lib64/python3.13/urllib/__init__.py
# could not create '/usr/lib64/python3.13/urllib/__pycache__/__init__.cpython-313.pyc': OSError(30, 'Read-only file system')

CC @churchyard This is pointing to an issue on the Python side of things.

If I run the same commands (https://pagure.io/workstation-ostree-config/pull-request/505#comment-201649) on the bytecode files, I correctly get 0.

What issue? Is the mtime of /usr/lib64/python3.13/urllib/__init__.py 0 and the mtime in /usr/lib64/python3.13/urllib/__pycache__/__init__.cpython-313.pyc also 0?

A link to the image that exhibits the issue?

To reproduce:
1. Install latest Silverblue / KInoite from https://openqa.fedoraproject.org/nightlies.html
2. Run $ python3 -v -c 'import mailbox' 2>&1 | grep '# bytecode is stale for' -A2

Expected output: nothing
Actual output:

# bytecode is stale for 'urllib'
# code object from /usr/lib64/python3.13/urllib/__init__.py
# could not create '/usr/lib64/python3.13/urllib/__pycache__/__init__.cpython-313.pyc': OSError(30, 'Read-only file sys

You can verify that /usr/lib64/python3.13/urllib/__init__.py has mtime 0 and that running the python code from https://pagure.io/workstation-ostree-config/pull-request/505#comment-201649 gives 0 as mtime for the bytecode.

Thus add-determinism worked, but likely somewhere in Python it does not accept this bytecode as valid.

So… I see the problem, but I think the issue is different.

I downloaded https://kojipkgs.fedoraproject.org/compose/branched/Fedora-41-20240821.n.0/compose/Kinoite/x86_64/iso/Fedora-Kinoite-ostree-x86_64-41-20240821.n.0.iso and installed a VM in libvirt with all defaults.

After rebooting into the installed image:

$ ls -l /usr/lib64/python3.13/urllib/
total 164
-rw-r--r--. 2 root root   2415 Jan  1  1970 error.py
-rw-r--r--. 1 root root      0 Aug 22 11:46 __init__.py
-rw-r--r--. 2 root root  44922 Jan  1  1970 parse.py
drwxr-xr-x. 1 root root    984 Jan  1  1970 __pycache__
-rw-r--r--. 2 root root 101549 Jan  1  1970 request.py
-rw-r--r--. 2 root root   2361 Jan  1  1970 response.py
-rw-r--r--. 2 root root   9424 Jan  1  1970 robotparser.py

As you can see, something has bumped the mtime of __init__.py. The file is empty, so I think the contents weren't actually modified.

$ find /usr/lib64/python3.13/ -mtime 0
/usr/lib64/python3.13/email/mime/__init__.py
/usr/lib64/python3.13/pydoc_data/__init__.py
/usr/lib64/python3.13/site-packages/_selinux.cpython-313-x86_64-linux-gnu.so
/usr/lib64/python3.13/site-packages/PIL/py.typed
/usr/lib64/python3.13/site-packages/cairo/py.typed
/usr/lib64/python3.13/site-packages/selinux-3.7.dist-info/REQUESTED
/usr/lib64/python3.13/site-packages/setools/py.typed
/usr/lib64/python3.13/urllib/__init__.py
$ find /usr/lib64/python3.13/ -mtime 0|xargs ls -l 
-rw-r--r--. 1 root root  0 Aug 22 11:46 /usr/lib64/python3.13/email/mime/__init__.py
-rw-r--r--. 1 root root  0 Aug 22 11:46 /usr/lib64/python3.13/pydoc_data/__init__.py
-rw-r--r--. 1 root root  0 Aug 22 11:46 /usr/lib64/python3.13/site-packages/cairo/py.typed
-rw-r--r--. 1 root root  0 Aug 22 11:46 /usr/lib64/python3.13/site-packages/PIL/py.typed
-rw-r--r--. 1 root root  0 Aug 22 11:46 /usr/lib64/python3.13/site-packages/selinux-3.7.dist-info/REQUESTED
lrwxrwxrwx. 2 root root 48 Aug 22 11:41 /usr/lib64/python3.13/site-packages/_selinux.cpython-313-x86_64-linux-gnu.so -> selinux/_selinux.cpython-313-x86_64-linux-gnu.so
-rw-r--r--. 1 root root  0 Aug 22 11:46 /usr/lib64/python3.13/site-packages/setools/py.typed
-rw-r--r--. 1 root root  0 Aug 22 11:46 /usr/lib64/python3.13/urllib/__init__.py

11:46 is approximately the time when I did the installation.
journalctl --list-boots says that the first boot was Thu 2024-08-22 11:56:24 CEST, so it seems that the issue occurs prior to the first boot, during the installation.

This seems to be a fairly widespread thing:

$ sudo find /usr -mtime 0|wc -l
30530
$ sudo find /usr -mtime 0 -type f|wc -l
104
$ sudo find /usr -mtime 0 -type f \! -empty|wc -l
0

Empty files are initialized incorrectly?

(find -mtime 0 lists files modified recently. The man page says "exactly 0 days ago", and a bit later "any fractional part is ignored". This description isn't great, but anyway, this is what we need here, since the machine was installed less than 1 day ago.)

Nice catch. This looks like an ostree issue.

Might be https://github.com/ostreedev/ostree/issues/2809

I'm reverting this as this causing issues with package layering: https://github.com/fedora-silverblue/issue-tracker/issues/590