Postfix different behaviour

[Davide Belloni]

Hi,
I've a postfix server with the following configuration:

command_directory = /usr/sbin
config_directory = /etc/postfix-queuein
daemon_directory = /usr/libexec/postfix
data_directory = /var/lib/postfix-queuein
debug_peer_level = 2
default_privs = nobody
header_checks = regexp:/etc/postfix-queuein/header_check
html_directory = no
inet_interfaces = all
inet_protocols = ipv4
local_recipient_maps =
mail_owner = postfix
mailq_path = /usr/bin/mailq.postfix
manpage_directory = /usr/share/man
maximal_backoff_time = 5m
message_size_limit = 25600000
minimal_backoff_time = 1m
multi_instance_enable = yes
multi_instance_group = mta
multi_instance_name = postfix-queuein
multi_instance_wrapper = ${command_directory}/postmulti -p --
mydomain = xxx.it
myhostname = smtp-01.xxx.it
mynetworks_style = subnet
myorigin = $mydomain
newaliases_path = /usr/bin/newaliases.postfix
queue_directory = /var/spool/postfix-queuein
queue_run_delay = 1m
readme_directory = /usr/share/doc/postfix-2.6.6/README_FILES
relay_domains =
relayhost = 127.0.0.1:10025
sample_directory = /usr/share/doc/postfix-2.6.6/samples
sender_canonical_classes = envelope_sender, header_sender
sender_canonical_maps = regexp:/etc/postfix-queuein/canonical
sendmail_path = /usr/sbin/sendmail.postfix
setgid_group = postdrop
smtpd_banner = $myhostname ESMTP _xxxsmtpd_
smtpd_end_of_data_restrictions = check_policy_service inet:127.0.0.1:10031
smtpd_recipient_restrictions = check_policy_service inet:127.0.0.1:10031 reject
unknown_local_recipient_reject_code = 550

The daemon at 10031 port is a cluebringer instance for access control policy.

