https://bz.apache.org/SpamAssassin/show_bug.cgi?id=3790
TM <tm@del.bg> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |tm@del.bg
--- Comment #16 from TM <tm@del.bg> ---
I'm hitting this behaviour if I enable the shortcircuit plugin, which is the
default with SpamHaus recommended configs from
https://github.com/spamhaus/spamassassin-dqs
The exact error message is:
bayes: cannot open bayes databases /%PATH%/.spamassassin/bayes_* R/W: lock
failed: Interrupted system call
Here's the process and fd situation at the time:
# ps axfuww|grep spam
root 11325 0.0 0.5 189900 102632 ? SNs Oct13 0:16 /usr/bin/perl
-T -w /usr/sbin/spamd --create-prefs --max-children 6 --helper-home-dir
--socketpath=/tmp/spamd.sock --vpopmail --username=vpopmail --syslog=local5 -d
--pidfile=/var/run/spamd.pid
vpopmail 1877 0.7 0.7 248604 157164 ? SN 18:01 1:01 \_ spamd
child
vpopmail 2142 0.2 0.6 227440 139140 ? SN 20:12 0:02 \_ spamd
child
# ls -la /proc/1877/fd
...
lrwx------ 1 root root 64 Oct 14 19:22 12 ->
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/0/colcrock.user/eeveem/.spamassassin/bayes.mutex
# cat /proc/1877/fdinfo/12
...
lock: 1: FLOCK ADVISORY WRITE 1877 fd:11:89801696 0 EOF
And here's spamd debug log:
Oct 14 14:51:49 serverX spamd[1248]: spamd: accept() on fd 5
Oct 14 14:51:49 serverX spamd[1248]: spamd: got connection over /tmp/spamd.sock
Oct 14 14:51:49 serverX spamd[1248]: bayes: learner_new
self=Mail::SpamAssassin::Plugin::Bayes=HASH(0x14a666070c30),
bayes_store_module=Mail::SpamAssassin::BayesStore::DBM
Oct 14 14:51:49 serverX spamd[1248]: bayes: learner_new: got
store=Mail::SpamAssassin::BayesStore::DBM=HASH(0x14a66aef5028)
Oct 14 14:51:49 serverX spamd[1248]: bayes: tie-ing to DB file R/O
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_toks
Oct 14 14:51:49 serverX spamd[1248]: bayes: tie-ing to DB file R/O
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_seen
Oct 14 14:51:49 serverX spamd[1248]: bayes: found bayes db version 3
Oct 14 14:51:49 serverX spamd[1248]: bayes: DB journal sync: last sync:
1602689761
Oct 14 14:51:49 serverX spamd[1248]: bayes: opportunistic call found journal
sync due
Oct 14 14:51:49 serverX spamd[1248]: bayes: bayes journal sync starting
Oct 14 14:51:49 serverX spamd[1248]: locker: mode is 384
Oct 14 14:51:49 serverX spamd[1248]: locker: safe_lock: created
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: locker: safe_lock: trying to get lock on
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes
with 10 timeout
Oct 14 14:51:49 serverX spamd[1248]: locker: safe_lock: link to
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex:
link ok
Oct 14 14:51:49 serverX spamd[1248]: bayes: tie-ing to DB file R/W
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_toks
Oct 14 14:51:49 serverX spamd[1248]: bayes: tie-ing to DB file R/W
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_seen
Oct 14 14:51:49 serverX spamd[1248]: bayes: found bayes db version 3
Oct 14 14:51:49 serverX spamd[1248]: locker: refresh_lock: refresh
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: locker: refresh_lock: refresh
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: locker: refresh_lock: refresh
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: locker: refresh_lock: refresh
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: bayes: synced databases from journal in 0
seconds: 3596 unique entries (4296 total entries)
Oct 14 14:51:49 serverX spamd[1248]: bayes: bayes journal sync completed
Oct 14 14:51:49 serverX spamd[1248]: spamd: running as uid 502
Oct 14 14:51:49 serverX spamd[1248]: spamd: checking message
<0.0.0.41.1D6A259278E2C40.2E5EA1@mail.trkcgfd.work> for nick@wahine.user:502
# here should be the unlocking; see bellow
Oct 14 14:51:49 serverX spamd[1248]: shortcircuit: s/c spam due to
RCVD_IN_ZEN_LASTEXTERNAL, using score of 100
Oct 14 14:51:49 serverX spamd[1248]: spamd: identified spam (124.9/5.0) for
nick@wahine.user:502 in 0.3 seconds, 7051 bytes.
Oct 14 14:51:49 serverX spamd[1248]: spamd: result: Y 124 -
RCVD_IN_PSBL,RCVD_IN_ZEN_LASTEXTERNAL,SHORTCIRCUIT,SH_DBL_HEADERS,URIBL_CSS,URIBL_CSS_A,URIBL_DBL_SPAM,URIBL_ZRD
scantime=0.3,size=7051,user=nick@wahine.user,uid=502,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=/tmp/spamd.sock,mid=<0.0.0.41.1D6A259278E2C40.2E5EA1@mail.trkcgfd.work>,autolearn=disabled,shortcircuit=spam
Disabling Mail::SpamAssassin::Plugin::Shortcircuit in sh.pre resolves the
problem. Without shortcircuit things look like this:
Oct 14 15:02:52 serverX spamd[1248]: spamd: running as uid 502
Oct 14 15:02:52 serverX spamd[1248]: spamd: checking message
<1113.927824369.202010141902431022559.0033804522@e.rh.com> for
nick@wahine.user:502
Oct 14 15:02:52 serverX spamd[1248]: bayes: tie-ing to DB file R/O
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_toks
Oct 14 15:02:53 serverX spamd[1248]: bayes: tie-ing to DB file R/O
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_seen
Oct 14 15:02:53 serverX spamd[1248]: bayes: found bayes db version 3
Oct 14 15:02:53 serverX spamd[1248]: bayes: DB journal sync: last sync:
1602702172
Oct 14 15:02:53 serverX spamd[1248]: bayes: corpus size: nspam = 23980, nham =
34868
Oct 14 15:02:53 serverX spamd[1248]: bayes: tokenized body: 461 tokens
Oct 14 15:02:53 serverX spamd[1248]: bayes: tokenized uri: 929 tokens
Oct 14 15:02:53 serverX spamd[1248]: bayes: tokenized invisible: 323 tokens
Oct 14 15:02:53 serverX spamd[1248]: bayes: tokenized header: 111 tokens
Oct 14 15:02:53 serverX spamd[1248]: bayes: score = 2.77555756156289e-16
Oct 14 15:02:53 serverX spamd[1248]: bayes: DB journal sync: last sync:
1602702172
Oct 14 15:02:53 serverX spamd[1248]: bayes: DB expiry: tokens in DB: 134983,
Expiry max size: 150000, Oldest atime: 1599401606, Newest atime: 1602702125,
Last expire: 1602158934, Current time: 1602702173
Oct 14 15:02:53 serverX spamd[1248]: bayes: untie-ing
Oct 14 15:02:53 serverX spamd[1248]: bayes: files locked, now unlocking lock
Oct 14 15:02:53 serverX spamd[1248]: locker: safe_unlock: unlocked
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 15:02:56 serverX spamd[1248]: spamd: clean message (2.5/5.0) for
nick@wahine.user:502 in 3.5 seconds, 21580 bytes.
Oct 14 15:02:56 serverX spamd[1248]: spamd: result: . 2 -
BAYES_00,DCC_CHECK,DIGEST_MULTIPLE,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_FONT_LOW_CONTRAST,HTML_MESSAGE,PYZOR_CHECK,SPF_HELO_NONE
scantime=3.5,size=21580,user=nick@wahine.user,uid=502,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=/tmp/spamd.sock,mid=<1113.927824369.202010141902431022559.0033804522@e.rh.com>,bayes=0.000000,autolearn=no
autolearn_force=no,shortcircuit=no
--
You are receiving this mail because:
You are the assignee for the bug.
TM <tm@del.bg> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |tm@del.bg
--- Comment #16 from TM <tm@del.bg> ---
I'm hitting this behaviour if I enable the shortcircuit plugin, which is the
default with SpamHaus recommended configs from
https://github.com/spamhaus/spamassassin-dqs
The exact error message is:
bayes: cannot open bayes databases /%PATH%/.spamassassin/bayes_* R/W: lock
failed: Interrupted system call
Here's the process and fd situation at the time:
# ps axfuww|grep spam
root 11325 0.0 0.5 189900 102632 ? SNs Oct13 0:16 /usr/bin/perl
-T -w /usr/sbin/spamd --create-prefs --max-children 6 --helper-home-dir
--socketpath=/tmp/spamd.sock --vpopmail --username=vpopmail --syslog=local5 -d
--pidfile=/var/run/spamd.pid
vpopmail 1877 0.7 0.7 248604 157164 ? SN 18:01 1:01 \_ spamd
child
vpopmail 2142 0.2 0.6 227440 139140 ? SN 20:12 0:02 \_ spamd
child
# ls -la /proc/1877/fd
...
lrwx------ 1 root root 64 Oct 14 19:22 12 ->
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/0/colcrock.user/eeveem/.spamassassin/bayes.mutex
# cat /proc/1877/fdinfo/12
...
lock: 1: FLOCK ADVISORY WRITE 1877 fd:11:89801696 0 EOF
And here's spamd debug log:
Oct 14 14:51:49 serverX spamd[1248]: spamd: accept() on fd 5
Oct 14 14:51:49 serverX spamd[1248]: spamd: got connection over /tmp/spamd.sock
Oct 14 14:51:49 serverX spamd[1248]: bayes: learner_new
self=Mail::SpamAssassin::Plugin::Bayes=HASH(0x14a666070c30),
bayes_store_module=Mail::SpamAssassin::BayesStore::DBM
Oct 14 14:51:49 serverX spamd[1248]: bayes: learner_new: got
store=Mail::SpamAssassin::BayesStore::DBM=HASH(0x14a66aef5028)
Oct 14 14:51:49 serverX spamd[1248]: bayes: tie-ing to DB file R/O
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_toks
Oct 14 14:51:49 serverX spamd[1248]: bayes: tie-ing to DB file R/O
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_seen
Oct 14 14:51:49 serverX spamd[1248]: bayes: found bayes db version 3
Oct 14 14:51:49 serverX spamd[1248]: bayes: DB journal sync: last sync:
1602689761
Oct 14 14:51:49 serverX spamd[1248]: bayes: opportunistic call found journal
sync due
Oct 14 14:51:49 serverX spamd[1248]: bayes: bayes journal sync starting
Oct 14 14:51:49 serverX spamd[1248]: locker: mode is 384
Oct 14 14:51:49 serverX spamd[1248]: locker: safe_lock: created
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: locker: safe_lock: trying to get lock on
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes
with 10 timeout
Oct 14 14:51:49 serverX spamd[1248]: locker: safe_lock: link to
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex:
link ok
Oct 14 14:51:49 serverX spamd[1248]: bayes: tie-ing to DB file R/W
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_toks
Oct 14 14:51:49 serverX spamd[1248]: bayes: tie-ing to DB file R/W
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_seen
Oct 14 14:51:49 serverX spamd[1248]: bayes: found bayes db version 3
Oct 14 14:51:49 serverX spamd[1248]: locker: refresh_lock: refresh
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: locker: refresh_lock: refresh
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: locker: refresh_lock: refresh
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: locker: refresh_lock: refresh
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 14:51:49 serverX spamd[1248]: bayes: synced databases from journal in 0
seconds: 3596 unique entries (4296 total entries)
Oct 14 14:51:49 serverX spamd[1248]: bayes: bayes journal sync completed
Oct 14 14:51:49 serverX spamd[1248]: spamd: running as uid 502
Oct 14 14:51:49 serverX spamd[1248]: spamd: checking message
<0.0.0.41.1D6A259278E2C40.2E5EA1@mail.trkcgfd.work> for nick@wahine.user:502
# here should be the unlocking; see bellow
Oct 14 14:51:49 serverX spamd[1248]: shortcircuit: s/c spam due to
RCVD_IN_ZEN_LASTEXTERNAL, using score of 100
Oct 14 14:51:49 serverX spamd[1248]: spamd: identified spam (124.9/5.0) for
nick@wahine.user:502 in 0.3 seconds, 7051 bytes.
Oct 14 14:51:49 serverX spamd[1248]: spamd: result: Y 124 -
RCVD_IN_PSBL,RCVD_IN_ZEN_LASTEXTERNAL,SHORTCIRCUIT,SH_DBL_HEADERS,URIBL_CSS,URIBL_CSS_A,URIBL_DBL_SPAM,URIBL_ZRD
scantime=0.3,size=7051,user=nick@wahine.user,uid=502,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=/tmp/spamd.sock,mid=<0.0.0.41.1D6A259278E2C40.2E5EA1@mail.trkcgfd.work>,autolearn=disabled,shortcircuit=spam
Disabling Mail::SpamAssassin::Plugin::Shortcircuit in sh.pre resolves the
problem. Without shortcircuit things look like this:
Oct 14 15:02:52 serverX spamd[1248]: spamd: running as uid 502
Oct 14 15:02:52 serverX spamd[1248]: spamd: checking message
<1113.927824369.202010141902431022559.0033804522@e.rh.com> for
nick@wahine.user:502
Oct 14 15:02:52 serverX spamd[1248]: bayes: tie-ing to DB file R/O
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_toks
Oct 14 15:02:53 serverX spamd[1248]: bayes: tie-ing to DB file R/O
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes_seen
Oct 14 15:02:53 serverX spamd[1248]: bayes: found bayes db version 3
Oct 14 15:02:53 serverX spamd[1248]: bayes: DB journal sync: last sync:
1602702172
Oct 14 15:02:53 serverX spamd[1248]: bayes: corpus size: nspam = 23980, nham =
34868
Oct 14 15:02:53 serverX spamd[1248]: bayes: tokenized body: 461 tokens
Oct 14 15:02:53 serverX spamd[1248]: bayes: tokenized uri: 929 tokens
Oct 14 15:02:53 serverX spamd[1248]: bayes: tokenized invisible: 323 tokens
Oct 14 15:02:53 serverX spamd[1248]: bayes: tokenized header: 111 tokens
Oct 14 15:02:53 serverX spamd[1248]: bayes: score = 2.77555756156289e-16
Oct 14 15:02:53 serverX spamd[1248]: bayes: DB journal sync: last sync:
1602702172
Oct 14 15:02:53 serverX spamd[1248]: bayes: DB expiry: tokens in DB: 134983,
Expiry max size: 150000, Oldest atime: 1599401606, Newest atime: 1602702125,
Last expire: 1602158934, Current time: 1602702173
Oct 14 15:02:53 serverX spamd[1248]: bayes: untie-ing
Oct 14 15:02:53 serverX spamd[1248]: bayes: files locked, now unlocking lock
Oct 14 15:02:53 serverX spamd[1248]: locker: safe_unlock: unlocked
/home/vpopmail/sa-bayes-db/home/vpopmail/domains/wahine.user/nick/.spamassassin/bayes.mutex
Oct 14 15:02:56 serverX spamd[1248]: spamd: clean message (2.5/5.0) for
nick@wahine.user:502 in 3.5 seconds, 21580 bytes.
Oct 14 15:02:56 serverX spamd[1248]: spamd: result: . 2 -
BAYES_00,DCC_CHECK,DIGEST_MULTIPLE,DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_FONT_LOW_CONTRAST,HTML_MESSAGE,PYZOR_CHECK,SPF_HELO_NONE
scantime=3.5,size=21580,user=nick@wahine.user,uid=502,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=/tmp/spamd.sock,mid=<1113.927824369.202010141902431022559.0033804522@e.rh.com>,bayes=0.000000,autolearn=no
autolearn_force=no,shortcircuit=no
--
You are receiving this mail because:
You are the assignee for the bug.