Postfix - Temporary lookup failure

[hever]

Hallo zusammen,

auf einem Produktivserver erhalte ich immer mal wieder folgende Fehlermeldung:
Temporary lookup failure

Das Problem lässt sich nicht 100% reproduzieren und ist deswegen (für mich) nicht leicht zu lösen.
Es tritt bsp. auf wenn ich mehrere E-Mails nacheinander verschicke. Sei es über einen E-Mail-Client oder über eine Variation folgenden Shell Befehls:

Code: Select all

smtp-source -4c -f loadtest@mydomain.tld -S LOADTEST -t address@domain.tld -N -m 50  inet:myserver.tld

Der Client erhält dann:

smtp-source: fatal: recipient rejected: 451 4.3.0 <2address@domain.tld>: Temporary lookup failure

Das Problem ist hier wieder das dieser Fehler nicht immer auftritt. Ich habe schon manche Nächte damit verbracht das Problem zu lösen und konnte dann gut 1000 Mails ohne Probleme verschicken und auch in den Tagen darauf (tagsüber) gab es keine Probleme. Immer wenn ich glaube es gelöst zu haben kommt es nach ein paar Tagen wieder. Die Adresse 2address@domain.tld existiert bzw. ein entsprechender catchall. Mal funktioniert eine E-Mail-Adresse, mal nicht (es liegt also nicht daran, das die Adresse nicht existiert).

Nachtrag:
Momentan ist der Server kaum nutzbar und ich erhalte ebenfalls die Fehlermeldung
smtp-source: fatal: data 451 4.3.0 Error: queue file write error
Nach einem Postfix restart gehen ca. 100 Mails raus, dann kommen die Fehler wieder.

/var/log/mail.log (problematischer Bereich hervorgehoben):

