I'm using Postfix 2.8.5 built from source and amavisd-new 2.6.4 from
Scientific Linux distribution. I have virtual domain 'virtdom.cz' and
some subdomain 'subdomain.virtdom.cz'. The server receives the message and
passes it to amavisd-new.
As you can see from the config, the re...@virtdom.cz shlould be rewritten
to
re...@subdomain.virtdom.cz and then passed to amavisd-new. The map always
finds the key/value pair, but then Postfix does not pass the newly found
address to amavis. Why?
Below are 2 different cases, that appear - the first one is bad delivery,
the
second is the proper one where things work properly as expected.
You can see it on the recipient address passed to the
amavisd-new on port 10024 (find ESMTP::10024). I cannot fully reproduce
this
error, it happens somehow.
Bad:
mail goes from sen...@ourdom.cz to re...@virtdom.cz, key/value pair is
found
by map and bad address re...@virtdom.cz is passed into amavis. The mail is
not
delivered properly.
Proper:
mail goes from othersen...@virtdom.cz to the same recipient as in the bad
example (re...@virtdom.cz), key/value pair is found by map, but proper
address
re...@subdomain.virtdom.cz is passed into amavis as recipient address and
things work fine (finally delivered as expected).
Any hints? Some missconfiguration?
The first difference that I notited was before/after input_transp_cleanup,
but
was not able to find, what this means and if this is problem or not.
The logs are shortened, addresses rewritten.
Any help appreciated!
Tomas
----- main.cf ----------------------------------------------------
content_filter = smtp-amavis:[127.0.0.1]:10024
virtual_alias_maps = proxy:pgsql:/etc/postfix/alias_mailbox_maps.cf
----- alias_mailbox_maps.cf --------------------------------------
re...@virtdom.cz re...@subdomain.virtdom.cz
----------- bad delivery ------------------------------------------
Dec 7 15:05:53 mail postfix/smtpd[3935]: connect from
client.name.cz[1.2.3.4]
Dec 7 15:05:53 mail postfix/smtpd[3935]: setting up TLS connection from
client.name.cz[1.2.3.4]
...
Dec 7 15:05:53 mail postfix/smtpd[3935]: < client.name.cz[1.2.3.4]: MAIL
FROM:<sen...@ourdom.cz> SIZE=420
..
Dec 7 15:05:53 mail postfix/smtpd[3935]: resolve_clnt: `' ->
`re...@virtdom.cz' -> transp=`virtual' host=`virtdom.cz'
rcpt=`re...@virtdom.cz' flags= class=virtual
...
Dec 7 15:05:53 mail postfix/smtpd[3935]: dict_proxy_lookup:
table=pgsql:/etc/postfix/pgsql-v5/alias_mailbox_maps.cf
flags=lock|fold_fix key=re...@virtdom.cz -> status=0
result=re...@subdomain.virtdom.cz
Dec 7 15:05:53 mail postfix/smtpd[3935]: maps_find: virtual_alias_maps:
proxy:pgsql:/etc/postfix/pgsql-v5/alias_mailbox_maps.cf(0,lock|fold_fix):
re...@virtdom.cz = re...@subdomain.virtdom.cz
Dec 7 15:05:53 mail postfix/smtpd[3935]: mail_addr_find: re...@virtdom.cz
-> re...@subdomain.virtdom.cz
Dec 7 15:05:53 mail postfix/smtpd[3935]: smtpd_check_rewrite: trying:
permit_inet_interfaces
Dec 7 15:05:53 mail postfix/smtpd[3935]: permit_inet_interfaces:
client.name.cz 1.2.3.4
Dec 7 15:05:53 mail postfix/smtpd[3935]: before input_transp_cleanup:
cleanup flags = enable_header_body_filter enable_automatic_bcc
enable_address_mapping enable_milters
Dec 7 15:05:53 mail postfix/smtpd[3935]: after input_transp_cleanup:
cleanup flags = enable_header_body_filter
Dec 7 15:05:53 mail postfix/smtpd[3935]: connect to subsystem
public/cleanup
Dec 7 15:05:53 mail postfix/smtpd[3935]: vstream_buf_get_ready: fd 24 got
19
Dec 7 15:05:53 mail postfix/smtpd[3935]: public/cleanup socket: wanted
attribute: queue_id
Dec 7 15:05:53 mail postfix/smtpd[3935]: input attribute name: queue_id
Dec 7 15:05:53 mail postfix/smtpd[3935]: input attribute value: DDFF2193
Dec 7 15:05:53 mail postfix/smtpd[3935]: public/cleanup socket: wanted
attribute: (list terminator)
Dec 7 15:05:53 mail postfix/smtpd[3935]: input attribute name: (end)
Dec 7 15:05:53 mail postfix/smtpd[3935]: send attr flags = 130
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type T len 17 data
1323266753
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type L len 29 data
smtp-amavi
...
Dec 7 15:05:53 mail postfix/smtpd[3935]: > client.name.cz[1.2.3.4]: 354
End data with <CR><LF>.<CR><LF>
Dec 7 15:05:53 mail postfix/smtpd[3935]: vstream_fflush_some: fd 9 flush
37
Dec 7 15:05:53 mail postfix/smtpd[3935]: vstream_buf_get_ready: fd 9 got
516
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type N len 37 data
Message-ID
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type N len 37 data
Date: Wed,
...
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type N len 64 data
X-Antiviru
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type N len 25 data
X-Antiviru
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type N len 0 data
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type N len 4 data mail
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type X len 0 data
Dec 7 15:05:53 mail postfix/smtpd[3935]: rec_put: type E len 0 data
...
Dec 7 15:05:53 mail postfix/qmgr[8014]: DDFF2193:
from=<sen...@ourdom.cz>, size=694, nrcpt=1 (queue active)
...
Dec 7 15:05:53 mail postfix/smtpd[3935]: > client.name.cz[1.2.3.4]: 250
2.0.0 Ok: queued as DDFF2193
Dec 7 15:05:53 mail postfix/smtpd[3935]: watchdog_pat: 0x7fd218869410
Dec 7 15:05:53 mail postfix/smtpd[3935]: vstream_fflush_some: fd 9 flush
34
Dec 7 15:05:53 mail amavis[2295]: (02295-17) ESMTP::10024
/var/spool/amavisd/tmp/amavis-20111207T145533-02295: <sen...@ourdom.cz> ->
<re...@virtdom.cz> SIZE=694 Received: from mail.server.net ([127.0.0.1])
by localhost (mail.server.net [127.0.0.1]) (amavisd-new, port 10024) with
ESMTP for <re...@virtdom.cz>; Wed, 7 Dec 2011 15:05:53 +0100 (CET)
...
Dec 7 15:05:53 mail postfix/smtpd[3935]: vstream_buf_get_ready: fd 9 got
6
Dec 7 15:05:53 mail postfix/smtpd[3935]: < client.name.cz[1.2.3.4]: QUIT
Dec 7 15:05:53 mail postfix/smtpd[3935]: > client.name.cz[1.2.3.4]: 221
2.0.0 Bye
----------- proper delivery -----------------------------------------
Dec 12 08:54:16 mail postfix/smtpd[2723]: connect from
another.client.cz[5.6.7.8]
Dec 12 08:54:16 mail postfix/smtpd[2723]: setting up TLS connection from
another.client.cz[5.6.7.8]
...
Dec 12 08:54:19 mail postfix/smtpd[2723]: < another.client.cz[5.6.7.8]:
MAIL FROM:<othersen...@virtdom.cz>
...
Dec 12 08:54:19 mail postfix/smtpd[2723]: resolve_clnt: `' ->
`re...@virtdom.cz' -> transp=`virtual' host=`virtdom.cz'
rcpt=`re...@virtdom.cz' flags= class=virtual
...
Dec 12 08:54:19 mail postfix/smtpd[2723]: dict_proxy_lookup:
table=pgsql:/etc/postfix/pgsql-v5/alias_mailbox_maps.cf
flags=lock|fold_fix key=re...@virtdom.cz -> status=0
result=re...@subdomain.virtdom.cz
Dec 12 08:54:19 mail postfix/smtpd[2723]: maps_find: virtual_alias_maps:
proxy:pgsql:/etc/postfix/pgsql-v5/alias_mailbox_maps.cf(0,lock|fold_fix):
re...@virtdom.cz = re...@subdomain.virtdom.cz
Dec 12 08:54:19 mail postfix/smtpd[2723]: mail_addr_find: re...@virtdom.cz
-> re...@subdomain.virtdom.cz
Dec 12 08:54:19 mail postfix/smtpd[2723]: smtpd_check_rewrite: trying:
permit_inet_interfaces
Dec 12 08:54:19 mail postfix/smtpd[2723]: permit_inet_interfaces:
another.client.cz 5.6.7.8
Dec 12 08:54:19 mail postfix/smtpd[2723]: before input_transp_cleanup:
cleanup flags = enable_header_body_filter enable_automatic_bcc
enable_address_mapping enable_milters
Dec 12 08:54:19 mail postfix/smtpd[2723]: after input_transp_cleanup:
cleanup flags = enable_automatic_bcc enable_address_mapping
Dec 12 08:54:19 mail postfix/smtpd[2723]: connect to subsystem
public/cleanup
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 24 got
19
Dec 12 08:54:19 mail postfix/smtpd[2723]: public/cleanup socket: wanted
attribute: queue_id
Dec 12 08:54:19 mail postfix/smtpd[2723]: input attribute name: queue_id
Dec 12 08:54:19 mail postfix/smtpd[2723]: input attribute value: 2AF75114
Dec 12 08:54:19 mail postfix/smtpd[2723]: public/cleanup socket: wanted
attribute: (list terminator)
Dec 12 08:54:19 mail postfix/smtpd[2723]: input attribute name: (end)
Dec 12 08:54:19 mail postfix/smtpd[2723]: send attr flags = 176
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type T len 17 data
1323676459
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type L len 29 data
smtp-amavi
...
Dec 12 08:54:19 mail postfix/smtpd[2723]: > another.client.cz[5.6.7.8]:
354 End data with <CR><LF>.<CR><LF>
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_fflush_some: fd 9 flush
37
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
45
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 43 data
Date: Mon,
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
36
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
2
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 36 data
From: Toma
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
31
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
2
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 31 data
X-X-Sender
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
38
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
2
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 38 data To:
Roman
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
23
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 21 data
Subject: p
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
67
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 65 data
Message-ID
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
47
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 45 data
User-Agent
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
19
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 17 data
MIME-Versi
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
59
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 57 data
Content-Ty
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
2
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 0 data
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
25
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type N len 23 data
pokus, vym
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
3
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type X len 0 data
Dec 12 08:54:19 mail postfix/smtpd[2723]: rec_put: type E len 0 data
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_fflush_some: fd 24 flush
593
Dec 12 08:54:19 mail postfix/cleanup[2861]: 2AF75114:
message-id=<alpine.lfd.2.02.1112120853550.26...@another.client.cz>
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 24 got
18
Dec 12 08:54:19 mail postfix/smtpd[2723]: public/cleanup socket: wanted
attribute: status
Dec 12 08:54:19 mail postfix/smtpd[2723]: input attribute name: status
Dec 12 08:54:19 mail postfix/smtpd[2723]: input attribute value: 0
Dec 12 08:54:19 mail postfix/smtpd[2723]: public/cleanup socket: wanted
attribute: reason
Dec 12 08:54:19 mail postfix/smtpd[2723]: input attribute name: reason
Dec 12 08:54:19 mail postfix/smtpd[2723]: input attribute value: (end)
Dec 12 08:54:19 mail postfix/smtpd[2723]: public/cleanup socket: wanted
attribute: (list terminator)
Dec 12 08:54:19 mail postfix/smtpd[2723]: input attribute name: (end)
Dec 12 08:54:19 mail postfix/qmgr[32764]: 2AF75114:
from=<othersen...@virtdom.cz>, size=587, nrcpt=1 (queue active)
...
Dec 12 08:54:19 mail postfix/smtpd[2723]: > another.client.cz[5.6.7.8]:
250 2.0.0 Ok: queued as 2AF75114
Dec 12 08:54:19 mail postfix/smtpd[2723]: watchdog_pat: 0x7ff963cf2450
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_fflush_some: fd 9 flush
34
Dec 12 08:54:19 mail postfix/smtpd[2723]: vstream_buf_get_ready: fd 9 got
6
Dec 12 08:54:19 mail postfix/smtpd[2723]: < another.client.cz[5.6.7.8]:
QUIT
Dec 12 08:54:19 mail postfix/smtpd[2723]: > another.client.cz[5.6.7.8]:
221 2.0.0 Bye
...
Dec 12 08:54:19 mail postfix/smtpd[2723]: disconnect from
another.client.cz[5.6.7.8]
Dec 12 08:54:19 mail amavis[897]: (00897-10) ESMTP::10024
/var/spool/amavisd/tmp/amavis-20111212T084736-00897:
<othersen...@virtdom.cz> -> <re...@subdomain.virtdom.cz> SIZE=587
Received: from mail.server.net ([127.0.0.1]) by localhost (mail.server.net
[127.0.0.1]) (amavisd-new, port 10024) with ESMTP for
<re...@subdomain.virtdom.cz>; Mon, 12 Dec 2011 08:54:19 +0100 (CET)
-------------- master.cf -----------------------------------
#
==========================================================================
# service type private unpriv chroot wakeup maxproc command + args
# (yes) (yes) (yes) (never) (100)
#
==========================================================================
smtp inet n - n - - smtpd
-o receive_override_options=no_header_body_checks
#submission inet n - n - - smtpd
# -o smtpd_etrn_restrictions=reject
# -o smtpd_client_restrictions=permit_sasl_authenticated,reject
smtps inet n - n - - smtpd
-o smtpd_tls_wrappermode=yes
-o smtpd_sasl_auth_enable=yes
-o receive_override_options=no_address_mappings
#submission inet n - n - - smtpd
# -o smtpd_etrn_restrictions=reject
# -o smtpd_enforce_tls=yes -o smtpd_sasl_auth_enable=yes
#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
smtp unix - - n - - smtp
-o receive_override_options=no_address_mappings
# When relaying mail as backup MX, disable fallback_relay to avoid MX
loops
relay unix - - n - - smtp
-o fallback_relay=
# -o smtp_helo_timeout=5 -o smtp_connect_timeout=5
showq unix n - n - - showq
error 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 - 20 smtp
-o smtp_data_done_timeout=1200
-o smtp_send_xforward_command=yes
-o disable_dns_lookups=yes
-o max_use=20
127.0.0.1:10025 inet n - n - - smtpd
-o content_filter=
-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
-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 smtpd_milters=
-o local_header_rewrite_clients=
-o local_recipient_maps=
-o relay_recipient_maps=
-o
receive_override_options=no_address_mappings,no_header_body_checks,no_unknown_recipient_checks
retry unix - - n - - error
proxywrite unix - - n - 1 proxymap
#smtp inet n - n - 1 postscreen
#smtpd pass - - n - - smtpd
#dnsblog unix - - n - 0 dnsblog
#tlsproxy unix - - n - 0 tlsproxy
