Postfix stellt Mails an einen bestimmten Benutzer nicht zu

Sylvia Gelman sgelman at rmr.tu-darmstadt.de
Mi Mai 8 14:04:48 CEST 2019


Hallo Kai,

ohne debug Modus erkennt man nicht viel, dies ist das komplette Log beim 
Senden einer Nachricht die dann in der Queue dauerhaft bleibt:

May  8 13:44:12 server postfix/smtpd[28381]: connect from 
client.rt.e-technik.domain.de[IP]
May  8 13:44:12 server postfix/smtpd[28381]: Anonymous TLS connection 
established from client.rt.e-technik.domain.de[IP]: TLSv1.2 with cipher 
ECDHE-RSA-AES128
-GCM-SHA256 (128/128 bits)
May  8 13:44:12 server postfix/smtpd[28381]: 931E4240DF1: 
client=client.rt.e-technik.domain.de[IP]
May  8 13:44:12 server postfix/cleanup[28385]: 931E4240DF1: 
message-id=<4401d636-0ef2-5e43-cccf-b3dbf4ca3078 at domain.de>
May  8 13:44:12 server postfix/qmgr[28369]: 1AD5F240CBB: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 931E4240DF1: 
from=<sgelman at domain.de>, size=989, nrcpt=1 (queue active)
May  8 13:44:12 server postfix/qmgr[28369]: AFECC240FAC: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 8D67B24092E: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 9B5BE2412F2: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: E57042401C0: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 6591B240C30: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 4B1C92401BE: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 887BE2414AF: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 1017B24014C: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 56DBF240F35: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: B9725240D4F: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: 78BE1240A20: skipped, still 
being delivered
May  8 13:44:12 server postfix/qmgr[28369]: C133624159E: skipped, still 
being delivered
May  8 13:44:12 server postfix/smtpd[28381]: disconnect from 
client.rt.e-technik.domain.de[IP]

Wie gesagt, im Debug Modus sieht man als letzte Zeile dies:

May  8 11:13:03 server postfix/local[25188]: set_eugid: euid 3147 egid 2002

dann steigt er aus, es kommt einfach garnichts mehr.

Bei einer normalen Mail die zugestellt wird, geht es ab hier 
folgendermaßen weiter:

May 8 11:14:29 server postfix/local[25197]: set_eugid: euid 3005 egid 2017

May 8 11:14:29 server postfix/local[25197]: set_eugid: euid 110 egid 116

May 8 11:14:29 server postfix/local[25197]: deliver_dotforward: path 
/home/atest/.forward expand_status 0 look_status -1

May 8 11:14:29 server postfix/local[25197]: deliver_mailbox[3]: local 
atest recip atest at server.rt.e-technik.domain.de exten deliver 
atest at server.rt.e-technik.domain.de exp_from

May 8 11:14:29 server postfix/local[25197]: been_here: mailbox atest: 0

May 8 11:14:29 server postfix/local[25197]: connect to subsystem 
private/cyrus

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: status

May 8 11:14:29 server postfix/local[25197]: input attribute name: status

May 8 11:14:29 server postfix/local[25197]: input attribute value: 0

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: (list terminator)

May 8 11:14:29 server postfix/local[25197]: input attribute name: (end)

May 8 11:14:29 server postfix/local[25197]: send attr flags = 3

May 8 11:14:29 server postfix/local[25197]: send attr queue_name = active

May 8 11:14:29 server postfix/local[25197]: send attr queue_id = A682F240BE8

May 8 11:14:29 server postfix/local[25197]: send attr offset = 796

May 8 11:14:29 server postfix/local[25197]: send attr size = 991

May 8 11:14:29 server postfix/local[25197]: send attr nexthop = 
server.rt.e-technik.domain.de

May 8 11:14:29 server postfix/local[25197]: send attr encoding = 8bit