Feb 25 12:04:33 myhost postfix/pipe[17944]: CAC2C4536B: to=<ADDRESS@DOMAIN.TLD>, relay=spamassassin, delay=4.4, delays=0.21/0.01/0/4.2, dsn=2.0.0, status=sent (delivered via spamassassin service)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: status
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: status
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute value: (end)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: diag_type
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: diag_type
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute value: (end)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: diag_text
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: diag_text
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute value: (end)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: mta_type
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: mta_type
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute value: (end)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: mta_mname
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: mta_mname
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute value: (end)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: action
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: action
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute value: (end)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: reason
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: reason
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute value: (end)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: status
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: status
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute value: 0
Feb 25 12:04:33 myhost postfix/qmgr[17894]: private/spamassassin socket: wanted attribute: (list terminator)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: input attribute name: (end)
Feb 25 12:04:33 myhost postfix/qmgr[17894]: qmgr_queue_unthrottle: queue dummy
Feb 25 12:04:33 myhost postfix/qmgr[17894]: qmgr_active_done: CAC2C4536B
Feb 25 12:04:33 myhost postfix/qmgr[17894]: CAC2C4536B: removed
Feb 25 12:04:33 myhost postfix/qmgr[17894]: qmgr_job_free: CAC2C4536B spamassassin
Feb 25 12:04:33 myhost postfix/qmgr[17894]: mail_flow_put: 2 2
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: send attr address = address@domain.tld
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: master_notify: status 1
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: master_notify: status 0
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: rewrite socket: wanted attribute: request
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: input attribute name: request
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: input attribute value: rewrite
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: rewrite socket: wanted attribute: rule
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: input attribute name: rule
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: input attribute value: local
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: rewrite socket: wanted attribute: address
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: input attribute name: address
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: input attribute value: ADDRESS@DOMAIN.TLD
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: rewrite socket: wanted attribute: (list terminator)
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: input attribute name: (end)
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: `local' `ADDRESS@DOMAIN.TLD' -> `ADDRESS@DOMAIN.TLD'
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: send attr flags = 0
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: send attr address = ADDRESS@DOMAIN.TLD
Feb 25 12:04:33 myhost postfix/trivial-rewrite[17899]: master_notify: status 1
Feb 25 12:04:33 myhost postfix/proxymap[17897]: master_notify: status 0
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: request
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: request
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute value: lookup
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: table
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: table
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute value: mysql:/etc/postfix/mysql_virtual_alias_maps.cf
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: flags
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: flags
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute value: 16448
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: key
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: key
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute value: ADDRESS@DOMAIN.TLD
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: (list terminator)
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: (end)
Feb 25 12:04:33 myhost postfix/proxymap[17897]: send attr status = 2
Feb 25 12:04:33 myhost postfix/proxymap[17897]: send attr value =
Feb 25 12:04:33 myhost postfix/proxymap[17897]: master_notify: status 1
Feb 25 12:04:33 myhost postfix/cleanup[17898]: warning: 3269D4536F: virtual_alias_maps map lookup problem for ADDRESS@DOMAIN.TLD
Feb 25 12:04:33 myhost spamd[5887]: prefork: child states: II
Feb 25 12:04:33 myhost postfix/smtpd[17892]: connection established
Feb 25 12:04:33 myhost postfix/smtpd[17892]: master_notify: status 0
Feb 25 12:04:33 myhost postfix/smtpd[17892]: name_mask: resource
Feb 25 12:04:33 myhost postfix/smtpd[17892]: name_mask: software
Feb 25 12:04:33 myhost postfix/smtpd[17892]: xsasl_dovecot_server_create: SASL service=smtp, realm=(null)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: connect from xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: xxx.adsl.alicedsl.de: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: xx.xxx.xxx.xxx: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: xxx.adsl.alicedsl.de: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: xx.xxx.xxx.xxx: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_hostname: xxx.adsl.alicedsl.de ~? 127.0.0.1/32
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_hostaddr: xx.xxx.xxx.xxx ~? 127.0.0.1/32
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_hostname: xxx.adsl.alicedsl.de ~? xxx.xxx.xxx.xxx/xx
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_hostaddr: xx.xxx.xxx.xxx ~? xxx.xxx.xxx.xxx/xx
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: xxx.adsl.alicedsl.de: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: xx.xxx.xxx.xxx: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: send attr request = connect
Feb 25 12:04:33 myhost postfix/smtpd[17892]: send attr ident = smtp:xx.xxx.xxx.xxx
Feb 25 12:04:33 myhost postfix/smtpd[17892]: private/anvil: wanted attribute: status
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute name: status
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute value: 0
Feb 25 12:04:33 myhost postfix/smtpd[17892]: private/anvil: wanted attribute: count
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute name: count
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute value: 1
Feb 25 12:04:33 myhost postfix/smtpd[17892]: private/anvil: wanted attribute: rate
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute name: rate
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute value: 6
Feb 25 12:04:33 myhost postfix/smtpd[17892]: private/anvil: wanted attribute: (list terminator)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute name: (end)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 220 mail.myhost.net ESMTP
Feb 25 12:04:33 myhost postfix/smtpd[17892]: < xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: EHLO [192.168.178.23]
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250-mail.myhost.net
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250-PIPELINING
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250-SIZE 16777216
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250-VRFY
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250-ETRN
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: xxx.adsl.alicedsl.de: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: xx.xxx.xxx.xxx: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250-STARTTLS
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250-ENHANCEDSTATUSCODES
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250-8BITMIME
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250 DSN
Feb 25 12:04:33 myhost postfix/smtpd[17892]: < xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: MAIL FROM:<address@domain.tld> SIZE=366
Feb 25 12:04:33 myhost postfix/smtpd[17892]: extract_addr: input: <address@domain.tld>
Feb 25 12:04:33 myhost postfix/smtpd[17892]: smtpd_check_addr: addr=address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: ctable_locate: leave existing entry key address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: extract_addr: in: <address@domain.tld>, result: address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: fsspace: .: block size 4096, blocks free 418107
Feb 25 12:04:33 myhost postfix/smtpd[17892]: smtpd_check_queue: blocks 4096 avail 418107 min_free 0 msg_size_limit 16777216
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 250 2.1.0 Ok
Feb 25 12:04:33 myhost postfix/smtpd[17892]: < xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: RCPT TO:<address@domain.tld>
Feb 25 12:04:33 myhost postfix/smtpd[17892]: extract_addr: input: <address@domain.tld>
Feb 25 12:04:33 myhost postfix/smtpd[17892]: smtpd_check_addr: addr=address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: ctable_locate: leave existing entry key address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: extract_addr: in: <address@domain.tld>, result: address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: >>> START Recipient address RESTRICTIONS <<<
Feb 25 12:04:33 myhost postfix/smtpd[17892]: generic_checks: name=permit_sasl_authenticated
Feb 25 12:04:33 myhost postfix/smtpd[17892]: generic_checks: name=permit_sasl_authenticated status=0
Feb 25 12:04:33 myhost postfix/smtpd[17892]: generic_checks: name=reject_unauth_destination
Feb 25 12:04:33 myhost postfix/smtpd[17892]: reject_unauth_destination: address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: permit_auth_destination: address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: ctable_locate: leave existing entry key address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: generic_checks: name=reject_unauth_destination status=0
Feb 25 12:04:33 myhost postfix/smtpd[17892]: generic_checks: name=reject_unlisted_recipient
Feb 25 12:04:33 myhost postfix/smtpd[17892]: >>> CHECKING RECIPIENT MAPS <<<
Feb 25 12:04:33 myhost postfix/smtpd[17892]: ctable_locate: leave existing entry key address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: maps_find: recipient_canonical_maps: address@domain.tld: not found
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_string: myhost.de ~? mail.myhost.net
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_string: myhost.de ~? localhost.myhost.net
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_string: myhost.de ~? localhost
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_string: myhost.de ~? myhost.net
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: myhost.de: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: maps_find: recipient_canonical_maps: @myhost.de: not found
Feb 25 12:04:33 myhost postfix/smtpd[17892]: mail_addr_find: address@domain.tld -> (not found)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: maps_find: canonical_maps: address@domain.tld: not found
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_string: myhost.de ~? mail.myhost.net
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_string: myhost.de ~? localhost.myhost.net
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_string: myhost.de ~? localhost
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_string: myhost.de ~? myhost.net
Feb 25 12:04:33 myhost postfix/smtpd[17892]: match_list_match: myhost.de: no match
Feb 25 12:04:33 myhost postfix/smtpd[17892]: maps_find: canonical_maps: @myhost.de: not found
Feb 25 12:04:33 myhost postfix/smtpd[17892]: mail_addr_find: address@domain.tld -> (not found)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: send attr request = lookup
Feb 25 12:04:33 myhost postfix/smtpd[17892]: send attr table = mysql:/etc/postfix/mysql_virtual_alias_maps.cf
Feb 25 12:04:33 myhost postfix/smtpd[17892]: send attr flags = 16448
Feb 25 12:04:33 myhost postfix/smtpd[17892]: send attr key = address@domain.tld
Feb 25 12:04:33 myhost postfix/smtpd[17892]: private/proxymap socket: wanted attribute: status
Feb 25 12:04:33 myhost postfix/proxymap[17897]: master_notify: status 0
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: request
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: request
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute value: lookup
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: table
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: table
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute value: mysql:/etc/postfix/mysql_virtual_alias_maps.cf
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: flags
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: flags
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute value: 16448
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: key
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: key
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute value: address@domain.tld
Feb 25 12:04:33 myhost postfix/proxymap[17897]: proxymap socket: wanted attribute: (list terminator)
Feb 25 12:04:33 myhost postfix/proxymap[17897]: input attribute name: (end)
Feb 25 12:04:33 myhost postfix/proxymap[17897]: send attr status = 2
Feb 25 12:04:33 myhost postfix/proxymap[17897]: send attr value =
Feb 25 12:04:33 myhost postfix/proxymap[17897]: master_notify: status 1
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute name: status
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute value: 2
Feb 25 12:04:33 myhost postfix/smtpd[17892]: private/proxymap socket: wanted attribute: value
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute name: value
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute value: (end)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: private/proxymap socket: wanted attribute: (list terminator)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: input attribute name: (end)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: dict_proxy_lookup: table=mysql:/etc/postfix/mysql_virtual_alias_maps.cf flags=lock|fold_fix key=address@domain.tld -> status=2 result=
Feb 25 12:04:33 myhost postfix/smtpd[17892]: maps_find: virtual_alias_maps: address@domain.tld: search aborted
Feb 25 12:04:33 myhost postfix/smtpd[17892]: mail_addr_find: address@domain.tld -> (try again)
Feb 25 12:04:33 myhost postfix/smtpd[17892]: NOQUEUE: reject: RCPT from xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 451 4.3.0 <address@domain.tld>: Temporary lookup failure; from=<address@domain.tld> to=<address@domain.tld> proto=ESMTP helo=<[192.168.178.23]>
Feb 25 12:04:33 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 451 4.3.0 <address@domain.tld>: Temporary lookup failure
Feb 25 12:04:35 myhost postfix/smtpd[17892]: < xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: QUIT
Feb 25 12:04:35 myhost postfix/smtpd[17892]: > xxx.adsl.alicedsl.de[xx.xxx.xxx.xxx]: 221 2.0.0 Bye
Feb 25 12:04:35 myhost postfix/smtpd[17892]: match_hostname: xxx.adsl.alicedsl.de ~? 127.0.0.1/32
Feb 25 12:04:35 myhost postfix/smtpd[17892]: match_hostaddr: xx.xxx.xxx.xxx ~? 127.0.0.1/32
Feb 25 12:04:35 myhost postfix/smtpd[17892]: match_hostname: xxx.adsl.alicedsl.de ~? xxx.xxx.xxx.xxx/xx
Feb 25 12:04:35 myhost postfix/smtpd[17892]: match_hostaddr: xx.xxx.xxx.xxx ~? xxx.xxx.xxx.xxx/xx
Feb 25 12:04:35 myhost postfix/smtpd[17892]: match_list_match: xxx.adsl.alicedsl.de: no match
Feb 25 12:04:35 myhost postfix/smtpd[17892]: match_list_match: xx.xxx.xxx.xxx: no match
Feb 25 12:04:35 myhost postfix/smtpd[17892]: send attr request = disconnect
Feb 25 12:04:35 myhost postfix/smtpd[17892]: send attr ident = smtp:xx.xxx.xxx.xxx
Feb 25 12:04:35 myhost postfix/smtpd[17892]: private/anvil: wanted attribute: status
Feb 25 12:04:35 myhost postfix/smtpd[17892]: input attribute name: status
Feb 25 12:04:35 myhost postfix/smtpd[17892]: input attribute value: 0
Feb 25 12:04:35 myhost postfix/smtpd[17892]: private/anvil: wanted attribute: (list terminator)
Feb 25 12:04:35 myhost postfix/smtpd[17892]: input attribute name: (end)
Feb 25 12:04:35 myhost postfix/smtpd[17892]: smtpd_chat_notify: notify postmaster
Feb 25 12:04:35 myhost postfix/smtpd[17892]: connect to subsystem public/cleanup
Feb 25 12:04:35 myhost postfix/smtpd[17892]: public/cleanup socket: wanted attribute: queue_id
Feb 25 12:04:35 myhost postfix/smtpd[17892]: input attribute name: queue_id
Feb 25 12:04:35 myhost postfix/smtpd[17892]: input attribute value: AC6B74536B
Feb 25 12:04:35 myhost postfix/smtpd[17892]: public/cleanup socket: wanted attribute: (list terminator)
Feb 25 12:04:35 myhost postfix/smtpd[17892]: input attribute name: (end)
Feb 25 12:04:35 myhost postfix/smtpd[17892]: send attr flags = 32
Feb 25 12:04:35 myhost postfix/smtpd[17892]: public/cleanup socket: wanted attribute: status

