spamassassin --report does not train BAYES

Wed Aug 17 09:25:39 UTC 2016

Did anyone else experience such a behavior or might it be related to
some 'special' configuration issues? Could it be a file
ownership/permission problem?

Thanks,
  Marc

P.S.: Debug Log-Output is attached below...

Am 11.08.2016 um 16:30 schrieb Marc:
> Dear list,
>
> I have recently discovered some strange behavior.
>
> If I use 'spamassassin -r < {spammessage}' reporting to DCC/Razor/Pyzor
> *seems* to work according to debug. Bayes learning *should* also work
> (as I made sure that 'bayes_learn_during_report' is set to 1, which is
> the default anyway).
> However, checking with 'spamassassin -t < {spammessage}' only gives
> BAYES_50.
>
> If I afterwards perform 'sa-learn --dbpath $DB_DIR --forget
> {spammessage}' and 'sa-learn --dbpath $DB_DIR --spam {spammessage}',
> things work out and I get a BAYES score of 1.0000.
>
> ======
> Setup:
>     Mailscanner version 4.84.5
>     SpamAssassin version 3.4.1
>     Perl version 5.18.4
>     ----
>     DB_DIR=/volume1/MailPlus/spamassassin
>     local.cf: bayes_path              /volume1/MailPlus/spamassassin/bayes
>    
> =====
>
> Any clues?
>
> Thanks,
>   Marc
>
__
  bait: mailbait at hohestieg.net
  also bait: http://www.hohestieg.net/notforhumans.html

