The original problem was explained and fixed however it seems to have resurfaced. Either that, or it was not fixed at all.
In short:
- FreshPorts sees the first commit for a port on a branch
- the commit is deleting that port
- FreshPorts detects that the port has been deleted
- It forgets, somehow, that the port is deleted
- FreshPorts tries to refresh the database based on the port
- This fails because the port is not found in the ports tree
- FreshPorts raises a sanity test failure because it cannot understand how this can happen
My current theory: something is reseting the status flag for that port, swapping it from Deleted to Active. That may be part of FreshPorts trying to record all the files touched by this commit. The commit in question is 8e7c184e8620e1568983be5b8beabd4047650f70 – of note, this commit renames several ports. I am going to pick on devel/rubygem-google-apis-compute_v1_057 , which (at the time of writing) was deleted on head and still active on 2024Q4 (NOTE: this is relative to FreshPorts – both ports are deleted in the FreeBSD ports tree).
Wild idea: The solution might be as simple as changing the process to read from the database first, before processing the port it already has in local storage.
Let’s do some analysis.
Save all the things
verifyport.pm::_CompileListOfPorts() builds up the list of ports touched by this commit and returns %ListOfPorts. This is an array of port data structures indexed by category/port text values.
FreshPorts wants to save the files into the database. So it does stuff like this:
freshports.dvl=# SELECT Pathname_ID('/ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057-XXX/');
pathname_id
-------------
(1 row)
freshports.dvl=#
A bit about logging
The PostgreSQL database server is logging all statements. That greatly aids forensics like this. It doesn’t take up as much space as I thought it might:
[16:50 pg03 dvl ~] % ls -lh /var/log/postgresql.log* -rw-r----- 1 postgres logcheck 180M 2024.11.26 16:50 /var/log/postgresql.log -rw-r----- 1 postgres logcheck 755M 2024.11.26 00:00 /var/log/postgresql.log.0 -rw-r----- 1 postgres logcheck 168M 2024.11.25 00:00 /var/log/postgresql.log.1 -rw-r----- 1 postgres logcheck 303M 2024.11.24 00:00 /var/log/postgresql.log.2 -rw-r----- 1 postgres logcheck 325M 2024.11.23 00:00 /var/log/postgresql.log.3 -rw-r----- 1 postgres logcheck 252M 2024.11.22 00:00 /var/log/postgresql.log.4 -rw-r----- 1 postgres logcheck 255M 2024.11.21 00:00 /var/log/postgresql.log.5 -rw-r----- 1 postgres logcheck 173M 2024.11.20 00:00 /var/log/postgresql.log.6 [16:50 pg03 dvl ~] %
That’s slightly less than 500M. Let’s triple the log retention, just because it appears I can. That 21 was a 7 before I made the change:
[16:53 pg03 dvl /usr/local/etc/newsyslog.conf.d] % cat postgresql.conf /var/log/postgresql.log postgres:logcheck 640 21 * $D0 GB /var/db/postgres/data16/postmaster.pid 30
Back to the analysis
That query found nothing, so it adds the file like this:
freshports.dvl=# begin;
BEGIN
freshports.dvl=*# SELECT Element_Add('/ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057-XXX/Makefile', 'F');
element_add
-------------
1444611
(1 row)
freshports.dvl=*# SELECT Pathname_ID('/ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057-XXX/Makefile');
pathname_id
-------------
1444611
(1 row)
freshports.dvl=*# SELECT Pathname_ID('/ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057-XXX/');
pathname_id
-------------
1444610
(1 row)
freshports.dvl=*# select * from element where id = 1444610;
id | name | parent_id | directory_file_flag | status
---------+----------------------------------------+-----------+---------------------+--------
1444610 | rubygem-google-apis-compute_v1_057-XXX | 1434642 | D | A
(1 row)
freshports.dvl=*# rollback;
I am reproducing the steps based on the logs, and using a slightly different pathname. This ensures I don’t conflict with data already in the database.
That last statement, that’s the “port” I just created by adding the Makefile. I put that in quotes, because although the directory now exists in the tree (the element table), there is no entry in the ports table.
I must point out, the commit only refers to these items, as converted to XML here:
<FILE Action="Delete" Path="devel/rubygem-google-apis-compute_v1_057/Makefile"/>
<FILE Action="Delete" Path="devel/rubygem-google-apis-compute_v1_057/distinfo"/>
<FILE Action="Delete" Path="devel/rubygem-google-apis-compute_v1_057/pkg-descr"/>
FreshPorts recognizes that a port is deleted if the Makefile is removed.
Isolating logs
There are four FreshPorts nodes using this database server. They are all logged in the same file. For ease of searching I want to pull out only the log entries for one node (dvl). Here is how I did that.
I searched for log entries like this:
Nov 26 13:38:06 pg03 postgres[85235]: [439-1] 2024-11-26 13:38:06.016 UTC [85235] LOG: statement:
select Pathname_ID('/ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057/Makefile')
I then searched for the first occurrence of 85235 in the logs:
Nov 26 13:38:05 pg03 postgres[85235]: [8-1] 2024-11-26 13:38:05.212 UTC [85235] LOG: connection received: host=10.55.0.81 port=62136 Nov 26 13:38:05 pg03 postgres[85235]: [9-1] 2024-11-26 13:38:05.266 UTC [85235] LOG: connection authenticated: identity="commits_dvl" method=md5 (/usr/local/etc/postgresql.pg_hba.d/pg_hba.local.conf:63)
I repeated this until I found commits_dvl (as opposed to commits_test or commits_stage). The users on each node differ. This makes it easier to track down things such as this. I could just look for a connection from 10.55.0.81 (which is dvl-ingress01.int.unixathome.org) and that would be enough. This is just the way I prefer to do this.
To grab all those log entries:
[18:53 pg03 dvl ~ % sudo grep 85235 /var/log/postgresql.log > ~/tmp/85235.log [18:54 pg03 dvl ~] % wc -l ~/tmp/85235.log 15024 /usr/home/dvl/tmp/85235.log [18:54 pg03 dvl ~] %
Back to the analysis
However, later on in the logs, I see this n
Taking all the log entries and looking the ports they added, I see every single one is Active.
freshports.dvl=# select id, status, element_id, element_pathname(element_id) from ports where element_id in (1444512, 1444399, 1444345, 1444404, 1444424, 1444508, 1444524, 1444533, 1444353, 1444520, 1444438, 1444476, 1444418, 1444442, 1444454, 1444484, 1444544, 1444480, 1444552, 1444363, 1444522, 1444556, 1444492, 1444458, 1444331, 1444375, 1444492, 1444458, 1444331, 1444375, 1444474, 1444383, 1444341, 1444410, 1444379, 1444365, 1444446, 1444460, 1444371, 1444349, 1444488, 1444416, 1444548, 1444529, 1444393, 1444486, 1444337, 1444408, 1444385, 1444464, 1444560, 1444516, 1444540, 1444397, 1444361, 1444432, 1444401, 1444468, 1444450, 1444333, 1444428, 1444369, 1444496, 1444357, 1444389, 1444420, 1444504, 1444504, 1444351, 1444351, 1444537, 1444500 ) order by element_pathname(element_id); id | status | element_id | element_pathname --------+--------+------------+----------------------------------------------------------------------------- 121217 | A | 1444331 | /ports/branches/2024Q4/devel/rubygem-danger 121248 | A | 1444333 | /ports/branches/2024Q4/devel/rubygem-faraday_middleware-aws-sigv4-gitlab 121235 | A | 1444337 | /ports/branches/2024Q4/devel/rubygem-gapic-common-gitlab 121221 | A | 1444341 | /ports/branches/2024Q4/devel/rubygem-google-apis-androidpublisher_v3-gitlab 121195 | A | 1444345 | /ports/branches/2024Q4/devel/rubygem-google-apis-androidpublisher_v3034 121228 | A | 1444349 | /ports/branches/2024Q4/devel/rubygem-google-apis-cloudbilling_v1 121256 | A | 1444351 | /ports/branches/2024Q4/devel/rubygem-google-apis-cloudresourcemanager_v1 121201 | A | 1444353 | /ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1-gitlab 121252 | A | 1444357 | /ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057 121243 | A | 1444361 | /ports/branches/2024Q4/devel/rubygem-google-apis-container_v1 121212 | A | 1444363 | /ports/branches/2024Q4/devel/rubygem-google-apis-container_v1beta1 121224 | A | 1444365 | /ports/branches/2024Q4/devel/rubygem-google-apis-core-gitlab 121250 | A | 1444369 | /ports/branches/2024Q4/devel/rubygem-google-apis-iam_v1 121227 | A | 1444371 | /ports/branches/2024Q4/devel/rubygem-google-apis-iamcredentials_v1-gitlab 121218 | A | 1444375 | /ports/branches/2024Q4/devel/rubygem-google-apis-monitoring_v3-gitlab 121223 | A | 1444379 | /ports/branches/2024Q4/devel/rubygem-google-apis-pubsub_v1-gitlab 121220 | A | 1444383 | /ports/branches/2024Q4/devel/rubygem-google-apis-serviceusage_v1 121237 | A | 1444385 | /ports/branches/2024Q4/devel/rubygem-google-apis-sqladmin_v1beta4-gitlab 121253 | A | 1444389 | /ports/branches/2024Q4/devel/rubygem-google-apis-sqladmin_v1beta4_041 121233 | A | 1444393 | /ports/branches/2024Q4/devel/rubygem-google-apis-storage_v1-gitlab 121242 | A | 1444397 | /ports/branches/2024Q4/devel/rubygem-graphlient 121194 | A | 1444399 | /ports/branches/2024Q4/devel/rubygem-licensee 121245 | A | 1444401 | /ports/branches/2024Q4/devel/rubygem-webfinger 121196 | A | 1444404 | /ports/branches/2024Q4/dns/rubygem-google-apis-dns_v1-gitlab 121236 | A | 1444408 | /ports/branches/2024Q4/mail/rubygem-gitlab-mail_room 121222 | A | 1444410 | /ports/branches/2024Q4/net/rubygem-fog-google-gitlab 121230 | A | 1444416 | /ports/branches/2024Q4/net/rubygem-gitlab-fog-azure-rm 121205 | A | 1444418 | /ports/branches/2024Q4/net/rubygem-google-cloud-compute-v1 121254 | A | 1444420 | /ports/branches/2024Q4/net/rubygem-google-cloud-core-gitlab 121197 | A | 1444424 | /ports/branches/2024Q4/net/rubygem-google-cloud-env-gitlab 121249 | A | 1444428 | /ports/branches/2024Q4/net/rubygem-google-cloud-location-gitlab 121244 | A | 1444432 | /ports/branches/2024Q4/net/rubygem-google-cloud-storage-gitlab 121203 | A | 1444438 | /ports/branches/2024Q4/net/rubygem-google-cloud-storage_transfer-gitlab 121206 | A | 1444442 | /ports/branches/2024Q4/net/rubygem-google-cloud-storage_transfer-v1-gitlab 121225 | A | 1444446 | /ports/branches/2024Q4/net/rubygem-oauth2-gitlab 121247 | A | 1444450 | /ports/branches/2024Q4/net/rubygem-octokit-gitlab 121207 | A | 1444454 | /ports/branches/2024Q4/net/rubygem-omniauth-auth0-gitlab 121216 | A | 1444458 | /ports/branches/2024Q4/net/rubygem-omniauth-azure-activedirectory-v2 121226 | A | 1444460 | /ports/branches/2024Q4/net/rubygem-omniauth-github-gitlab 121238 | A | 1444464 | /ports/branches/2024Q4/net/rubygem-omniauth-google-oauth2-gitlab 121246 | A | 1444468 | /ports/branches/2024Q4/net/rubygem-omniauth-oauth2-gitlab 121219 | A | 1444474 | /ports/branches/2024Q4/net/rubygem-openid_connect 121204 | A | 1444476 | /ports/branches/2024Q4/security/rubygem-acme-client-gitlab 121210 | A | 1444480 | /ports/branches/2024Q4/security/rubygem-googleauth-gitlab 121208 | A | 1444484 | /ports/branches/2024Q4/security/rubygem-omniauth-alicloud 121234 | A | 1444486 | /ports/branches/2024Q4/security/rubygem-omniauth-atlassian-oauth2 121229 | A | 1444488 | /ports/branches/2024Q4/security/rubygem-omniauth-oauth2-generic-gitlab 121215 | A | 1444492 | /ports/branches/2024Q4/security/rubygem-rack-oauth2-gitlab 121251 | A | 1444496 | /ports/branches/2024Q4/security/rubygem-signet-gitlab 121258 | A | 1444500 | /ports/branches/2024Q4/textproc/rubygem-elasticsearch-api-gitlab 121255 | A | 1444504 | /ports/branches/2024Q4/textproc/rubygem-elasticsearch-gitlab 121198 | A | 1444508 | /ports/branches/2024Q4/textproc/rubygem-elasticsearch-model-gitlab 121193 | A | 1444512 | /ports/branches/2024Q4/textproc/rubygem-elasticsearch-model713 121240 | A | 1444516 | /ports/branches/2024Q4/textproc/rubygem-elasticsearch-transport-gitlab 121202 | A | 1444520 | /ports/branches/2024Q4/textproc/rubygem-google-cloud-artifact_registry-v1 121213 | A | 1444522 | /ports/branches/2024Q4/textproc/rubygem-google-cloud-profiler-v2 121199 | A | 1444524 | /ports/branches/2024Q4/textproc/rubygem-rouge-gitlab 121232 | A | 1444529 | /ports/branches/2024Q4/www/rubygem-faraday-follow_redirects-gitlab 121200 | A | 1444533 | /ports/branches/2024Q4/www/rubygem-faraday-gitlab 121257 | A | 1444537 | /ports/branches/2024Q4/www/rubygem-faraday-http-cache 121241 | A | 1444540 | /ports/branches/2024Q4/www/rubygem-faraday-net_http-gitlab 121209 | A | 1444544 | /ports/branches/2024Q4/www/rubygem-faraday-net_http_persistent-gitlab 121231 | A | 1444548 | /ports/branches/2024Q4/www/rubygem-faraday-retry-gitlab 121211 | A | 1444552 | /ports/branches/2024Q4/www/rubygem-faraday-typhoeus-gitlab 121214 | A | 1444556 | /ports/branches/2024Q4/www/rubygem-json-jwt-gitlab 121239 | A | 1444560 | /ports/branches/2024Q4/www/rubygem-swd (66 rows) freshports.dvl=#
That’s a definite bug. :) I am sure this is the cause of the error.
What’s all this eh?
In the database logs, I found this (the timestamp etc has been trimmed)
select Pathname_ID('/ports/branches/2024Q4/textproc/rubygem-elasticsearch-model713/Makefile')
select Pathname_ID('/ports/branches/2024Q4/textproc/rubygem-elasticsearch-model713')
select Element_Add('/ports/branches/2024Q4/textproc/rubygem-elasticsearch-model713/Makefile',
select Pathname_ID('/ports/branches/2024Q4/textproc/rubygem-elasticsearch-model713/Makefile')
select *, element_pathname(id) as pathname from element where id = 1444513
It’s grabbing the Makefile, failing, grabbing the parent/port/directory, and failing again. So it starts adding, then grabbing what it just added.
Where is this in the code? It’s in element.pm::save() – the code tries to get get the parent_id of this node, which does not exist. If we are inserting, parent_id will be derived. If we are updating, we already have the parent_id. I have commented out the code which tries to grab parent_id. Let’s see how that goes.
I’m thinking, it’s not this code causing the issue.
Back to the ingress logs
I went back to the commit processing logs. I wanted to look at these messages again:
this commit is NOT ON head
FILE ==: Delete, /ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057/Makefile, 8e7c184e8620e1568983be5b8beabd4047650f70, ports, devel, rubygem-google-apis-compute_v1_057, Makefile, 543
YES, this file is in the ports tree
We have already seen that category 'devel' in this commit. It has id = '10'
checking for port='devel/rubygem-google-apis-compute_v1_057'
* * * not found in existing cache. we'll have to load/create that port!
fetching by _FetchElementIDByPartialPathName: '/ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057'
sql = 'select Pathname_ID('/ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057')'
Element::FetchByName - here is what that SQL returned
Element::FetchByName found: 1444357
done....
I found this element id for that pathname: 1444357
sql = 'SET CLIENT_ENCODING TO 'SQL_ASCII';
select ports.*,
categories.name as category,
element.name as name,
element_pathname(element.id, FALSE) as element_pathname
from ports, categories, element
where ports.element_id = 1444357
and ports.category_id = categories.id
and ports.element_id = element.id'
port not retrieved with /ports/branches/2024Q4/devel/rubygem-google-apis-compute_v1_057. This must be a new port.
SETTING CATEGORY = 10
THIS PORT HAS BEEN DELETED
See how it fetched an element with id 1444357? You can see that in the list of ports in the “Back to the analysis” section.
The code right there is. Some notes:
- needs_refresh is an attribute with dubious value – I suspect it can be dropped/ignored now.
- refreshing the port – FreshPorts at one time, did refresh the ports during commit processing and it used a field in the database to track such items. It is now deprecated as far as I can tell.
#
# $port now contains the port for this file.
# let's adjust the needs_refresh value.
#
# if we just deleted the Makefile for this port, there's no sense in refreshing the port.
# because it's been deleted.
#
if (defined($extra) && $extra eq $FreshPorts::Constants::FILE_MAKEFILE && ($action eq $FreshPorts::Constants::REMOVE || $action eq $FreshPorts::Constants::DELETE)) {
#
# EDIT 2020-07-30 - for git processing, we want to delete the parent of $extra when we detect that the
# port Makefile is being deleted. see https://news.freshports.org/2020/07/29/git-changing-libraries-gave-us-new-xml-options/
# This should be straight forward.
#
# we are deleted (local value, never actually saved to db)
#
# instead of setting $port->{deleted} = 1;, try this:1444512 re https://github.com/FreshPorts/freshports/issues/528
$port->SetDeleted();
print "THIS PORT HAS BEEN DELETED\n";
Line 14 says it: never saved to db.
I think this is the place to patch the code. I think this is the patch:
# instead of setting $port->{deleted} = 1;, try this:1444512 re https://github.com/FreshPorts/freshports/issues/528
if $port->IsActive() {
$port->SetDeleted();
$port->savePortTableOnly();
}
NOTE: Later, I removed the savePortTableOnly() call; see below.
After time away
After getting a hot drink, I realized, no, that won’t work. status is a derived field. Is it not saved to the database, ever. Invoking that save function would not have deleted the port.
So what does delete a port?
This code deletes a port. It’s in verifyport.pm:
sub _DeleteDeletedPorts($;$) {
#
# For each deleted port, delete the element which corresponds to that port
#
my $PortsRef = shift;
my %Ports = %{$PortsRef};
my $dbh = shift;
my $element = FreshPorts::Element->new($dbh);
#
# refresh each and every port we are told about
#
print "# # # # Deleting deleted ports # # # #\n\n";
while (my ($portname, $port) = each %Ports) {
if ($port->IsDeleted()) {
print "deleting : port = $portname, port_id = '$port->{id}', ' element_id = $port->{element_id}'\n";
$element->{id} = $port->{element_id};
if (defined($element->FetchByID())) {
$element->{status} = $FreshPorts::Element::Deleted;
$element->save();
}
}
}
print "# # # # Finished deleting deleted ports # # # #\n\n";
}
NOTE TO SELF: We could also use $element->update_status($FreshPorts::Element::Deleted)
The problem is $port->IsDeleted(), or something messing with what it uses:
sub IsActive {
my $this = shift;
return ($this->{status} eq $FreshPorts::Element::Active);
}
sub IsDeleted {
my $this = shift;
return ($this->{status} eq $FreshPorts::Element::Deleted);
}
sub SetActive {
my $this = shift;
my $OldStatus = $this->{status};
$this->{status} = $FreshPorts::Element::Active;
return $OldStatus;
}
sub SetDeleted {
my $this = shift;
my $OldStatus = $this->{status};
$this->{status} = $FreshPorts::Element::Deleted;
return $OldStatus;
}
I wonder if $port is being refreshed from the database and it’s overwriting the local status I have set.
Batteries and hard drive
An aside: the batteries for the UP and the hard drive for the server have arrived (about 2 hours ago).
In the meantime, I’ve had a feed of tacos with sweet potatoes and black beans (nom nom nom). And Jeopardy (recorded) has just started on the TV.
I think I have a lead…
The main things
verifyport.pm has several main parts (written in Perl):
- %ListOfPorts = _CompileListOfPorts($CommitBranch, $commit_log_id, $Files, $dbh, $RepoType);
- for each port, ensure that we save away the new needs_refresh value, this will also create any ports which need to be created (DING DING DING)
- _RecordPortFilesTouchedByThatCommit($commit_log_id, $Files, \%ListOfPorts, $dbh);
- _DeleteDeletedPorts (\%ListOfPorts, $dbh);
- _UndeleteResurrectedPorts(\%ListOfPorts, $Files, $dbh);
I suspect it’s step 2 which is refreshing the status field.
These are the log entries for the port in interest:
port = devel/rubygem-google-apis-compute_v1_057
category_id='10', needs_refresh='0'
into FreshPorts::Port::_save
sql is insert into ports (id, element_id, category_id, last_commit_id) values (
121252,
1444357,
10, 1047780)
leaving FreshPorts::Port::_save
just created that port. Now loading it back in....
sql is insert into commit_log_ports
(commit_log_id, port_id, needs_refresh, port_version, port_revision, port_name_revision) values
(1047780, 121252, 0,
NULL, NULL, PackageName(121252) || '-' || NULL)
size of %CommitLogPorts for devel/rubygem-google-apis-compute_v1_057 is '61'
Right there, you can see it being saved and being read back in. That entirely overwrites the $port variable, including status.
Here’s what I think the fix is:
if ($IsActive) {
# we were active before, if we aren't now, we need to fix that
#
if (!$port->IsActive()) {
# we were active and now we're not: fix that
print "This port was active and after that save(), it was not - fixing.\n";
$port->SetActive();
}
} else {
# we were not active, i.e. we were deleted
if (!$port->IsDeleted()) {
# we were deleted and now we're not: fix that
print "This port was deleted and after that save(), it was not - fixing.\n";
$port->SetDeleted();
}
}
NOTE that this will not update the database, but it will set $port->{status} so that _DeleteDeletedPorts() will delete the port later.
Testing
Here we go, creating the testing database, which will restore from last night.
[1:21 pg02 dvl ~] % createdb freshports.dvl -E SQL_ASCII -T template0 -O postgres
[1:21 pg02 dvl ~] % psql -l
List of databases
Name | Owner | Encoding | Locale Provider | Collate | Ctype | ICU Locale | ICU Rules | Access privileges
----------------+----------+-----------+-----------------+---------+---------+------------+-----------+-----------------------
freshports.dvl | postgres | SQL_ASCII | libc | C | C.UTF-8 | | |
postgres | postgres | UTF8 | libc | C | C.UTF-8 | | |
template0 | postgres | UTF8 | libc | C | C.UTF-8 | | | =c/postgres +
| | | | | | | | postgres=CTc/postgres
template1 | postgres | UTF8 | libc | C | C.UTF-8 | | | =c/postgres +
| | | | | | | | postgres=CTc/postgres
Then:
[1:21 pg02 dvl ~] % sudo su -l postgres $ cd ~dvl $ ls bin freshports.org.dump src dumping globals.sql tmp $ psql freshports.dvl psql (16.5, server 16.4) Type "help" for help. freshports.dvl=# create language plperl; CREATE EXTENSION freshports.dvl=# exit $ time pg_restore -j 70 -d freshports.dvl ~dvl/freshports.org.dump pg_restore: error: could not execute query: ERROR: role "rdsadmin" does not exist Command was: ALTER SCHEMA public OWNER TO rdsadmin;
The next day (7:23 at the coffee shop, on the Wednesday before USA Thanksgiving), I found the output:
pg_restore: warning: errors ignored on restore: 1
2777.08 real 161.14 user 36.53 sys
$
So about 45 minutes. I’m glad I kept watching TV, had a good sleep, and I’m back at this the next day.
I also modified files in /usr/local/etc/freshports/ to use the new database:
[12:25 dvl-nginx01 dvl /usr/local/etc/freshports] % sudo grep -l pg03 * database.php fp-listen.ini [12:25 dvl-nginx01 dvl /usr/local/etc/freshports] % sudo joe `sudo grep -l pg03 *`
That effort was duplicated on the corresponding ingress node:
[12:31 dvl-ingress01 dvl /usr/local/etc/freshports] % sudo grep -l pg03 * config.ini config.pm config.sh [12:31 dvl-ingress01 dvl /usr/local/etc/freshports] % sudo joe `sudo grep -l pg03 *`
Reinjecting the commit
I saved the files, in read-only mode, to an easy-to-find location:
[12:36 dvl-ingress01 dvl ~/tmp/8e7c184e8620e1568983be5b8beabd4047650f70] % ls -l total 345 -r--r--r-- 1 dvl dvl 2241847 2024.11.26 13:39 2024.11.26.13.32.55.000018.8e7c184e8620e1568983be5b8beabd4047650f70.log -r--r--r-- 1 dvl dvl 15551 2024.11.26 13:36 2024.11.26.13.32.55.000018.8e7c184e8620e1568983be5b8beabd4047650f70.xml
That saves me from having to go to the official location: ~freshports/message-queues/archive/2024_11/2024_11_26/
There is a queue of commits waiting for processing by the freshports daemon:
[12:39 dvl-ingress01 dvl ~/tmp/8e7c184e8620e1568983be5b8beabd4047650f70] % ls ~ ~ingress/message-queues/incoming | wc -l
173
With these commands, I stop the ingress daemon (which adds to the above mentioned queue), and I move the queue contents out of the way):
[12:41 dvl-ingress01 dvl ~ingress/message-queues] % sudo service ingress stop Stopping ingress. Waiting for PIDS: 73475, 73475. [12:41 dvl-ingress01 dvl ~ingress/message-queues] % sudo mv incoming/* holding/ [12:41 dvl-ingress01 dvl ~ingress/message-queues] %
Next, the commit is reinjected into the processing stream:
[12:42 dvl-ingress01 dvl ~ingress/message-queues] % sudo service freshports status freshports is not running. [12:42 dvl-ingress01 dvl ~ingress/message-queues] % sudo service freshports start Cannot 'start' freshports. Set freshports_enable to YES in /etc/rc.conf or use 'onestart' instead of 'start'. [12:43 dvl-ingress01 dvl ~ingress/message-queues] % sudo service freshports onestart Starting freshports. [12:44 dvl-ingress01 dvl ~ingress/message-queues] % sudo cp -ip ~/tmp/8e7c184e8620e1568983be5b8beabd4047650f70/2024.11.26.13.32.55.000018.8e7c184e8620e1568983be5b8beabd4047650f70.xml ~ingress/message-queues/incoming/
Then I wait. There are many ports in this commit (68 I think); processing will take more than a couple of minutes.
I lied. It took about 2-3 minutes.
Reviewing the results
The first thing I checked: Any sanity test failure? No, good.
Next: Are all the ports deleted on the branch actually marked as deleted? Yes.
Then: review the logs. Do I see the expected entries?
What entries? Specifically, ports being marked as deleted.
I see four of these, one each for the ports deleted on the branch:
[12:56 dvl-ingress01 dvl ~freshports/message-queues/recent] % grep 'This port was' 2024.11.26.13.32.55.000018.8e7c184e8620e1568983be5b8beabd4047650f70.log This port was deleted and after that save(), it was not - fixing. This port was deleted and after that save(), it was not - fixing. This port was deleted and after that save(), it was not - fixing. This port was deleted and after that save(), it was not - fixing.
The “Deleting deleted ports” section has much more output. Isn’t that often the case? You start debugging something, add more logging, it stays.
I will show only a few lines.
# # # # Deleting deleted ports # # # # must we delete: textproc/rubygem-google-cloud-artifact_registry-v1, port_id = '91311', ' element_id = 1373973' ???? no, we don't delete that must we delete: security/rubygem-omniauth-atlassian-oauth2, port_id = '91312', ' element_id = 1373938' ???? no, we don't delete that must we delete: net/rubygem-fog-google-gitlab, port_id = '91313', ' element_id = 1373861' ???? no, we don't delete that ... must we delete: devel/rubygem-google-apis-androidpublisher_v3034, port_id = '91305', ' element_id = 1373795' ???? yes, yes, we must delete that must we delete: net/rubygem-google-cloud-storage_transfer-gitlab, port_id = '91318', ' element_id = 1373889' ???? no, we don't delete that ... must we delete: devel/rubygem-google-apis-compute_v1_057, port_id = '91339', ' element_id = 1373807' ???? yes, yes, we must delete that must we delete: devel/rubygem-google-apis-monitoring_v3-gitlab, port_id = '91340', ' element_id = 1373825' ???? no, we don't delete that ... must we delete: devel/rubygem-google-apis-sqladmin_v1beta4_041, port_id = '91277', ' element_id = 1373839' ???? yes, yes, we must delete that must we delete: dns/rubygem-google-apis-dns_v1-gitlab, port_id = '91275', ' element_id = 1373854' ???? no, we don't delete that must we delete: security/rubygem-rack-oauth2-gitlab, port_id = '91276', ' element_id = 1373944' ???? no, we don't delete that must we delete: textproc/rubygem-elasticsearch-model713, port_id = '91287', ' element_id = 1373965' ???? yes, yes, we must delete that ... must we delete: devel/rubygem-gapic-common-gitlab, port_id = '91297', ' element_id = 1373787' ???? no, we don't delete that # # # # Finished deleting deleted ports # # # #
Good. That is as expected.
Oh wait. The next section gave me some concern:
# # # # Resurrecting deleted ports # # # # found a deleted port: port='rubygem-google-apis-compute_v1_057', port_id='91339', element_id='1373807' now looking for files which were modified...
Wait, will this undo everything I just “fixed”?
Thankfully, no. The code will scan the files affected by that commit and see if any of them belong to that port. If the file was added or modified, the port needs to be undeleted (i.e. resurrected). No such files were found. All good.
What’s next
I will commit my changes, build new releases and get the new packages into production. This needs to be done sooner rather than later, because future commits can affect these ports. Mainly, I want to be sure the ports which should be deleted are deleted.
But first, I have an idea: rerun that commit on a copy of the database from this morning. Load the database up, delete that one commit, rerun the commit. Still all OK? If so, it’s good to move the code onto the other nodes.
That means it’s time to head home from the coffee shop.
The next test
While still at the shop, I started the database restore. When I got home, I did some stuff with the replacement UPS batteries. Now that I’m waiting for a battery to charge, I’m back on this.
The database is restored, and let’s run another test.
Oh, wait, my first test failed. The commit is already in the database. I need to delete it first.
Done. Commit reinjected. Success.
Time to commit and package.
done
Adding to the post now. It’s 4:37 pm on 2024-11-27 : all nodes have been updated as of about 17:00 UTC today. All good.
