i'm migrating a v3 -> v4 install
after rules cleanup, mostly so far, so good
in logs I _am_ now seeing numbers of these "info: async: aborting after XXX s,
deadline shrunk ..." msgs,
Mon Dec 19 22:37:30 2022 [17726] info: async: aborting after 4.738 s,
deadline shrunk: URIBL, A/sendgrid.net.multi.surbl.org, rules: SURBL_BLOCKED,
URIBL_WS_SURBL, URIBL_PH_SURBL, URIBL_ABUSE_SURBL, URIBL_CR_SURBL,
URIBL_MW_SURBL
they _are_ just 'info' notices, but do say "aborting" which certainly sound
unhealthy.
searching in "deadline shrunk" i've not found anything yet re: what to do about
it.
with
spamd ... --debug=timing,async
a detailed log example,
...
Tue Dec 20 11:16:14 2022 [54384] dbg: async: starting:
SH_ZRD_HEADERS_VERY_FRESH, HASHBL,
A/compiling.spamassassin.taint.org.your_dqs_key.zrd.dq.spamhaus.net (timeout
15.0s, min 3.0s)
Tue Dec 20 11:16:14 2022 [54384] dbg: async: query
3889/IN/A/compiling.spamassassin.taint.org.your_dqs_key.zrd.dq.spamhaus.net
already underway, adding no.2, rules: SH_ZRD_HEADERS_FRESH
Tue Dec 20 11:16:15 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=0.0), did 0 callbacks
Tue Dec 20 11:16:15 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:15 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=0.0), did 0 callbacks
Tue Dec 20 11:16:15 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:15 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=0.0), did 0 callbacks
Tue Dec 20 11:16:15 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:16 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:16 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:17 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:17 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:18 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:18 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:19 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:19 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:20 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:20 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:21 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:21 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:22 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:22 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:23 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:23 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:24 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:24 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:25 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:25 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:26 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:26 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:27 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:27 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:28 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=1.0), did 0 callbacks
Tue Dec 20 11:16:28 2022 [54384] dbg: async: queries still pending: HASHBL=2
Tue Dec 20 11:16:28 2022 [54384] dbg: async: reducing select timeout from 1.0
to 0.2 s
Tue Dec 20 11:16:28 2022 [54384] dbg: async: select found 0 responses ready
(t.o.=0.2), did 0 callbacks
Tue Dec 20 11:16:28 2022 [54384] dbg: async: escaping: lost or timed out
requests or responses
Tue Dec 20 11:16:28 2022 [54384] info: async: aborting after 13.670 s, deadline
shrunk: HASHBL,
A/compiling.spamassassin.taint.org.your_dqs_key.dbl.dq.spamhaus.net, rules:
SH_DBL_HEADERS
Tue Dec 20 11:16:28 2022 [54384] info: async: aborting after 13.670 s, deadline
shrunk: HASHBL,
A/compiling.spamassassin.taint.org.your_dqs_key.zrd.dq.spamhaus.net, rules:
SH_ZRD_HEADERS_FRESH, SH_ZRD_HEADERS_VERY_FRESH
Tue Dec 20 11:16:28 2022 [54384] dbg: async: calling callback/abort on key
A/compiling.spamassassin.taint.org.your_dqs_key.dbl.dq.spamhaus.net, rules:
SH_DBL_HEADERS
Tue Dec 20 11:16:28 2022 [54384] dbg: async: calling callback/abort on key
A/compiling.spamassassin.taint.org.your_dqs_key.zrd.dq.spamhaus.net, rules:
SH_ZRD_HEADERS_VERY_FRESH
Tue Dec 20 11:16:28 2022 [54384] dbg: async: calling callback/abort on key
A/compiling.spamassassin.taint.org.your_dqs_key.zrd.dq.spamhaus.net, rules:
SH_ZRD_HEADERS_FRESH
Tue Dec 20 11:16:28 2022 [54384] dbg: async: aborted 2 remaining lookups
Tue Dec 20 11:16:28 2022 [54384] dbg: async: timing: 0.001 .
A/compiling.spamassassin.taint.org.fresh.fmb.la (AskDNS)
Tue Dec 20 11:16:28 2022 [54384] dbg: async: timing: 13.670 X
A/compiling.spamassassin.taint.org.your_dqs_key.zrd.dq.spamhaus.net
Tue Dec 20 11:16:28 2022 [54384] dbg: async: timing: 13.670 X
A/compiling.spamassassin.taint.org.your_dqs_key.dbl.dq.spamhaus.net
...
I run SA4 + DQS (v4 beta) rules in with Postfix/postscreen
in SA's conf, I don't need the redundant check, so I've
skip_rbl_checks 1
which I suspect may not be sufficient?
What config change do I need here to stop/fix those aborts?
Or being just 'info', do I care?
