Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Martin Gregorie]

On Thu, 2018-01-11 at 22:15 +, RW wrote:
> On Thu, 11 Jan 2018 09:46:24 -0600
> David Jones wrote:
> 
> 
> > I bet most mirrors have a cron entry like "*/10" ... If we still
> > see
> > problems I can extend the delay some more.
> 
> But the point of a longer delay is that it gives rsync a guaranteed
> minimum head start on the DNS. It doesn't rely on behaviour that
> works today but might fail in 5 years time when everyone's forgotten
> why the delay was needed.
> 
Relying on some fixed time offset like this is problematic because it
can be upset by network failures or slowdowns as well as unsynchronised
clocks on the various hosts. Using some sort of refresh completion
indicator is a better solution. 

For instance, use a marker file that is deleted before the mirror
refresh starts and is replaced as the last action in the refresh
sequence. sa-update would first check whether the marker is present. If
it is not, then it knows that a refresh is in progress, and should wait
for a few seconds and look again. When the marker is present it can do
the download. If the gpg key is in a separate file, then this could
also serve as the marker file.

Another possibility would be to do the refresh by using the new ruleset
 under a temporary name and renaming it on completion so it replaces
the  previous version. This effectibely makes the download file into
its own completion marker.


Martin

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Kevin A. McGrail]

On 1/11/2018 5:20 PM, Bill Cole wrote:

On 11 Jan 2018, at 12:58 (-0500), Kevin A. McGrail wrote:


And not to run GPG if we don't even download anything.


I have not had this issue myself so I all I have is the one example in 
the ticket, but the logged bad hash there was for a partial download: 
the first 14372 bytes of 1749638.tar.gz. If there was no download, the 
attempt to hash a nonexistent file would fail without generating a 
hash and emitting some error.



Thanks.

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[David Jones]

On 01/11/2018 04:15 PM, RW wrote:

On Thu, 11 Jan 2018 09:46:24 -0600
David Jones wrote:



I bet most mirrors have a cron entry like "*/10" ... If we still see
problems I can extend the delay some more.


But the point of a longer delay is that it gives rsync a guaranteed
minimum head start on the DNS. It doesn't rely on behaviour that
works today but might fail in 5 years time when everyone's forgotten
why the delay was needed.

 



I am not sure what you are suggesting we do differently.  I am open to 
suggestions.  I added a comment to the script so it should be pretty 
clear why the sleep command was added back.


Another bug was opened to add more logic to sa-update to handle download 
problems and retry a few times to handle mirror problems better.


--
David Jones

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Bill Cole]

On 11 Jan 2018, at 12:58 (-0500), Kevin A. McGrail wrote:


And not to run GPG if we don't even download anything.


I have not had this issue myself so I all I have is the one example in 
the ticket, but the logged bad hash there was for a partial download: 
the first 14372 bytes of 1749638.tar.gz. If there was no download, the 
attempt to hash a nonexistent file would fail without generating a hash 
and emitting some error.


--
Bill Cole
b...@scconsult.com or billc...@apache.org
(AKA @grumpybozo and many *@billmail.scconsult.com addresses)
Currently Seeking Steady Work: https://linkedin.com/in/billcole

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[RW]

On Thu, 11 Jan 2018 09:46:24 -0600
David Jones wrote:


> I bet most mirrors have a cron entry like "*/10" ... If we still see
> problems I can extend the delay some more.

But the point of a longer delay is that it gives rsync a guaranteed
minimum head start on the DNS. It doesn't rely on behaviour that
works today but might fail in 5 years time when everyone's forgotten
why the delay was needed.

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Kevin A. McGrail]

On 1/11/2018 12:57 PM, David Jones wrote:

On 01/11/2018 11:24 AM, Kevin A. McGrail wrote:

On 1/11/2018 10:46 AM, David Jones wrote:


There will be a 30 second to a few minutes delay for the DNS updates 
to propagate even for DNS caches that don't have the TXT record in 
their cache.


I bet most mirrors have a cron entry like "*/10" so they should pull 
the files at 8:40 AM UTC -- a few minutes before the DNS updates at 
8:42 AM UTC.


If we still see problems I can extend the delay some more. 


I think any race condition should be handled more gracefully by 
sa-update, wouldn't you think?




It wouldn't be a bad idea to create a loop with a few retries and 
random sleeps for a few minutes if there is a 404 returned.


