Error updating SpamAssassin Rules. Code=4

BBM

Verified User
Joined
Jun 8, 2013
Messages
332
Location
Dutch Mountains
"cron.daily" reported this error yesterday, and again today;

Code:
Error updating SpamAssassin Rules. Code=4
Was this error shown because some update-servers couldn't be found, or that some modules weren't installed?
If the latter, I wonder how it's possible that this error hasn't been reported much earlier?

How to fix?


Error-log:
Code:
/etc/cron.daily/sa-update:

Error updating SpamAssassin Rules. Code=4

Mar 17 04:24:05.942 [11826] dbg: logger: adding facilities: all
Mar 17 04:24:05.943 [11826] dbg: logger: logging level is DBG
Mar 17 04:24:05.943 [11826] dbg: generic: SpamAssassin version 3.4.1
Mar 17 04:24:05.943 [11826] dbg: generic: Perl 5.010001, PREFIX=/usr, DEF_RULES_DIR=/usr/share/spamassassin, LOCAL_RULES_DIR=/etc/mail/spamassassin, LOCAL_STATE_DIR=/var/lib/spamassassin
Mar 17 04:24:05.943 [11826] dbg: config: timing enabled
Mar 17 04:24:05.947 [11826] dbg: config: score set 0 chosen.
Mar 17 04:24:05.955 [11826] dbg: generic: sa-update version svn1652181
Mar 17 04:24:05.955 [11826] dbg: generic: using update directory: /var/lib/spamassassin/3.004001
Mar 17 04:24:06.030 [11826] dbg: diag: perl platform: 5.010001 linux
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: Digest::SHA1, version 2.12
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: HTML::Parser, version 3.64
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: Net::DNS, version 0.65
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: NetAddr::IP, version 4.027
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: Time::HiRes, version 1.9721
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: Archive::Tar, version 1.58
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: IO::Zlib, version 1.09
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: Digest::SHA1, version 2.12
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: MIME::Base64, version 3.08
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: DB_File, version 1.82
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: Net::SMTP, version 2.31
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module not installed: Mail::SPF ('require' failed)
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module not installed: Geo::IP ('require' failed)
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module not installed: Net::CIDR::Lite ('require' failed)
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module not installed: Razor2::Client::Agent ('require' failed)
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module not installed: IO::Socket::IP ('require' failed)
Mar 17 04:24:06.030 [11826] dbg: diag: [...] module installed: IO::Socket::INET6, version 2.56
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module installed: IO::Socket::SSL, version 1.31
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module installed: Compress::Zlib, version 2.021
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module installed: Mail::DKIM, version 0.37
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module installed: DBI, version 1.609
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module installed: Getopt::Long, version 2.38
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module installed: LWP::UserAgent, version 5.833
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module installed: HTTP::Date, version 5.831
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module installed: Encode::Detect::Detector, version 1.01
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module not installed: Net::Patricia ('require' failed)
Mar 17 04:24:06.031 [11826] dbg: diag: [...] module not installed: Net::DNS::Nameserver ('require' failed)
Mar 17 04:24:06.032 [11826] dbg: util: secure_tmpfile created a temporary file /tmp/.spamassassin11826zkCkEqtmp
Mar 17 04:24:06.032 [11826] dbg: channel: attempting channel sought.rules.yerp.org
Mar 17 04:24:06.032 [11826] dbg: channel: using existing directory /var/lib/spamassassin/3.004001/sought_rules_yerp_org
Mar 17 04:24:06.032 [11826] dbg: channel: channel cf file /var/lib/spamassassin/3.004001/sought_rules_yerp_org.cf
Mar 17 04:24:06.032 [11826] dbg: channel: channel pre file /var/lib/spamassassin/3.004001/sought_rules_yerp_org.pre
Mar 17 04:24:06.033 [11826] dbg: channel: metadata version = 3402014020421, from file /var/lib/spamassassin/3.004001/sought_rules_yerp_org.cf
Mar 17 04:24:06.038 [11826] dbg: dns: 1.4.3.sought.rules.yerp.org => 3402014020421, parsed as 3402014020421
Mar 17 04:24:06.039 [11826] dbg: channel: current version is 3402014020421, new version is 3402014020421, skipping channel
Mar 17 04:24:06.039 [11826] dbg: channel: attempting channel updates.spamassassin.org
Mar 17 04:24:06.039 [11826] dbg: channel: using existing directory /var/lib/spamassassin/3.004001/updates_spamassassin_org
Mar 17 04:24:06.039 [11826] dbg: channel: channel cf file /var/lib/spamassassin/3.004001/updates_spamassassin_org.cf
Mar 17 04:24:06.039 [11826] dbg: channel: channel pre file /var/lib/spamassassin/3.004001/updates_spamassassin_org.pre
Mar 17 04:24:06.040 [11826] dbg: channel: metadata version = 1826702, from file /var/lib/spamassassin/3.004001/updates_spamassassin_org.cf
Mar 17 04:24:06.042 [11826] dbg: dns: 1.4.3.updates.spamassassin.org => 1826926, parsed as 1826926
Mar 17 04:24:06.043 [11826] dbg: channel: preparing temp directory for new channel
Mar 17 04:24:06.043 [11826] dbg: channel: created tmp directory /tmp/.spamassassin11826E7N3lwtmp
Mar 17 04:24:06.043 [11826] dbg: generic: lint checking site pre files once before attempting channel updates
Mar 17 04:24:06.043 [11826] dbg: generic: SpamAssassin version 3.4.1
Mar 17 04:24:06.043 [11826] dbg: generic: Perl 5.010001, PREFIX=/usr, DEF_RULES_DIR=/usr/share/spamassassin, LOCAL_RULES_DIR=/etc/mail/spamassassin, LOCAL_STATE_DIR=/var/lib/spamassassin
Mar 17 04:24:06.044 [11826] dbg: config: timing enabled
Mar 17 04:24:06.046 [11826] dbg: config: score set 0 chosen.
Mar 17 04:24:06.047 [11826] dbg: ignore: using a test message to lint rules
Mar 17 04:24:06.047 [11826] dbg: config: using "/etc/mail/spamassassin" for site rules pre files
Mar 17 04:24:06.048 [11826] dbg: config: read file /etc/mail/spamassassin/init.pre
Mar 17 04:24:06.048 [11826] dbg: config: read file /etc/mail/spamassassin/v310.pre
Mar 17 04:24:06.049 [11826] dbg: config: read file /etc/mail/spamassassin/v312.pre
Mar 17 04:24:06.050 [11826] dbg: config: read file /etc/mail/spamassassin/v320.pre
Mar 17 04:24:06.050 [11826] dbg: config: read file /etc/mail/spamassassin/v330.pre
Mar 17 04:24:06.051 [11826] dbg: config: read file /etc/mail/spamassassin/v340.pre
Mar 17 04:24:06.053 [11826] dbg: config: read file /etc/mail/spamassassin/v341.pre
Mar 17 04:24:06.053 [11826] dbg: config: using "/tmp/.spamassassin11826E7N3lwtmp/doesnotexist" for sys rules pre files
Mar 17 04:24:06.053 [11826] dbg: config: using "/tmp/.spamassassin11826E7N3lwtmp/doesnotexist" for default rules dir
Mar 17 04:24:06.054 [11826] dbg: config: using "/tmp/.spamassassin11826E7N3lwtmp/doesnotexist/doesnotexist" for user prefs file
Mar 17 04:24:06.054 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::URIDNSBL from @INC
Mar 17 04:24:06.060 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::Hashcash from @INC
Mar 17 04:24:06.063 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::SPF from @INC
Mar 17 04:24:06.067 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::Pyzor from @INC
Mar 17 04:24:06.070 [11826] dbg: pyzor: local tests only, disabling Pyzor
Mar 17 04:24:06.070 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::Razor2 from @INC
Mar 17 04:24:06.073 [11826] dbg: razor2: local tests only, skipping Razor
Mar 17 04:24:06.073 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::SpamCop from @INC
Mar 17 04:24:06.076 [11826] dbg: reporter: local tests only, disabling SpamCop
Mar 17 04:24:06.077 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::AutoLearnThreshold from @INC
Mar 17 04:24:06.078 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::WhiteListSubject from @INC
Mar 17 04:24:06.080 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::MIMEHeader from @INC
Mar 17 04:24:06.081 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::ReplaceTags from @INC
Mar 17 04:24:06.083 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::DKIM from @INC
Mar 17 04:24:06.090 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::Check from @INC
Mar 17 04:24:06.097 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::HTTPSMismatch from @INC
Mar 17 04:24:06.098 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::URIDetail from @INC
Mar 17 04:24:06.100 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::Bayes from @INC
Mar 17 04:24:06.108 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::BodyEval from @INC
Mar 17 04:24:06.111 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::DNSEval from @INC
Mar 17 04:24:06.114 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::HTMLEval from @INC
Mar 17 04:24:06.117 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::HeaderEval from @INC
Mar 17 04:24:06.123 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::MIMEEval from @INC
Mar 17 04:24:06.126 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::RelayEval from @INC
Mar 17 04:24:06.130 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::URIEval from @INC
Mar 17 04:24:06.131 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::WLBLEval from @INC
Mar 17 04:24:06.136 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::VBounce from @INC
Mar 17 04:24:06.138 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::ImageInfo from @INC
Mar 17 04:24:06.140 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::FreeMail from @INC
Mar 17 04:24:06.144 [11826] dbg: plugin: loading Mail::SpamAssassin::Plugin::AskDNS from @INC
Mar 17 04:24:06.148 [11826] dbg: config: finish parsing
Mar 17 04:24:06.149 [11826] dbg: plugin: Mail::SpamAssassin::Plugin::ReplaceTags=HASH(0x345d1b8) implements 'finish_parsing_end', priority 0
Mar 17 04:24:06.149 [11826] dbg: plugin: Mail::SpamAssassin::Plugin::FreeMail=HASH(0x38bae60) implements 'finish_parsing_end', priority 0
Mar 17 04:24:06.149 [11826] dbg: replacetags: replacing tags
Mar 17 04:24:06.149 [11826] dbg: replacetags: done replacing tags
Mar 17 04:24:06.149 [11826] dbg: FreeMail: no freemail_domains entries defined, disabling plugin
Mar 17 04:24:06.149 [11826] dbg: config: score set 0 chosen.
Mar 17 04:24:06.150 [11826] dbg: dns: EDNS, UDP payload size 4096
Mar 17 04:24:06.150 [11826] dbg: dns: servers obtained from Net::DNS : [80.69.67.66]:53, [80.69.66.67]:53
Mar 17 04:24:06.150 [11826] dbg: dns: nameservers set to 80.69.67.66, 80.69.66.67
Mar 17 04:24:06.150 [11826] dbg: dns: using socket module: IO::Socket::INET6 version 2.56
Mar 17 04:24:06.150 [11826] dbg: dns: is Net::DNS::Resolver available? yes
Mar 17 04:24:06.150 [11826] dbg: dns: Net::DNS version: 0.65
Mar 17 04:24:06.150 [11826] dbg: config: time limit 300.0 s
Mar 17 04:24:06.150 [11826] dbg: message: main message type: text/plain
Mar 17 04:24:06.150 [11826] dbg: message: ---- MIME PARSER START ----
Mar 17 04:24:06.150 [11826] dbg: message: parsing normal part
Mar 17 04:24:06.151 [11826] dbg: message: storing a body to memory
Mar 17 04:24:06.151 [11826] dbg: message: ---- MIME PARSER END ----
Mar 17 04:24:06.151 [11826] dbg: check: pms new, time limit in 299.999 s
Mar 17 04:24:06.151 [11826] dbg: plugin: Mail::SpamAssassin::Plugin::DNSEval=HASH(0x36c47c0) implements 'check_start', priority 0
Mar 17 04:24:06.152 [11826] dbg: plugin: Mail::SpamAssassin::Plugin::Check=HASH(0x358aed0) implements 'check_main', priority 0
Mar 17 04:24:06.152 [11826] dbg: config: trusted_networks are not configured; it is recommended that you configure trusted_networks manually
Mar 17 04:24:06.152 [11826] dbg: metadata: X-Spam-Relays-Trusted: 
Mar 17 04:24:06.152 [11826] dbg: metadata: X-Spam-Relays-Untrusted: 
Mar 17 04:24:06.152 [11826] dbg: metadata: X-Spam-Relays-Internal: 
Mar 17 04:24:06.152 [11826] dbg: metadata: X-Spam-Relays-External: 
Mar 17 04:24:06.153 [11826] dbg: plugin: Mail::SpamAssassin::Plugin::AskDNS=HASH(0x38bb7d8) implements 'extract_metadata', priority 0
Mar 17 04:24:06.153 [11826] dbg: dns: is DNS available? 0
Mar 17 04:24:06.153 [11826] dbg: check: tagrun - tag AUTHORDOMAIN is now ready, value: compiling.spamassassin.taint.org
Mar 17 04:24:06.153 [11826] dbg: check: tagrun - tag RELAYSTRUSTED is now ready, value: 
Mar 17 04:24:06.153 [11826] dbg: check: tagrun - tag RELAYSUNTRUSTED is now ready, value: 
Mar 17 04:24:06.153 [11826] dbg: check: tagrun - tag RELAYSINTERNAL is now ready, value: 
Mar 17 04:24:06.153 [11826] dbg: check: tagrun - tag RELAYSEXTERNAL is now ready, value: 
Mar 17 04:24:06.153 [11826] dbg: check: tagrun - tag LANGUAGES is now ready, value: <UNDEF>
Mar 17 04:24:06.153 [11826] dbg: message: no encoding detected
Mar 17 04:24:06.153 [11826] dbg: plugin: Mail::SpamAssassin::Plugin::URIDNSBL=HASH(0x33147f8) implements 'parsed_metadata', priority 0
Mar 17 04:24:06.153 [11826] dbg: rules: local tests only, ignoring RBL eval
Mar 17 04:24:06.154 [11826] dbg: check: check_main, time limit in 299.997 s
Mar 17 04:24:06.155 [11826] dbg: dns: harvest_dnsbl_queries
Mar 17 04:24:06.155 [11826] dbg: check: is spam? score=0 required=5
Mar 17 04:24:06.155 [11826] dbg: check: tests=
Mar 17 04:24:06.155 [11826] dbg: check: subtests=
Mar 17 04:24:06.156 [11826] dbg: timing: total 108 ms - init: 103 (95.8%), parse: 0.63 (0.6%), extract_message_metadata: 1.35 (1.3%), get_uri_detail_list: 1.01 (0.9%)
Mar 17 04:24:06.156 [11826] dbg: plugin: Mail::SpamAssassin::Plugin::MIMEHeader=HASH(0x3447960) implements 'finish_tests', priority 0
Mar 17 04:24:06.156 [11826] dbg: plugin: Mail::SpamAssassin::Plugin::Check=HASH(0x358aed0) implements 'finish_tests', priority 0
Mar 17 04:24:06.157 [11826] dbg: generic: lint check of site pre files succeeded, continuing with channel updates
Mar 17 04:24:06.157 [11826] dbg: channel: protocol family available: inet,inet6
Mar 17 04:24:06.157 [11826] dbg: channel: reading MIRRORED.BY file /var/lib/spamassassin/3.004001/updates_spamassassin_org/MIRRORED.BY
Mar 17 04:24:06.158 [11826] dbg: channel: parsing MIRRORED.BY file for channel updates.spamassassin.org
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.dnswl.org/ weight=3
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://www.sa-update.pccc.com/ weight=5
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.secnap.net/ weight=5
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.space-pro.be/ weight=1
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.ena.com/ weight=5
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.razx.cloud/ weight=5
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.fossies.org/ weight=1
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.verein-clean.net/ weight=10
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.bitwell.fi/ weight=10
Mar 17 04:24:06.158 [11826] dbg: channel: found mirror http://sa-update.spamassassin.org/ weight=10
Mar 17 04:24:06.159 [11826] dbg: channel: selected mirror http://sa-update.razx.cloud
Mar 17 04:24:06.159 [11826] dbg: http: url: http://sa-update.razx.cloud/1826926.tar.gz
Mar 17 04:24:06.159 [11826] dbg: http: downloading to: /var/lib/spamassassin/3.004001/updates_spamassassin_org/1826926.tar.gz, new
Mar 17 04:24:06.159 [11826] dbg: util: current PATH is: /sbin:/bin:/usr/sbin:/usr/bin
Mar 17 04:24:06.159 [11826] dbg: util: executable for curl was found at /usr/bin/curl
Mar 17 04:24:06.159 [11826] dbg: http: /usr/bin/curl -s -L -O --remote-time -g --max-redirs 2 --connect-timeout 30 --max-time 300 --fail -o 1826926.tar.gz -- http://sa-update.razx.cloud/1826926.tar.gz
Mar 17 04:24:06.490 [11826] dbg: http: process [11827], exit status: exit 0
Mar 17 04:24:06.492 [11826] dbg: http: url: http://sa-update.razx.cloud/1826926.tar.gz.sha1
Mar 17 04:24:06.492 [11826] dbg: http: downloading to: /var/lib/spamassassin/3.004001/updates_spamassassin_org/1826926.tar.gz.sha1, new
Mar 17 04:24:06.492 [11826] dbg: util: executable for curl was found at /usr/bin/curl
Mar 17 04:24:06.493 [11826] dbg: http: /usr/bin/curl -s -L -O --remote-time -g --max-redirs 2 --connect-timeout 30 --max-time 300 --fail -o 1826926.tar.gz.sha1 -- http://sa-update.razx.cloud/1826926.tar.gz.sha1
Mar 17 04:24:06.518 [11826] dbg: http: process [11829], exit status: exit 0
Mar 17 04:24:06.520 [11826] dbg: sha1: verification wanted: fd8ec858acb7ae0e9a49382c7369e694968c285c
Mar 17 04:24:06.520 [11826] dbg: sha1: verification result: 827c899b550da86b6d0997573bb6a3101bc8ad0b
channel: SHA1 verification failed, channel failed
Mar 17 04:24:06.520 [11826] dbg: generic: cleaning up temporary directory/files
Mar 17 04:24:06.520 [11826] dbg: generic: cleaning directory /tmp/.spamassassin11826E7N3lwtmp
Mar 17 04:24:06.572 [11826] dbg: diag: updates complete, exiting with code 4
 