May 8 11:14:29 server postfix/local[25197]: send attr sender = 
sgelman at domain.de

May 8 11:14:29 server postfix/local[25197]: send attr envelope_id =

May 8 11:14:29 server postfix/local[25197]: send attr ret_flags = 0

May 8 11:14:29 server postfix/local[25197]: send attr time = [data 88 bytes]

May 8 11:14:29 server postfix/local[25197]: send attr log_client_name = 
client.rt.e-technik.domain.de

May 8 11:14:29 server postfix/local[25197]: send attr log_client_address 
= IP

May 8 11:14:29 server postfix/local[25197]: send attr log_client_port = 
59252

May 8 11:14:29 server postfix/local[25197]: send attr log_protocol_name 
= ESMTP

May 8 11:14:29 server postfix/local[25197]: send attr log_helo_name = [IP]

May 8 11:14:29 server postfix/local[25197]: send attr sasl_method =

May 8 11:14:29 server postfix/local[25197]: send attr sasl_username =

May 8 11:14:29 server postfix/local[25197]: send attr sasl_sender =

May 8 11:14:29 server postfix/local[25197]: send attr log_ident = 
A682F240BE8

May 8 11:14:29 server postfix/local[25197]: send attr rewrite_context = 
remote

May 8 11:14:29 server postfix/local[25197]: send attr recipient_count = 1

May 8 11:14:29 server postfix/local[25197]: send attr original_recipient 
= atest at domain.de

May 8 11:14:29 server postfix/local[25197]: send attr recipient = 
atest at server.rt.e-technik.domain.de

May 8 11:14:29 server postfix/local[25197]: send attr offset = 
18446744073709551615

May 8 11:14:29 server postfix/local[25197]: send attr dsn_orig_rcpt = 
rfc822;atest at domain.de

May 8 11:14:29 server postfix/local[25197]: send attr notify_flags = 0

May 8 11:14:29 server cyrus/master[25200]: about to exec 
/usr/lib/cyrus/bin/lmtpd

May 8 11:14:29 server cyrus/lmtpunix[25200]: executed

May 8 11:14:29 server cyrus/lmtpunix[25200]: accepted connection

May 8 11:14:29 server cyrus/lmtpunix[25200]: lmtp connection preauth'd 
as postman

May 8 11:14:29 server cyrus/lmtpunix[25200]: Delivered: 
<f1f1c902-f952-dcc1-e911-541009709f76 at domain.de> to mailbox: user.atest

May 8 11:14:29 server cyrus/lmtpunix[25200]: USAGE atest user: 0.004000 
sys: 0.000000

May 8 11:14:29 server postfix/pipe[25198]: A682F240BE8: 
to=<atest at server.rt.e-technik.domain.de>, orig_to=<atest at domain.de>, 
relay=cyrus, delay=0.28, delays=0.04/0.15/0/0.09, dsn=2.0.0, status=sent 
(delivered via cyrus service)

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: status

May 8 11:14:29 server postfix/local[25197]: input attribute name: status

May 8 11:14:29 server postfix/local[25197]: input attribute value: (end)

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: diag_type

May 8 11:14:29 server postfix/local[25197]: input attribute name: diag_type

May 8 11:14:29 server postfix/local[25197]: input attribute value: (end)

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: diag_text

May 8 11:14:29 server postfix/local[25197]: input attribute name: diag_text

May 8 11:14:29 server postfix/local[25197]: input attribute value: (end)

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: mta_type

May 8 11:14:29 server postfix/local[25197]: input attribute name: mta_type

May 8 11:14:29 server postfix/local[25197]: input attribute value: (end)

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: mta_mname

May 8 11:14:29 server postfix/local[25197]: input attribute name: mta_mname

May 8 11:14:29 server postfix/local[25197]: input attribute value: (end)

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: action

May 8 11:14:29 server postfix/local[25197]: input attribute name: action