Agreed.  And not to run GPG if we don't even download anything. Can you 
open a bugzilla if you think that's a good course of action?

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[David Jones]

On 01/11/2018 11:24 AM, Kevin A. McGrail wrote:

On 1/11/2018 10:46 AM, David Jones wrote:


There will be a 30 second to a few minutes delay for the DNS updates 
to propagate even for DNS caches that don't have the TXT record in 
their cache.


I bet most mirrors have a cron entry like "*/10" so they should pull 
the files at 8:40 AM UTC -- a few minutes before the DNS updates at 
8:42 AM UTC.


If we still see problems I can extend the delay some more. 


I think any race condition should be handled more gracefully by 
sa-update, wouldn't you think?




It wouldn't be a bad idea to create a loop with a few retries and random 
sleeps for a few minutes if there is a 404 returned.


--
David Jones

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Kevin A. McGrail]

On 1/11/2018 10:46 AM, David Jones wrote:


There will be a 30 second to a few minutes delay for the DNS updates 
to propagate even for DNS caches that don't have the TXT record in 
their cache.


I bet most mirrors have a cron entry like "*/10" so they should pull 
the files at 8:40 AM UTC -- a few minutes before the DNS updates at 
8:42 AM UTC.


If we still see problems I can extend the delay some more. 


I think any race condition should be handled more gracefully by 
sa-update, wouldn't you think?

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[David Jones]

On 01/11/2018 09:02 AM, RW wrote:

On Wed, 10 Jan 2018 14:06:52 -0600
David Jones wrote:


On 01/10/2018 12:40 PM, Alex wrote:

Hi,

On Wed, Jan 10, 2018 at 12:21 PM, Kevin A. McGrail
 wrote:

On 1/10/2018 11:23 AM, David Jones wrote:


I need to see the debug verbose output of one that fails to
troubleshoot further.



Agreed.  We need someone to run with -D and log it and IDEALLY run
a few right after to see if it resolves.  I'm guessing one mirror
is blocking or something.


I've updated my sa-cron script to loop to try again should it fail
due to this error, as well as provide the debugging info on every
run.


I received some detailed information from one of the mirror hosters
that made me think I need to put back in a delay of the TXT update
used by sa-update to give the mirrors time to pull the new ruleset
files.

I have put a 10 minute delay in place on the DNS TXT updates



Is 10 minutes long enough? The link below recommends that the mirrors
should sync every 10 minutes.  If that's still correct then 10 minutes
still leaves a race.


https://wiki.apache.org/spamassassin/SaUpdateMirrorSetup




There will be a 30 second to a few minutes delay for the DNS updates to 
propagate even for DNS caches that don't have the TXT record in their cache.


I bet most mirrors have a cron entry like "*/10" so they should pull the 
files at 8:40 AM UTC -- a few minutes before the DNS updates at 8:42 AM UTC.


If we still see problems I can extend the delay some more.

--
David Jones

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[RW]

On Wed, 10 Jan 2018 14:06:52 -0600
David Jones wrote:

> On 01/10/2018 12:40 PM, Alex wrote:
> > Hi,
> > 
> > On Wed, Jan 10, 2018 at 12:21 PM, Kevin A. McGrail
> >  wrote:  
> >> On 1/10/2018 11:23 AM, David Jones wrote:  
> >>>
> >>> I need to see the debug verbose output of one that fails to
> >>> troubleshoot further.  
> >>
> >>
> >> Agreed.  We need someone to run with -D and log it and IDEALLY run
> >> a few right after to see if it resolves.  I'm guessing one mirror
> >> is blocking or something.  
> > 
> > I've updated my sa-cron script to loop to try again should it fail
> > due to this error, as well as provide the debugging info on every
> > run. 
> 
> I received some detailed information from one of the mirror hosters
> that made me think I need to put back in a delay of the TXT update
> used by sa-update to give the mirrors time to pull the new ruleset
> files.
> 
> I have put a 10 minute delay in place on the DNS TXT updates 


Is 10 minutes long enough? The link below recommends that the mirrors
should sync every 10 minutes.  If that's still correct then 10 minutes
still leaves a race. 


https://wiki.apache.org/spamassassin/SaUpdateMirrorSetup

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Alex]

Hi,

