With LMTP testing in the Postfix logs I am getting "Temporary internal error"

Discussion:

(too old to reply)

t***@mm.st

2011-10-04 16:05:50 UTC

Hello,

I am building a Postfix 2.8.5 server. And I am delivering my mail only
to the Dovecot IMAP mail store using LMTP.

I am following the Wiki pages at www.postfix.org/VIRTUAL_README.html and
http://www.postfix.org/lmtp.8.html for guidance in these things.

In the testing of LMTP delivery I am having a challenge. I receive in
Postfix logs for 'lmtp -v' a few "Temporary internal error" messages.

I see the several messages, but I do not know the next step in
understanding and fixing it.

Can you help me to learn what next to do or how to see more details that
are useful?

For your interest in helping I am including that log information in this
message.

TJ

sendmail -i -t <<EOF
From: root
To: ***@tjserver.loc
Subject: testing
testing
EOF

Log ->

Oct 4 08:26:17 tjserver postfix/pickup[7145]: 086E9204BE: uid=0
from=<root>
Oct 4 08:26:17 tjserver postfix/cleanup[7148]: 086E9204BE:
message-id=<***@tjserver.loc>
Oct 4 08:26:17 tjserver postfix/qmgr[7143]: 086E9204BE:
from=<***@tjserver.loc>, size=387, nrcpt=1 (queue active)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: ipv4
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: inet_addr_local: configured
4 IPv4 addresses
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: process generation: 54 (54)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: match_string:
fast_flush_domains ~? debug_peer_list
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: match_string:
fast_flush_domains ~? smtpd_access_maps
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: match_list_match:
fast_flush_domains: no match
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: canonical
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: virtual
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: dns
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: host name lookup methods:
dns
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: auto_clnt_create:
transport=local endpoint=private/scache
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: connection established
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: master_notify: status 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: deliver_request_initial:
send initial status
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr status = 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 3
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: queue_name
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
queue_name
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
active
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: queue_id
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
queue_id
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
086E9204BE
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: offset
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
offset
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 190
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: size
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: size
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 387
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: nexthop
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
nexthop
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
unix:private/dovecot-lmtp
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: encoding
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
encoding
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: sender
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
sender
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
***@tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: envelope_id
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
envelope_id
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: ret_flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
ret_flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: time
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: time
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
mCWLTgAAAADExg4AAAAAAJkli04AAAAAgh8BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA==
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_client_name
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
log_client_name
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_client_address
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
log_client_address
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_client_port
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
log_client_port
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_protocol_name
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
log_protocol_name
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_helo_name
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
log_helo_name
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: sasl_method
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
sasl_method
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: sasl_username
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
sasl_username
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: sasl_sender
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
sasl_sender
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_ident
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
log_ident
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: rewrite_context
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
rewrite_context
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
local
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: recipient_count
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
recipient_count
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 1
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: (list terminator)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: (end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: original_recipient
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
original_recipient
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
***@tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: recipient
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
recipient
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
***@tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: offset
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
offset
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 617
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: dsn_orig_rcpt
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
dsn_orig_rcpt
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value:
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: notify_flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
notify_flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: (list terminator)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: (end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: deliver_request_get: file
active/086E9204BE
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: deliver_message: from
***@tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: smtp_connect_unix: trying:
private/dovecot-lmtp...
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: global TLS level: none
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 220 tjserver.loc Dovecot LMTP ready
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: LHLO tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250-tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250-8BITMIME
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250-ENHANCEDSTATUSCODES
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250 PIPELINING
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: server features: 0x7 size 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: Using LMTP PIPELINING, TCP
send buffer size is 256960, PIPELINING buffer size is 4096
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: MAIL FROM:<***@tjserver.loc>
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: RCPT TO:<***@tjserver.loc>
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: DATA
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250 2.1.0 OK
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250 2.1.5 OK
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 354 OK
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: .
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: QUIT
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 451 4.3.0 <***@tjserver.loc>
Temporary internal error
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: connect to subsystem
private/defer
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr nrequest = 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr flags = 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr queue_id =
086E9204BE
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr
original_recipient = ***@tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr recipient =
***@tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr offset = 617
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr dsn_orig_rcpt =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr notify_flags = 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr status = 4.3.0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr diag_type = smtp
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr diag_text = 451
4.3.0 <***@tjserver.loc> Temporary internal error
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr mta_type = dns
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr mta_mname =
tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr action = delayed
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr reason = host
tjserver.loc[private/dovecot-lmtp] said: 451 4.3.0 <***@tjserver.loc>
Temporary internal error (in reply to end of DATA command)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: private/defer socket:
wanted attribute: status
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name:
status
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: private/defer socket:
wanted attribute: (list terminator)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: (end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: 086E9204BE:
to=<***@tjserver.loc>, relay=tjserver.loc[private/dovecot-lmtp],
delay=0.13, delays=0.11/0.02/0/0, dsn=4.3.0, status=deferred (host
tjserver.loc[private/dovecot-lmtp] said: 451 4.3.0 <***@tjserver.loc>
Temporary internal error (in reply to end of DATA command))
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: flush_add: site
tjserver.loc id 086E9204BE
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: match_hostname:
tjserver.loc ~? localhost.tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: match_hostname:
tjserver.loc ~? localhost
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: match_list_match:
tjserver.loc: no match
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: flush_add: site
tjserver.loc id 086E9204BE status 4
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: smtp_loop: got 1 of 1
end-of-data replies
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 221 2.0.0 Client quit
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: resource
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: software
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: deliver_request_final:
send: "" -1
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr status =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr diag_type =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr diag_text =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr mta_type =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr mta_mname =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr action =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr reason =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr status =
4294967295
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: master_notify: status 1
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: connection closed

Reindl Harald

2011-10-04 16:07:58 UTC

Permalink

DO NOT post verbose logging unless required!

Post by t***@mm.st
Hello,
I am building a Postfix 2.8.5 server. And I am delivering my mail only
to the Dovecot IMAP mail store using LMTP.
I am following the Wiki pages at www.postfix.org/VIRTUAL_README.html and
http://www.postfix.org/lmtp.8.html for guidance in these things.
In the testing of LMTP delivery I am having a challenge. I receive in
Postfix logs for 'lmtp -v' a few "Temporary internal error" messages.
I see the several messages, but I do not know the next step in
understanding and fixing it.
Can you help me to learn what next to do or how to see more details that
are useful?
For your interest in helping I am including that log information in this
message.
TJ
sendmail -i -t <<EOF
From: root
Subject: testing
testing
EOF
Log ->
Oct 4 08:26:17 tjserver postfix/pickup[7145]: 086E9204BE: uid=0
from=<root>
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: ipv4
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: inet_addr_local: configured
4 IPv4 addresses
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: process generation: 54 (54)
fast_flush_domains ~? debug_peer_list
fast_flush_domains ~? smtpd_access_maps
fast_flush_domains: no match
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: canonical
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: virtual
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: dns
dns
transport=local endpoint=private/scache
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: connection established
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: master_notify: status 0
send initial status
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr status = 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 3
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: queue_name
queue_name
active
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: queue_id
queue_id
086E9204BE
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: offset
offset
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 190
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: size
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: size
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 387
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: nexthop
nexthop
unix:private/dovecot-lmtp
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: encoding
encoding
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: sender
sender
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: envelope_id
envelope_id
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: ret_flags
ret_flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: time
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: time
mCWLTgAAAADExg4AAAAAAJkli04AAAAAgh8BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA==
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_client_name
log_client_name
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_client_address
log_client_address
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_client_port
log_client_port
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_protocol_name
log_protocol_name
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_helo_name
log_helo_name
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: sasl_method
sasl_method
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: sasl_username
sasl_username
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: sasl_sender
sasl_sender
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: log_ident
log_ident
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: rewrite_context
rewrite_context
local
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: recipient_count
recipient_count
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 1
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: (list terminator)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: (end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: original_recipient
original_recipient
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: recipient
recipient
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: offset
offset
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 617
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: dsn_orig_rcpt
dsn_orig_rcpt
(end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: notify_flags
notify_flags
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: lmtp socket: wanted
attribute: (list terminator)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: (end)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: deliver_request_get: file
active/086E9204BE
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: deliver_message: from
private/dovecot-lmtp...
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: global TLS level: none
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 220 tjserver.loc Dovecot LMTP ready
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: LHLO tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250-tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250-8BITMIME
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250-ENHANCEDSTATUSCODES
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250 PIPELINING
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: server features: 0x7 size 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: Using LMTP PIPELINING, TCP
send buffer size is 256960, PIPELINING buffer size is 4096
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: DATA
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250 2.1.0 OK
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 250 2.1.5 OK
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 354 OK
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: .
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: >
tjserver.loc[private/dovecot-lmtp]: QUIT
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
Temporary internal error
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: connect to subsystem
private/defer
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr nrequest = 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr flags = 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr queue_id =
086E9204BE
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr recipient =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr offset = 617
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr dsn_orig_rcpt =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr notify_flags = 0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr status = 4.3.0
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr diag_type = smtp
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr diag_text = 451
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr mta_type = dns
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr mta_mname =
tjserver.loc
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr action = delayed
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr reason = host
Temporary internal error (in reply to end of DATA command)
wanted attribute: status
status
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute value: 0
wanted attribute: (list terminator)
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: input attribute name: (end)
delay=0.13, delays=0.11/0.02/0/0, dsn=4.3.0, status=deferred (host
Temporary internal error (in reply to end of DATA command))
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: flush_add: site
tjserver.loc id 086E9204BE
tjserver.loc ~? localhost.tjserver.loc
tjserver.loc ~? localhost
tjserver.loc: no match
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: flush_add: site
tjserver.loc id 086E9204BE status 4
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: smtp_loop: got 1 of 1
end-of-data replies
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: <
tjserver.loc[private/dovecot-lmtp]: 221 2.0.0 Client quit
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: resource
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: name_mask: software
send: "" -1
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr status =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr diag_type =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr diag_text =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr mta_type =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr mta_mname =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr action =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr reason =
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: send attr status =
4294967295
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: master_notify: status 1
Oct 4 08:26:17 tjserver postfix/lmtp[7150]: connection closed

--
Mit besten Grüßen, Reindl Harald
the lounge interactive design GmbH
A-1060 Vienna, Hofmühlgasse 17
CTO / software-development / cms-solutions
p: +43 (1) 595 3999 33, m: +43 (676) 40 221 40
icq: 154546673, http://www.thelounge.net/

http://www.thelounge.net/signature.asc.what.htm

e***@espphotography.com

2011-10-04 16:10:39 UTC

Permalink

Do not quote the entire message with verbose logs unless required! :)

Post by Reindl Harald
DO NOT post verbose logging unless required!

Wietse Venema

2011-10-04 16:29:04 UTC

Permalink

Post by t***@mm.st
delay=0.13, delays=0.11/0.02/0/0, dsn=4.3.0, status=deferred (host
Temporary internal error (in reply to end of DATA command))

POSTFIX the messenger of bad news, and the news is that the DOVECOT
server has a problem. Don't blame POSTFIX for the bad news.

Wietse

Duane Hill

2011-10-04 16:33:41 UTC

Permalink

<SNIP LOGS>

You should look here: http://wiki2.dovecot.org/HowTo/PostfixDovecotLMTP

--
duihi77

t***@mm.st

2011-10-04 16:35:56 UTC

Permalink

I have not made any blame. I am asking a question to learn. So nothing
needed to accuse.

On Tuesday, October 04, 2011 12:29 PM, "Wietse Venema"

Post by Wietse Venema

Post by t***@mm.st
delay=0.13, delays=0.11/0.02/0/0, dsn=4.3.0, status=deferred (host
Temporary internal error (in reply to end of DATA command))

POSTFIX the messenger of bad news, and the news is that the DOVECOT
server has a problem. Don't blame POSTFIX for the bad news.
Wietse

t***@mm.st

2011-10-04 16:38:50 UTC

Permalink

Hello Duane,

Post by Duane Hill
You should look here: http://wiki2.dovecot.org/HowTo/PostfixDovecotLMTP

Thank you for the link. I think I already have tried to follow it to set
up these servers.

May be I have missed then something in Dovecot since I am told I am
wrongly 'blame' Postfix.

I will go there and try again.

TJ

Helder Oliveira

2011-10-04 16:45:01 UTC

Permalink

Post by t***@mm.st
Hello Duane,

Post by Duane Hill
You should look here: http://wiki2.dovecot.org/HowTo/PostfixDovecotLMTP

Thank you for the link. I think I already have tried to follow it to set
up these servers.
May be I have missed then something in Dovecot since I am told I am
wrongly 'blame' Postfix.
I will go there and try again.
TJ

Shooting the messenger is very common, learn and let it go

t***@mm.st

2011-10-04 16:48:51 UTC

Permalink

This post might be inappropriate. Click to display it.

Helder Oliveira

2011-10-04 16:53:33 UTC

Permalink

Post by t***@mm.st
On Tuesday, October 04, 2011 5:45 PM, "Helder Oliveira"

Post by Helder Oliveira
Shooting the messenger is very common, learn and let it go

I do not understand why you accuse of shooting anything. I have not
made any blame. There is wrong reaction to my just asking a first
question.
I see now what many people say of this community that it is so hard on
the newest users.

You are over reacting… no one is being rude with you or making you a hard time… let it go and solve you problem, that's the most important atm

t***@mm.st

2011-10-04 16:59:13 UTC

Permalink

This post might be inappropriate. Click to display it.

s***@gmail.com

2015-08-04 17:27:47 UTC

Permalink

I'm having the same problem, anyone figure anything out on this? This thread is 4 years old =/

l***@gmail.com

2019-11-14 21:14:27 UTC

Permalink

Hey there
I was dealing with the same thing.
domain: domain.com
RCPT:reciever
FROM : sender

my logs from:/var/log/mail.log

Nov 14 20:48:33 lucideus postfix/qmgr[18907]: 9C409C0CE1: from=<***@domain.com>, size=370, nrcpt=1 (queue active)
Nov 14 20:48:33 lucideus postfix/lmtp[28367]: 9C409C0CE1: to=<***@domain.com>, relay=domain.com[private/dovecot-lmtp], delay=0.14, delays=0.08/0.01/0.01/0.03, dsn=4.3.0, status=deferred (host domain.com[private/dovecot-lmtp] said: 451 4.3.0 <***@domain.com> Temporary internal error (in reply to end of DATA command))
Nov 14 20:49:14 lucideus postfix/scache[28297]: statistics: start interval Nov 14 20:45:54
Nov 14 20:49:14 lucideus postfix/scache[28297]: statistics: domain lookup hits=0 miss=3 success=0%
Nov 14 20:49:14 lucideus postfix/scache[28297]: statistics: max simultaneous domains=0 addresses=1 connection=3
Nov 14 20:49:45 lucideus postfix/pickup[27359]: 993DCC0CEA: uid=0 from=<***@domain.com>
Nov 14 20:49:45 lucideus opendmarc[11005]: ignoring connection from localhost
Nov 14 20:49:45 lucideus postfix/cleanup[28365]: 993DCC0CEA: message-id=<***@domain.com>
Nov 14 20:49:45 lucideus opendkim[11024]: 993DCC0CEA: DKIM-Signature field added (s=mail, d=domain.com)
Nov 14 20:49:45 lucideus postfix/qmgr[18907]: 993DCC0CEA: from=<***@domain.com>, size=370, nrcpt=1 (queue active)
Nov 14 20:49:45 lucideus postfix/lmtp[28367]: 993DCC0CEA: to=<***@domain.com>, relay=domain.com[private/dovecot-lmtp], delay=0.12, delays=0.07/0/0.02/0.03, dsn=4.3.0, status=deferred (host domain.com[private/dovecot-lmtp] said: 451 4.3.0 <***@domain.com> Temporary internal error (in reply to end of DATA command))

#
# my logs from: /var/log/dovecot.log
#
Nov 14 20:48:33 lmtp(28368, ***@domain.com): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscr
iptions=yes location=mbox:~/:INBOX=/var/mail/vhosts/domain.com/reciever
Nov 14 20:48:33 lmtp(28368, ***@domain.com): Debug: fs: root=/var/mail/vhosts/domain.com/reciever, index=, indexpvt=, control=, inbox=/var
/mail/vhosts/domain.com/reciever, alt=
Nov 14 20:48:33 lmtp(28368, ***@domain.com): Error: User initialization failed: Namespace '': mbox: mbox root directory can't be a file:
/var/mail/vhosts/domain.com/reciever (http://wiki2.dovecot.org/MailLocation/Mbox)
Nov 14 20:48:33 lmtp(28368): Info: Disconnect from local: Successful quit
Nov 14 20:49:41 master: Warning: Killed with signal 15 (by pid=28402 uid=0 code=kill)
Nov 14 20:49:41 master: Info: Dovecot v2.2.33.2 (d6601f4ec) starting up for imap, pop3, lmtp (core dumps disabled)
#
# my patch
#
Tried several things, but this did the job

rm /mail/vhosts/domain.com/reciever
#
# remove this file so that it can make dir
#
hope this helps, It's one of the generic cases for temporary internal error
other case may be like not enough permissions to create directory or file.