May 8 11:14:29 server postfix/local[25197]: input attribute value: (end)

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: reason

May 8 11:14:29 server postfix/local[25197]: input attribute name: reason

May 8 11:14:29 server postfix/local[25197]: input attribute value: (end)

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: status

May 8 11:14:29 server postfix/local[25197]: input attribute name: status

May 8 11:14:29 server postfix/local[25197]: input attribute value: 0

May 8 11:14:29 server postfix/local[25197]: private/cyrus socket: wanted 
attribute: (list terminator)

May 8 11:14:29 server postfix/local[25197]: input attribute name: (end)

May 8 11:14:29 server postfix/local[25197]: deliver_request_final: send: 
"" 0

May 8 11:14:29 server postfix/local[25197]: send attr status =

May 8 11:14:29 server postfix/local[25197]: send attr diag_type =

May 8 11:14:29 server postfix/local[25197]: send attr diag_text =

May 8 11:14:29 server postfix/local[25197]: send attr mta_type =

May 8 11:14:29 server postfix/local[25197]: send attr mta_mname =

May 8 11:14:29 server postfix/local[25197]: send attr action =

May 8 11:14:29 server postfix/local[25197]: send attr reason =

May 8 11:14:29 server postfix/local[25197]: send attr status = 0

May 8 11:14:29 server postfix/local[25197]: master_notify: status 1

May 8 11:14:29 server postfix/qmgr[25181]: A682F240BE8: removed

May 8 11:14:29 server postfix/local[25197]: connection closed

May 8 11:14:29 server postfix/local[25197]: watchdog_stop: 0x55ce67b12120

May 8 11:14:29 server postfix/local[25197]: watchdog_start: 0x55ce67b12120


Am 08.05.19 um 12:15 schrieb Kai Fürstenberg:
> Hi Sylvia,
>
> zunächst habe ich mich einmal geirrt: Postfix loggt kein "queued as", er
> gibt dieses aber an den einliefernden Server zurück, der es seinerseits
> loggt oder loggen kann.
>
>
> Bitte kein verbose und kein rumgeschnippsel mehr.
> Ich hätte gerne mal ein komplettes Log in ganz normaler Form.
>
> Nimm also bitte mal alle -vv raus aus der master.cf, postfix reload,
> postfix flush und poste den kompletten Logausschnmitt am besten so wie
> es ist, ohne Auslassungen oder Ergänzungen.
>
> Bzw. liefere mal eine neue Mail an den Empfänger ein und poste den
> kompletten Logausschnmitt am besten so wie es ist, ohne Auslassungen
> oder Ergänzungen.
>
>>> mich irritiert, dass es keine Logeinträge gibt. Mich irritiert auch,
>>> dass unter mailq keine Angaben zur Verzögerung eingetragen sind.
>>> Normalerweise steht da, warum es länger dauert oder ob die Mail of HOLD
>>> steht.
>> ja das irritiert mich ja auch, es müsste schon längst der Sender
>> informiert worden sein, dass die Mail nicht zugestellt werden konnte.
>>>    Evtl. vorher den
>>> Loglevel von Cyrus höhersetzen.
>> Wo setze ich den Loglevel von Cyrus höher? Finde dazu nichts.
> Der Loglevel von Cyrus wird über syslogd gesteuert. In der Cyrus-Zeile
> musst du debug gesondert setzen.
>
> Wie gesagt, ist ewig her, dass ich den benutzt habe...
>
-- 
Sylvia Gelman
IT Organisation
Technische Universität Darmstadt
Institut für Automatisierungstechnik und Mechatronik - IAT
Fachgebiet Regelungsmethoden und Robotik (RMR)
Landgraf-Georg-Str. 4
Gebäude S3|10 Raum 409
D-64283 Darmstadt
Tel.: +49 6151 / 16-25055
Email: sgelman at rmr.tu-darmstadt.de



Mehr Informationen über die Mailingliste postfix-users