>>> Agreed.  We need someone to run with -D and log it and IDEALLY run a few
>>> right after to see if it resolves.  I'm guessing one mirror is blocking
>>> or
>>> something.
>>
>>
>> I've updated my sa-cron script to loop to try again should it fail due
>> to this error, as well as provide the debugging info on every run.
>>
> I received some detailed information from one of the mirror hosters that
> made me think I need to put back in a delay of the TXT update used by
> sa-update to give the mirrors time to pull the new ruleset files.
>
> I have put a 10 minute delay in place on the DNS TXT updates which may clear
> up this problem in roughly 12 hours.  It looks like there was about a 6
> minute window when DNS had updated right after 08:31 AM UTC before all
> mirrors had updated by 08:41 AM UTC.
>
> Thanks to all of those who enabled debugging.  Please keep them enabled for
> the next few days or weeks in case this doesn't complete resolve the issue.

Last night's run was successful, from sa-update.ena.com. I am curious
about the "WARNING: This key is not certified with a trusted
signature!" Is it just a self-signed cert?

If you'd like the full output, please let me know. I'll leave the
debugging enabled for another week. This will otherwise be the last
post unless there's an error. All times are EST.

Jan 11 04:10:02.765 [7209] dbg: channel: reading MIRRORED.BY file
/var/lib/spamassassin/3.004002/updates_spamassassin_org/MIRRORED.BY
Jan 11 04:10:02.765 [7209] dbg: channel: parsing MIRRORED.BY file for
channel updates.spamassassin.org
Jan 11 04:10:02.765 [7209] dbg: channel: found mirror
http://sa-update.dnswl.org/ weight=3
Jan 11 04:10:02.765 [7209] dbg: channel: found mirror
http://www.sa-update.pccc.com/ weight=5
Jan 11 04:10:02.765 [7209] dbg: channel: found mirror
http://sa-update.secnap.net/ weight=5
Jan 11 04:10:02.765 [7209] dbg: channel: found mirror
http://sa-update.space-pro.be/ weight=1
Jan 11 04:10:02.765 [7209] dbg: channel: found mirror
http://sa-update.ena.com/ weight=5
Jan 11 04:10:02.765 [7209] dbg: channel: found mirror
http://sa-update.razx.cloud/ weight=5
Jan 11 04:10:02.766 [7209] dbg: channel: found mirror
http://sa-update.fossies.org/ weight=1
Jan 11 04:10:02.766 [7209] dbg: channel: found mirror
http://sa-update.verein-clean.net/ weight=10
Jan 11 04:10:02.766 [7209] dbg: channel: found mirror
http://sa-update.bitwell.fi/ weight=10
Jan 11 04:10:02.766 [7209] dbg: channel: found mirror
http://sa-update.spamassassin.org/ weight=5
DNS A query: sa-update.ena.com -> 96.5.1.5, 96.4.1.5
Jan 11 04:10:02.796 [7209] dbg: channel: selected mirror
http://sa-update.ena.com
fetching http://sa-update.ena.com/1820847.tar.gz
Jan 11 04:10:02.796 [7209] dbg: http: url:
http://sa-update.ena.com/1820847.tar.gz
Jan 11 04:10:02.796 [7209] dbg: http: downloading to:
/var/lib/spamassassin/3.004002/updates_spamassassin_org/1820847.tar.gz,
new
Jan 11 04:10:02.797 [7209] dbg: util: executable for curl was found at
/usr/bin/curl
Jan 11 04:10:02.797 [7209] dbg: http: /usr/bin/curl -s -L -O
--remote-time -g --max-redirs 2 --connect-timeout 30 --max-time 300
--fail -o 1820847.tar.gz -- http://sa-update.ena.com/1820847.tar.gz
Jan 11 04:10:03.313 [7209] dbg: http: process [7265], exit status: exit 0
http: (curl) GET http://sa-update.ena.com/1820847.tar.gz, success
fetching http://sa-update.ena.com/1820847.tar.gz.sha1
Jan 11 04:10:03.315 [7209] dbg: http: url:
http://sa-update.ena.com/1820847.tar.gz.sha1
Jan 11 04:10:03.315 [7209] dbg: http: downloading to:
/var/lib/spamassassin/3.004002/updates_spamassassin_org/1820847.tar.gz.sha1,
new
Jan 11 04:10:03.315 [7209] dbg: util: executable for curl was found at
/usr/bin/curl
Jan 11 04:10:03.315 [7209] dbg: http: /usr/bin/curl -s -L -O
--remote-time -g --max-redirs 2 --connect-timeout 30 --max-time 300
--fail -o 1820847.tar.gz.sha1 --
http://sa-update.ena.com/1820847.tar.gz.sha1
Jan 11 04:10:03.394 [7209] dbg: http: process [7311], exit status: exit 0
http: (curl) GET http://sa-update.ena.com/1820847.tar.gz.sha1, success
fetching http://sa-update.ena.com/1820847.tar.gz.asc
Jan 11 04:10:03.394 [7209] dbg: http: url:
http://sa-update.ena.com/1820847.tar.gz.asc
Jan 11 04:10:03.394 [7209] dbg: http: downloading to:
/var/lib/spamassassin/3.004002/updates_spamassassin_org/1820847.tar.gz.asc,
new
Jan 11 04:10:03.395 [7209] dbg: util: executable for curl was found at
/usr/bin/curl
Jan 11 04:10:03.395 [7209] dbg: http: /usr/bin/curl -s -L -O
--remote-time -g --max-redirs 2 --connect-timeout 30 --max-time 300
--fail -o 1820847.tar.gz.asc --
http://sa-update.ena.com/1820847.tar.gz.asc
Jan 11 04:10:03.468 [7209] dbg: http: process [7321], exit status: exit 0
http: (curl) GET http://sa-update.ena.com/1820847.tar.gz.asc, success
Jan 11 04:10:03.470 [7209] dbg: sha1: verification wanted:
9e6b9fa533ac60fa622fdec544a83eb2b7941771
Jan 11 04:10:03.470 [7209] dbg: sha1: verification result:
9e6b9fa533ac60fa622fdec544a83eb2b7941771
Jan 11 04:10:03.470 [7209] dbg: channel: populating 

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[David Jones]

