Overnight, these messages appeared in the dev.freshports logs. This is not the first time this has happened.
EDIT: 2024-02-18 – it was ZFS snapshot related. These directories each have a ZFS file system behind them. The cache is cleared by zfs rollback. My solution: destroy the snapshot I was rolling back to, change the permissions, take the snapshot. Solved.
This is the fp-listen daemon (a small python script) which runs on each FreshPorts website – it listens for backend NOTIFY messages from PostgreSQL. These messages indicate something in cache needs clearing.
In this case, a sanity test failure clearing failed, because of permissions.
Jan 29 12:15:05 dev-nginx01 fp_listen[13815]: Traceback (most recent call last): Jan 29 12:15:05 dev-nginx01 fp_listen[13815]: File "/usr/local/lib/python3.9/site-packages/fp-listen/fp-listen.py", line 408, in <module> Jan 29 12:15:05 dev-nginx01 fp_listen[13815]: CommitsCacheClear() Jan 29 12:15:05 dev-nginx01 fp_listen[13815]: File "/usr/local/lib/python3.9/site-packages/fp-listen/fp-listen.py", line 226, in CommitsCacheClear Jan 29 12:15:05 dev-nginx01 fp_listen[13815]: os.remove(filename) Jan 29 12:15:05 dev-nginx01 fp_listen[13815]: PermissionError: [Errno 13] Permission denied: '/var/db/freshports/cache/general/sanity_test_failures.PageSize100.PageNum1.html' Jan 29 12:21:06 dev-nginx01 fp_listen[13815]: Traceback (most recent call last): Jan 29 12:21:06 dev-nginx01 fp_listen[13815]: File "/usr/local/lib/python3.9/site-packages/fp-listen/fp-listen.py", line 408, in <module> Jan 29 12:21:06 dev-nginx01 fp_listen[13815]: CommitsCacheClear() Jan 29 12:21:06 dev-nginx01 fp_listen[13815]: File "/usr/local/lib/python3.9/site-packages/fp-listen/fp-listen.py", line 226, in CommitsCacheClear Jan 29 12:21:06 dev-nginx01 fp_listen[13815]: os.remove(filename) Jan 29 12:21:06 dev-nginx01 fp_listen[13815]: PermissionError: [Errno 13] Permission denied: '/var/db/freshports/cache/general/sanity_test_failures.PageSize100.PageNum1.html'
I have seen this. Many times before. It gets corrected. It comes back. Somewhere, something is messing with permissions.
The highlighted lines below need to be chmod g+w.
[13:17 dev-nginx01 dan ~] % ls -l ~freshports/cache total 442 drwxr-xr-x 14 www freshports 14 2024.01.25 23:59 categories/ drwxrwxr-x 118 www freshports 118 2024.01.24 20:25 commits/ drwxrwxr-x 4 www freshports 4 2024.01.23 10:18 daily/ drwxr-xr-x 2 www freshports 5 2024.01.29 09:48 general/ drwxrwxr-x 2 freshports freshports 9 2024.01.29 13:15 html/ drwxrwxr-x 2 www freshports 3 2024.01.29 13:14 news/ drwxrwxr-x 59 www freshports 59 2024.01.29 06:31 packages/ drwxr-xr-x 2 www freshports 2 2021.02.28 18:20 pages/ drwxrwxr-x 61 www freshports 61 2024.01.29 06:31 ports/ -rw-r--r-- 1 www freshports 2118502 2024.01.29 09:50 searchlog.txt drwxr-xr-x 2 www freshports 2 2024.01.29 13:14 spooling/
Compare with production:
[13:22 aws-1-nginx01 dan ~] % ls -l ~freshports/cache total 89518 drwxrwxr-x 118 www freshports 118 2024.01.24 12:25 categories/ drwxrwxr-x 5195 www freshports 5195 2024.01.29 13:20 commits/ drwxrwxr-x 7 www freshports 7 2024.01.22 21:19 daily/ drwxrwxr-x 2 www freshports 1315 2024.01.29 13:13 general/ drwxrwxr-x 2 freshports freshports 8 2024.01.29 13:21 html/ drwxrwxr-x 2 www freshports 11 2024.01.29 13:21 news/ drwxrwxr-x 64 www freshports 64 2024.01.29 12:27 packages/ drwxrwxr-x 2 www freshports 2 2021.03.25 23:29 pages/ drwxrwxr-x 71 www freshports 149 2024.01.29 13:04 ports/ -rw-r--r-- 1 www freshports 179991938 2024.01.29 13:17 searchlog.txt drwxrwxr-x 2 www freshports 2 2024.01.29 13:22 spooling/
The spooling directory appears OK. If anything I suspect it might not need the g+w.
This problem always arises after the host is rebooted.
To help diagnosis, I stopped the jail and examined the permissions from the host:
[13:17 r730-01 dvl ~] % sudo service jail stop dev-nginx01 Stopping jails: dev-nginx01. [13:24 r730-01 dvl ~] % ls -l /jails/dev-nginx01/var/db/freshports/cache total 346 drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 categories/ drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 commits/ drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 daily/ drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 general/ drwxr-xr-x 2 root 10001 2 2021.02.28 19:19 html/ drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 news/ drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 packages/ drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 pages/ drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 ports/ -rw-r--r-- 1 www 10001 2118502 2024.01.29 09:50 searchlog.txt drwxrwxr-x 2 root 10001 2 2021.02.28 19:18 spooling/ [13:25 r730-01 dvl ~] %
As you can see here, the permissions are as expected (html does not need to be
g+w
; it is mounted via nullfs and is read-only).
This confirms it is all unmounted:
[13:25 r730-01 dvl ~] % mount | grep dev-nginx01 data02/jails/dev-nginx01 on /jails/dev-nginx01 (zfs, local, noatime, nfsv4acls)
After starting the jail, the problem permissions are back:
[13:28 r730-01 dvl ~] % sudo service jail start dev-nginx01 Starting jails: dev-nginx01. [13:29 r730-01 dvl ~] % ls -l /jails/dev-nginx01/var/db/freshports/cache total 442 drwxr-xr-x 14 www 10001 14 2024.01.25 23:59 categories/ drwxrwxr-x 118 www 10001 118 2024.01.24 20:25 commits/ drwxrwxr-x 4 www 10001 4 2024.01.23 10:18 daily/ drwxr-xr-x 2 www 10001 5 2024.01.29 09:48 general/ drwxrwxr-x 2 10001 10001 9 2024.01.29 13:27 html/ drwxrwxr-x 2 www 10001 3 2024.01.29 13:14 news/ drwxrwxr-x 59 www 10001 59 2024.01.29 06:31 packages/ drwxr-xr-x 2 www 10001 2 2021.02.28 18:20 pages/ drwxrwxr-x 61 www 10001 61 2024.01.29 06:31 ports/ -rw-r--r-- 1 www 10001 2118502 2024.01.29 09:50 searchlog.txt drwxr-xr-x 2 www 10001 2 2024.01.29 13:29 spooling/ [13:29 r730-01 dvl ~] % mount | grep dev-nginx01 data02/jails/dev-nginx01 on /jails/dev-nginx01 (zfs, local, noatime, nfsv4acls) /jails/dev-ingress01/var/db/freshports/cache/html on /jails/dev-nginx01/var/db/freshports/cache/html (nullfs, local, noatime, noexec, nosuid, read-only, nfsv4acls) devfs on /jails/dev-nginx01/dev (devfs) data02/freshports/dev-nginx01/www/freshports on /jails/dev-nginx01/usr/local/www/freshports (zfs, local, noatime, nfsv4acls) data02/freshports/dev-nginx01/www/freshsource on /jails/dev-nginx01/usr/local/www/freshsource (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/spooling on /jails/dev-nginx01/var/db/freshports/cache/spooling (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/daily on /jails/dev-nginx01/var/db/freshports/cache/daily (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/general on /jails/dev-nginx01/var/db/freshports/cache/general (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/commits on /jails/dev-nginx01/var/db/freshports/cache/commits (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/pages on /jails/dev-nginx01/var/db/freshports/cache/pages (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/news on /jails/dev-nginx01/var/db/freshports/cache/news (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/packages on /jails/dev-nginx01/var/db/freshports/cache/packages (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/ports on /jails/dev-nginx01/var/db/freshports/cache/ports (zfs, local, noatime, nfsv4acls) data02/freshports/jailed/dev-nginx01/cache/categories on /jails/dev-nginx01/var/db/freshports/cache/categories (zfs, local, noatime, nfsv4acls)
Reset and restart
Let’s try resetting the permissions and restarting the jail.
[8:24 pro03 dan ~] % dn Last login: Mon Jan 29 13:17:40 2024 from pro03.startpoint.vpn.unixathome.org [13:31 dev-nginx01 dan ~] % cd ~freshports/cache [13:31 dev-nginx01 dan ~freshports/cache] % ls -l total 442 drwxr-xr-x 14 www freshports 14 2024.01.25 23:59 categories/ drwxrwxr-x 118 www freshports 118 2024.01.24 20:25 commits/ drwxrwxr-x 4 www freshports 4 2024.01.23 10:18 daily/ drwxr-xr-x 2 www freshports 5 2024.01.29 09:48 general/ drwxrwxr-x 2 freshports freshports 9 2024.01.29 13:30 html/ drwxrwxr-x 2 www freshports 3 2024.01.29 13:14 news/ drwxrwxr-x 59 www freshports 59 2024.01.29 06:31 packages/ drwxr-xr-x 2 www freshports 2 2021.02.28 18:20 pages/ drwxrwxr-x 61 www freshports 61 2024.01.29 06:31 ports/ -rw-r--r-- 1 www freshports 2118502 2024.01.29 09:50 searchlog.txt drwxr-xr-x 2 www freshports 2 2024.01.29 13:29 spooling/ [13:31 dev-nginx01 dan ~freshports/cache] % sudo chmod g+w categories general pages spooling [13:31 dev-nginx01 dan ~freshports/cache] % ls -l total 442 drwxrwxr-x 14 www freshports 14 2024.01.25 23:59 categories/ drwxrwxr-x 118 www freshports 118 2024.01.24 20:25 commits/ drwxrwxr-x 4 www freshports 4 2024.01.23 10:18 daily/ drwxrwxr-x 2 www freshports 5 2024.01.29 09:48 general/ drwxrwxr-x 2 freshports freshports 9 2024.01.29 13:30 html/ drwxrwxr-x 2 www freshports 3 2024.01.29 13:14 news/ drwxrwxr-x 59 www freshports 59 2024.01.29 06:31 packages/ drwxrwxr-x 2 www freshports 2 2021.02.28 18:20 pages/ drwxrwxr-x 61 www freshports 61 2024.01.29 06:31 ports/ -rw-r--r-- 1 www freshports 2118502 2024.01.29 09:50 searchlog.txt drwxrwxr-x 2 www freshports 2 2024.01.29 13:31 spooling/ [13:32 dev-nginx01 dan ~freshports/cache] % Connection to dev-nginx01.int.unixathome.org closed by remote host. Connection to dev-nginx01.int.unixathome.org closed. [8:32 pro03 dan ~] %
That looks right. Let’s log back in.
[8:32 pro03 dan ~] % dn Last login: Mon Jan 29 13:31:59 2024 from pro03.startpoint.vpn.unixathome.org [13:33 dev-nginx01 dan ~] % ls -l ~freshports/cache total 442 drwxrwxr-x 14 www freshports 14 2024.01.25 23:59 categories/ drwxrwxr-x 118 www freshports 118 2024.01.24 20:25 commits/ drwxrwxr-x 4 www freshports 4 2024.01.23 10:18 daily/ drwxrwxr-x 2 www freshports 5 2024.01.29 09:48 general/ drwxrwxr-x 2 freshports freshports 9 2024.01.29 13:33 html/ drwxrwxr-x 2 www freshports 3 2024.01.29 13:14 news/ drwxrwxr-x 59 www freshports 59 2024.01.29 06:31 packages/ drwxrwxr-x 2 www freshports 2 2021.02.28 18:20 pages/ drwxrwxr-x 61 www freshports 61 2024.01.29 06:31 ports/ -rw-r--r-- 1 www freshports 2118502 2024.01.29 09:50 searchlog.txt drwxrwxr-x 2 www freshports 2 2024.01.29 13:33 spooling/ [13:34 dev-nginx01 dan ~] %
That is correct. Whatever is messing this up is not the start/stop stuff.
What I should have done
I should have checked the mount point before I stopping the jail the first time. It may be overlapping mount points. For the record, this is what we have now:
[13:36 r730-01 dvl ~] % zfs list | grep dev-nginx01 data02/freshports/dev-nginx01 51.7M 1.29T 96K none data02/freshports/dev-nginx01/www 51.6M 1.29T 96K /jails/dev-nginx01/usr/local/www data02/freshports/dev-nginx01/www/freshports 48.7M 1.29T 48.7M /jails/dev-nginx01/usr/local/www/freshports data02/freshports/dev-nginx01/www/freshsource 2.82M 1.29T 2.82M /jails/dev-nginx01/usr/local/www/freshsource data02/freshports/jailed/dev-nginx01 158M 1.29T 96K none data02/freshports/jailed/dev-nginx01/cache 158M 1.29T 96K /var/db/freshports/cache data02/freshports/jailed/dev-nginx01/cache/categories 260K 1.29T 188K /var/db/freshports/cache/categories data02/freshports/jailed/dev-nginx01/cache/commits 5.86M 1.29T 5.79M /var/db/freshports/cache/commits data02/freshports/jailed/dev-nginx01/cache/daily 572K 1.29T 500K /var/db/freshports/cache/daily data02/freshports/jailed/dev-nginx01/cache/general 1.22M 1.29T 1.15M /var/db/freshports/cache/general data02/freshports/jailed/dev-nginx01/cache/news 240K 1.29T 168K /var/db/freshports/cache/news data02/freshports/jailed/dev-nginx01/cache/packages 19.9M 1.29T 19.8M /var/db/freshports/cache/packages data02/freshports/jailed/dev-nginx01/cache/pages 160K 1.29T 96K /var/db/freshports/cache/pages data02/freshports/jailed/dev-nginx01/cache/ports 129M 1.29T 129M /var/db/freshports/cache/ports data02/freshports/jailed/dev-nginx01/cache/spooling 216K 1.29T 120K /var/db/freshports/cache/spooling data02/jails/dev-nginx01 5.10G 1.29T 5.05G /jails/dev-nginx01
My plan: check back here the next time this happens. I should have created this post long ago.
It happened again this morning.
It might be the zfs rollbacks. :)