> On 07 Apr 2016, at 12:59, Joerg Jung <[email protected]> wrote:
>
>
>> Am 07.04.2016 um 11:51 schrieb Michiel van Es <[email protected]>:
>>
>> oops, forgot to reply-all (and miss [email protected]), send again ->
>>
>>> On 07 Apr 2016, at 11:30, Joerg Jung <[email protected]> wrote:
>>>
>>>
>>>>> On 07 Apr 2016, at 10:17, Michiel van Es <[email protected]> wrote:
>>>>>
>>>>>
>>>>> On 07 Apr 2016, at 10:02, Joerg Jung <[email protected]> wrote:
>>>>>
>>>>>
>>>>>>> On 07 Apr 2016, at 08:47, Michiel van Es <[email protected]> wrote:
>>>>>>> On 07 Apr 2016, at 08:41, Joerg Jung <[email protected]> wrote:
>>>>>>>
>>>>>>>>> What asr version have you installed? Recent one?
>>>>>>>>>
>>>>>>>>> You can also do a tcpdump please, to see what
>>>>>>>>> exactly goes over the wire (and comes back)?
>>>>>>>>>
>>>>>>>>> Also please temporarily disable all other filters, to
>>>>>>>>> rule-out chain problems.
>>>>>>>>
>>>>>>>> I installed libasr, opensmtpd and OpenSMTPD-Extras from github to
>>>>>>>> ensure the latest version.
>>>>>>>>
>>>>>>>> I use the following config to only use dnsbl:
>>>>>>>>
>>>>>>>> filter dnsbl dnsbl "-h" "psbl.surriel.com"
>>>>>>>> filter filter-clamav clamav
>>>>>>>> filter all chain dnsbl
>>>>>>>> filter sub chain filter-clamav
>>>>>>>> pki server.pragmasec.nl key
>>>>>>>> "/etc/letsencrypt/archive/server.pragmasec.nl/privkey1.pem"
>>>>>>>> pki server.pragmasec.nl certificate
>>>>>>>> "/etc/letsencrypt/archive/server.pragmasec.nl/fullchain1.pem"
>>>>>>>> listen on lo
>>>>>>>> listen on ens3 port 25 filter all hostname server.pragmasec.nl tls pki
>>>>>>>> server.pragmasec.nl
>>>>>>>> listen on ens3 port 587 filter sub hostname server.pragmasec.nl
>>>>>>>> tls-require pki server.pragmasec.nl auth mask-source
>>>>>>>> expire 7d
>>>>>>>> table vdomains "/usr/local/etc/vdomains"
>>>>>>>> table vusers "/usr/local/etc/vusers"
>>>>>>>> accept from any for domain <vdomains> virtual <vusers> deliver to mda
>>>>>>>> "/usr/lib/dovecot/dovecot-lda -f %{sender} -a %{rcpt}"
>>>>>>>> accept from local for any relay
>>>>>>>>
>>>>>>>> tcpdump of any traffic to psbl.surriel.org: (this seems useless as the
>>>>>>>> traffic is only dns and goes to the forwarders via my dnsmasq local
>>>>>>>> cache)
>>>>>>>> tcpdump -i any | grep ’74.92.59.67'
>>>>>>>>
>>>>>>>> *nothing*
>>>>>>>>
>>>>>>>> the error with strace and running with smtpd -d -v -T filter:
>>>>>>>>
>>>>>>>> epoll_wait(3, debug: smtp: new client on listener: 0x79d0c0
>>>>>>>> smtp-in: New session 71768b23cba98cf7 from host
>>>>>>>> pro-mail-smtp-001.bol.com [185.14.168.222]
>>>>>>>> filter: post-event event=EVENT_CONNECT filter=dnsbl
>>>>>>>> filter: new query QUERY_CONNECT
>>>>>>>> filter: filter_drain_query
>>>>>>>> 71768b247df9084f[QUERY_CONNECT=178.21.114.197 <->
>>>>>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x795bc0[datalen=0,eom=(nil),ofile=(nil)]]
>>>>>>>> filter: running filter filter:dnsbl[hooks=0xffffffff,flags=0x0000] for
>>>>>>>> query 71768b247df9084f[QUERY_CONNECT=178.21.114.197 <->
>>>>>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x795bc0[datalen=0,eom=(nil),ofile=(nil)]]
>>>>>>>> filter: waiting for running query
>>>>>>>> 71768b247df9084f[QUERY_CONNECT=178.21.114.197 <->
>>>>>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x795bc0[datalen=0,eom=(nil),ofile=(nil)]]
>>>>>>>> dnsbl[22353]: debug: on_connect: checking
>>>>>>>> 222.168.14.185.psbl.surriel.com.
>>>>>>>> dnsbl[22353]: warn: session 71768b23cba98cf7: event_dispatch: REJECT
>>>>>>>> address
>>>>>>>> filter: imsg IMSG_FILTER_RESPONSE from procfilter
>>>>>>>> dnsbl[hooks=0xffffffff,flags=0x0000]
>>>>>>>> filter: filter_drain_query
>>>>>>>> 71768b247df9084f[QUERY_CONNECT=178.21.114.197 <->
>>>>>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x795bc0[datalen=0,eom=(nil),ofile=(nil)]]
>>>>>>>> filter: filter_end_query 71768b247df9084f[QUERY_CONNECT=178.21.114.197
>>>>>>>> <->
>>>>>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x795bc0[datalen=0,eom=(nil),ofile=(nil)]]
>>>>>>>> filter: query 71768b247df9084f done: status=FILTER_CLOSE code=554
>>>>>>>> response="5.7.1 Address in DNSBL"
>>>>>>>> smtp-in: Failed command on session 71768b23cba98cf7: "" => 554 5.7.1
>>>>>>>> Address in DNSBL
>>>>>>>> smtp-in: Closing session 71768b23cba98cf7
>>>>>>>> debug: smtp: 0x859c80: deleting session: done
>>>>>>>> filter: post-event event=EVENT_DISCONNECT filter=dnsbl
>>>>>>>>
>>>>>>>> dnsmasq logging:
>>>>>>>>
>>>>>>>> Apr 7 07:48:41 server dnsmasq[6018]: query[A]
>>>>>>>> 222.168.14.185.psbl.surriel.com from 127.0.0.1
>>>>>>>> Apr 7 07:48:41 server dnsmasq[6018]: forwarded
>>>>>>>> 222.168.14.185.psbl.surriel.com to 95.85.9.86
>>>>>>>> Apr 7 07:48:41 server dnsmasq[6018]: reply
>>>>>>>> 222.168.14.185.psbl.surriel.com is NXDOMAIN
>>>>>>>>
>>>>>>>> any more pointers what could go wrong?
>>>>>>>
>>>>>>> To me, this really looks like a bug/problem in libasr now (Ubuntu
>>>>>>> specific).
>>>>>>
>>>>>> The libasr is from github (I tried 14.04 and 16.04) but can try a
>>>>>> different distro to check if others also have this issue?
>>>>>
>>>>> Others, e.g. FreeBSD and OpenBSD and some Linux (Debian/Alpine?) are
>>>>> known to work.
>>>>> For example, I use filter-dnsbl in production on OpenBSD.
>>>>
>>>> Hmm Ubuntu should be a derivative from Debian but I can also try that oner
>>>> later on.
>>>> BSD’s are not an option yet because of docker I am using for some
>>>> containers (I do see the FreeBSD docker option, might try that later ;) )
>>>>
>>>>>
>>>>>>> Despite the NXDOMAIN reply, this condition seems to become true for you:
>>>>>>> https://github.com/OpenSMTPD/OpenSMTPD-extras/blob/master/extras/wip/filters/filter-dnsbl/filter_dnsbl.c#L44
>>>>>>>
>>>>>>> The question is why does it become true und what is the value of:
>>>>>>> ar->ar_gai_errno (and why has it this value).
>>>>>>> Can you add/print the value to the log line please? For example:
>>>>>>> log_warnx("warn: session %016"PRIx64": event_dispatch: REJECT address
>>>>>>> ar_gai_errno=%d", *q, ar->ar_gai_errno);
>>>>>>
>>>>>> where do I need to add it? in which file? to
>>>>>> /extras/wip/filters/filter-dnsbl/filter_dnsbl.c and recompile the
>>>>>> OpenSMTPD-Extras?
>>>>>
>>>>> Yes, the log_warnx() from line 45 in filter_dnsbl.c
>>>>> https://github.com/OpenSMTPD/OpenSMTPD-extras/blob/master/extras/wip/filters/filter-dnsbl/filter_dnsbl.c#L45
>>>>>
>>>>> Just add ar->ar_gai_errno as additional argument like this:
>>>>> log_warnx("warn: session %016"PRIx64": event_dispatch: REJECT address
>>>>> ar_gai_errno=%d", *q, ar->ar_gai_errno);
>>>>>
>>>>> ...recompile and see log for the errno value. I hope this gives some
>>>>> insight (at least is a start).
>>>>
>>>> Did that, restart smtpd and got the following:
>>>>
>>>> debug: smtp: new client on listener: 0x9b40f0
>>>> smtp-in: New session 668445e741ecfaa7 from host
>>>> pro-mail-smtp-001.bol.com[185.14.168.222]
>>>> filter: post-event event=EVENT_CONNECT filter=dnsbl
>>>> filter: new query QUERY_CONNECT
>>>> filter: filter_drain_query 668445e8da5533e5[QUERY_CONNECT=178.21.114.197
>>>> <->
>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x9acbf0[datalen=0,eom=(nil),ofile=(nil)]]
>>>> filter: running filter filter:dnsbl[hooks=0xffffffff,flags=0x0000] for
>>>> query 668445e8da5533e5[QUERY_CONNECT=178.21.114.197 <->
>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x9acbf0[datalen=0,eom=(nil),ofile=(nil)]]
>>>> filter: waiting for running query
>>>> 668445e8da5533e5[QUERY_CONNECT=178.21.114.197 <->
>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x9acbf0[datalen=0,eom=(nil),ofile=(nil)]]
>>>> dnsbl[24002]: debug: on_connect: checking 222.168.14.185.psbl.surriel.com.
>>>> dnsbl[24002]: warn: session 668445e741ecfaa7: event_dispatch: REJECT
>>>> address ar_gai_errno=-5
>>>> filter: imsg IMSG_FILTER_RESPONSE from procfilter
>>>> dnsbl[hooks=0xffffffff,flags=0x0000]
>>>> filter: filter_drain_query 668445e8da5533e5[QUERY_CONNECT=178.21.114.197
>>>> <->
>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x9acbf0[datalen=0,eom=(nil),ofile=(nil)]]
>>>> filter: filter_end_query 668445e8da5533e5[QUERY_CONNECT=178.21.114.197 <->
>>>> 185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x9acbf0[datalen=0,eom=(nil),ofile=(nil)]]
>>>> filter: query 668445e8da5533e5 done: status=FILTER_CLOSE code=554
>>>> response="5.7.1 Address in DNSBL"
>>>> smtp-in: Failed command on session 668445e741ecfaa7: "" => 554 5.7.1
>>>> Address in DNSBL
>>>> smtp-in: Closing session 668445e741ecfaa7
>>>> debug: smtp: 0xa70cb0: deleting session: done
>>>> filter: post-event event=EVENT_DISCONNECT filter=dnsbl
>>>>
>>>> I am not sure what 'event_dispatch: REJECT address ar_gai_errno=-5’ means..
>>>
>>> So, this is strange, I’m bit confused now :(
>>> You have only modified Line 45 in dnsbl_event_dispatch(), right?
>>
>> yes, like you said
>>
>>> Can you show me your whole modified dnsbl_event_dispatch(), please?
>>
>> tatic void
>> dnsbl_event_dispatch(struct asr_result *ar, void *arg)
>> {
>> uint64_t *q = arg;
>>
>> if (ar->ar_addrinfo)
>> freeaddrinfo(ar->ar_addrinfo);
>>
>> if (ar->ar_gai_errno != EAI_NODATA) {
>> log_warnx("warn: session %016"PRIx64": event_dispatch: REJECT
>> address ar_gai_errno=%d", *q, ar->ar_gai_errno);
>> filter_api_reject_code(*q, FILTER_CLOSE, 554, "5.7.1 Address in
>> DNSBL");
>> } else
>> filter_api_accept(*q);
>> free(q);
>> }
>>>
>>> gai_errno=-5 means: EAI_NODATA — because, it is defined in netdb.h:
>>> #define EAI_NODATA -5 /* no address associated with name */
>>>
>>> This is expected and fine because IP is not listed and not found.
>>>
>>> BUT, in line 44 in dnsbl_event_dispatch() we have:
>>>
>>> if (ar->ar_gai_errno != EAI_NODATA) {
>>> …
>>>
>>> How come that it enters the if statement, when it should NOT?
>>>
>>> Can you also please print the value of EAI_NODATA? e.g. can you add the
>>> following in line 43 right before the if statement:
>>> log_warnx("warn: DEBUG: ar_gai_errno=%d, EAI_NODATA=%d", ar->ar_gai_errno,
>>> EAI_NODATA);
>>>
>>
>> done.
>>
>> code looks like:
>>
>> dnsbl_event_dispatch(struct asr_result *ar, void *arg)
>> {
>> uint64_t *q = arg;
>>
>> if (ar->ar_addrinfo)
>> freeaddrinfo(ar->ar_addrinfo);
>> log_warnx("warn: DEBUG: ar_gai_errno=%d, EAI_NODATA=%d",
>> ar->ar_gai_errno, EAI_NODATA);
>> if (ar->ar_gai_errno != EAI_NODATA) {
>> log_warnx("warn: session %016"PRIx64": event_dispatch: REJECT
>> address ar_gai_errno=%d", *q, ar->ar_gai_errno);
>> filter_api_reject_code(*q, FILTER_CLOSE, 554, "5.7.1 Address in
>> DNSBL");
>> } else
>> filter_api_accept(*q);
>> free(q);
>> }
>>
>>
>> result:
>>
>> debug: smtp: new client on listener: 0x1f370f0
>> smtp-in: New session 2bda822bf9abd4a7 from host pro-mail-smtp-002.bol.com
>> [185.14.169.222]
>> filter: post-event event=EVENT_CONNECT filter=dnsbl
>> filter: new query QUERY_CONNECT
>> filter: filter_drain_query 2bda822cbded033e[QUERY_CONNECT=178.21.114.197 <->
>> 185.14.169.222(pro-mail-smtp-002.bol.com),filter_session@0x1f2fbf0[datalen=0,eom=(nil),ofile=(nil)]]
>> filter: running filter filter:dnsbl[hooks=0xffffffff,flags=0x0000] for query
>> 2bda822cbded033e[QUERY_CONNECT=178.21.114.197 <->
>> 185.14.169.222(pro-mail-smtp-002.bol.com),filter_session@0x1f2fbf0[datalen=0,eom=(nil),ofile=(nil)]]
>> filter: waiting for running query
>> 2bda822cbded033e[QUERY_CONNECT=178.21.114.197 <->
>> 185.14.169.222(pro-mail-smtp-002.bol.com),filter_session@0x1f2fbf0[datalen=0,eom=(nil),ofile=(nil)]]
>> dnsbl[25105]: debug: on_connect: checking 222.169.14.185.psbl.surriel.com.
>> dnsbl[25105]: warn: DEBUG: ar_gai_errno=-5, EAI_NODATA=-2
>> dnsbl[25105]: warn: session 2bda822bf9abd4a7: event_dispatch: REJECT address
>> ar_gai_errno=-5
>> filter: imsg IMSG_FILTER_RESPONSE from procfilter
>> dnsbl[hooks=0xffffffff,flags=0x0000]
>> filter: filter_drain_query 2bda822cbded033e[QUERY_CONNECT=178.21.114.197 <->
>> 185.14.169.222(pro-mail-smtp-002.bol.com),filter_session@0x1f2fbf0[datalen=0,eom=(nil),ofile=(nil)]]
>> filter: filter_end_query 2bda822cbded033e[QUERY_CONNECT=178.21.114.197 <->
>> 185.14.169.222(pro-mail-smtp-002.bol.com),filter_session@0x1f2fbf0[datalen=0,eom=(nil),ofile=(nil)]]
>> filter: query 2bda822cbded033e done: status=FILTER_CLOSE code=554
>> response="5.7.1 Address in DNSBL"
>> smtp-in: Failed command on session 2bda822bf9abd4a7: "" => 554 5.7.1 Address
>> in DNSBL
>> smtp-in: Closing session 2bda822bf9abd4a7
>> debug: smtp: 0x1ff3cb0: deleting session: done
>> filter: post-event event=EVENT_DISCONNECT filter=dnsbl
>
> Ok... that makes sense now.
> -2 seems to be EAI_NONAME which seems to be the error code specific on
> Ubuntu libc for NXDOMAIN replies, instead of EAI_NODATA.
>
> These error codes and related RFCs are subject to a lot of discussions.
> See here to get an idea: https://sourceware.org/bugzilla/show_bug.cgi?id=15726
> Especially, note the cross references to Ubuntu bugs ...
>
> Instead of trying to fit all distribution specific changes,
> the easiest might be to change the logic here and check for the returned
> address not being empty -- instead of errno.
>
> I'll try to come up with a proper diff to fix this, but give me some time as
> I'm very busy currently.
>
> As quick fix: you can just change the if statement to:
> if (ar->ar_gai_errno != EAI_NODATA && ar->ar_gai_errno != EAI_NONAME) {
like this? =>
dnsbl_event_dispatch(struct asr_result *ar, void *arg)
{
uint64_t *q = arg;
if (ar->ar_addrinfo)
freeaddrinfo(ar->ar_addrinfo);
log_warnx("warn: DEBUG: ar_gai_errno=%d, EAI_NODATA=%d",
ar->ar_gai_errno, EAI_NODATA);
if (ar->ar_gai_errno != EAI_NODATA && ar->ar_gai_errno != EAI_NONAME) {
log_warnx("warn: session %016"PRIx64": event_dispatch: REJECT
address ar_gai_errno=%d", *q, ar->ar_gai_errno);
filter_api_reject_code(*q, FILTER_CLOSE, 554, "5.7.1 Address in
DNSBL");
} else
filter_api_accept(*q);
free(q);
}
>
> ... and it should start working as expected. Can you confirm that, please?
if above is correct, it did not work:
dnsbl[26098]: warn: DEBUG: ar_gai_errno=-5, EAI_NODATA=-2
dnsbl[26098]: warn: session de57c06bd67994d3: event_dispatch: REJECT address
ar_gai_errno=-5
filter: imsg IMSG_FILTER_RESPONSE from procfilter
dnsbl[hooks=0xffffffff,flags=0x0000]
filter: filter_drain_query de57c06c3dc0ecca[QUERY_CONNECT=178.21.114.197 <->
185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x1588030[datalen=0,eom=(nil),ofile=(nil)]]
filter: filter_end_query de57c06c3dc0ecca[QUERY_CONNECT=178.21.114.197 <->
185.14.168.222(pro-mail-smtp-001.bol.com),filter_session@0x1588030[datalen=0,eom=(nil),ofile=(nil)]]
filter: query de57c06c3dc0ecca done: status=FILTER_CLOSE code=554
response="5.7.1 Address in DNSBL"
smtp-in: Failed command on session de57c06bd67994d3: "" => 554 5.7.1 Address in
DNSBL
smtp-in: Closing session de57c06bd67994d3
debug: smtp: 0x1655cf0: deleting session: done
filter: post-event event=EVENT_DISCONNECT filter=dnsbl
^Cinfo: queue handler exiting
info: scheduler handler exiting
info: ca agent exiting
warn: control -> queue: pipe closed
warn: lka -> queue: pipe closed
strace: Process 26091 detached
>
> Thanks,
> Regards,
> Jörg
>
> --
> You received this mail because you are subscribed to [email protected]
> To unsubscribe, send a mail to: [email protected]
>
--
You received this mail because you are subscribed to [email protected]
To unsubscribe, send a mail to: [email protected]
