On Sunday, the packages project was moved into production. This project was both fun and challenging.
The goal: within 1 hour of the repo being updated, FreshPorts has the packages imported and updated for your viewing pleasure.
Today, I went checking to see if a repo update had occurred. An issue was found and corrected. This post contains the details.
Why post this stuff?
My writing helps me remember and understand what went wrong and helps me avoid similar oversights in the future. It also helps document how the system works and will be useful when someone else takes over FreshPorts.
The repo update
Looking at the backend status page I saw that an update had occurred today at 1800 UTC:
Browsing over to the sysutils/bacula9-server page, I could see it was still listing the packages from the 2020-05-16 build:
Ideas
What follows are my investigations, writtten after the fact of where I looked and what I found.
Was it imported?
First, I checked the logs for events around 1800 UTC. I found plenty of evidence that the repo update had been detected and imported:
May 18 18:00:07 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: Starting up May 18 18:00:07 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:11:aarch64/latest : 2018-Sep-29 04:24 May 18 18:00:07 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:11:aarch64/quarterly : 2020-May-05 00:02 May 18 18:00:07 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:11:amd64/latest : 2020-May-13 21:25 May 18 18:00:08 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:11:amd64/quarterly : 2020-May-12 05:56 May 18 18:00:08 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:11:i386/latest : 2020-May-13 18:34 May 18 18:00:08 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:11:i386/quarterly : 2020-May-12 05:56 May 18 18:00:08 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:12:aarch64/latest : 2018-Oct-11 05:47 May 18 18:00:08 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:12:aarch64/quarterly : 2020-May-09 17:08 May 18 18:00:08 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:12:amd64/latest : 2020-May-13 20:01 May 18 18:00:08 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:12:amd64/quarterly : 2020-May-12 05:30 May 18 18:00:08 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:12:i386/latest : 2020-May-13 17:58 May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:12:i386/quarterly : 2020-May-12 05:41 May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:13:aarch64/latest : 2020-May-16 06:24 May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:13:aarch64/quarterly : May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:13:amd64/latest : 2020-May-18 04:59 May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:13:amd64/quarterly : May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:13:i386/latest : 2020-May-18 05:40 May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: checking: FreeBSD:13:i386/quarterly : May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: There are 2 new repos ready for import: ['FreeBSD:13:amd64/latest : 2020-May-18 04:59', 'FreeBSD:13:i386/latest : 2020-May-18 05:40'] May 18 18:00:09 x8dtu-ingress01 check_repos_for_new_stuff.py[46975]: finishes May 18 18:00:10 x8dtu-ingress01 fp-daemon[47094]: yes, there is a job waiting May 18 18:00:10 x8dtu-ingress01 FreshPorts[47095]: flag '/var/db/freshports/signals/vuxml' not set. no work for process_vuxml.sh (/usr/local/libexec/freshports) May 18 18:00:10 x8dtu-ingress01 FreshPorts[47095]: /var/db/freshports/signals/new_repo_ready_for_import exists. About to run import_packagesite.py (/usr/local/libexec/freshports) May 18 18:00:10 x8dtu-ingress01 import_packagesite.py[47105]: Starting up May 18 18:00:10 x8dtu-ingress01 import_packagesite.py[47105]: we have 2 repos to process May 18 18:00:10 x8dtu-ingress01 import_packagesite.py[47105]: importing FreeBSD:13:amd64/latest May 18 18:00:10 x8dtu-ingress01 import_packagesite.py[47105]: command is: /usr/local/libexec/freshports/fetch-extract-parse-import-one-abi.sh FreeBSD:13:amd64 latest May 18 18:00:10 x8dtu-ingress01 freshports[47108]: got into /usr/local/libexec/freshports/fetch-extract-parse-import-one-abi.sh May 18 18:00:10 x8dtu-ingress01 dan[47109]: starting /usr/local/libexec/freshports/fetch-extract-parse-import-one-abi.sh May 18 18:00:25 x8dtu-ingress01 import-via-copy-packagesite-all-raw-fields.py[47420]: Starting up May 18 18:00:25 x8dtu-ingress01 syslogd: last message repeated 1 times May 18 18:00:25 x8dtu-ingress01 import-via-copy-packagesite-all-raw-fields.py[47420]: copying in from packagesite.tsv May 18 18:00:27 x8dtu-ingress01 import-via-copy-packagesite-all-raw-fields.py[47420]: Finishing May 18 18:00:27 x8dtu-ingress01 dan[47428]: finished importing FreeBSD:13:amd64/latest May 18 18:00:27 x8dtu-ingress01 import_packagesite.py[47105]: calling PackagesLastCheckedSetImportDate() May 18 18:00:27 x8dtu-ingress01 import_packagesite.py[47105]: importing FreeBSD:13:i386/latest May 18 18:00:27 x8dtu-ingress01 import_packagesite.py[47105]: command is: /usr/local/libexec/freshports/fetch-extract-parse-import-one-abi.sh FreeBSD:13:i386 latest May 18 18:00:27 x8dtu-ingress01 freshports[47430]: got into /usr/local/libexec/freshports/fetch-extract-parse-import-one-abi.sh May 18 18:00:27 x8dtu-ingress01 dan[47431]: starting /usr/local/libexec/freshports/fetch-extract-parse-import-one-abi.sh May 18 18:00:30 x8dtu-ingress01 import-via-copy-packagesite-all-raw-fields.py[47465]: Starting up May 18 18:00:30 x8dtu-ingress01 syslogd: last message repeated 1 times May 18 18:00:30 x8dtu-ingress01 import-via-copy-packagesite-all-raw-fields.py[47465]: copying in from packagesite.tsv May 18 18:00:31 x8dtu-ingress01 import-via-copy-packagesite-all-raw-fields.py[47465]: Finishing May 18 18:00:31 x8dtu-ingress01 dan[47480]: finished importing FreeBSD:13:i386/latest May 18 18:00:31 x8dtu-ingress01 import_packagesite.py[47105]: calling PackagesLastCheckedSetImportDate() May 18 18:00:31 x8dtu-ingress01 import_packagesite.py[47105]: There are 2 repos which need post-import processing: ['FreeBSD:13:amd64:latest', 'FreeBSD:13:i386:latest'] May 18 18:00:31 x8dtu-ingress01 import_packagesite.py[47105]: Finishing May 18 18:00:31 x8dtu-ingress01 FreshPorts[47095]: Finished running import_packagesite.py (/usr/local/libexec/freshports) May 18 18:00:31 x8dtu-ingress01 FreshPorts[47095]: flag '/var/db/freshports/signals/refresh_moved' not set. no work for process_moved.sh (/usr/local/libexec/freshports) May 18 18:00:31 x8dtu-ingress01 FreshPorts[47095]: flag '/var/db/freshports/signals/refresh_updating' not set. no work for process_updating.sh (/usr/local/libexec/freshports) May 18 18:00:31 x8dtu-ingress01 FreshPorts[47095]: /var/db/freshports/signals/new_repo_imported exists. About to run UpdatePackagesFromRawPackages.py (/usr/local/libexec/freshports) May 18 18:00:31 x8dtu-ingress01 UpdatePackagesFromRawPackages.py[47481]: Starting up May 18 18:00:31 x8dtu-ingress01 UpdatePackagesFromRawPackages.py[47481]: updating packages table for FreeBSD:13:amd64/latest May 18 18:00:37 x8dtu-ingress01 UpdatePackagesFromRawPackages.py[47481]: updating packages table for FreeBSD:13:i386/latest May 18 18:02:16 x8dtu-ingress01 UpdatePackagesFromRawPackages.py[47481]: There were 2 repos updated in packages. May 18 18:02:16 x8dtu-ingress01 UpdatePackagesFromRawPackages.py[47481]: Finishing May 18 18:02:16 x8dtu-ingress01 FreshPorts[47095]: Finished running UpdatePackagesFromRawPackages.py (/usr/local/libexec/freshports)
Conclusion: data import is working properly.
Was the cache cleared
For cache clearing to occur, the above process issues a PostgreSQL NOTIFY.
My next idea was fp-listen on the x8dtu-nginx01 host was not listening for the new events for clearing the package cache. The logs indicated it was not:
I went looking for the list output upon startup:
May 17 01:38:07 x8dtu-nginx01 fp-listen[42345]: Starting up - this should not occur often
May 17 01:38:07 x8dtu-nginx01 fp-listen[42345]: These are the (event name, script name) pairs we are ready for:
May 17 01:38:07 x8dtu-nginx01 fp-listen[42345]: ('port_updated', 'listen_port')
May 17 01:38:07 x8dtu-nginx01 fp-listen[42345]: ('ports_moved', 'listen_ports_moved')
May 17 01:38:07 x8dtu-nginx01 fp-listen[42345]: ('ports_updating', 'listen_ports_updating')
May 17 01:38:07 x8dtu-nginx01 fp-listen[42345]: ('vuxml', 'listen_vuxml')
May 17 01:38:07 x8dtu-nginx01 fp-listen[42345]: ('category_new', 'listen_category_new')
May 17 01:38:07 x8dtu-nginx01 fp-listen[42345]: ('date_updated', 'listen_date_updated')
Comparing it to dev, I found packages_imported was missing.
May 12 20:36:53 dev-nginx01 fp-listen[59516]: Starting up - this should not occur often
May 12 20:36:53 dev-nginx01 fp-listen[59516]: These are the (event name, script name) pairs we are ready for:
May 12 20:36:53 dev-nginx01 fp-listen[59516]: ('port_updated', 'listen_port')
May 12 20:36:53 dev-nginx01 fp-listen[59516]: ('ports_moved', 'listen_ports_moved')
May 12 20:36:53 dev-nginx01 fp-listen[59516]: ('ports_updating', 'listen_ports_updating')
May 12 20:36:53 dev-nginx01 fp-listen[59516]: ('vuxml', 'listen_vuxml')
May 12 20:36:53 dev-nginx01 fp-listen[59516]: ('category_new', 'listen_category_new')
May 12 20:36:53 dev-nginx01 fp-listen[59516]: ('date_updated', 'listen_date_updated')
May 12 20:36:53 dev-nginx01 fp-listen[59516]: ('packages_imported', 'listen_packages_imported')
Checking the webserver
Checking the webserver, I was about to restart the fp-listen process when I thought to check this output:
$ ps auwwx | grep readproc root 49860 0.0 0.0 10680 2180 - IJ Sun14 0:00.00 /usr/local/bin/readproctitle service errors: ................................................................................................................ ..................................................................................cannot open 'main_tank/data/freshports/backend/cache/packages': missing '@' delimiter in snapshot name\ncannot open 'main_tank/data/freshports/backend/cache/packages': missing '@' delimiter in snapshot name\n
HAH! So the NOTIFY was received.
The issue was configuration as shown by my change here:
[dan@x8dtu-nginx01:/usr/local/etc/freshports] $ sudo diff -ruN fp-listen.ini~ fp-listen.ini --- fp-listen.ini~ 2020-05-17 13:25:50.000000000 +0000 +++ fp-listen.ini 2020-05-18 19:35:58.964021000 +0000 @@ -18,7 +18,7 @@ NEWS_CACHE_DIR = %(BASEDIR)s/cache/news/ # this is the name of the zfs filesystem to rollback, including the snapshot name -PKG_ZFS_SNAPSHOT = main_tank/data/freshports/backend/cache/packages +PKG_ZFS_SNAPSHOT = main_tank/data/freshports/backend/cache/packages@empty [flags] # used for processing category updates [dan@x8dtu-nginx01:/usr/local/etc/freshports] $
The snapshot name was missing.
Clearing the cache
I cleared the cache by entering this command:
[dan@x8dtu-nginx01:~] $ echo zfs rollback main_tank/data/freshports/backend/cache/packages@empty | sudo su -fm freshports
Checking the webpage
Now the sysutils/bacula9-server page shows:
Now that’s the refreshed data.
What about the missing LISTEN for information?
Remember when I said the host was not listening for the new events? Let’s check farther into the logs:
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: Starting up - this should not occur often
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: These are the (event name, script name) pairs we are ready for:
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: ('port_updated', 'listen_port')
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: ('ports_moved', 'listen_ports_moved')
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: ('ports_updating', 'listen_ports_updating')
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: ('vuxml', 'listen_vuxml')
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: ('category_new', 'listen_category_new')
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: ('date_updated', 'listen_date_updated')
May 17 12:59:32 x8dtu-nginx01 fp-listen[14300]: ('packages_imported', 'listen_packages_imported')
Yeah, there it is. It was listening. I was looking too early in the logs
A lingering issue
While inspecting the logs, I noticed that fp-listen was restarting often, sometimes hundreds of times a day.
[dan@x8dtu-nginx01:~] $ sudo grep -c 'Starting up - this should not occur often' /var/log/freshports/freshports.log* /var/log/freshports/freshports.log:0 /var/log/freshports/freshports.log.0:85 /var/log/freshports/freshports.log.1:255 /var/log/freshports/freshports.log.10:0 /var/log/freshports/freshports.log.11:0 /var/log/freshports/freshports.log.12:0 /var/log/freshports/freshports.log.13:0 /var/log/freshports/freshports.log.2:159 /var/log/freshports/freshports.log.3:119 /var/log/freshports/freshports.log.4:236 /var/log/freshports/freshports.log.5:129 /var/log/freshports/freshports.log.6:0 /var/log/freshports/freshports.log.7:0 /var/log/freshports/freshports.log.8:0 /var/log/freshports/freshports.log.9:0
This is an issue I noticed earlier and fixed. I also think it was related to a recent issue.
The problem occurs when trying to clear the cache for for a port. This appears in the logs as:
May 17 12:59:32 x8dtu-nginx01 fp-listen[2856]: removing glob /var/db/freshports/cache/ports/devel/py-setuptools/*
There have been no restarted since May 17 17:01:28. Checking the logs, I see this was intentional, because I restarted the fp-listen process at that time.
May 17 17:01:28 x8dtu-nginx01 sudo[38174]: dan : TTY=pts/2 ; PWD=/var/db/freshports/cache/packages ; USER=root ; COMMAND=/usr/local/bin/svc -t /var/service/fp-listen
I’m guessing I did that right after adding the required new entry to the database, something like this:
-- insert this so fp-listen knows to listen
freshports.org=# insert into listen_for ( name, script_name ) values ('listen_for', 'ClearPackagesCache');
The original is found in my git repo
Welcome to packages
I’m glad that work is now in production, not just because it was complex, but also because of how seamlessly the data is imported and presented to the user.
If you notice issues, please let me know. If you are a maintainer and you know the repo has a lagged version, please check to see if FreshPorts detects them.
Thank you.
Edit: 2020-05-22
fp-listen was not restarted after the update to fp-listen.ini:
[dan@x8dtu-nginx01:/usr/local/etc/freshports] $ ps auwwx | grep fp-listen freshports 38176 0.0 0.0 29348 19668 - SJ Sun17 0:58.23 /usr/local/bin/python3.7 /usr/local/lib/python3.7/site-packages/fp-listen/fp-listen.pyc root 49862 0.0 0.0 10696 2192 - IJ Sun14 0:00.02 supervise fp-listen dan 66966 0.0 0.0 11176 2676 0 R+J 20:40 0:00.00 grep fp-listen [dan@x8dtu-nginx01:/usr/local/etc/freshports] $ ls -l fp-listen.ini -rw-r----- 1 root freshports 813 May 18 19:35 fp-listen.ini [dan@x8dtu-nginx01:/usr/local/etc/freshports] $
The date on the file is after the date on the process. Rookie error.
fp-listen has been restarted.
Edit: 2020-05-22
That’s what we want to see!
May 24 01:00:28 x8dtu-nginx01 fp-listen[67261]: Just woke up! ************* May 24 01:00:28 x8dtu-nginx01 fp-listen[67261]: Got NOTIFY: pid='71564', channel='packages_imported', payload='' May 24 01:00:28 x8dtu-nginx01 fp-listen[67261]: found key packages_imported May 24 01:00:28 x8dtu-nginx01 fp-listen[67261]: invoking PackagesCacheClear() May 24 01:00:28 x8dtu-nginx01 fp-listen[67261]: Time to rollback main_tank/data/freshports/backend/cache/packages@empty May 24 01:00:30 x8dtu-nginx01 fp-listen[67261]: zfs rollback succeeded. May 24 01:00:30 x8dtu-nginx01 fp-listen[67261]: Done with PackagesCacheClear()
Done. Closing this issue.