Lösungsansätze:
- Das Problem trat zunächst auf als ich noch keinen lokalen DNS-Server installiert hatte. Nach der Installation von bind9 schien das Problem das erste mal verschwunden.
- Als das Problem dann wieder auftrat habe ich proxymap (http://www.postfix.org/proxymap.8.html) eingesetzt und die Wake up time (http://www.postfix.org/master.5.html) für den smtp Dienst auf 60 gesetzt. (Proxymap alleine hat nicht viel gebracht aber in Verbindung mit der Wake up time schon.)

Mögliche Ursachen (meiner Ansicht nach):
- Ich vermute stark das es irgendetwas mit der DNS-Namensauflösung zutun hat, ich kann jedoch nicht herausfinden was. Ich habe in einer Mailingliste gelesen, das Fehler wie mail_addr_find: address@domain.tld -> (try again) wohl teilweise auf eine DNS-Namensauflösung zurückzuführen sind, der source code an der Stelle hat mich aber auch nicht besonders weiter gebracht. (http://groups.google.com/group/list.pos ... 2cb7924052)
- Ich denke nicht das es am MySQL Server liegt, folgender Befehl (fragt 1000 mal hintereinander die DB ab) läuft problemlos durch.

Code: Select all

 yes address@domain.tld | sed 1000q | postmap -q - mysql:/etc/postfix/mysql_virtual_alias_maps.cf 

Ich möchte nicht einfach wild etwas verändern sondern das Problem verstehen, darum stelle ich jetzt ein paar Fragen:
Woran kann dieses Problem liegen, was könnte alles damit zutun haben ?
Sollte ich die Wake up time nochmal verändern?
Sollte ich versuchen den lokalen cache im DNS Server zu verändern?
Kann ich irgendwie einstellen, das wenn der Temporary Lookup Failure kommt, Postfix einfach nochmal versucht die Mail zuzustellen?
Kann es sein das Postfix nach einigen Tagen einfach überläuft? Scheint mir nicht so aber vielleicht doch ?

# free -m -t
total used free shared buffers cached
Mem: 3926 1765 2161 0 135 1146
-/+ buffers/cache: 484 3442
Swap: 0 0 0
Total: 3926 1765 2161

# vmstat
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
1 0 0 2215572 138896 1175084 0 0 2 59 69 35 2 1 97 0

Für jede Hilfe und jeden Tipp wäre ich dankbar.

Ich hab schon viele Beiträge in Mailinglisten gelesen. Das Problem tritt wohl häufiger auf, ich konnte jedoch noch keine wirklich nützlichen Informationen finden.


postconf -n:

alias_database =
alias_maps =
append_dot_mydomain = no
biff = no
broken_sasl_auth_clients = yes
config_directory = /etc/postfix
html_directory = /usr/share/doc/postfix/html
inet_interfaces = all
mailbox_command = procmail -a "$EXTENSION"
mailbox_size_limit = 0
message_size_limit = 16777216
mydestination = $myhostname localhost.$mydomain localhost $mydomain
mydomain = domain.tld
myhostname = mail.domain.tld
mynetworks_style = host
myorigin = hosting.domain.tld
proxy_read_maps = $local_recipient_maps $mydestination $virtual_alias_maps $virtual_alias_domains $virtual_mailbox_maps $virtual_mailbox_domains $relay_recipient_maps $relay_domains $canonical_maps $sender_canonical_maps $recipient_canonical_maps $relocated_maps $transport_maps $mynetworks $smtpd_sender_login_maps
queue_directory = /var/spool/postfix
readme_directory = /usr/share/doc/postfix
recipient_delimiter = +
relayhost =
smtp_tls_CAfile = /etc/postfix/ca.crt
smtp_tls_cert_file = /etc/postfix/postfix-server.crt
smtp_tls_key_file = /etc/postfix/postfix-server.key
smtp_tls_security_level = may
smtpd_banner = $myhostname ESMTP
smtpd_error_sleep_time = 1s
smtpd_hard_error_limit = 20
smtpd_recipient_limit = 1000
smtpd_recipient_restrictions = permit_sasl_authenticated reject_unauth_destination reject_unlisted_recipient
smtpd_reject_unlisted_recipient = yes
smtpd_sasl_auth_enable = yes
smtpd_sasl_authenticated_header = yes
smtpd_sasl_path = private/auth
smtpd_sasl_security_options = noanonymous
smtpd_sasl_type = dovecot
smtpd_sender_login_maps = proxy:mysql:/etc/postfix/mysql_smtpd_sender_login_maps.cf
smtpd_soft_error_limit = 10
smtpd_tls_CAfile = /etc/postfix/ca.crt
smtpd_tls_auth_only = yes
smtpd_tls_cert_file = /etc/postfix/postfix-server.crt
smtpd_tls_key_file = /etc/postfix/postfix-server.key
smtpd_tls_security_level = may
virtual_alias_maps = proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf
virtual_gid_maps = static:8
virtual_mailbox_base = /var/mail
virtual_mailbox_domains = proxy:mysql:/etc/postfix/mysql_virtual_mailbox_domains.cf
virtual_mailbox_maps = proxy:mysql:/etc/postfix/mysql_virtual_mailbox_maps.cf
virtual_minimum_uid = 1025
virtual_transport = dovecot-lda
virtual_uid_maps = proxy:mysql:/etc/postfix/mysql_virtual_uid_maps.cf

/etc/postfix/master.cf

################################################################################
#
# ==========================================================================
# service type private unpriv chroot wakeup maxproc command + args
# (yes) (yes) (yes) (never) (100)
# ==========================================================================
# Postfix SMTP server
smtp inet n - y 60 - smtpd -v
-o content_filter=spamassassin:dummy

#submission inet n - - - - smtpd
# -o smtpd_enforce_tls=yes
# -o smtpd_sasl_auth_enable=yes
# -o smtpd_client_restrictions=permit_sasl_authenticated,reject

#smtps inet n - - - - smtpd
# -o smtpd_tls_wrappermode=yes
# -o smtpd_sasl_auth_enable=yes
# -o smtpd_client_restrictions=permit_sasl_authenticated,reject

# Postfix QMQP server
#628 inet n - - - - qmqpd

# Postfix local mail pickup
pickup fifo n - y 60 1 pickup

# canonicalize and enqueue Postfix message
cleanup unix n - y - 0 cleanup

# Postfix queue manager
qmgr fifo n - n 300 1 qmgr -v

# Postfix TLS session cache and PRNG manager
tlsmgr unix - - y 1000? 1 tlsmgr

# Postfix address rewriting and resolving daemon
rewrite unix - - y - - trivial-rewrite -v

# Postfix delivery status reports
bounce unix - - y - 0 bounce
defer unix - - y - 0 bounce
trace unix - - y - 0 bounce

# Postfix address verification server
verify unix - - y - 1 verify

# Postfix fast flush server
flush unix n - y 1000? 0 flush

# Postfix lookup table proxy server
proxymap unix - - n - - proxymap -v

# Postfix SMTP+LMTP client
smtp unix - - y - - smtp

# When relaying mail as backup MX, disable fallback_relay to avoid MX loops
relay unix - - y - - smtp
-o fallback_relay=
# -o smtp_helo_timeout=5 -o smtp_connect_timeout=5

# list the Postfix mail queue
showq unix n - y - - showq

# Postfix error/retry mail delivery agent
error unix - - y - - error
retry unix - - y - - error

# Postfix discard mail delivery agent
discard unix - - y - - discard

# Postfix local mail delivery
local unix - n n - - local

# Postfix virtual domain mail delivery agent
virtual unix - n n - - virtual

# Postfix SMTP+LMTP client
#lmtp unix - - - - - lmtp

# Postfix session count and request rate control
anvil unix - - y - 1 anvil

# Postfix shared connection cache server
scache unix - - y - 1 scache

#
# ====================================================================
# Interfaces to non-Postfix software. Be sure to examine the manual
# pages of the non-Postfix software to find out what options it wants.
#
# Many of the following services use the Postfix pipe(8) delivery
# agent. See the pipe(8) man page for information about ${recipient}
# and other message envelope options.
# ====================================================================
#
# Spamassassin conent filter
spamassassin unix - n n - - pipe
flags=Rq user=spamassassin argv=/etc/spamassassin/mark_spam_header.sh
-f ${sender} -- ${recipient}

# Dovecot LDA
dovecot-lda unix - n n - - pipe
flags=DRhu user=mail:mail argv=/usr/lib/dovecot/deliver -d ${recipient}

/var/log/mail.err (ist voll von):

Feb 25 14:12:00 myhost postfix/trivial-rewrite[6115]: fatal: proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): table lookup problem
Feb 25 14:16:21 myhost postfix/trivial-rewrite[6370]: fatal: proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): table lookup problem
Feb 25 14:16:23 myhost postfix/trivial-rewrite[6369]: fatal: proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): table lookup problem
Feb 25 14:16:24 myhost postfix/trivial-rewrite[6515]: fatal: proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): table lookup problem
Feb 25 14:16:25 myhost postfix/trivial-rewrite[6516]: fatal: proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): table lookup problem
Feb 25 14:16:26 myhost postfix/trivial-rewrite[6517]: fatal: proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): table lookup problem
Feb 25 14:16:26 myhost postfix/trivial-rewrite[6518]: fatal: proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): table lookup problem
Feb 25 14:16:27 myhost postfix/trivial-rewrite[6519]: fatal: proxy:mysql:/etc/postfix/mysql_virtual_alias_maps.cf(0,lock|fold_fix): table lookup problem