With the followinig command (from a postfix's client)
$ while [ : ]; do (echo "helo client.xxx.it"; sleep 1; echo "MAIL FROM: a_su...@xxx.it"; sleep 1; echo "RCPT TO:tes...@xxx.it"; sleep 6) | nc smtp-01.xxx.it 25; done

usually I receive the following responses:

220 smtp-01.xxx.it ESMTP _xxxsmtpd_
250 smtp-01.xxx.it
250 2.1.0 Ok
250 2.1.5 Ok

Instead sometimes (for example 1 time over 30) the postfix output is:

220 smtp-01.xxx.it ESMTP _xxxsmtpd_
250 smtp-01.xxx.it
250 2.1.0 Ok
554 5.7.1 <tes...@xxx.it>: Recipient address rejected: Access denied

The cluebringer daemon seems to not be queried in the latter case (the relative log is missing), the network dump on smtp server shows the same data (predictably).
The postfix log, in debug mode, is the following:

postfix-queuein/smtpd[29163]: connect from unknown[X.X.X.X]
postfix-queuein/smtpd[29163]: match_hostname: unknown ~? 127.0.0.0/8
postfix-queuein/smtpd[29163]: match_hostaddr: X.X.X.X ~? 127.0.0.0/8
postfix-queuein/smtpd[29163]: match_hostname: unknown ~? X.X.X.0/24
postfix-queuein/smtpd[29163]: match_hostaddr: X.X.X.X ~? X.X.X.0/24
postfix-queuein/smtpd[29163]: match_hostname: unknown ~? X.X.X.X/32
postfix-queuein/smtpd[29163]: match_hostaddr: X.X.X.X ~? X.X.X.X/32
postfix-queuein/smtpd[29163]: match_list_match: unknown: no match
postfix-queuein/smtpd[29163]: match_list_match: X.X.X.X: no match
postfix-queuein/smtpd[29163]: send attr request = connect
postfix-queuein/smtpd[29163]: send attr ident = smtp:X.X.X.X
postfix-queuein/smtpd[29163]: vstream_fflush_some: fd 11 flush 42
postfix-queuein/smtpd[29163]: vstream_buf_get_ready: fd 11 got 25
postfix-queuein/smtpd[29163]: private/anvil: wanted attribute: status
postfix-queuein/smtpd[29163]: input attribute name: status
postfix-queuein/smtpd[29163]: input attribute value: 0
postfix-queuein/smtpd[29163]: private/anvil: wanted attribute: count
postfix-queuein/smtpd[29163]: input attribute name: count
postfix-queuein/smtpd[29163]: input attribute value: 1
postfix-queuein/smtpd[29163]: private/anvil: wanted attribute: rate
postfix-queuein/smtpd[29163]: input attribute name: rate
postfix-queuein/smtpd[29163]: input attribute value: 3
postfix-queuein/smtpd[29163]: private/anvil: wanted attribute: (list terminator)
postfix-queuein/smtpd[29163]: input attribute name: (end)
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 220 smtp-01.xxx.it ESMTP _xxxsmtpd_
postfix-queuein/smtpd[29163]: watchdog_pat: 0x7f084d84a4e0
postfix-queuein/smtpd[29163]: vstream_fflush_some: fd 10 flush 40
postfix-queuein/smtpd[29163]: vstream_buf_get_ready: fd 10 got 24
postfix-queuein/smtpd[29163]: < unknown[X.X.X.X]: ehlo client.xxx.it
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250-smtp-01.xxx.it
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250-PIPELINING
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250-SIZE 25600000
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250-VRFY
postfix-queuein/smtpd[29163]: match_list_match: unknown: no match
postfix-queuein/smtpd[29163]: match_list_match: X.X.X.X: no match
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250-ETRN
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250-ENHANCEDSTATUSCODES
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250-8BITMIME
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250 DSN
postfix-queuein/smtpd[29163]: watchdog_pat: 0x7f084d84a4e0
postfix-queuein/smtpd[29163]: vstream_fflush_some: fd 10 flush 125
postfix-queuein/smtpd[29163]: vstream_buf_get_ready: fd 10 got 43
postfix-queuein/smtpd[29163]: < unknown[X.X.X.X]: mail FROM:<a_su...@xxx.it> size=2681
postfix-queuein/smtpd[29163]: extract_addr: input: <a_su...@xxx.it>
postfix-queuein/smtpd[29163]: smtpd_check_addr: addr=a_su...@xxx.it
postfix-queuein/smtpd[29163]: ctable_locate: move existing entry key a_su...@xxx.it
postfix-queuein/smtpd[29163]: extract_addr: in: <a_su...@xxx.it>, result: a_su...@xxx.it
postfix-queuein/smtpd[29163]: fsspace: .: block size 4096, blocks free 672011
postfix-queuein/smtpd[29163]: smtpd_check_queue: blocks 4096 avail 672011 min_free 0 msg_size_limit 25600000
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250 2.1.0 Ok
postfix-queuein/smtpd[29163]: watchdog_pat: 0x7f084d84a4e0
postfix-queuein/smtpd[29163]: vstream_fflush_some: fd 10 flush 14
postfix-queuein/smtpd[29163]: vstream_buf_get_ready: fd 10 got 31
postfix-queuein/smtpd[29163]: < unknown[X.X.X.X]: rcpt TO:<tes...@xxx.it>
postfix-queuein/smtpd[29163]: extract_addr: input: <tes...@xxx.it>
postfix-queuein/smtpd[29163]: smtpd_check_addr: addr=tes...@xxx.it
postfix-queuein/smtpd[29163]: ctable_locate: move existing entry key tes...@xxx.it
postfix-queuein/smtpd[29163]: extract_addr: in: <tes...@xxx.it>, result: tes...@xxx.it
postfix-queuein/smtpd[29163]: >>> START Recipient address RESTRICTIONS <<<
postfix-queuein/smtpd[29163]: generic_checks: name=check_policy_service
postfix-queuein/smtpd[29163]: event_request_timer: reset 0x7f084cea0dc0 0x7f084d849770 300
postfix-queuein/smtpd[29163]: send attr request = smtpd_access_policy
postfix-queuein/smtpd[29163]: send attr protocol_state = RCPT
postfix-queuein/smtpd[29163]: send attr protocol_name = ESMTP
postfix-queuein/smtpd[29163]: send attr client_address = X.X.X.X
postfix-queuein/smtpd[29163]: send attr client_name = unknown
postfix-queuein/smtpd[29163]: send attr reverse_client_name = unknown
postfix-queuein/smtpd[29163]: send attr helo_name = client.xxx.it
postfix-queuein/smtpd[29163]: send attr sender = a_su...@xxx.it
postfix-queuein/smtpd[29163]: send attr recipient = tes...@xxx.it
postfix-queuein/smtpd[29163]: send attr recipient_count = 0
postfix-queuein/smtpd[29163]: send attr queue_id =
postfix-queuein/smtpd[29163]: send attr instance = 71eb.574ef661.5fcf8.0
postfix-queuein/smtpd[29163]: send attr size = 2681
postfix-queuein/smtpd[29163]: send attr etrn_domain =
postfix-queuein/smtpd[29163]: send attr stress =
postfix-queuein/smtpd[29163]: send attr sasl_method =
postfix-queuein/smtpd[29163]: send attr sasl_username =
postfix-queuein/smtpd[29163]: send attr sasl_sender =
postfix-queuein/smtpd[29163]: send attr ccert_subject =
postfix-queuein/smtpd[29163]: send attr ccert_issuer =
postfix-queuein/smtpd[29163]: send attr ccert_fingerprint =
postfix-queuein/smtpd[29163]: send attr encryption_protocol =
postfix-queuein/smtpd[29163]: send attr encryption_cipher =
postfix-queuein/smtpd[29163]: send attr encryption_keysize = 0
postfix-queuein/smtpd[29163]: vstream_fflush_some: fd 13 flush 471
postfix-queuein/smtpd[29163]: vstream_buf_get_ready: fd 13 got 14
postfix-queuein/smtpd[29163]: 127.0.0.1:10031: wanted attribute: action
postfix-queuein/smtpd[29163]: input attribute name: action
postfix-queuein/smtpd[29163]: input attribute value: DUNNO
postfix-queuein/smtpd[29163]: 127.0.0.1:10031: wanted attribute: (list terminator)
postfix-queuein/smtpd[29163]: input attribute name: (end)
postfix-queuein/smtpd[29163]: check_table_result: inet:127.0.0.1:10031 DUNNO policy query
postfix-queuein/smtpd[29163]: generic_checks: name=check_policy_service status=0
postfix-queuein/smtpd[29163]: generic_checks: name=reject
postfix-queuein/smtpd[29163]: NOQUEUE: reject: RCPT from unknown[X.X.X.X]: 554 5.7.1 <tes...@xxx.it>: Recipient address rejected: Access denied; from=<a_su...@xxx.it> to=<tes...@xxx.it> proto=ESMTP helo=<client.xxx.it>
postfix-queuein/smtpd[29163]: generic_checks: name=reject status=2
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 554 5.7.1 <tes...@xxx.it>: Recipient address rejected: Access denied
postfix-queuein/smtpd[29163]: watchdog_pat: 0x7f084d84a4e0
postfix-queuein/smtpd[29163]: vstream_fflush_some: fd 10 flush 76
postfix-queuein/smtpd[29163]: vstream_buf_get_ready: fd 10 got 6
postfix-queuein/smtpd[29163]: < unknown[X.X.X.X]: rset
postfix-queuein/smtpd[29163]: > unknown[X.X.X.X]: 250 2.0.0 Ok
postfix-queuein/smtpd[29163]: watchdog_pat: 0x7f084d84a4e0
postfix-queuein/smtpd[29163]: vstream_fflush_some: fd 10 flush 14
postfix-queuein/smtpd[29163]: smtp_get: EOF
postfix-queuein/smtpd[29163]: match_hostname: unknown ~? 127.0.0.0/8
postfix-queuein/smtpd[29163]: match_hostaddr: X.X.X.X ~? 127.0.0.0/8
postfix-queuein/smtpd[29163]: match_hostname: unknown ~? X.X.X.0/24
postfix-queuein/smtpd[29163]: match_hostaddr: X.X.X.X ~? X.X.X.0/24
postfix-queuein/smtpd[29163]: match_hostname: unknown ~? X.X.X.X/32
postfix-queuein/smtpd[29163]: match_hostaddr: X.X.X.X ~? X.X.X.X/32
postfix-queuein/smtpd[29163]: match_list_match: unknown: no match
postfix-queuein/smtpd[29163]: match_list_match: X.X.X.X: no match
postfix-queuein/smtpd[29163]: send attr request = disconnect
postfix-queuein/smtpd[29163]: send attr ident = smtp:X.X.X.X
postfix-queuein/smtpd[29163]: vstream_fflush_some: fd 11 flush 45
postfix-queuein/smtpd[29163]: vstream_buf_get_ready: fd 11 got 10
postfix-queuein/smtpd[29163]: private/anvil: wanted attribute: status
postfix-queuein/smtpd[29163]: input attribute name: status
postfix-queuein/smtpd[29163]: input attribute value: 0
postfix-queuein/smtpd[29163]: private/anvil: wanted attribute: (list terminator)
postfix-queuein/smtpd[29163]: input attribute name: (end)
postfix-queuein/smtpd[29163]: lost connection after RSET from unknown[X.X.X.X]
postfix-queuein/smtpd[29163]: disconnect from unknown[X.X.X.X]

What can be the problem?
Thanks,

[d.agosti...@gmail.com]

Hi
Maybe the 6 seconds sleep triggers the error ?