There is no solution here. I’m documenting for future such events.
From time to time, I’ve been seeing this message in the logs:
Dec 31 03:00:27 dev-ingress01 import_packagesite.py[37149]: No repos need importing. How did this happen? This should never happen.
Today, I decided to look into why.
In /var/log/freshports/freshports.log, I found:
Dec 31 03:00:25 dev-ingress01 check_repos_for_new_stuff.py[33900]: There are 10 new repos ready for import: ['FreeBSD:12:aarch64/latest : ', 'FreeBSD:12:aarch64/quarterly : ', 'FreeBSD:12:amd64/latest : ', 'FreeBSD:12:amd64/quarterly : ', 'FreeBSD:12:armv6/latest : ', 'FreeBSD:12:armv6/quarterly : ', 'FreeBSD:12:armv7/latest : ', 'FreeBSD:12:armv7/quarterly : ', 'FreeBSD:12:i386/latest : ', 'FreeBSD:12:i386/quarterly : ']
OK, so those are the repos which it thinks needs importing.
Let’s pick one ABI and research FreeBSD:12:aarch64.
Above that entry, we find:
Dec 31 00:00:04 dev-ingress01 check_repos_for_new_stuff.py[79776]: checking: FreeBSD:12:aarch64/latest : Thu, 11 Oct 2018 05:47:38 GMT Dec 31 00:00:04 dev-ingress01 check_repos_for_new_stuff.py[79776]: checking: FreeBSD:12:aarch64/quarterly : Sun, 24 Dec 2023 20:12:56 GMT Dec 31 01:00:04 dev-ingress01 check_repos_for_new_stuff.py[55459]: checking: FreeBSD:12:aarch64/latest : Thu, 11 Oct 2018 05:47:38 GMT Dec 31 01:00:04 dev-ingress01 check_repos_for_new_stuff.py[55459]: checking: FreeBSD:12:aarch64/quarterly : Sun, 24 Dec 2023 20:12:56 GMT Dec 31 02:00:03 dev-ingress01 check_repos_for_new_stuff.py[36093]: checking: FreeBSD:12:aarch64/latest : Thu, 11 Oct 2018 05:47:38 GMT Dec 31 02:00:04 dev-ingress01 check_repos_for_new_stuff.py[36093]: checking: FreeBSD:12:aarch64/quarterly : Sun, 24 Dec 2023 20:12:56 GMT Dec 31 03:00:04 dev-ingress01 check_repos_for_new_stuff.py[33900]: checking: FreeBSD:12:aarch64/latest : Dec 31 03:00:04 dev-ingress01 check_repos_for_new_stuff.py[33900]: checking: FreeBSD:12:aarch64/quarterly :
First, why did the date field suddenly go empty?
That date value is the Last-modified value when fetching the repo. For example:
[14:09 dev-ingress01 dan ~/scripts] % curl -sI https://pkg.freebsd.org/FreeBSD:12:aarch64/latest/packagesite.txz HTTP/2 404 server: nginx date: Sun, 31 Dec 2023 14:10:11 GMT content-type: text/html content-length: 146
Which is a 404 – Could it be that the repo was deleted from the server sometime between 02:00:04 and 03:00:04 on Dec 31?
Given there is no repo to be downloaded, should it have been flagged for refreshing? No.
We always update the packages_last_checked.last_checked date column by invoking:
SELECT * FROM PackagesLastCheckedSetRepoDate('FreeBSD:12:aarch64','latest',NULL)
The return values from that function (either true or false) indicates if we need to import. From the code, we find:
syslog.syslog(syslog.LOG_NOTICE, 'checking: ' + row['abi_name'] + '/' + row['package_set'] + ' : ' + str(repo_date or ""))
# now we update the last_checked and repo_date in the packages_last_checked table
# PackagesLastCheckedSetRepoDate(a_abi_name text, a_package_set text, a_CheckedDate text)
cursUpdate.callproc('PackagesLastCheckedSetRepoDate', (row['abi_name'],row['package_set'], repo_date))
retval = cursUpdate.fetchone()[0]
if retval == 1:
ReposWhichNeedImporting.append(row['abi_name'] + '/' + row['package_set'] + ' : ' + str(repo_date or ""))
Let’s look at PackagesLastCheckedSetRepoDate():
CREATE OR REPLACE FUNCTION PackagesLastCheckedSetRepoDate(a_abi_name text, a_package_set package_sets, a_RepoDate timestamp) returns boolean AS
$$
DECLARE
l_repo_date timestamp;
BEGIN
SELECT repo_date
INTO l_repo_date
FROM packages_last_checked PLC, abi
WHERE PLC.abi_id = abi.id
AND abi.name = a_abi_name
AND package_set = a_package_set
FOR UPDATE OF PLC;
-- last_checked must always be updated
UPDATE packages_last_checked PLC
SET last_checked = CURRENT_TIMESTAMP,
repo_date = CASE WHEN repo_date = a_RepoDate THEN repo_date ELSE a_RepoDate END,
import_date = CASE WHEN repo_date = a_RepoDate THEN import_date ELSE null END,
processed_date = CASE WHEN repo_date = a_RepoDate THEN processed_date ELSE null END
FROM abi
WHERE PLC.abi_id = abi.id
AND abi.name = a_abi_name
AND package_set = a_package_set;
-- we compare against the value before the update
RETURN l_repo_date IS DISTINCT FROM a_RepoDate;
END;
$$ LANGUAGE 'plpgsql' VOLATILE;
There we go. The repo_date gets set to NULL when it is not found. That is why it suddenly disappears.
I suspect the RETURN needs to account for null values of a_RepoDate.
Perhaps: RETURN a_RepoDate IS NOT NULL AND l_repo_date IS DISTINCT FROM a_RepoDate;
.
Testing
I reset the data to be what it was at 02:00:04:
freshports.dev=# begin; update packages_last_checked set repo_date = '2018-10-11 05:47:38' where abi_id = 9 and package_set = 'latest';
BEGIN
UPDATE 1
freshports.dev=*# commit;
COMMIT
freshports.dev=# select * from packages_last_checked where abi_id in (select id from abi where name like ('FreeBSD:12:aarch64'));
abi_id | package_set | last_checked | repo_date | import_date | processed_date
--------+-------------+-------------------------------+------------------------+-------------+----------------
9 | latest | 2023-12-31 15:00:04.296634+00 | 2018-10-11 05:47:38+00 | |
9 | quarterly | 2023-12-31 15:00:04.296634+00 | | |
(2 rows)
freshports.dev=#
In a transaction, I updated that stored procedure, and got this result:
freshports.dev=*# SELECT * FROM PackagesLastCheckedSetRepoDate('FreeBSD:12:aarch64','latest',NULL)
;
packageslastcheckedsetrepodate
--------------------------------
f
(1 row)
That’s the right result. With the old stored procedure, I got:
freshports.dev=*# SELECT * FROM PackagesLastCheckedSetRepoDate('FreeBSD:12:aarch64','latest',NULL);
packageslastcheckedsetrepodate
--------------------------------
t
(1 row)
Now let’s wait for the next repo to be deleted.
Actual testing
At the top of the next hour, we got:
Dec 31 16:00:03 dev-ingress01 FreshPorts[5123]: into /usr/local/etc/periodic/hourly/900.freshports-check-repos-for-new-builds Dec 31 16:00:03 dev-ingress01 check_repos_for_new_stuff.py[5142]: Starting up Dec 31 16:00:04 dev-ingress01 check_repos_for_new_stuff.py[5142]: checking: FreeBSD:12:aarch64/latest : ... Dec 31 17:03:20 dev-ingress01 check_repos_for_new_stuff.py[5142]: checking: FreeBSD:14:i386/quarterly : Sun, 31 Dec 2023 14:28:10 GMT ... Dec 31 17:03:23 dev-ingress01 check_repos_for_new_stuff.py[5142]: There are 1 new repos ready for import: ['FreeBSD:14:i386/quarterly : Sun, 31 Dec 2023 14:28:10 GMT'] Dec 31 17:03:23 dev-ingress01 check_repos_for_new_stuff.py[5142]: finishes ... Dec 31 17:03:26 dev-ingress01 import_packagesite.py[49299]: Starting up Dec 31 17:03:26 dev-ingress01 import_packagesite.py[49299]: we have 1 repos to process Dec 31 17:03:26 dev-ingress01 import_packagesite.py[49299]: importing FreeBSD:14:i386/quarterly Dec 31 17:03:26 dev-ingress01 import_packagesite.py[49299]: command is: /usr/local/libexec/freshports/fetch-extract-parse-import-one-abi.sh FreeBSD:14:i386 quarterly Dec 31 17:03:26 dev-ingress01 fetch-extract-parse-import-one-abi.sh[49306]: starting /usr/local/libexec/freshports/fetch-extract-parse-import-one-abi.sh Dec 31 17:03:29 dev-ingress01 import-via-copy-packagesite-all-raw-fields.py[49343]: Starting up Dec 31 17:03:29 dev-ingress01 syslogd: last message repeated 1 times Dec 31 17:03:29 dev-ingress01 import-via-copy-packagesite-all-raw-fields.py[49343]: copying in from packagesite.tsv Dec 31 17:03:30 dev-ingress01 import-via-copy-packagesite-all-raw-fields.py[49343]: Finishing Dec 31 17:03:30 dev-ingress01 fetch-extract-parse-import-one-abi.sh[49354]: finished importing FreeBSD:14:i386/quarterly Dec 31 17:03:30 dev-ingress01 fetch-extract-parse-import-one-abi.sh[49358]: finishes Dec 31 17:03:30 dev-ingress01 import_packagesite.py[49299]: calling PackagesLastCheckedSetImportDate() Dec 31 17:03:30 dev-ingress01 import_packagesite.py[49299]: There are 1 repos which need post-import processing: ['FreeBSD:14:i386:quarterly'] Dec 31 17:03:30 dev-ingress01 import_packagesite.py[49299]: Finishing Dec 31 17:03:30 dev-ingress01 FreshPorts[49297]: Finished running import_packagesite.py (/usr/local/libexec/freshports) Dec 31 17:03:30 dev-ingress01 FreshPorts[49297]: flag '/var/db/freshports/signals/ports_to_refresh' not set. no work for refresh-ports.sh (/usr/local/libexec/freshports) Dec 31 17:03:30 dev-ingress01 FreshPorts[49297]: /var/db/freshports/signals/new_repo_imported exists. About to run UpdatePackagesFromRawPackages.py (/usr/local/libexec/freshports) Dec 31 17:03:30 dev-ingress01 UpdatePackagesFromRawPackages.py[49359]: Starting up Dec 31 17:03:30 dev-ingress01 UpdatePackagesFromRawPackages.py[49359]: updating packages table for FreeBSD:14:i386/quarterly Dec 31 17:03:33 dev-ingress01 UpdatePackagesFromRawPackages.py[49359]: There were 1 repos updated in packages. Dec 31 17:03:33 dev-ingress01 UpdatePackagesFromRawPackages.py[49359]: Finishing Dec 31 17:03:33 dev-ingress01 FreshPorts[49297]: Finished running UpdatePackagesFromRawPackages.py (/usr/local/libexec/freshports)
Success.
