Bug 7331 - channel: SHA1 verification failed, channel failed
Summary: channel: SHA1 verification failed, channel failed
Status: RESOLVED FIXED
Alias: None
Product: Spamassassin
Classification: Unclassified
Component: sa-update (show other bugs)
Version: SVN Trunk (Latest Devel Version)
Hardware: PC Linux
: P2 major
Target Milestone: Undefined
Assignee: Dave Jones
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-06-25 00:16 UTC by jidanni
Modified: 2020-08-14 21:30 UTC (History)
6 users (show)



Attachment Type Modified Status Actions Submitter/CLA Status
sa-update -D, but of a good run text/plain None jidanni@jidanni.org [NoCLA]
An HTML page is sent by the update server text/plain None peter@peternowee.com [NoCLA]
sa-update -D of a bad run text/plain None peter@peternowee.com [NoCLA]

Note You need to log in before you can comment on or make changes to this bug.
Description jidanni 2016-06-25 00:16:50 UTC
Why is this happening for my United States machine, but not my Asian machines?

Jun 25 08:02:55.439 [29035] dbg: channel: parsing MIRRORED.BY file for channel updates.spamassassin.org
Jun 25 08:02:55.440 [29035] dbg: channel: found mirror http://sa-update.dnswl.org/ weight=1
Jun 25 08:02:55.440 [29035] dbg: channel: found mirror http://www.sa-update.pccc.com/ weight=5
Jun 25 08:02:55.440 [29035] dbg: channel: found mirror http://sa-update.secnap.net/ weight=5
Jun 25 08:02:55.440 [29035] dbg: channel: found mirror http://sa-update.space-pro.be/ weight=1
Jun 25 08:02:55.706 [29035] dbg: channel: selected mirror http://sa-update.secnap.net
Jun 25 08:02:55.707 [29035] dbg: http: url: http://sa-update.secnap.net/1749638.tar.gz
Jun 25 08:02:55.707 [29035] dbg: http: downloading to: /home/jidanni1/.spamassassin-tree/var/spamassassin/4.000000/updates_spamassassin_org/1749638.tar.gz, update
Jun 25 08:02:55.707 [29035] dbg: util: executable for curl was found at /usr/bin/curl
Jun 25 08:02:55.707 [29035] dbg: http: /usr/bin/curl -s -L -O --remote-time -g --max-redirs 2 --connect-timeout 30 --max-time 300 --fail -o 1749638.tar.gz -z 1749638.tar.gz -- http://sa-update.secnap.net/1749638.tar.gz
Jun 25 08:02:55.934 [29035] dbg: http: process [29049], exit status: exit 0
Jun 25 08:02:55.934 [29035] dbg: http: url: http://sa-update.secnap.net/1749638.tar.gz.sha1
Jun 25 08:02:55.934 [29035] dbg: http: downloading to: /home/jidanni1/.spamassassin-tree/var/spamassassin/4.000000/updates_spamassassin_org/1749638.tar.gz.sha1, update
Jun 25 08:02:55.935 [29035] dbg: util: executable for curl was found at /usr/bin/curl
Jun 25 08:02:55.935 [29035] dbg: http: /usr/bin/curl -s -L -O --remote-time -g --max-redirs 2 --connect-timeout 30 --max-time 300 --fail -o 1749638.tar.gz.sha1 -z 1749638.tar.gz.sha1 -- http://sa-update.secnap.net/1749638.tar.gz.sha1
Jun 25 08:02:56.160 [29035] dbg: http: process [29051], exit status: exit 0
Jun 25 08:02:56.161 [29035] dbg: http: url: http://sa-update.secnap.net/1749638.tar.gz.asc
Jun 25 08:02:56.161 [29035] dbg: http: downloading to: /home/jidanni1/.spamassassin-tree/var/spamassassin/4.000000/updates_spamassassin_org/1749638.tar.gz.asc, update
Jun 25 08:02:56.161 [29035] dbg: util: executable for curl was found at /usr/bin/curl
Jun 25 08:02:56.161 [29035] dbg: http: /usr/bin/curl -s -L -O --remote-time -g --max-redirs 2 --connect-timeout 30 --max-time 300 --fail -o 1749638.tar.gz.asc -z 1749638.tar.gz.asc -- http://sa-update.secnap.net/1749638.tar.gz.asc
Jun 25 08:02:56.389 [29035] dbg: http: process [29053], exit status: exit 0
Jun 25 08:02:56.389 [29035] dbg: sha1: verification wanted: 5f08b36a5dc56c81b758f1aafe4cfb0afa5dcfad
Jun 25 08:02:56.389 [29035] dbg: sha1: verification result: da3fe29840d7b717c0931b331dcb671b23cf4b5a
channel: SHA1 verification failed, channel failed
Jun 25 08:02:56.390 [29035] dbg: generic: cleaning up temporary directory/files
Jun 25 08:02:56.390 [29035] dbg: generic: cleaning directory /tmp/.spamassassin29035fVUynftmp
Jun 25 08:02:56.390 [29035] dbg: diag: updates complete, exiting with code 4
Comment 1 Jonathan Kamens 2018-01-08 20:38:28 UTC
This has recently started happening to me regularly on my Linode. I've seen it four times in the last month, after literally not seeing it even once in my several years of running SpamAssassin.