____
LOG OUTPUT:
Aug 17 11:13:06.878 [1328] dbg: logger: logging level is DBG
Aug 17 11:13:06.879 [1328] dbg: generic: SpamAssassin version 3.4.1
Aug 17 11:13:06.879 [1328] dbg: generic: Perl 5.018004,
PREFIX=/var/packages/MailPlus-Server/target,
DEF_RULES_DIR=/var/packages/MailPlus-Server/target/share/spamassassin,
LOCAL_RULES_DIR=/var/packages/MailPlus-Server/target/etc/spamassassin,
LOCAL_STATE_DIR=/var/packages/MailPlus-Server/target/var/spamassassin
Aug 17 11:13:07.794 [1328] dbg: plugin: loading
Mail::SpamAssassin::Plugin::DCC from @INC
Aug 17 11:13:07.808 [1328] dbg: dcc: network tests on, registering DCC
Aug 17 11:13:07.808 [1328] dbg: plugin: loading
Mail::SpamAssassin::Plugin::Pyzor from @INC
Aug 17 11:13:07.814 [1328] dbg: pyzor: network tests on, attempting Pyzor
Aug 17 11:13:07.814 [1328] dbg: plugin: loading
Mail::SpamAssassin::Plugin::Razor2 from @INC
Aug 17 11:13:07.924 [1328] dbg: razor2: razor2 is available, version 2.84
Aug 17 11:13:07.924 [1328] dbg: plugin: loading
Mail::SpamAssassin::Plugin::SpamCop from @INC
Aug 17 11:13:07.949 [1328] dbg: reporter: network tests on, attempting
SpamCop
Aug 17 11:13:13.547 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::Bayes=HASH(0x4267b10) implements
'learner_new', priority 0
Aug 17 11:13:13.547 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::TxRep=HASH(0x43ba9c8) implements
'learner_new', priority 0
Aug 17 11:13:13.547 [1328] dbg: bayes: learner_new
self=Mail::SpamAssassin::Plugin::Bayes=HASH(0x4267b10),
bayes_store_module=Mail::SpamAssassin::BayesStore::DBM
Aug 17 11:13:13.576 [1328] dbg: bayes: learner_new: got
store=Mail::SpamAssassin::BayesStore::DBM=HASH(0x44c1f18)
Aug 17 11:13:13.577 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::Bayes=HASH(0x4267b10) implements
'learner_is_scan_available', priority 0
Aug 17 11:13:13.577 [1328] dbg: bayes: tie-ing to DB file R/O
/volume1/MailPlus/spamassassin/bayes_toks
Aug 17 11:13:13.578 [1328] dbg: bayes: tie-ing to DB file R/O
/volume1/MailPlus/spamassassin/bayes_seen
Aug 17 11:13:13.580 [1328] dbg: bayes: found bayes db version 3
Aug 17 11:13:13.580 [1328] dbg: bayes: DB journal sync: last sync:
1471415411
Aug 17 11:13:13.581 [1328] dbg: config: score set 3 chosen.
Aug 17 11:13:13.582 [1328] dbg: dns: EDNS, UDP payload size 4096
Aug 17 11:13:13.583 [1328] dbg: dns: servers obtained from Net::DNS :
[192.168.1.10]:53, [87.118.100.175]:53
Aug 17 11:13:13.583 [1328] dbg: dns: nameservers set to 192.168.1.10,
87.118.100.175
Aug 17 11:13:13.583 [1328] dbg: dns: using socket module:
IO::Socket::INET6 version 2.71
Aug 17 11:13:13.583 [1328] dbg: dns: is Net::DNS::Resolver available? yes
Aug 17 11:13:13.583 [1328] dbg: dns: Net::DNS version: 0.73
Aug 17 11:13:13.584 [1328] dbg: config: time limit 300.0 s
Aug 17 11:13:13.587 [1328] dbg: message: main message type:
multipart/alternative
Aug 17 11:13:13.588 [1328] dbg: markup: removing markup
Aug 17 11:13:13.588 [1328] dbg: config: time limit 300.0 s
Aug 17 11:13:13.591 [1328] dbg: message: main message type:
multipart/alternative
Aug 17 11:13:13.594 [1328] dbg: check: pms new, time limit in 299.995 s
Aug 17 11:13:13.597 [1328] dbg: netset: trusted_networks lookup on
127.0.0.1, 26 networks, result: 1, 0.544 ms
Aug 17 11:13:13.597 [1328] dbg: netset: internal_networks lookup on
127.0.0.1, 3 networks, result: 1, 0.486 ms
Aug 17 11:13:13.597 [1328] dbg: received-header: relay 127.0.0.1
trusted? yes internal? yes msa? no
Aug 17 11:13:13.607 [1328] dbg: received-header: found fetchmail marker,
restarting parse
Aug 17 11:13:13.611 [1328] dbg: netset: trusted_networks lookup on
2607:f8b0:400c:c08::244, 26 networks, result: 0, 1.655 ms
Aug 17 11:13:13.611 [1328] dbg: received-header: relay
2607:f8b0:400c:c08::244 trusted? no internal? no msa? no
Aug 17 11:13:13.661 [1328] dbg: markup: removing markup
Aug 17 11:13:13.662 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::DCC=HASH(0x36ece38) implements
'plugin_report', priority 0
Aug 17 11:13:13.662 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::Pyzor=HASH(0x3780520) implements
'plugin_report', priority 0
Aug 17 11:13:13.662 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::Razor2=HASH(0x37b9f90) implements
'plugin_report', priority 0
Aug 17 11:13:13.662 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::SpamCop=HASH(0x3c2dd10) implements
'plugin_report', priority 0
Aug 17 11:13:13.663 [1328] dbg: util: executable for cdcc was found at
/usr/local/bin/cdcc
Aug 17 11:13:13.663 [1328] dbg: dcc: dcc_pgm_path, found cdcc in
env.path: /usr/local/bin/cdcc
Aug 17 11:13:13.677 [1328] dbg: dcc: `/usr/local/bin/cdcc -qV homedir
libexecdir` reports '1.3.158 homedir=/var/dcc libexecdir=/var/dcc/libexec '
Aug 17 11:13:13.677 [1328] dbg: dcc: use 'dcc_libexec /var/dcc/libexec'
from cdcc
Aug 17 11:13:13.677 [1328] dbg: dcc: use 'dcc_home /var/dcc' from cdcc
Aug 17 11:13:13.677 [1328] dbg: dns: entering helper-app run mode
Aug 17 11:13:13.679 [1328] dbg: reporter: connecting to local socket
/var/dcc/dccifd
Aug 17 11:13:17.999 [1328] dbg: dns: leaving helper-app run mode
Aug 17 11:13:18.000 [1328] dbg: reporter: dccifd responded with
'X-DCC--Metrics: diskstation 1481; bulk Body=many Fuz1=many Fuz2=many'
Aug 17 11:13:18.000 [1328] info: reporter: spam reported to DCC
Aug 17 11:13:18.000 [1328] dbg: util: executable for pyzor was found at
/bin/pyzor
Aug 17 11:13:18.000 [1328] dbg: pyzor: pyzor is available: /bin/pyzor
Aug 17 11:13:18.001 [1328] dbg: util: secure_tmpfile created a temporary
file /tmp/.spamassassin1328zg3U3itmp
Aug 17 11:13:18.001 [1328] dbg: check: create_fulltext_tmpfile, written
4618 bytes to file /tmp/.spamassassin1328zg3U3itmp
Aug 17 11:13:18.001 [1328] dbg: dns: entering helper-app run mode
Aug 17 11:13:18.002 [1328] dbg: pyzor: opening pipe: /bin/pyzor report <
/tmp/.spamassassin1328zg3U3itmp
Aug 17 11:13:18.007 [1368] dbg: util: setuid: ruid=0 euid=0
Aug 17 11:13:18.319 [1328] dbg: pyzor: [1368] reporter finished successfully
Aug 17 11:13:18.319 [1328] dbg: dns: leaving helper-app run mode
Aug 17 11:13:18.320 [1328] info: reporter: spam reported to Pyzor
Aug 17 11:13:18.320 [1328] dbg: dns: entering helper-app run mode
Aug 17 11:13:21.561 [1328] dbg: dns: leaving helper-app run mode
Aug 17 11:13:21.562 [1328] info: reporter: spam reported to Razor
Aug 17 11:13:22.409 [1328] dbg: reporter: SpamCop sent FROM
root at diskstation.hohestieg.selfhost.eu
Aug 17 11:13:22.409 [1328] dbg: reporter: SpamCop received 250 sender
<root at diskstation.hohestieg.selfhost.eu> ok
Aug 17 11:13:22.593 [1328] dbg: reporter: SpamCop sent TO
spamassassin-submit at spam.spamcop.net
Aug 17 11:13:22.593 [1328] dbg: reporter: SpamCop received 250 recipient
<spamassassin-submit at spam.spamcop.net> ok
Aug 17 11:13:23.150 [1328] dbg: reporter: SpamCop sent DATA
Aug 17 11:13:23.151 [1328] dbg: reporter: SpamCop received 250 go ahead
Aug 17 11:13:23.151 [1328] dbg: reporter: [...] ok: Message 978152756
accepted
Aug 17 11:13:23.334 [1328] dbg: reporter: SpamCop sent QUIT
Aug 17 11:13:23.335 [1328] dbg: reporter: SpamCop received 221
vmx.spamcop.net
Aug 17 11:13:23.335 [1328] info: reporter: spam reported to SpamCop
Aug 17 11:13:23.336 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::MIMEHeader=HASH(0x1f7a000) implements
'finish_tests', priority 0
Aug 17 11:13:23.337 [1328] dbg: plugin:
Mail::SpamAssassin::Plugin::Check=HASH(0x1f7a348) implements
'finish_tests', priority 0
Aug 17 11:13:23.338 [1328] dbg: netset: cache trusted_networks
hits/attempts: 0/2, 0.0 %
Aug 17 11:13:23.343 [1328] dbg: netset: cache internal_networks
hits/attempts: 0/1, 0.0 %
Aug 17 11:13:23.396 [1328] dbg: bayes: untie-ing
1 message(s) examined.