emmh wrote to mention that the vuxml posts on FreshPorts were out of date. I checked. Sure enough. They were.
Checking the sites
On the homepage, under Latest Vulnerabilities, the latest entry was dated Oct 17. And here it was, November. Something is wrong. The beta website showed Aug 14. And my dev website showed Sep 23. What’s up with that?
vuxml pages
Next step, the vuxml page. That shows 2012-10-22, which is 5 days later than Oct 17, the latest vulnerability. This is possible, if the latest updates only amended data, as opposed to adding new entries. The vuxml pages for beta and dev reflected the dates shown under their respective Latest Vulnerabilities sections.
the commits
Hmm. Well, have we been processing the commits for vuln.xml? Looked at each of production, beta, and dev, every one reports the last commit as 27 Nov 2012 20:09:35. Checking the svn repository for /head/security/vuxml/vuln.xml, the latest commit there is Tue Nov 27 20:09:34 2012. Off by one second. That’s close enough. It is the same commit, as verified by the svn revision number: 307861.
Conclusion so far
So far, we have established that FreshPorts has all the latest commits. What it does not have is the processing of the vuxml file which records which ports are vulnerable. More precisely, the vuxml.php page and the Latest Vulnerabilities section are each out of date.
Conclusion: FreshPorts is correctly processing the incoming commits. FreshPorts is not doing the post-processing of that commit.
This is good. Post-processing of commits takes data from the database and processes it. The important stage is getting the data into the database in a timely fashion. That, we have established, is taking page.
Looking at post-processing
Every run of the vuxml post processing is logged. Looking at those logs:
[dan@ngaio:/usr/websites/freshports.org/scripts-log] $ ls -lt total 0 -rw-r----- 1 dan dan 0 Nov 28 00:00 vuxml.log -rw-r----- 1 dan dan 0 Nov 27 00:00 vuxml.log.0 -rw-r----- 1 dan dan 0 Nov 26 00:00 vuxml.log.1 -rw-r----- 1 dan dan 0 Nov 25 00:00 vuxml.log.2 -rw-r----- 1 dan dan 0 Nov 24 00:00 vuxml.log.3 -rw-r----- 1 dan dan 0 Nov 23 00:00 vuxml.log.4 -rw-r----- 1 dan dan 0 Nov 22 00:00 vuxml.log.5 -rw-r----- 1 dan dan 0 Nov 21 00:00 vuxml.log.6 -rw-r----- 1 dan dan 0 Nov 20 00:00 vuxml.log.7 -rw-r----- 1 dan dan 0 Nov 19 00:00 vuxml.log.8 -rw-r----- 1 dan dan 0 Nov 18 00:00 vuxml.log.9 -rw-r----- 1 dan dan 0 Nov 17 00:00 vuxml.log.10 -rw-r----- 1 dan dan 0 Nov 16 00:00 vuxml.log.11 -rw-r----- 1 dan dan 0 Nov 15 00:00 vuxml.log.12 -rw-r----- 1 dan dan 0 Nov 14 00:00 vuxml.log.13 -rw-r----- 1 dan dan 0 Nov 13 00:00 vuxml.log.14 [dan@ngaio:/usr/websites/freshports.org/scripts-log] $
Oh. Everything is empty. Zero. Nothing in there. These file entries are rotated daily and controlled by entries in /etc/newsyslog.conf. Tne logs on all servers were empty. Conclusion: post processing is not being run at all.
How is post-processing controlled
Processing of commits and post-processing is handled by the freshports daemon (fp-daemon.sh). This is a shell script controlled by daemontools. Every 3 seconds, this script looks in the incoming directory for new commits. For every commit found, it launches a script and processes that commit. After each commit is processed, fp-daemon.sh looks to see if there are any post-processing jobs that need to be run. It does this by checking the job_waiting flag, which is determined by the existence of a file at ${SCRIPTDIR}/${q}/dynamic/job_waiting, where:
- SCRIPTDIR is the directory for the scripts (e.g. the commit processing scripts)
- q is the name of the queue we are processing (usually freshports.org)
When that file is present, fp-daemon.sh will launch the perl script job-waiting.pl.
job-waiting.pl is rather simple. It looks for various flags, and runs the script which relates to that flag.
There are several steps here. Let’s see which one is broken.
Testing the processing
Let’s start off by setting the vuxml post-processing flag. From the scripts directory, let’s do this:
$ touch ../dynamic/vuxml
And now, indicate that a job is waiting to run:
$ touch ../dynamic/job_waiting
Looking at /var/log/messages, I see:
Nov 28 14:23:00 ngaio fp-daemon: yes, there is a job waiting Nov 28 14:23:00 ngaio FreshPorts[14476]: flag not set. no work for process_updating.sh Nov 28 14:23:00 ngaio FreshPorts[14476]: flag not set. no work for process_moved.sh Nov 28 14:23:00 ngaio FreshPorts[14476]: flag not set. no work for process_www_en_ports_categories.sh Nov 28 14:23:00 ngaio FreshPorts[14476]: /usr/websites/freshports.org/dynamic/vuxml exists. About to run process_vuxml.sh Nov 28 14:23:00 ngaio FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml processing begins Nov 28 14:25:50 ngaio FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml finishes Nov 28 14:25:50 ngaio FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml terminates Nov 28 14:25:50 ngaio FreshPorts[14476]: Finished running process_vuxml.sh
Notes on the above:
- Lines 1 shows that a job is waiting to run
- Lines 2-5 are the job-waiting.pl script logging as it checks what needs to be run
- Line 6 is the start of vuxml post processing
I confirmed that /usr/websites/freshports.org/scripts-log/vuxml.log was being updated.
Clearly, the scripts work as designed if the flags are set. After processing was completed, looking at the vuxml.php page showed an updated date which reflected the last commit against vuln.xml.
Conclusion: the flags are not being set.
Let’s get the websites up to date first
The above testing was on my dev box. Now, let’s do the same on the beta box. This time, I did just one touch, but two files:
$ touch ../dynamic/vuxml ../dynamic/job_waiting
And the log says:
Nov 28 14:42:27 nyi fp-daemon: yes, there is a job waiting Nov 28 14:42:28 nyi FreshPorts[29746]: flag not set. no work for process_updating.sh Nov 28 14:42:28 nyi FreshPorts[29746]: flag not set. no work for process_moved.sh Nov 28 14:42:28 nyi FreshPorts[29746]: flag not set. no work for process_www_en_ports_categories.sh Nov 28 14:42:28 nyi FreshPorts[29746]: /usr/websites/freshports.org/dynamic/vuxml exists. About to run process_vuxml.sh Nov 28 14:42:28 nyi FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml processing begins Nov 28 14:42:37 nyi FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml ident begins Nov 28 14:42:37 nyi FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml latest begins Nov 28 14:42:53 nyi FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml finishes Nov 28 14:42:53 nyi FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml terminates Nov 28 14:42:53 nyi FreshPorts[29746]: Finished running process_vuxml.sh
All very good. But looking at the vuxml page on dev shows no change. It still says:
Revision: 302538 Date: 2012-08-14 Time: 23:17:56Z Committer: mandree
Looking at the logs shows that nothing was updated. Line 7 above clearly shows that vuxml ident was run. This is the script which updates the vuxml.php page. Let’s look closer at that script. vuxml_ident.pl is run by process_vuxml.sh, which in turn is launched by job-waiting.pl. In process_vuxml.sh, we find this line:
/usr/bin/perl ./vuxml_ident.pl ${PORTSDIR}/security/vuxml/vuln.xml > ${BASEDIR}/dynamic/vuxml_revision
Oh. There it is. PORTSDIR. I bet that’s it. Let’s check the setting:
$ grep PORTSDIR config.sh PORTSDIR="/home/dan/ports"
*ding* *ding* *ding* *ding* *ding* *ding*
Comparing that to the dev server setting:
$ grep PORTSDIR config.sh PORTSDIR="/wdc/dan/PORTS-SVN"
Ignoring the directory prefix, notice that the beta box is running vuxml post-processing against the old CVS directory, not the currently used SVN directory. The fix is this on beta:
$ grep PORTSDIR config.sh PORTSDIR="/home/dan/PORTS-SVN"
Now, let’s run that again:
$ touch ../dynamic/vuxml ../dynamic/job_waiting
This time, the post processing will be against the SVN version of the file, not the CVS version of the file (which is horribly outdated not, because that local copy of the ports tree has not been updated in quite some time).
I repeated the same process on production (which had the correct PORTSDIR setting).
Now that the website are up to date, we just have to check as to why the flags are not being set.
What sets the flags?
Now we’re off hunting. First, what sets that flag?
$ grep job_waiting * config.pm:$FreshPorts::Config::JobWaiting = $FreshPorts::Config::BaseDir . '/dynamic/job_waiting'; config.pm.sample:$FreshPorts::Config::JobWaiting = $FreshPorts::Config::BaseDir . '/dynamic/job_waiting';
OK, what uses that constant:
$ grep FreshPorts::Config::JobWaiting * config.pm:$FreshPorts::Config::JobWaiting = $FreshPorts::Config::BaseDir . '/dynamic/job_waiting'; config.pm.sample:$FreshPorts::Config::JobWaiting = $FreshPorts::Config::BaseDir . '/dynamic/job_waiting'; special_processing_files.pm: `/usr/bin/touch $FreshPorts::Config::JobWaiting`; special_processing_files.pm: `/usr/bin/touch $FreshPorts::Config::JobWaiting`; special_processing_files.pm: `/usr/bin/touch $FreshPorts::Config::JobWaiting`; special_processing_files.pm: `/usr/bin/touch $FreshPorts::Config::JobWaiting`;
It appears special_processing_files.pm is what we need. Looking there, we find this function (displayed only in part here):
sub Eat($;$;$;$;$) {
my $dbh = shift;
my $Action = shift;
my $File = shift;
my $Revision = shift;
my $Repository = shift;
my $ErrorCode = 0;
#
# By the time we have been called, the file has been fetched
# so we are free to process as we please.
# we don't use the DB yet, but we have this code here in case we do.
my $sth;
my $sql;
my @row;
if ($File eq $FreshPorts::Constants::PORTS_MOVED) {
# no need to fetch this file, it's in the ports tree.
# fetching such files is part of the usual process.
print "applying special processing to $File\n";
Sys::Syslog::syslog('notice', "applying special processing to $File");
`/usr/bin/touch $FreshPorts::Config::MovedFileFlag`;
`/usr/bin/touch $FreshPorts::Config::JobWaiting`;
}
if ($File eq $FreshPorts::Constants::PORTS_UPDATING) {
# no need to fetch this file, it's in the ports tree.
# fetching such files is part of the usual process.
print "applying special processing to $File\n";
Sys::Syslog::syslog('notice', "applying special processing to $File");
`/usr/bin/touch $FreshPorts::Config::UpdatingFileFlag`;
`/usr/bin/touch $FreshPorts::Config::JobWaiting`;
}
if ($File eq $FreshPorts::Constants::VUXML) {
# no need to fetch this file, it's in the ports tree.
# fetching such files is part of the usual process.
print "applying special processing to $File\n";
Sys::Syslog::syslog('notice', "applying special processing to $File");
`/usr/bin/touch $FreshPorts::Config::VuXMLFileFlag`;
`/usr/bin/touch $FreshPorts::Config::JobWaiting`;
}
Notice line 37. Notice also that we’re in a function called Eat(). Let’s check the code for calls to that function.
if ($action eq $FreshPorts::Messages::FileUpdate) {
print "Observer has noticed that commit '" . $object->id() . "' contains file $params{FilePath} as revision $params{FileRevision} in repository $params{Repository}\n";
FreshPorts::SpecialProcessingFiles::Eat($class->{dbh}, $params{FileAction}, $params{FilePath}, $params{FileRevision}, $params{Repository});
}
See that print? Let’s check the logs for that message when we are processing a vuxml file.
$ grep 'Observer has noticed that commit' 2012.11.28.14.37.34.29230.txt.loading | grep vuln.xml Observer has noticed that commit '201211281437.qASEbOBT050471@svn.freebsd.org' contains file /ports/head/security/vuxml/vuln.xml as revision 307907 in repository ports
AHAH!
See that pathname: /ports/head/security/vuxml/vuln.xml
Let’s compare that to the constant used in line 37 in the source code snippet listed above.
$ grep FreshPorts::Constants::VUXML *
constants.pm:$FreshPorts::Constants::VUXML_URL = 'http://www.vuxml.org/freebsd/';
constants.pm:$FreshPorts::Constants::VUXML = 'ports/security/vuxml/vuln.xml';
report-security-notice.pl: $Body .= " $FreshPorts::Constants::VUXML_URL" . $row->{vid} . ".html\n\n";
special_processing_files.pm: if ($File eq $FreshPorts::Constants::VUXML) {
vuln_latest.pl: print FILE '<TR><TD align="left"><A HREF="' . $FreshPorts::Constants::VUXML_URL . $row->{vid} . '.html">' . $row->{port} . '</a>';
There is the problem. The constant is out of date and does not reflect the new structure of the ports tree now that it is in SVN.
The patch
This is the patch for the constants. You’ll see that I updated this for several files.
$ cvs di constants.pm Index: constants.pm =================================================================== RCS file: /home/repositories/freshports-1/scripts/constants.pm,v retrieving revision 1.14 diff -r1.14 constants.pm 78,81c78,81 < $FreshPorts::Constants::VUXML = 'ports/security/vuxml/vuln.xml'; < $FreshPorts::Constants::PORTS_UPDATING = 'ports/UPDATING'; < $FreshPorts::Constants::PORTS_MOVED = 'ports/MOVED'; < $FreshPorts::Constants::BSD_PORT_MK = 'ports/Mk/bsd.port.mk'; --- > $FreshPorts::Constants::VUXML = '/ports/head/security/vuxml/vuln.xml'; > $FreshPorts::Constants::PORTS_UPDATING = '/ports/head/UPDATING'; > $FreshPorts::Constants::PORTS_MOVED = '/ports/head/MOVED'; > $FreshPorts::Constants::BSD_PORT_MK = '/ports/head/Mk/bsd.port.mk';
FYI, I just noticed that $FreshPorts::Constants::BSD_PORT_MK is not used by the code anywhere. It should be removed.
Testing the change
The easiest way to test this change is to rerun the latest commit against security/vuxml.
First step, delete the old commit. I know the message id, as obtained from the logs, or from the security/vuxml webpage.
$ psql freshports.org psql (8.4.12, server 8.4.13) Type "help" for help. freshports.org=# begin; BEGIN freshports.org=# delete from commit_log where message_id = '201211281437.qASEbOBT050471@svn.freebsd.org'; DELETE 1 freshports.org=# commit; COMMIT freshports.org=#
Now, re-inject that commit email into the incoming stream.
$ mv 2012.11.28.14.37.34.29230.txt.raw ../incoming/2012.11.28.14.37.34.29230.txt
What do I see in the logs?
Nov 28 16:34:34 ngaio fp-daemon: found stuff in /home/dan/FreshPorts/freshports.org/msgs/FreeBSD/incoming Nov 28 16:34:34 ngaio fp-daemon: processing /home/dan/FreshPorts/freshports.org/msgs/FreeBSD/incoming/2012.11.28.14.37.34.29230.txt Nov 28 16:34:36 ngaio FreshPorts[74634]: applying special processing to /ports/head/security/vuxml/vuln.xml Nov 28 16:34:37 ngaio fp-listen: Just woke up! ************* Nov 28 16:34:37 ngaio fp-listen: got port_updated and I need to call listen_port Nov 28 16:34:37 ngaio fp-listen: checking for cache entries to remove... Nov 28 16:34:37 ngaio fp-listen: COUNT: 1 entries to process Nov 28 16:34:37 ngaio fp-listen: removing glob /usr/websites/freshports.org/dynamic/caching/cache/ports/security/vuxml/* Nov 28 16:34:37 ngaio fp-listen: DELETE FROM cache_clearing_ports WHERE id = 1396727 Nov 28 16:34:37 ngaio fp-listen: finished Nov 28 16:38:35 ngaio fp-listen: Just woke up! ************* Nov 28 16:38:35 ngaio fp-listen: got port_updated and I need to call listen_port Nov 28 16:38:35 ngaio fp-listen: checking for cache entries to remove... Nov 28 16:38:35 ngaio fp-listen: COUNT: 1 entries to process Nov 28 16:38:35 ngaio fp-listen: removing glob /usr/websites/freshports.org/dynamic/caching/cache/ports/security/vuxml/* Nov 28 16:38:35 ngaio fp-listen: DELETE FROM cache_clearing_ports WHERE id = 1396728 Nov 28 16:38:35 ngaio fp-listen: finished Nov 28 16:38:35 ngaio fp-daemon: result=0 Nov 28 16:38:35 ngaio fp-daemon: yes, there is a job waiting Nov 28 16:38:35 ngaio FreshPorts[76367]: flag not set. no work for process_updating.sh Nov 28 16:38:35 ngaio FreshPorts[76367]: flag not set. no work for process_moved.sh Nov 28 16:38:35 ngaio FreshPorts[76367]: flag not set. no work for process_www_en_ports_categories.sh Nov 28 16:38:35 ngaio FreshPorts[76367]: /usr/websites/freshports.org/dynamic/vuxml exists. About to run process_vuxml.sh Nov 28 16:38:35 ngaio FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml processing begins Nov 28 16:38:41 ngaio FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml ident begins Nov 28 16:38:41 ngaio FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml latest begins Nov 28 16:38:49 ngaio FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml finishes Nov 28 16:38:49 ngaio FreshPorts /usr/websites/freshports.org/scripts/process_vuxml.sh: vuxml terminates
OK, that seems normal, especially line 28. That four minute delay between lines 10 and 11 is expected. That’s the ‘svn up’ processing time. Yes, it really does take 4 minutes to svn up the tree.
Confirmed
To summarize, the problems were:
- out of date entry in configuration file
- incorrect entries in constants file
Item 1 was corrected in place. Item 2 will be committed and pushed to the other websites.
Post note
As part of preventative maintenance, I decided to do this:
$ mv ~/ports ~/ports-DELETE-ME
Any future references to the old CVS ports tree should now be glaringly obvious.