When I retry the next day it invariably works.

Is there a problem with the SpamAssassin update infrastructure? Is it overloaded? Can something be done?
Comment 2 Bill Cole 2018-01-08 23:58:44 UTC
(In reply to Jonathan Kamens from comment #1)

> Is there a problem with the SpamAssassin update infrastructure? Is it
> overloaded? Can something be done?

I have not seen this at all. The specific error implies a corrupted rules tarball, which is unlikely to be a load issue. I don't know if the mirrors are updated atomically but if they are not, this could be the result, particularly if you're running sa-update around 08:30 UTC, which is roughly when the daily updates are ready to go out. KAM or Dave Jones could probably say whether mirroring is done atomically (i.e. sending the file to a temporary name them moving it to its accessible name) and when those actually complete.
Comment 3 jidanni 2018-01-09 03:42:10 UTC
I am now getting this error lots these days, maybe every two or three days, and I update at 10:00 UTC.
Comment 4 Kevin A. McGrail 2018-01-09 13:22:54 UTC
Please add more logs and if you can, try manually downloading the files.  

The exact update I use is /usr/bin/rsync --timeout=280 -T /tmp -ta --delete --address=69.171.29.39  rsync.spamassassin.org::updates /htdocs/sa-update.pccc.com/html 

-delay-updates could make things more atomic but by default it's going to use a tmp dir for the files.  


My big question is does a subsequent run fix the issue?  Is there a specific mirror that might be having the issue?
Comment 5 Jonathan Kamens 2018-01-09 15:05:37 UTC
(In reply to Kevin A. McGrail from comment #4)
> Please add more logs and if you can, try manually downloading the files.

I'm getting the error from sa-update.cron, so (a) I'm not around when it happens in the middle of the night to retry it immediately, and (b) I have no idea where, if anywhere, the logs from sa-update.cron are captured.

If you can advise me how to configure or modify the cron job so that it captures logs, I will be glad to follow your advice to collect additional information.

> My big question is does a subsequent run fix the issue?  Is there a specific
> mirror that might be having the issue?

When I get the error overnight and then rerun the update during the day when I notice it, it usually works the second time.
Comment 6 Dave Jones 2018-01-10 20:06:37 UTC
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.

Dave
Comment 7 Dave Jones 2018-01-11 18:15:43 UTC
Timing delays in DNS updates with ruleset updates on mirrors should be resolved.  We will monitor this situation a few more days before closing this bug.

Further sa-update enhancements to better handle mirror issues is in bug 7530.
Comment 8 Dave Jones 2018-01-18 12:40:59 UTC
This has been fixed.
Comment 9 jidanni 2020-07-31 11:26:44 UTC
Today:

channel 'updates.spamassassin.org': SHA512 verification failed, channel failed
Jul 31 03:22:33.329 [22953] dbg: generic: cleaning up temporary directory/files
Jul 31 03:22:33.329 [22953] dbg: generic: cleaning directory /tmp/.spamassassin22953OQDsLktmp
Jul 31 03:22:33.329 [22953] dbg: diag: updates complete, exiting with code 4

A second run worked though.
Comment 10 jidanni 2020-07-31 11:28:52 UTC
Same problem, US machine, not Asian machine.
Latest SVN version.
Comment 11 jidanni 2020-07-31 11:34:26 UTC
Happened at Jul 31 03:22:33.329 California time.
Fri Jul 31 10:22:33.329 UTC.
Comment 12 Kevin A. McGrail 2020-07-31 18:44:43 UTC
Can you run sa-update with -D so you get full output and we can research the issue?
Comment 13 jidanni 2020-08-02 06:51:14 UTC
(That was the -D output... anyway today it works fine. Which makes sense: it is an occasional problem with the networks it is connecting to, not something one could debug at home.)
Comment 14 Kevin A. McGrail 2020-08-02 11:25:22 UTC
I meant the entire -D output as I want to see if maybe there is a mirror or file that is corrupt somewhere.

If you have it again, please post the entire -D output or email it to me.
Comment 15 jidanni 2020-08-02 19:11:20 UTC
Created attachment 5712 [details]
sa-update -D, but of a good run

By the way, it seems more debugging info should be shown about what exactly it is connecting to. Anyway, this is a good run.
Comment 16 Kevin A. McGrail 2020-08-03 00:38:02 UTC
(In reply to jidanni from comment #15)
> Created attachment 5712 [details]
> sa-update -D, but of a good run
> 
> By the way, it seems more debugging info should be shown about what exactly
> it is connecting to. Anyway, this is a good run.

This isn't a good run.  This is a run saying nothing was needed.  A good run won't help just one when there is a problem.

If you delete you /var/lib/spamassassin dir (the default location for rules) and run sa-update -D, you'll see a LOT more information.
Comment 17 peter@peternowee.com 2020-08-09 08:55:27 UTC
Created attachment 5714 [details]
An HTML page is sent by the update server

Update of 2020-08-09 07:41:54.089 UTC
Debian buster (10.5), spamassassin 3.4.2-1+deb10u2
Comment 18 peter@peternowee.com 2020-08-09 09:05:08 UTC
Created attachment 5715 [details]
sa-update -D of a bad run

I experienced the `SHA512 verification failure` problem before on:
- 2020-07-31 07:47:19 UTC
- 2020-08-03 08:32:43 UTC
- 2020-08-07 08:26:26 UTC
- 2020-08-09 07:41:54 UTC (today, with debug output, see attachment)

On other days there was no problem. Manual runs later on the day were
no problem either.

Debian buster (10.5), spamassassin 3.4.2-1+deb10u2
Comment 19 Kevin A. McGrail 2020-08-09 14:40:16 UTC
Comment on attachment 5714 [details]
An HTML page is sent by the update server

How did you download the sha512 file?  Was it automated or manual?  That looks like the HTML message from http://sa-update.pccc.com/, for example.
Comment 20 Kevin A. McGrail 2020-08-09 14:42:48 UTC
Comment on attachment 5715 [details]
sa-update -D of a bad run

http://sa-update.bitwell.fi/ is stale.  We are trying to reach Jari and hope he is well.  His server disk space is full and calls have not been answered.  Keep him and everyone in this pandemic in your thoughts, please.

Delete your MIRRORED.BY file to force SA to grab the latest list of mirrors where his server is removed from consideration.
Comment 21 peter@peternowee.com 2020-08-14 08:55:06 UTC
With the new list of mirrors I have not seen the error again, so thank you for that. I assume your questions in comment 19 were answered by the other attachment you looked at in comment 20, otherwise please let me know.

I also hope Jani is ok. Thank you all for your hard work.
Comment 22 peter@peternowee.com 2020-08-14 09:12:02 UTC
Jari, I mean. Hope he is ok.
Comment 23 Kevin A. McGrail 2020-08-14 21:30:48 UTC
+1 to Jari and closing this ticket as resolved due to mirror issues.