On 01/10/2018 12:40 PM, Alex wrote:

Hi,

On Wed, Jan 10, 2018 at 12:21 PM, Kevin A. McGrail
 wrote:

On 1/10/2018 11:23 AM, David Jones wrote:


I need to see the debug verbose output of one that fails to troubleshoot
further.



Agreed.  We need someone to run with -D and log it and IDEALLY run a few
right after to see if it resolves.  I'm guessing one mirror is blocking or
something.


I've updated my sa-cron script to loop to try again should it fail due
to this error, as well as provide the debugging info on every run.



I received some detailed information from one of the mirror hosters that 
made me think I need to put back in a delay of the TXT update used by 
sa-update to give the mirrors time to pull the new ruleset files.


I have put a 10 minute delay in place on the DNS TXT updates which may 
clear up this problem in roughly 12 hours.  It looks like there was 
about a 6 minute window when DNS had updated right after 08:31 AM UTC 
before all mirrors had updated by 08:41 AM UTC.


Thanks to all of those who enabled debugging.  Please keep them enabled 
for the next few days or weeks in case this doesn't complete resolve the 
issue.


--
David Jones

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Alex]

Hi,

On Wed, Jan 10, 2018 at 12:21 PM, Kevin A. McGrail
 wrote:
> On 1/10/2018 11:23 AM, David Jones wrote:
>>
>> I need to see the debug verbose output of one that fails to troubleshoot
>> further.
>
>
> Agreed.  We need someone to run with -D and log it and IDEALLY run a few
> right after to see if it resolves.  I'm guessing one mirror is blocking or
> something.

I've updated my sa-cron script to loop to try again should it fail due
to this error, as well as provide the debugging info on every run.

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Kevin A. McGrail]

On 1/10/2018 11:23 AM, David Jones wrote:
I need to see the debug verbose output of one that fails to 
troubleshoot further. 


Agreed.  We need someone to run with -D and log it and IDEALLY run a few 
right after to see if it resolves.  I'm guessing one mirror is blocking 
or something.



Regards,
KAM

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Martin Gregorie]

On Wed, 2018-01-10 at 15:23 +, RW wrote:
> On Wed, 10 Jan 2018 15:10:52 +
> Martin Gregorie wrote:
> 
> 
> > The update defaults to being run from /etc/cron.weekly/sa-update,
> > which runs /usr/bin/sa-update without any other parameters and does
> > nothing else except for decoding the exit code and mailing all
> > output
> > to root: I think its the standard SA script.
> 
> I don't see it, it's probably redhat specific. Perhaps you could post
> it.
> 
here you go:

 sa_update ==
