Join Log in
Score:1
Sumak avatar Server

SMTP 550 5.1.1 but mailbox exists

ru flag
Sumak

I'm creating a mailbox on our Postfix server. We've a script which synchronize our LDAP to our Webmail (~RoundCube), and then we must execute the following command on the Postfix server:

echo -e "[email protected]\tOK" >> /etc/postfix/virtual_mailbox
echo -e "[email protected]\[email protected]" >> /etc/postfix/virtual_alias # if we want an alias
postmap /etc/postfix/virtual_mailbox && postmap /etc/postfix/virtual_alias
/etc/init.d/postfix reload

This procedure used to work until last week and we're not able to explain/solve the issue.

Sending a test mail though the Webmail to the newly created mailbox returns:

<[email protected]>: host 127.0.0.1[127.0.0.1] said: 550-Mailbox unknown.  Either
    there is no mailbox associated with this 550-name or you do not have
    authorization to see it. 550 5.1.1 User unknown (in reply to RCPT TO
    command)

However, Postfix responds 250 2.1.0 Ok to the RCP TO:<[email protected]> command:

$ nc our.mail.server.tld 25
220 our.mail.server.tld ESMTP Postfix (CentOS)
HELO domain.tld
250 our.mail.server.tld
MAIL FROM:<>
250 2.1.0 Ok
RCPT TO:<[email protected]>
250 2.1.0 Ok
DATA
Subject: testing
test email
.
250 2.0.0 Ok: queued as 7E8B043

But the maillog indicates a 550 5.1.1 User unknow... (log anonymized)