[hever]

Nachtrag:
Momentan ist der Server kaum nutzbar und ich erhalte ebenfalls die Fehlermeldung
smtp-source: fatal: data 451 4.3.0 Error: queue file write error
Nach einem Postfix restart gehen ca. 100 Mails raus, dann kommen die Fehler wieder.

Diesen Fehler hab ich selbst durch das debuggen mit smtp -v verursacht.
Trotzdem geht momentan keine Mail raus. Immer kommt ein Temporary Lookup Failure.
Das ist gut und schlecht.

Es gehen nach einem Postfix restart also ca. 50 Mails raus und dann kommt der Lookup Failure.

[Joe User]

Es gibt Probleme mit Deiner MySQL-Verbindung:

Code: Select all

Feb 25 12:04:33 myhost postfix/cleanup[17898]: warning: 3269D4536F: virtual_alias_maps map lookup problem for ADDRESS@DOMAIN.TLD

Wie sehen Deine virtual_alias_maps.cf und die DB-Struktur aus? Ist der MySQLd zeitweilig überlastet (max_connections, table locks, etc.) oder down?

[hever]

... aber

Code: Select all

 yes address@domain.tld | sed 1000q | postmap -q - mysql:/etc/postfix/mysql_virtual_alias_maps.cf 

gibt 1000x folgendes aus:

address@domain.tld ADDRESS@DOMAIN.TLD

postmap cached doch nicht und fragt wirklich 1000 mal die DB oder nicht?

Der MySQL Server ist da und läuft auch wirklich sehr schnell (ich habs jetzt nur über phpmyadmin getestet).

Bestimmt lässt sich noch etwas verbessern, zb. Caches hochsetzen ? (Wie gesagt ich will nicht einfach rumprobieren, sondern verstehen da dieser Fehler echt nervt.)

/etc/mysql/my.cnf:

# This will be passed to all mysql clients
# It has been reported that passwords should be enclosed with ticks/quotes
# escpecially if they contain "#" chars...
# Remember to edit /etc/mysql/debian.cnf when changing the socket location.
[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock

# Here is entries for some specific programs
# The following values assume you have at least 32M ram

# This was formally known as [safe_mysqld]. Both versions are currently parsed.
[mysqld_safe]
socket = /var/run/mysqld/mysqld.sock
nice = 0

[mysqld]
#
# * Basic Settings
#
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
language = /usr/share/mysql/english
skip-external-locking
#
# Instead of skip-networking the default is now to listen only on
# localhost which is more compatible and is not less secure.
#bind-address = 127.0.0.1
#
# * Fine Tuning
#
key_buffer = 16M
max_allowed_packet = 16M
thread_stack = 128K
thread_cache_size = 8
max_connections = 10000
#table_cache = 64
#thread_concurrency = 10
#
# * Query Cache Configuration
#
query_cache_limit = 1M
query_cache_size = 16M
#
# * Logging and Replication
#
# Both location gets rotated by the cronjob.
# Be aware that this log type is a performance killer.
#log = /var/log/mysql/mysql.log
#
# Error logging goes to syslog. This is a Debian improvement
#
# Here you can see queries with especially long duration
#log_slow_queries = /var/log/mysql/mysql-slow.log
#long_query_time = 2
#log-queries-not-using-indexes
#
# The following can be used as easy to replay backup logs or for replication.
#server-id = 1
log_bin = /var/log/mysql/mysql-bin.log
# WARNING: Using expire_logs_days without bin_log crashes the server! See README.Debian!
expire_logs_days = 10
max_binlog_size = 100M
#binlog_do_db = include_database_name
#binlog_ignore_db = include_database_name
#
# * BerkeleyDB
#
# Using BerkeleyDB is now discouraged as its support will cease in 5.1.12.
skip-bdb
#
# * InnoDB
#
# InnoDB is enabled by default with a 10MB datafile in /var/lib/mysql/.
# Read the manual for more InnoDB related options. There are many!
# You might want to disable InnoDB to shrink the mysqld process by circa 100MB.
#skip-innodb
#
# * Security Features
#
# Read the manual, too, if you want chroot!
# chroot = /var/lib/mysql/
#
#
# For generating SSL certificates I recommend the OpenSSL GUI "tinyca".
#
# ssl-ca=/etc/mysql/cacert.pem
# ssl-cert=/etc/mysql/server-cert.pem
# ssl-key=/etc/mysql/server-key.pem



[mysqldump]
quick
quote-names
max_allowed_packet = 16M

[mysql]
#no-auto-rehash # faster start of mysql but no tab completition

[isamchk]
key_buffer = 16M
#
# * NDB Cluster
#
# See /usr/share/doc/mysql-server-*/README.Debian for more information.
#
# The following configuration is read by the NDB Data Nodes (ndbd processes)
# not from the NDB Management Nodes (ndb_mgmd processes).
#
# [MYSQL_CLUSTER]
# ndb-connectstring=127.0.0.1


#
# * IMPORTANT: Additional settings that can override those from this file!
#
!includedir /etc/mysql/conf.d/

[hever]

Es gibt Probleme mit Deiner MySQL-Verbindung:

Code: Select all

Feb 25 12:04:33 myhost postfix/cleanup[17898]: warning: 3269D4536F: virtual_alias_maps map lookup problem for ADDRESS@DOMAIN.TLD

Ich habe cleanup mail in den verbose modus gesetzt, aber erhalte keine weiteren Informationen. Wie kann ich den Fehler verfolgen, also sehen, was das lookup problem genau ist ?

[Joe User]

Wie sehen Deine virtual_alias_maps.cf und die DB-Struktur aus?

[hever]

/etc/postfix/mysql_virtual_alias_maps.conf:

hosts = 127.0.0.1
user = postfix
password = ***

dbname = ***

query = SELECT target_address
FROM `view_emailaccount_alias`
WHERE alias REGEXP '(^%s.?$)'
AND (
NOW() BETWEEN `forward_start` AND `forward_end`
OR forward_start IS NULL AND forward_end IS NULL )
ORDER BY forward_start DESC
LIMIT 1

Die DB Struktur ist zu komplex um sie jetzt hier zu posten.

Ich habe dort nicht weiter nach dem Fehler gesucht weil postmap immer die richtige Mailadresse zurückgeliefert hat. Meinst du ich sollte dort nochmal nach dem Fehler suchen? Es gibt ein paar spam adressen mit einigen ungültigen Zeichen die zu einem Temporary lookup failure führen, weil die REGEXP fehlschlägt, aber alle anderen Adressen sind simple und funktionieren meist. (Meist weil sonst der TLO fehler kommt... In den DB logs ist aber nichts ungewöhnlich und ich kann die queries selber erfolgreich ausführen.)
Nochmal die Frage: Wenn postmap funktioniert sollte es doch nicht an der DB liegen oder?

[hever]

Ich habs nochmal überprüft bei einem " Error: queue file write error" der doch manchmal noch kommt und bei einem " Temporary lookup failure" erscheinen entsprechende abfragen im mysql.log. Postfix kann sich also mit dem MySQL Server verbinden und auch eine Abfrage durchführen. Es wird wohl so sein das manchmal einfach kein Ergebnis zurückgeliefert wird. (Bei einer Adresse die zuvor noch funktionierte). Also liegt es wohl schon irgendwie an der DB.

Immer noch: Nur postmap funktioniert einwandfrei ?

Welche MySQL Server Einstellungen beeinflussen dieses Verhalten?

[Joe User]

Versuche es mal mit:

Code: Select all

user = dbuser
password = dbpass
hosts = localhost
dbname = dbname
query = SELECT target_address FROM view_emailaccount_alias WHERE alias='%s' AND ( NOW() BETWEEN forward_start AND forward_end OR forward_start IS NULL AND forward_end IS NULL ) ORDER BY forward_start DESC LIMIT 1

Ein Beispiel-Row mit reellen Daten (eMail-Adresse darfst Du ersetzen) und das Tabellen-Schema wären dennoch hilfreicher...

[hever]

(Ich habe gerade proxymap also "proxy:" vor jeder lookup table rausgenommen und mom. erhalte ich dadurch Fehlermeldungen mit denen ich etwas anfangen kann.)
"warning: connect to mysql server localhost: Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)"
Ich versuche jetzt erstmal die Fehler zu beheben und werde weiteres Berichten.

[hever]

So JoeUser,

nachdem ich proxy: entfernt hatte bekam ich endlich einige Fehlermeldungen mit denen ich etwas anfangen konnte.

Letztendlich habe ich in meinen Queries das REGEXP durch ein LIKE ersetzt und seitdem gab es bisher keine Probleme mehr.
(Ich hab mal ein paar tausend mails durchgeschickt.)
Ich denke das @ hat in der REGEXP manchmal für irgendwelche Probleme gesorgt, auch wenn ich mir nicht erklären kann warum nur manchmal oder überhaupt.

Ich hoffe sehr das dieses Thema endgültig erledigt ist. Ich werde jetzt noch ein paar kleine Fehler überprüfen und dann auch proxy wieder verwenden. (Es ist schon wieder so spät und diesen Erfolg hatte ich nun schon öfters, hoffentlich hat es wirklich nicht mysteriöser weise etwas mit der Zeit zutun)

Ansonten vielen Dank Joe User!
Du hast mir wirklich mit Weitblick geholfen und ich hätte wahrscheinlich die query nicht nochmal überdacht.