Advanced
Mailing List Archive

Mailing List Archive

  1. Home >
  2. SpamAssassin>
  3. users
SA4 spamhaus/DQS "async: aborting" log messages?
pgnet.dev at gmail
Dec 20, 2022, 8:26 AM
Post #1 of 3 (130 views)
Permalink
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?
Re: SA4 spamhaus/DQS "async: aborting" log messages? [ In reply to ]
riccardo.alfieri at spamteq
Dec 20, 2022, 8:46 AM
Post #2 of 3 (130 views)
Permalink
Probably asking the obvious, but did you actually substitute
"your_dqs_key" with your *actual* DQS key, right?

On 20/12/22 17:26, PGNet Dev wrote:
>
> 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
>
--
Best regards,
Riccardo Alfieri

Spamhaus Technology
https://www.spamhaus.com/
Re: SA4 spamhaus/DQS "async: aborting" log messages? [ In reply to ]
pgnet.dev at gmail
Dec 20, 2022, 11:43 AM
Post #3 of 3 (130 views)
Permalink
>> Probably asking the obvious, but did you actually substitute "your_dqs_key" with your *actual* DQS key, right?
>
> Heh.
>
> Not initially -- but yes, since.

and, after waiting awhile, i see it's not unique to DQS queries,

Tue Dec 20 14:34:27 2022 [916] info: async: aborting after 6.441 s, deadline shrunk: URIBL, A/www.amazon.com.multi.surbl.org, rules: SURBL_BLOCKED, URIBL_CR_SURBL, URIBL_PH_SURBL, URIBL_MW_SURBL, URIBL_ABUSE_SURBL, URIBL_WS_SURBL
Tue Dec 20 14:34:27 2022 [916] info: async: aborting after 6.440 s, deadline shrunk: URIBL, A/amazonses.com.multi.surbl.org, rules: URIBL_WS_SURBL, SURBL_BLOCKED, URIBL_CR_SURBL, URIBL_PH_SURBL, URIBL_MW_SURBL, URIBL_ABUSE_SURBL
Tue Dec 20 14:34:27 2022 [916] info: async: aborting after 6.443 s, deadline shrunk: URIBL, A/amazon.com.multi.surbl.org, rules: URIBL_WS_SURBL, URIBL_ABUSE_SURBL, SURBL_BLOCKED, URIBL_CR_SURBL, URIBL_MW_SURBL, URIBL_PH_SURBL
Tue Dec 20 14:34:27 2022 [916] info: async: aborting after 6.446 s, deadline shrunk: URIBL, A/www.swiship.com.multi.surbl.org, rules: URIBL_ABUSE_SURBL, SURBL_BLOCKED, URIBL_PH_SURBL, URIBL_CR_SURBL, URIBL_MW_SURBL, URIBL_WS_SURBL
Tue Dec 20 14:34:27 2022 [916] info: async: aborting after 6.436 s, deadline shrunk: URIBL, A/images-na.ssl-images-amazon.com.multi.surbl.org, rules: URIBL_ABUSE_SURBL, URIBL_MW_SURBL, URIBL_CR_SURBL, URIBL_PH_SURBL, SURBL_BLOCKED, URIBL_WS_SURBL

©2024 GT.net. A Gossamer Threads company.
5th Floor, 455 Granville St., Vancouver, BC V6C 1T1, Canada | Legal