# edited following Nikita Kipriyanov recommendation 
Jul  8 15:07:36 srv postfix/smtp[30469]: > 127.0.0.1[127.0.0.1]:10024: RCPT TO:<[email protected]> ORCPT=rfc822;[email protected]
Jul  8 15:07:36 srv postfix/smtp[30469]: < 127.0.0.1[127.0.0.1]:10024: 250 2.1.5 Recipient <[email protected]> OK
Jul  8 15:07:37 srv postfix/smtpd[30492]: < localhost[127.0.0.1]: RCPT TO:<[email protected]> ORCPT=rfc822;[email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: extract_addr: input: <[email protected]>
Jul  8 15:07:37 srv postfix/smtpd[30492]: smtpd_check_addr: [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: send attr address = [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: input attribute value: [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: rewrite_clnt: local: [email protected] -> [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: send attr address = [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: input attribute value: [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: resolve_clnt: `' -> `[email protected]' -> transp=`lmtp' host=`127.0.0.1:24' rcpt=`[email protected]' flags= class=virtual
Jul  8 15:07:37 srv postfix/smtpd[30492]: ctable_locate: install entry key [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: extract_addr: in: <[email protected]>, result: [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: ctable_locate: leave existing entry key [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: milter_macro_lookup: result "[email protected]"
Jul  8 15:07:37 srv postfix/smtpd[30492]: ctable_locate: leave existing entry key [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: ctable_locate: leave existing entry key [email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: milter8_rcpt_event: milter inet:127.0.0.1:8891: rcpt <[email protected]> ORCPT=rfc822;[email protected]
Jul  8 15:07:37 srv postfix/smtpd[30492]: event: SMFIC_RCPT; macros: {rcpt_addr}[email protected] {rcpt_host}=127.0.0.1:24 {rcpt_mailer}=lmtp
Jul  8 15:07:37 srv postfix/lmtp[30505]: > 127.0.0.1[127.0.0.1]:24: RCPT TO:<[email protected]>
Jul  8 15:07:37 srv cyrus/lmtp[18927]: verify_user(user.test) failed: Mailbox does not exist
Jul  8 15:07:37 srv postfix/lmtp[30505]: send attr original_recipient = [email protected]
Jul  8 15:07:37 srv postfix/lmtp[30505]: send attr recipient = [email protected]
Jul  8 15:07:37 srv postfix/lmtp[30505]: send attr dsn_orig_rcpt = rfc822;[email protected]
Jul  8 15:07:37 srv amavis[23265]: (23265-17) Passed BAD-HEADER-7 {RelayedInternal}, MYNETS LOCAL [172.16.10.39]:2828 <> -> <[email protected]>, mail_id: nTFlKNl0Vr0b, Hits: 5.677, size: 300, queued_as: C7DB445, 1476 ms
Jul  8 15:07:37 srv postfix/smtp[30469]: 73B0143: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=49, delays=48/0/0/1.5, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as C7DB445)
Jul  8 15:07:37 srv postfix/lmtp[30505]: C7DB445: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:24, delay=0.11, delays=0.09/0/0/0.03, dsn=5.1.1, status=bounced (host 127.0.0.1[127.0.0.1] said: 550-Mailbox unknown.  Either there is no mailbox associated with this 550-name or you do not have authorization to see it. 550 5.1.1 User unknown (in reply to RCPT TO command))

Any idea about this behavior ? Why RCPT TO returns 250 2.1.5 Ok whith netcat, but in the end stay stuck with a 550 5.1.1 User unknown ?

master.cf 
# ==========================================================================
# service type  private unpriv  chroot  wakeup  maxproc command + args
#               (yes)   (yes)   (yes)   (never) (100)
# ==========================================================================
smtp      inet  n       -       n       -       -       smtpd
submission inet n       -       n       -       -       smtpd
  -o smtpd_tls_security_level=encrypt
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_recipient_restrictions=permit_sasl_authenticated,reject
  -o milter_macro_daemon_name=ORIGINATING
smtps     inet  n       -       n       -       -       smtpd
  -o smtpd_tls_wrappermode=yes
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_client_restrictions=permit_sasl_authenticated,reject
  -o milter_macro_daemon_name=ORIGINATING
#628      inet  n       -       n       -       -       qmqpd
pickup    fifo  n       -       n       60      1       pickup
cleanup   unix  n       -       n       -       0       cleanup
qmgr      fifo  n       -       n       300     1       qmgr
#qmgr     fifo  n       -       n       300     1       oqmgr
tlsmgr    unix  -       -       n       1000?   1       tlsmgr
rewrite   unix  -       -       n       -       -       trivial-rewrite
bounce    unix  -       -       n       -       0       bounce
defer     unix  -       -       n       -       0       bounce
trace     unix  -       -       n       -       0       bounce
verify    unix  -       -       n       -       1       verify
flush     unix  n       -       n       1000?   0       flush
proxymap  unix  -       -       n       -       -       proxymap
proxywrite unix -       -       n       -       1       proxymap
smtp      unix  -       -       n       -       -       smtp
# When relaying mail as backup MX, disable fallback_relay to avoid MX loops
relay     unix  -       -       n       -       -       smtp
        -o smtp_fallback_relay=
#       -o smtp_helo_timeout=5 -o smtp_connect_timeout=5
showq     unix  n       -       n       -       -       showq
error     unix  -       -       n       -       -       error
retry     unix  -       -       n       -       -       error
discard   unix  -       -       n       -       -       discard
local     unix  -       n       n       -       -       local
virtual   unix  -       n       n       -       -       virtual
lmtp      unix  -       -       n       -       -       lmtp
anvil     unix  -       -       n       -       1       anvil
scache    unix  -       -       n       -       1       scache

smtp-amavis unix -      -       n     -       8  smtp
    -o smtp_data_done_timeout=1200
    -o smtp_send_xforward_command=yes
    -o disable_dns_lookups=yes

127.0.0.1:10025 inet n  -       n     -       -  smtpd
    -o content_filter=
    -o local_recipient_maps=
    -o relay_recipient_maps=
    -o smtpd_restriction_classes=
    -o smtpd_delay_reject=no
    -o smtpd_client_restrictions=permit_mynetworks,reject
    -o smtpd_helo_restrictions=
    -o smtpd_sender_restrictions=
    -o smtpd_recipient_restrictions=permit_mynetworks,reject
    -o smtpd_data_restrictions=reject_unauth_pipelining
    -o smtpd_end_of_data_restrictions=
    -o mynetworks=127.0.0.0/8,<other_valids_networks>
    -o smtpd_error_sleep_time=0
    -o smtpd_soft_error_limit=1001
    -o smtpd_hard_error_limit=1000
    -o smtpd_client_connection_count_limit=0
    -o smtpd_client_connection_rate_limit=0
    -o receive_override_options=no_header_body_checks,no_unknown_recipient_checks
311
1 + 7
Nikita Kipriyanov avatar
za flag
Nikita Kipriyanov
You can temporary add 127.0.0.1 into `debug_peer_list`, for which Postfix daemons will execute with elevated log level. In the (greatly expanded) log it will explain how it interprets each configuration directive and this should give a clue where it fails. For now, I am sure how else to debug this, provided that you use a configuration which was "used to work" previously.
2
Reply
Sumak avatar
ru flag
Sumak
Thanks for your feedback. I've doing so and edited my answer. Could it be related to changes from our DNS records ? We're about to migrate our mailserver and the service providers we're working with may have already tweak the DNS.
0
Reply
Michael Hampton avatar
cz flag
Michael Hampton
Well that's odd. Please also post the `main.cf` file.
1
Reply
Nikita Kipriyanov avatar
za flag
Nikita Kipriyanov
Wow, I noticed something. According to your log, 73B0143 is being successfully received via SMTP at port 10025 as C7DB445, but immediately that thing tries to inject it via LMTP to port 24 where it gets bounced. What are the things that listen at ports 10025 (which accepts via smtp and relays via lmtp) and 24 (which rejects via lmtp)?
2
Reply
Sumak avatar
ru flag
Sumak
Is that unusual ? I'm afraid we don't have enough knowledge to interpret this fact. `smtpd` is listening port 10025 (with the options mentioned at the end of `master.cf`), and `[khelper]` port 24.
0
Reply
anx avatar
fr flag
anx
You mention ongoing migrations.. could someone have placed an empty LDAP server on the domain Cyrus was still directly fetching its users from?
0
Reply
anx avatar
fr flag
anx
`[khelper]` sounds more like a kernel thread and less like an LMTP service. Go look for *Cyrus* configuration, that is more likely what is listening on `24/tcp`
0
Reply
Score:0
anx avatar Server
fr flag
anx

Postfix simply returns what it was told by the LMTP service it tried to hand the mail over for delivery. If the expanded alias is correct, you have to check that service, not (just) Postfix.

Many things could have resulted in this scenario, but its fairly clear that the user/alias list of Postfix is no longer in sync with the user of the server Postfix passes the mailto (the detour via Amavis complicates the logs, but does not appear to be the problem).

Next diagnose step: Compare the user list available to your MDA (Cyrus IMAPd, by the looks of the error message) to the actual result of your postfix virtual mappings.

Query your postfix maps with these commands:

postmap -v -v -q [email protected] hash:/etc/postfix/virtual_mailbox
postmap -v -v -q [email protected] hash:/etc/postfix/virtual_alias

Querying like this is better than just trusting you executed the command correctly, because duplicates and typos are more obvious then. I think your setup generally only results in only one of the two maps.

Query the user list of the LMTP service using the information you'll find in its configuration to verify the mailbox really exists. To query the LDAP directly, use ldapsearch -U .. -H ldaps://.., to investigate specific servers use their provided utilities: for Dovecot, use doveadm user .. - for Cyrus use cyrusadm info [name], ..

Consider also failure modes like the LDAP server where you are keeping your user list was temporarily or permanently unreachable by a server or maintenance script meant to fetch that data.

Your could have eased this and can still ease future debugging by adding suitable syslog_name options in your master.cf - that way you can more easily tell which of your (apparently multiple similar) services has logged which lines.

submission inet n       -       n       -       -       smtpd
 -o syslog_name=postfix/submission
 -o smtpd_tls_security_level=encrypt
 -o ...
...
smtps     inet  n       -       n       -       -       smtpd
 -o syslog_name=postfix/smtps
 -o smtpd_tls_wrappermode=yes
 -o ...
...
127.0.0.1:10025 inet n  -       n     -       -  smtpd
 -o syslog_name=postfix/description
 -o ...
0 + 0
ธงชาติไทย
Elon Musk
I sit in a Tesla and translated this thread with Ai:

mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.