#!/bin/bash
#
# Update the Spamassassin rules
#
sau=/usr/bin/sa-update

if [ -x $sau ]
then
$sau
err=$?
case $err in
0)  echo "Spamassassin rules update completed.";
systemctl restart spamassassin;
echo "Spamassassin restarted." ;;

1)  echo "No Spamassassin rule updates available.";;

2)  echo "Spamassassin rules updates available";
echo "Site pre files lint check failed.";
echo "Fix the files and try again.";;

*)  echo "Spamassassin rules update failed: error=$err"
esac
else
echo "Error: $sau does not exist"
exit 0
fi
 
 sa_update ==


Martin
 

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[Alex]

Hi,

> Update:  If the downloads are successful but the GPG verification is
> failing, then this would not be a routing issue.
>
> The rsync'ing by the mirrors should happen quickly and the .sha1 and .asc
> files should sync quickly since they are very small files.  If the downloads
> are successful by sa-update, then it doesn't make sense that the PGP
> verification is failing.
>
> DNS updates (TTL) and mirror sync'ing delays would cause the downloads of
> the 3 files to fail if it were around 8:31 AM UTC.
>
> I need to see the debug verbose output of one that fails to troubleshoot
> further.

I'm seeing this here occasionally as well, including also on the 9th
around 4:30am EST

channel: SHA1 verification failed, channel failed
09-Jan-2018 04:28:55: SpamAssassin: Update available, but download or
extract failed

I figured it was a local issue, but was also going to report it after
it having occurred more than just a few times. This is on a fedora25
system. I've enabled debugging in my sa-cron script and will report
back with the debugging info when it next happens.

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[David Jones]

On 01/10/2018 10:08 AM, David Jones wrote:

On 01/10/2018 09:23 AM, RW wrote:

On Wed, 10 Jan 2018 15:10:52 +
Martin Gregorie wrote:



The update defaults to being run from /etc/cron.weekly/sa-update,
which runs /usr/bin/sa-update without any other parameters and does
nothing else except for decoding the exit code and mailing all output
to root: I think its the standard SA script.


I don't see it, it's probably redhat specific. Perhaps you could post
it.



Redhat and variants should have an /etc/sysconfig/sa-update file that 
lets you customize the cron'd sa-update.


We have added a number of sa-update mirrors in the past few months. It's 
possible there could be a local routing problem to one of them which 
would make this problem happen only occasionally for your specific ISP 
and not the rest of the Internet.




Update:  If the downloads are successful but the GPG verification is 
failing, then this would not be a routing issue.


The rsync'ing by the mirrors should happen quickly and the .sha1 and 
.asc files should sync quickly since they are very small files.  If the 
downloads are successful by sa-update, then it doesn't make sense that 
the PGP verification is failing.


DNS updates (TTL) and mirror sync'ing delays would cause the downloads 
of the 3 files to fail if it were around 8:31 AM UTC.


I need to see the debug verbose output of one that fails to troubleshoot 
further.


--
David Jones

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[David Jones]

On 01/10/2018 09:23 AM, RW wrote:

On Wed, 10 Jan 2018 15:10:52 +
Martin Gregorie wrote:



The update defaults to being run from /etc/cron.weekly/sa-update,
which runs /usr/bin/sa-update without any other parameters and does
nothing else except for decoding the exit code and mailing all output
to root: I think its the standard SA script.


I don't see it, it's probably redhat specific. Perhaps you could post
it.
  



Redhat and variants should have an /etc/sysconfig/sa-update file that 
lets you customize the cron'd sa-update.


We have added a number of sa-update mirrors in the past few months. 
It's possible there could be a local routing problem to one of them 
which would make this problem happen only occasionally for your specific 
ISP and not the rest of the Internet.


--
David Jones

Re: [Bug 7331] channel: SHA1 verification failed, channel failed

[RW]

On Wed, 10 Jan 2018 15:10:52 +
Martin Gregorie wrote:


> The update defaults to being run from /etc/cron.weekly/sa-update,
> which runs /usr/bin/sa-update without any other parameters and does
> nothing else except for decoding the exit code and mailing all output
> to root: I think its the standard SA script.

I don't see it, it's probably redhat specific. Perhaps you could post
it.