OpenSMTPD rejects ORCPT

[edwintorok]

Email from my domain registrar got rejected:

2016-02-16_09:25:25.54416 smtp-in: session 4bf92bb6c468a434: received invalid command: "RCPT TO:<domain@etorok.net> ORCPT=rfc822;domain@etorok.net"
2016-02-16_09:27:52.69822 smtp-in: session 4bf92bbec27f0655: received invalid command: "RCPT TO:<domain@etorok.net> ORCPT=rfc822;domain@etorok.net"

OpenSMTPD 5.7.3p1 on Debian Linux

[poolpOrg]

This is very likely a configuration issue on your side:

gilles@XXX:~$ nc mail.poolp.org 25
220 mx1.poolp.org ESMTP OpenSMTPD
HELO l
250 mx1.poolp.org Hello l [XXX], pleased to meet you
MAIL FROM:<gilles@opensmtpd.org>
250 2.0.0: Ok
RCPT TO:<gilles@opensmtpd.org> ORCPT=rfc822;gilles@opensmtpd.org
250 2.1.5 Destination address valid: Recipient ok

[edwintorok]

I'll try to get some debug logs

[poolpOrg]

regular log + config should be enough

[edwintorok]

Looks like my /etc/aliases wasn't uptodate and domain@etorok.net was an invalid recepient. I got confused by the 'invalid command' error in OpenSMTPD's log, thought it means that it was unable to parse the command.

Here is how to reproduce the invalid command message:

$ nc localhost 25
220 mail.etorok.net ESMTP OpenSMTPD
HELO f
250 mail.etorok.net Hello f [IPv6:::1], pleased to meet you
MAIL FROM:<foo@example.com>
250 2.0.0: Ok
RCPT TO:<nonexistent@etorok.net> ORCPT=nonexistent@etorok.net
550 Invalid recipient

The error code sent back to the remote server is correct, however in opensmtpd's log:

smtp-in: session ac2143bd7b2bed87: received invalid command: "RCPT TO:<nonexistent@etorok.net> ORCPT=nonexistent@etorok.net"

Debug output:

mproc: lka -> pony : 25 IMSG_SMTP_DNS_PTR
imsg: pony <- lka: IMSG_SMTP_DNS_PTR (len=25)
smtp: 0x1e91020: STATE_NEW -> STATE_CONNECTED
smtp-in: session ac2143bd7b2bed87: connection from host localhost [IPv6:::1] established
filter: new query QK_EVENT EVENT_CONNECT
filter: filter_drain_query ac2143beccf82dcf[QK_EVENT,EVENT_CONNECT,filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: filter_end_query ac2143beccf82dcf[QK_EVENT,EVENT_CONNECT,filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: new query QK_QUERY QUERY_CONNECT
filter: filter_drain_query ac2143bf3edaf3b6[QK_QUERY,QUERY_CONNECT=IPv6:::1 <-> IPv6:::1(localhost),filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: filter_end_query ac2143bf3edaf3b6[QK_QUERY,QUERY_CONNECT=IPv6:::1 <-> IPv6:::1(localhost),filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: query ac2143bf3edaf3b6 done: status=FILTER_OK code=0 response="(null)"
smtp: 0x1e91020: >>> 220 mail.etorok.net ESMTP OpenSMTPD
smtp: 0x1e91020: IO_LOWAT <io:0x1e91068 fd=4 to=300000 fl=W ib=0 ob=0>
smtp: 0x1e91020: IO_DATAIN <io:0x1e91068 fd=4 to=300000 fl=R ib=7 ob=0>
smtp: 0x1e91020: <<< HELO f
filter: new query QK_QUERY QUERY_HELO
filter: filter_drain_query ac2143c06c3dde55[QK_QUERY,QUERY_HELO=f,filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: filter_end_query ac2143c06c3dde55[QK_QUERY,QUERY_HELO=f,filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: query ac2143c06c3dde55 done: status=FILTER_OK code=0 response="(null)"
smtp: 0x1e91020: STATE_CONNECTED -> STATE_HELO
smtp: 0x1e91020: >>> 250 mail.etorok.net Hello f [IPv6:::1], pleased to meet you
smtp: 0x1e91020: IO_LOWAT <io:0x1e91068 fd=4 to=300000 fl=W ib=0 ob=0>
smtp: 0x1e91020: IO_DATAIN <io:0x1e91068 fd=4 to=300000 fl=R ib=28 ob=0>
smtp: 0x1e91020: <<< MAIL FROM:<foo@example.com>
filter: new query QK_QUERY QUERY_MAIL
filter: filter_drain_query ac2143c17c6415de[QK_QUERY,QUERY_MAIL=foo@example.com,filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: filter_end_query ac2143c17c6415de[QK_QUERY,QUERY_MAIL=foo@example.com,filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: query ac2143c17c6415de done: status=FILTER_OK code=0 response="(null)"
mproc: pony -> queue : 9 IMSG_SMTP_MESSAGE_CREATE
imsg: queue <- pony: IMSG_SMTP_MESSAGE_CREATE (len=9)
queue-backend: queue_message_create() -> 1 (c42a1b29)
mproc: queue -> pony : 19 IMSG_SMTP_MESSAGE_CREATE
imsg: pony <- queue: IMSG_SMTP_MESSAGE_CREATE (len=19)
smtp: 0x1e91020: >>> 250 2.0.0: Ok
smtp: 0x1e91020: IO_LOWAT <io:0x1e91068 fd=4 to=300000 fl=W ib=0 ob=0>
smtp: 0x1e91020: IO_DATAIN <io:0x1e91068 fd=4 to=300000 fl=R ib=62 ob=0>
smtp: 0x1e91020: <<< RCPT TO:<nonexistent@etorok.net> ORCPT=nonexistent@etorok.net
filter: new query QK_QUERY QUERY_RCPT
filter: filter_drain_query ac2143c2cecb7324[QK_QUERY,QUERY_RCPT=nonexistent@etorok.net,filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: filter_end_query ac2143c2cecb7324[QK_QUERY,QUERY_RCPT=nonexistent@etorok.net,filter_session@0x1e56a00[datalen=0,eom=(nil),ofile=(nil)]]
filter: query ac2143c2cecb7324 done: status=FILTER_OK code=0 response="(null)"
mproc: pony -> lka : 286 IMSG_SMTP_EXPAND_RCPT
imsg: lka <- pony: IMSG_SMTP_EXPAND_RCPT (len=286)
expand: 0x1e652f8: expand_insert() called for address:nonexistent@etorok.net[parent=(nil)]
expand: 0x1e652f8: inserted node 0x1e901f0
expand: lka_expand: address: nonexistent@etorok.net [depth=0]
lookup: check "ipv6:::1" as NETADDR in table static:<anyhost> -> found
lookup: check "nonexistent@etorok.net" as MAILADDR in table static:avenger -> 0
lookup: check "ipv6:::1" as NETADDR in table static:<anyhost> -> found
lookup: check "etorok.net" as DOMAIN in table static:domains -> found
rule matched: accept from <anyhost> for  domain domains alias aliases deliver to mda "procmail -a %{dest} -f"
expand: 0x1e652f8: expand_insert() called for username:nonexistent[parent=0x1e901f0, mapping=aliases, userbase=<getpwnam>]
expand: 0x1e652f8: inserted node 0x1e90660
expand: lka_expand: username: nonexistent [depth=1]
lookup: lookup "nonexistent" as ALIAS in table static:aliases -> 0
lookup: lookup "nonexistent" as USERINFO in table getpwnam:<getpwnam> -> 0
expand: lka_expand: user-part does not match system user
mproc: lka -> pony : 37 IMSG_SMTP_EXPAND_RCPT
expand: 0x1e652f8: clearing expand tree
imsg: pony <- lka: IMSG_SMTP_EXPAND_RCPT (len=37)
smtp: 0x1e91020: >>> 550 Invalid recipient
smtp-in: session ac2143bd7b2bed87: received invalid command: "RCPT TO:<nonexistent@etorok.net> ORCPT=nonexistent@etorok.net"

Perhaps opensmtpd could log the error code + reason sent to the remote in opensmtpd's log too? That would clear the confusion.

[poolpOrg]

yep, logging needs to be improved.

there's ongoing work to rework the entire log format and make it both less verbose, more informative and more concise.

I'll close this ticket since this was a configuration issue, thanks