Richard G

Verified User
Joined
Jul 6, 2008
Messages
4,218
Location
Maastricht
Just monitor it to be sure.
I had the same issue 2 months ago. But in my case it kept throwing error 4. The cause was the perl NET::DNS and a couple of other perl things which needed updating.
After that it worked fine again.
 

BBM

Verified User
Joined
Jun 8, 2013
Messages
332
Location
Dutch Mountains
No errors were shown today so I presume the issue 'solved itself'.
But I will look into possibly updating Perl modules if needed.
 

Richard G

Verified User
Joined
Jul 6, 2008
Messages
4,218
Location
Maastricht
Yep only if needed, because it can also break things.

I had the error 4 later on also once, and thought it started again, but it was also a one time event, caused by their servers, after that only 0 and 1 again, so everthing is fine.
 

dave097

Verified User
Joined
May 8, 2014
Messages
113
Does this problem still play by other people? (here well on different DA servers)
 

zEitEr

Super Moderator
Joined
Apr 11, 2005
Messages
13,854
Location
GMT +7.00
Happens with cron randomly on our side (never day by day) and usually can not be reproduced manually... so I don't worry much about it.
 

zEitEr

Super Moderator
Joined
Apr 11, 2005
Messages
13,854
Location
GMT +7.00
It's an issue with SHA1 verification. Had an issue today on one of servers under monthly support:

Code:
Apr 19 06:31:19.022 [21256] dbg: sha1: verification wanted: 3.4
Apr 19 06:31:19.023 [21256] dbg: sha1: verification result: fa0de9421fff05f4717860a0aa3f00c1545650db
channel: SHA1 verification failed, channel failed

and from BBM's post:

Code:
Mar 17 04:24:06.520 [11826] dbg: sha1: verification wanted: fd8ec858acb7ae0e9a49382c7369e694968c285c
Mar 17 04:24:06.520 [11826] dbg: sha1: verification result: 827c899b550da86b6d0997573bb6a3101bc8ad0b
channel: SHA1 verification failed, channel failed
Verification wanted and result are different for some reasons.


The issue might happen in the following cases:

- if SpamAssassasin mirrors are out of sync, and SHA1 of a .tar.gz file and a hash of .tar.gz stored in a .tar.gz.sha1 do not match each other.
- if a corrupted tar.gz file with an update is downloaded due to network issues.

Probably there might be other cases.

It's not a bug in SpamAssassin, and is not a bug in Custombuild either I'd rather say. That's it.
 
Top