marco at carcano.ch
2013-Feb-20 12:25 UTC
[Dovecot] Dovecot LDA LDAP lookups on samba4 server ends very often in timeouts
I hope that someone will be so kind to help me into solving this really
strange thing (don't know if it is a bug or not)
I have a samba4 server and want to use postfix+dovecot - dovecot
version is 2.0.11
as for the postfix side everything is OK (all the LDAP lookups works
without any error, tested also manually with postmap -q)
the real pain is with dovecot deliver:
it seems that sometimes lda tries to lookup to the LDPA (samba 4)
server, got a reply, an then report(after 2 minutes) a lookup timeout
error
the really strange thing is that (very seldom) lda works, but most of
the times I got the timeout error.
The strange thing is that if I use ldapsearch I never got timeout
neither late replies, and even postfix performs its lookups without any
issue
it seems something related to lda itself (I do not know if I have a
wrong configuration, but I think this is not a configuration issue,
otherwise it should not work at all)
here are the information logged when it does not work - after this log
you will find the one when I got the failure (if needed I can provide a
.pcap file too)
(trailing and leading spaces of AT charcater has been added by me)
############################## FAULTY DELIVER LOG
#############################################
Feb 20 12:20:50 sng02 postfix/smtpd[8928]: connect from
localhost[127.0.0.1]
Feb 20 12:21:14 sng02 postfix/smtpd[8928]: A38D4407F5:
client=localhost[127.0.0.1]
Feb 20 12:21:20 sng02 postfix/cleanup[8891]: A38D4407F5: warning:
header Subject: prova from localhost[127.0.0.1]; from=<marco @
senderdomain.tld> to=<mac @ mydomain.com> proto=SMTP
helo=<senderdomain.tld>
Feb 20 12:21:20 sng02 postfix/cleanup[8891]: A38D4407F5:
message-id=<20130220112114.A38D4407F5 @ srv01.mydomain.local>
Feb 20 12:21:20 sng02 postfix/qmgr[8889]: A38D4407F5: from=<marco @
senderdomain.tld>, size=371, nrcpt=1 (queue active)
Feb 20 12:21:20 sng02 dovecot: lda: Debug: Loading modules from
directory: /usr/lib64/dovecot
Feb 20 12:21:20 sng02 dovecot: lda: Debug: Module loaded:
/usr/lib64/dovecot/lib10_quota_plugin.so
Feb 20 12:21:20 sng02 dovecot: lda: Debug: Module loaded:
/usr/lib64/dovecot/lib20_expire_plugin.so
Feb 20 12:21:20 sng02 dovecot: lda: Debug: Module loaded:
/usr/lib64/dovecot/lib90_sieve_plugin.so
Feb 20 12:21:20 sng02 dovecot: auth: Debug: Loading modules from
directory: /usr/lib64/dovecot/auth
Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libauthdb_ldap.so
Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libdriver_mysql.so
Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libdriver_pgsql.so
Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libdriver_sqlite.so
Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libmech_gssapi.so
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_bind
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_simple_bind
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_sasl_bind
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_initial_request
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_new_connection 1 1 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_open_connection
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_connect_to_host: TCP
localhost:389
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_new_socket: 16
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_prepare_socket: 16
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_connect_to_host:
Trying ::1 389
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_pvt_connect: fd: 16
tm: -1 async: 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_open_defconn:
successful
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 20 12:21:20 sng02 dovecot: auth: Debug: master in:
USER#0111#011marco.carcano#011service=lda
Feb 20 12:21:20 sng02 dovecot: auth: Debug: password(marco.carcano):
passdb doesn't support credential lookups
Feb 20 12:21:20 sng02 dovecot: auth: Error: static(marco.carcano):
passdb doesn't support lookups, can't verify user's existence
Feb 20 12:21:20 sng02 dovecot: auth: Debug: ldap(marco.carcano): user
search: base=DC=mydomain,DC=local scope=subtree
filter=(sAMAccountname=marco.carcano) fields=Mailbox,dovecotMailQuota
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60
msgid -1
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 msgid
-1 (timeout 0 usec)
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld
0x6cba60 msgid -1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Connections:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20
12:21:20 2013
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Outstanding
Requests:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 1, origid 1,
status InProgress
Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request count
1 (abandoned 0)
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response
Queue:
Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response
count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x6cba60 msgid -1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x6cba60 NULL
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
-1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
1 message type bind
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 0 new
referrals
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: mark request
completed, ld 0x6cba60 msgid 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: request done: ld 0x6cba60
msgid 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: res_errno: 0, res_error:
<>, res_matched: <>
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_free_request (origid
1, msgid 1)
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_parse_result
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_search
Feb 20 12:21:20 sng02 dovecot: auth: Error: put_filter:
"(sAMAccountname=marco.carcano)"
Feb 20 12:21:20 sng02 dovecot: auth: Error: put_filter: simple
Feb 20 12:21:20 sng02 dovecot: auth: Error: put_simple_filter:
"sAMAccountname=marco.carcano"
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_initial_request
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_msgfree
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60
msgid -1
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 msgid
-1 (timeout 0 usec)
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld
0x6cba60 msgid -1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Connections:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20
12:21:20 2013
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Outstanding
Requests:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request count
1 (abandoned 0)
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response
Queue:
Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response
count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x6cba60 msgid -1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x6cba60 NULL
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60
msgid -1
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 msgid
-1 (timeout 0 usec)
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld
0x6cba60 msgid -1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Connections:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20
12:21:20 2013
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Outstanding
Requests:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request count
1 (abandoned 0)
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response
Queue:
Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response
count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x6cba60 msgid -1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x6cba60 NULL
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
-1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
2 message type search-entry
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_first_attribute
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_get_values
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_next_attribute
Feb 20 12:21:20 sng02 dovecot: auth: Debug: ldap(marco.carcano):
result: dovecotMailQuota(quota_rule=%$)=*:storage=8192M
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_msgfree
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60
msgid -1
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 msgid
-1 (timeout 0 usec)
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld
0x6cba60 msgid -1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Connections:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20
12:21:20 2013
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Outstanding
Requests:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request count
1 (abandoned 0)
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response
Queue:
Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response
count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x6cba60 msgid -1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x6cba60 NULL
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
-1 all 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
2 message type search-reference
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chase_v3referrals
Feb 20 12:21:20 sng02 dovecot: auth: Error:
ldap_url_parse_ext(ldap://mydomain.local/CN=Configuration,DC=mydomain,DC=local)
Feb 20 12:21:20 sng02 dovecot: auth: Error: re_encode_request: new
msgid 3, new dn <CN=Configuration,DC=mydomain,DC=local>
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chase_v3referral:
msgid 2, url
"ldap://mydomain.local/CN=Configuration,DC=mydomain,DC=local"
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_new_connection 0 1 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_open_connection
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_connect_to_host: TCP
mydomain.local:389
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_new_socket: 18
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_prepare_socket: 18
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_connect_to_host:
Trying 192.168.32.2:389
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_pvt_connect: fd: 18
tm: -1 async: 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: anonymous rebind via
ldap_sasl_bind("")
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_sasl_bind
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_initial_request
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60
msgid 4
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 msgid
4 (timeout 100000 usec)
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld
0x6cba60 msgid 4 all 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Connections:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: mydomain.local
port: 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20
12:21:20 2013
Feb 20 12:21:20 sng02 dovecot: auth: Error: rebind in progress
Feb 20 12:21:20 sng02 dovecot: auth: Error: queue is empty
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 3 status:
Connected
Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20
12:21:20 2013
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Outstanding
Requests:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 4, origid 4,
status InProgress
Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals 1,
parent count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request count
2 (abandoned 0)
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response
Queue:
Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response
count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x6cba60 msgid 4 all 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x6cba60 NULL
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
4 all 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
2 message type search-result
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 0 new
referrals
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: mark request
completed, ld 0x6cba60 msgid 2
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 0 s
99952 us to go
Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld
0x6cba60 msgid 4 all 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Connections:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: mydomain.local
port: 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20
12:21:20 2013
Feb 20 12:21:20 sng02 dovecot: auth: Error: rebind in progress
Feb 20 12:21:20 sng02 dovecot: auth: Error: queue is empty
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20
12:21:20 2013
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error:
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Outstanding
Requests:
Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 4, origid 4,
status InProgress
Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status RequestCompleted
Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals 1,
parent count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request count
2 (abandoned 0)
Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response
Queue:
Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty
Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response
count 0
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x6cba60 msgid 4 all 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x6cba60 NULL
Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
4 all 1
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 msgid
4 message type bind
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 0 new
referrals
Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: mark request
completed, ld 0x6cba60 msgid 4
Feb 20 12:21:22 sng02 postfix/smtpd[8928]: disconnect from
localhost[127.0.0.1]
Feb 20 12:23:55 sng02 dovecot: lda: Error: userdb
lookup(marco.carcano): Request timed out
Feb 20 12:23:55 sng02 dovecot: lda: Fatal: Internal error occurred.
Refer to server log for more information.
Feb 20 12:23:56 sng02 postfix/pipe[8897]: A38D4407F5: to=<marco.carcano
@ mydomain.local>, orig_to=<mac @ mydomain.com>, relay=dovecot,
delay=171, delays=16/0.01/0/155, dsn=4.3.0, status=deferred (temporary
failure)
Feb 20 12:24:10 sng02 dovecot: master: Warning: Killed with signal 15
(by pid=8946 uid=0 code=kill)
Feb 20 12:24:10 sng02 dovecot: auth: ldap(marco.carcano): Shutting down
Feb 20 12:24:10 sng02 dovecot: auth: Debug: master out: FAIL#0111
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_unbind
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_request (origid
2, msgid 3)
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_request (origid
2, msgid 2)
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_connection 1 1
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_send_unbind
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_connection:
actually freed
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_connection 1 1
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_send_unbind
Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_connection:
actually freed
Feb 20 12:24:18 sng02 postfix/postfix-script[8962]: stopping the
Postfix mail system
Feb 20 12:24:18 sng02 postfix/master[8886]: terminating on signal 15
############################## END OF FAULTY DELIVER LOG
#############################################
I'll add the log of a succefully delivered message in another mail
(otherwise I exceed message size limit of the list)
marco at carcano.ch
2013-Feb-20 14:49 UTC
[Dovecot] Dovecot LDA LDAP lookups on samba4 server ends very often in timeouts
just to complete the informations of this thread, here is the log of a
mail delivered succesfully
(trailing and leading spaces of AT charcater has been added by me)
############################## MAIL SUCCEFFULLY DELIVERED LOG
#############################################
Feb 19 17:41:01 sng02 postfix/smtpd[4006]: connect from
localhost[127.0.0.1]
Feb 19 17:41:28 sng02 postfix/smtpd[4006]: 95659407F5:
client=localhost[127.0.0.1]
Feb 19 17:41:36 sng02 postfix/cleanup[4011]: 95659407F5: warning:
header Subject: prova from localhost[127.0.0.1]; from=<marco @
senderdomain.tld> to=<mac @ mydomain.com> proto=SMTP
helo=<senderdomain.tld>
Feb 19 17:41:36 sng02 postfix/cleanup[4011]: 95659407F5:
message-id=<20130219164128.95659407F5 @ srv01.mydomain.local>
Feb 19 17:41:36 sng02 postfix/qmgr[3992]: 95659407F5: from=<marco @
senderdomain.tld>, size=371, nrcpt=1 (queue active)
Feb 19 17:41:36 sng02 dovecot: lda: Debug: Loading modules from
directory: /usr/lib64/dovecot
Feb 19 17:41:36 sng02 dovecot: lda: Debug: Module loaded:
/usr/lib64/dovecot/lib10_quota_plugin.so
Feb 19 17:41:36 sng02 dovecot: lda: Debug: Module loaded:
/usr/lib64/dovecot/lib20_expire_plugin.so
Feb 19 17:41:36 sng02 dovecot: lda: Debug: Module loaded:
/usr/lib64/dovecot/lib90_sieve_plugin.so
Feb 19 17:41:36 sng02 dovecot: auth: Debug: master in:
USER#0111#011marco.carcano#011service=lda
Feb 19 17:41:36 sng02 dovecot: auth: Debug: password(marco.carcano):
passdb doesn't support credential lookups
Feb 19 17:41:36 sng02 dovecot: auth: Error: static(marco.carcano):
passdb doesn't support lookups, can't verify user's existence
Feb 19 17:41:36 sng02 dovecot: auth: Debug: ldap(marco.carcano): user
search: base=DC=mydomain,DC=local scope=subtree
filter=(sAMAccountname=marco.carcano) fields=Mailbox,dovecotMailQuota
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap(marco.carcano):
Connection appears to be hanging, reconnecting
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_unbind
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_free_request (origid
2, msgid 3)
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_free_request (origid
2, msgid 2)
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_free_connection 1 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_unbind
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_free_connection:
actually freed
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_free_connection 1 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_unbind
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_free_connection:
actually freed
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_create
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_bind
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_simple_bind
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_sasl_bind
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_initial_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_new_connection 1 1 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_int_open_connection
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_connect_to_host: TCP
localhost:389
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_new_socket: 16
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_prepare_socket: 16
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_connect_to_host:
Trying ::1 389
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_pvt_connect: fd: 16
tm: -1 async: 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_open_defconn:
successful
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_result ld 0x666a60
msgid -1
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg ld 0x666a60 msgid
-1 (timeout 0 usec)
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg continue ld
0x666a60 msgid -1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Connections:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 19 17:41:36 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 19 17:41:36 sng02 dovecot: auth: Error: last used: Tue Feb 19
17:41:36 2013
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Outstanding
Requests:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 1, origid 1,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 request count
1 (abandoned 0)
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Response
Queue:
Feb 19 17:41:36 sng02 dovecot: auth: Error: Empty
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 response
count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x666a60 msgid -1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x666a60 NULL
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_int_select
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 msgid
-1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 msgid
1 message type bind
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 0 new
referrals
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: mark request
completed, ld 0x666a60 msgid 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: request done: ld 0x666a60
msgid 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: res_errno: 0, res_error:
<>, res_matched: <>
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_free_request (origid
1, msgid 1)
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_parse_result
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_search
Feb 19 17:41:36 sng02 dovecot: auth: Error: put_filter:
"(sAMAccountname=marco.carcano)"
Feb 19 17:41:36 sng02 dovecot: auth: Error: put_filter: simple
Feb 19 17:41:36 sng02 dovecot: auth: Error: put_simple_filter:
"sAMAccountname=marco.carcano"
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_initial_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_search
Feb 19 17:41:36 sng02 dovecot: auth: Error: put_filter:
"(sAMAccountname=marco.carcano)"
Feb 19 17:41:36 sng02 dovecot: auth: Error: put_filter: simple
Feb 19 17:41:36 sng02 dovecot: auth: Error: put_simple_filter:
"sAMAccountname=marco.carcano"
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_initial_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_msgfree
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_result ld 0x666a60
msgid -1
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg ld 0x666a60 msgid
-1 (timeout 0 usec)
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg continue ld
0x666a60 msgid -1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Connections:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 19 17:41:36 sng02 dovecot: auth: Error: refcnt: 3 status:
Connected
Feb 19 17:41:36 sng02 dovecot: auth: Error: last used: Tue Feb 19
17:41:36 2013
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Outstanding
Requests:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 3, origid 3,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 request count
2 (abandoned 0)
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Response
Queue:
Feb 19 17:41:36 sng02 dovecot: auth: Error: Empty
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 response
count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x666a60 msgid -1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x666a60 NULL
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_int_select
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_result ld 0x666a60
msgid -1
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg ld 0x666a60 msgid
-1 (timeout 0 usec)
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg continue ld
0x666a60 msgid -1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Connections:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 19 17:41:36 sng02 dovecot: auth: Error: refcnt: 3 status:
Connected
Feb 19 17:41:36 sng02 dovecot: auth: Error: last used: Tue Feb 19
17:41:36 2013
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Outstanding
Requests:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 3, origid 3,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 request count
2 (abandoned 0)
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Response
Queue:
Feb 19 17:41:36 sng02 dovecot: auth: Error: Empty
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 response
count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x666a60 msgid -1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x666a60 NULL
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_int_select
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 msgid
-1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 msgid
2 message type search-entry
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_msgfree
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_result ld 0x666a60
msgid -1
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg ld 0x666a60 msgid
-1 (timeout 0 usec)
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg continue ld
0x666a60 msgid -1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Connections:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 19 17:41:36 sng02 dovecot: auth: Error: refcnt: 3 status:
Connected
Feb 19 17:41:36 sng02 dovecot: auth: Error: last used: Tue Feb 19
17:41:36 2013
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Outstanding
Requests:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 3, origid 3,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 request count
2 (abandoned 0)
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Response
Queue:
Feb 19 17:41:36 sng02 dovecot: auth: Error: Empty
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 response
count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x666a60 msgid -1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x666a60 NULL
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_int_select
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 msgid
-1 all 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 msgid
2 message type search-reference
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chase_v3referrals
Feb 19 17:41:36 sng02 dovecot: auth: Error:
ldap_url_parse_ext(ldap://mydomain.local/CN=Configuration,DC=mydomain,DC=local)
Feb 19 17:41:36 sng02 dovecot: auth: Error: re_encode_request: new
msgid 4, new dn <CN=Configuration,DC=mydomain,DC=local>
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chase_v3referral:
msgid 2, url
"ldap://mydomain.local/CN=Configuration,DC=mydomain,DC=local"
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_new_connection 0 1 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_int_open_connection
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_connect_to_host: TCP
mydomain.local:389
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_new_socket: 18
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_prepare_socket: 18
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_connect_to_host:
Trying 192.168.32.2:389
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_pvt_connect: fd: 18
tm: -1 async: 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: anonymous rebind via
ldap_sasl_bind("")
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_sasl_bind
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_initial_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_send_server_request
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_result ld 0x666a60
msgid 5
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg ld 0x666a60 msgid
5 (timeout 100000 usec)
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg continue ld
0x666a60 msgid 5 all 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Connections:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * host: mydomain.local
port: 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 19 17:41:36 sng02 dovecot: auth: Error: last used: Tue Feb 19
17:41:36 2013
Feb 19 17:41:36 sng02 dovecot: auth: Error: rebind in progress
Feb 19 17:41:36 sng02 dovecot: auth: Error: queue is empty
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 19 17:41:36 sng02 dovecot: auth: Error: refcnt: 4 status:
Connected
Feb 19 17:41:36 sng02 dovecot: auth: Error: last used: Tue Feb 19
17:41:36 2013
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Outstanding
Requests:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 5, origid 5,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 3, origid 3,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 0,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: * msgid 2, origid 2,
status InProgress
Feb 19 17:41:36 sng02 dovecot: auth: Error: outstanding referrals 1,
parent count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 request count
3 (abandoned 0)
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Response
Queue:
Feb 19 17:41:36 sng02 dovecot: auth: Error: Empty
Feb 19 17:41:36 sng02 dovecot: auth: Error: ld 0x666a60 response
count 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList ld
0x666a60 msgid 5 all 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_chkResponseList
returns ld 0x666a60 NULL
Feb 19 17:41:36 sng02 dovecot: auth: Error: ldap_int_select
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 msgid
5 all 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 msgid
2 message type search-result
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: ld 0x666a60 0 new
referrals
Feb 19 17:41:36 sng02 dovecot: auth: Error: read1msg: mark request
completed, ld 0x666a60 msgid 2
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg ld 0x666a60 0 s
99954 us to go
Feb 19 17:41:36 sng02 dovecot: auth: Error: wait4msg continue ld
0x666a60 msgid 5 all 1
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Connections:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * host: mydomain.local
port: 0
Feb 19 17:41:36 sng02 dovecot: auth: Error: refcnt: 2 status:
Connected
Feb 19 17:41:36 sng02 dovecot: auth: Error: last used: Tue Feb 19
17:41:36 2013
Feb 19 17:41:36 sng02 dovecot: auth: Error: rebind in progress
Feb 19 17:41:36 sng02 dovecot: auth: Error: queue is empty
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error: * host: localhost port:
389 (default)
Feb 19 17:41:36 sng02 dovecot: auth: Error: refcnt: 3 status:
Connected
Feb 19 17:41:36 sng02 dovecot: auth: Error: last used: Tue Feb 19
17:41:36 2013
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error:
Feb 19 17:41:36 sng02 dovecot: auth: Error: ** ld 0x666a60 Outstanding
Requests:
Feb 19 17:41:36 sng02 dovecot: lda: Debug: auth input: marco.carcano
quota_rule=*:storage=8192M
Feb 19 17:41:36 sng02 dovecot: lda: Debug: Added userdb setting:
plugin/quota_rule=*:storage=8192M
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Effective
uid=8, gid=12, homeFeb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug:
Quota root:
name=User quota backend=maildir argsFeb 19 17:41:36 sng02 dovecot:
lda(marco.carcano): Debug: Quota rule:
root=User quota mailbox=* bytes=8589934592 messages=0
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota rule:
root=User quota mailbox=Trash bytes=+104857600 messages=0
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota
warning: bytes=8160437862 (95%) messages=0 reverse=no
command=quota-warning 95 marco.carcano
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota
warning: bytes=7301444403 (85%) messages=0 reverse=no
command=quota-warning 85 marco.carcano
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota
warning: bytes=6442450944 (75%) messages=0 reverse=no
command=quota-warning 75 marco.carcano
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota root:
name=Shared quota backend=maildir args=ns=Public/
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota rule:
root=Shared quota mailbox=* bytes=20971520000 messages=0
Feb 19 17:41:36 sng02 dovecot: lda: Error: user marco.carcano: Auth
USER lookup failed
Feb 19 17:41:36 sng02 dovecot: lda: Debug: auth input:
Feb 19 17:41:36 sng02 dovecot: lda: Fatal: Internal error occurred.
Refer to server log for more information.
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Namespace :
type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes,
subscriptions=yes
location=maildir:/home/mailboxstore/marco.carcano/Maildir
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: maildir++:
root=/home/mailboxstore/marco.carcano/Maildir, index=, control=,
inbox=/home/mailboxstore/marco.carcano/Maildir
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Namespace :
type=shared, prefix=shared/%u/, sep=/, inbox=no, hidden=no,
list=children, subscriptions=no
location=maildir:/home/mailboxstore/%Lu/Maildir:INDEX=/home/mailboxstore/marco.carcano/Maildir/shared/%Lu
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: shared:
root=/var/run/dovecot, index=, control=, inboxFeb 19 17:41:36 sng02 dovecot:
lda(marco.carcano): Debug: Namespace :
type=public, prefix=Public/, sep=/, inbox=no, hidden=no, list=yes,
subscriptions=no location=maildir:/home/mailboxstore/public
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: maildir++:
root=/home/mailboxstore/public, index=, control=, inboxFeb 19 17:41:36 sng02
dovecot: lda(marco.carcano): Debug: expire: No
expire setting - plugin disabled
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota root:
name=User quota backend=maildir argsFeb 19 17:41:36 sng02 dovecot:
lda(marco.carcano): Debug: Quota rule:
root=User quota mailbox=* bytes=1073741824 messages=0
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota rule:
root=User quota mailbox=Trash bytes=+104857600 messages=0
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota
warning: bytes=1020054732 (95%) messages=0 reverse=no
command=quota-warning 95 marco.carcano
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota
warning: bytes=912680550 (85%) messages=0 reverse=no
command=quota-warning 85 marco.carcano
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota
warning: bytes=805306368 (75%) messages=0 reverse=no
command=quota-warning 75 marco.carcano
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota root:
name=Shared quota backend=maildir args=ns=Public/
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: Quota rule:
root=Shared quota mailbox=* bytes=20971520000 messages=0
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: none: root=,
index=, control=, inboxFeb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Error:
User
marco.carcano doesn't have home dir set, disabling duplicate database
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: sieve: user's
script path /home/mailboxstore/marco.carcano/.dovecot.sieve doesn't
exist (using global script path in stead)
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: sieve: user
has no valid personal script
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano): Debug: sieve: no
scripts to execute: reverting to default delivery.
Feb 19 17:41:36 sng02 postfix/pipe[3995]: 7D9AE407E7: to=<marco.carcano
@ mydomain.local>, orig_to=<mac @ mydomain.com>, relay=dovecot,
delay=17102, delays=17034/0.05/0/68, dsn=4.3.0, status=deferred
(temporary failure)
Feb 19 17:41:36 sng02 dovecot: lda(marco.carcano):
msgid=<20130219164128.95659407F5 @ srv01.mydomain.local>: saved mail to
INBOX
Feb 19 17:41:36 sng02 postfix/pipe[4013]: 95659407F5: to=<marco.carcano
@ mydomain.local>, orig_to=<mac @ mydomain.com>, relay=dovecot,
delay=22, delays=22/0.02/0/0.14, dsn=2.0.0, status=sent (delivered via
dovecot service)
Feb 19 17:41:36 sng02 postfix/qmgr[3992]: 95659407F5: removed
Feb 19 17:41:38 sng02 postfix/smtpd[4006]: disconnect from
localhost[127.0.0.1]
############################## END OF MAIL SUCCEFFULLY DELIVERED LOG
#############################################
Christian Wiese
2013-Feb-20 14:52 UTC
[Dovecot] Dovecot LDA LDAP lookups on samba4 server ends very often in timeouts
Hi Marco, try to check if LDAP REFERRALS are enabled. I had a similar issue some time ago when trying to authenticate against an AD, which didn't worked (long timeouts) as long as I switched off REFERRALS in the systems ldap.conf. (more info you might get by 'man ldap.conf') Cheers, Chris Am Wed, 20 Feb 2013 13:25:39 +0100 schrieb marco at carcano.ch:> > I hope that someone will be so kind to help me into solving this > really strange thing (don't know if it is a bug or not) > > I have a samba4 server and want to use postfix+dovecot - dovecot > version is 2.0.11 > > as for the postfix side everything is OK (all the LDAP lookups works > without any error, tested also manually with postmap -q) > the real pain is with dovecot deliver: > > it seems that sometimes lda tries to lookup to the LDPA (samba 4) > server, got a reply, an then report(after 2 minutes) a lookup timeout > error > > the really strange thing is that (very seldom) lda works, but most of > the times I got the timeout error. > > The strange thing is that if I use ldapsearch I never got timeout > neither late replies, and even postfix performs its lookups without > any issue > it seems something related to lda itself (I do not know if I have a > wrong configuration, but I think this is not a configuration issue, > otherwise it should not work at all) > > here are the information logged when it does not work - after this > log you will find the one when I got the failure (if needed I can > provide a .pcap file too) > > (trailing and leading spaces of AT charcater has been added by me) > > ############################## FAULTY DELIVER LOG > ############################################# > > Feb 20 12:20:50 sng02 postfix/smtpd[8928]: connect from > localhost[127.0.0.1] > Feb 20 12:21:14 sng02 postfix/smtpd[8928]: A38D4407F5: > client=localhost[127.0.0.1] > Feb 20 12:21:20 sng02 postfix/cleanup[8891]: A38D4407F5: warning: > header Subject: prova from localhost[127.0.0.1]; from=<marco @ > senderdomain.tld> to=<mac @ mydomain.com> proto=SMTP > helo=<senderdomain.tld> > Feb 20 12:21:20 sng02 postfix/cleanup[8891]: A38D4407F5: > message-id=<20130220112114.A38D4407F5 @ srv01.mydomain.local> > Feb 20 12:21:20 sng02 postfix/qmgr[8889]: A38D4407F5: from=<marco @ > senderdomain.tld>, size=371, nrcpt=1 (queue active) > Feb 20 12:21:20 sng02 dovecot: lda: Debug: Loading modules from > directory: /usr/lib64/dovecot > Feb 20 12:21:20 sng02 dovecot: lda: Debug: Module loaded: > /usr/lib64/dovecot/lib10_quota_plugin.so > Feb 20 12:21:20 sng02 dovecot: lda: Debug: Module loaded: > /usr/lib64/dovecot/lib20_expire_plugin.so > Feb 20 12:21:20 sng02 dovecot: lda: Debug: Module loaded: > /usr/lib64/dovecot/lib90_sieve_plugin.so > Feb 20 12:21:20 sng02 dovecot: auth: Debug: Loading modules from > directory: /usr/lib64/dovecot/auth > Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded: > /usr/lib64/dovecot/auth/libauthdb_ldap.so > Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded: > /usr/lib64/dovecot/auth/libdriver_mysql.so > Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded: > /usr/lib64/dovecot/auth/libdriver_pgsql.so > Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded: > /usr/lib64/dovecot/auth/libdriver_sqlite.so > Feb 20 12:21:20 sng02 dovecot: auth: Debug: Module loaded: > /usr/lib64/dovecot/auth/libmech_gssapi.so > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_bind > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_simple_bind > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_sasl_bind > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_initial_request > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_new_connection 1 1 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_open_connection > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_connect_to_host: TCP > localhost:389 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_new_socket: 16 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_prepare_socket: 16 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_connect_to_host: > Trying ::1 389 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_pvt_connect: fd: 16 > tm: -1 async: 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_open_defconn: > successful > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_server_request > Feb 20 12:21:20 sng02 dovecot: auth: Debug: master in: > USER#0111#011marco.carcano#011service=lda > Feb 20 12:21:20 sng02 dovecot: auth: Debug: password(marco.carcano): > passdb doesn't support credential lookups > Feb 20 12:21:20 sng02 dovecot: auth: Error: static(marco.carcano): > passdb doesn't support lookups, can't verify user's existence > Feb 20 12:21:20 sng02 dovecot: auth: Debug: ldap(marco.carcano): user > search: base=DC=mydomain,DC=local scope=subtree > filter=(sAMAccountname=marco.carcano) fields=Mailbox,dovecotMailQuota > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60 > msgid -1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 > msgid -1 (timeout 0 usec) > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld > 0x6cba60 msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Connections: Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: > localhost port: 389 (default) > Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status: > Connected > Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20 > 12:21:20 2013 > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Outstanding Requests: > Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 1, origid 1, > status InProgress > Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals > 0, parent count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request > count 1 (abandoned 0) > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response > Queue: > Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response > count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld > 0x6cba60 msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList > returns ld 0x6cba60 NULL > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid 1 message type bind > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 0 > new referrals > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: mark request > completed, ld 0x6cba60 msgid 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: request done: ld 0x6cba60 > msgid 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: res_errno: 0, res_error: > <>, res_matched: <> > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_free_request (origid > 1, msgid 1) > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_parse_result > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_search > Feb 20 12:21:20 sng02 dovecot: auth: Error: put_filter: > "(sAMAccountname=marco.carcano)" > Feb 20 12:21:20 sng02 dovecot: auth: Error: put_filter: simple > Feb 20 12:21:20 sng02 dovecot: auth: Error: put_simple_filter: > "sAMAccountname=marco.carcano" > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_initial_request > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_server_request > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_msgfree > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60 > msgid -1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 > msgid -1 (timeout 0 usec) > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld > 0x6cba60 msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Connections: Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: > localhost port: 389 (default) > Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status: > Connected > Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20 > 12:21:20 2013 > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Outstanding Requests: > Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2, > status InProgress > Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals > 0, parent count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request > count 1 (abandoned 0) > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response > Queue: > Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response > count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld > 0x6cba60 msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList > returns ld 0x6cba60 NULL > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60 > msgid -1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 > msgid -1 (timeout 0 usec) > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld > 0x6cba60 msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Connections: Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: > localhost port: 389 (default) > Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status: > Connected > Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20 > 12:21:20 2013 > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Outstanding Requests: > Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2, > status InProgress > Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals > 0, parent count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request > count 1 (abandoned 0) > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response > Queue: > Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response > count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld > 0x6cba60 msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList > returns ld 0x6cba60 NULL > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid 2 message type search-entry > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_first_attribute > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_get_values > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_next_attribute > Feb 20 12:21:20 sng02 dovecot: auth: Debug: ldap(marco.carcano): > result: dovecotMailQuota(quota_rule=%$)=*:storage=8192M > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_msgfree > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60 > msgid -1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 > msgid -1 (timeout 0 usec) > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld > 0x6cba60 msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Connections: Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: > localhost port: 389 (default) > Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status: > Connected > Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20 > 12:21:20 2013 > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Outstanding Requests: > Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2, > status InProgress > Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals > 0, parent count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request > count 1 (abandoned 0) > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response > Queue: > Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response > count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld > 0x6cba60 msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList > returns ld 0x6cba60 NULL > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid -1 all 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid 2 message type search-reference > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chase_v3referrals > Feb 20 12:21:20 sng02 dovecot: auth: Error: > ldap_url_parse_ext(ldap://mydomain.local/CN=Configuration,DC=mydomain,DC=local) > Feb 20 12:21:20 sng02 dovecot: auth: Error: re_encode_request: new > msgid 3, new dn <CN=Configuration,DC=mydomain,DC=local> > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chase_v3referral: > msgid 2, url > "ldap://mydomain.local/CN=Configuration,DC=mydomain,DC=local" > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_server_request > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_new_connection 0 1 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_open_connection > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_connect_to_host: TCP > mydomain.local:389 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_new_socket: 18 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_prepare_socket: 18 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_connect_to_host: > Trying 192.168.32.2:389 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_pvt_connect: fd: 18 > tm: -1 async: 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: anonymous rebind via > ldap_sasl_bind("") > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_sasl_bind > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_initial_request > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_send_server_request > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_result ld 0x6cba60 > msgid 4 > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 > msgid 4 (timeout 100000 usec) > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld > 0x6cba60 msgid 4 all 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Connections: Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: > mydomain.local port: 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status: > Connected > Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20 > 12:21:20 2013 > Feb 20 12:21:20 sng02 dovecot: auth: Error: rebind in progress > Feb 20 12:21:20 sng02 dovecot: auth: Error: queue is empty > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: localhost port: > 389 (default) > Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 3 status: > Connected > Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20 > 12:21:20 2013 > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Outstanding Requests: > Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 4, origid 4, > status InProgress > Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals > 0, parent count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2, > status InProgress > Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals > 1, parent count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request > count 2 (abandoned 0) > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response > Queue: > Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response > count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld > 0x6cba60 msgid 4 all 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList > returns ld 0x6cba60 NULL > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid 4 all 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid 2 message type search-result > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 0 > new referrals > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: mark request > completed, ld 0x6cba60 msgid 2 > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg ld 0x6cba60 0 s > 99952 us to go > Feb 20 12:21:20 sng02 dovecot: auth: Error: wait4msg continue ld > 0x6cba60 msgid 4 all 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Connections: Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: > mydomain.local port: 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status: > Connected > Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20 > 12:21:20 2013 > Feb 20 12:21:20 sng02 dovecot: auth: Error: rebind in progress > Feb 20 12:21:20 sng02 dovecot: auth: Error: queue is empty > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: * host: localhost port: > 389 (default) > Feb 20 12:21:20 sng02 dovecot: auth: Error: refcnt: 2 status: > Connected > Feb 20 12:21:20 sng02 dovecot: auth: Error: last used: Wed Feb 20 > 12:21:20 2013 > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 > Outstanding Requests: > Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 4, origid 4, > status InProgress > Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals > 0, parent count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: * msgid 2, origid 2, > status RequestCompleted > Feb 20 12:21:20 sng02 dovecot: auth: Error: outstanding referrals > 1, parent count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 request > count 2 (abandoned 0) > Feb 20 12:21:20 sng02 dovecot: auth: Error: ** ld 0x6cba60 Response > Queue: > Feb 20 12:21:20 sng02 dovecot: auth: Error: Empty > Feb 20 12:21:20 sng02 dovecot: auth: Error: ld 0x6cba60 response > count 0 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList ld > 0x6cba60 msgid 4 all 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_chkResponseList > returns ld 0x6cba60 NULL > Feb 20 12:21:20 sng02 dovecot: auth: Error: ldap_int_select > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid 4 all 1 > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 > msgid 4 message type bind > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: ld 0x6cba60 0 > new referrals > Feb 20 12:21:20 sng02 dovecot: auth: Error: read1msg: mark request > completed, ld 0x6cba60 msgid 4 > Feb 20 12:21:22 sng02 postfix/smtpd[8928]: disconnect from > localhost[127.0.0.1] > Feb 20 12:23:55 sng02 dovecot: lda: Error: userdb > lookup(marco.carcano): Request timed out > Feb 20 12:23:55 sng02 dovecot: lda: Fatal: Internal error occurred. > Refer to server log for more information. > Feb 20 12:23:56 sng02 postfix/pipe[8897]: A38D4407F5: > to=<marco.carcano @ mydomain.local>, orig_to=<mac @ mydomain.com>, > relay=dovecot, delay=171, delays=16/0.01/0/155, dsn=4.3.0, > status=deferred (temporary failure) > Feb 20 12:24:10 sng02 dovecot: master: Warning: Killed with signal 15 > (by pid=8946 uid=0 code=kill) > Feb 20 12:24:10 sng02 dovecot: auth: ldap(marco.carcano): Shutting > down Feb 20 12:24:10 sng02 dovecot: auth: Debug: master out: FAIL#0111 > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_unbind > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_request (origid > 2, msgid 3) > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_request (origid > 2, msgid 2) > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_connection 1 1 > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_send_unbind > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_connection: > actually freed > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_connection 1 1 > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_send_unbind > Feb 20 12:24:10 sng02 dovecot: auth: Error: ldap_free_connection: > actually freed > Feb 20 12:24:18 sng02 postfix/postfix-script[8962]: stopping the > Postfix mail system > Feb 20 12:24:18 sng02 postfix/master[8886]: terminating on signal 15 > > ############################## END OF FAULTY DELIVER LOG > ############################################# > > I'll add the log of a succefully delivered message in another mail > (otherwise I exceed message size limit of the list) > >-- Kind regards, Mit freundlichen Gr??en, Christian Wiese Follow us on Facebook: <http://www.facebook.com/pages/Securepoint-GmbH/132451210137395> Follow us on Twitter: <http://twitter.com/SecurepointStat> --------------------------------------------------------------------- Securepoint GmbH Christian Wiese Salzstr. 1 D-21335 Lueneburg http://www.securepoint.de Tele: ++49 4131 2401-0 Fax: ++49 4131 2401-50 Lueneburg HRB 1776 --------------------------------------------------------------------- CONFIDENTIALITY : This e-mail and any attachments are confidential and may be privileged. If you are not a named recipient, please notify the sender immediately and do not disclose the contents to another person, use it for any purpose or store or copy the information in any medium. GEHEIMHALTUNGSPFLICHT : Dieses E-Mail und alle damit verbundenen Anlagen sind vertraulich und d?rfen nur bestimmten Personen zug?nglich gemacht werden. Sofern Sie nicht zu den angegebenen Empf?ngern geh?ren, benachrichtigen Sie bitte unverz?glich den Absender. Der Inhalt darf weder an Dritte weitergegeben noch zu anderen Zwecken verwendet werden. Die Informationen d?rfen auch nicht auf einem Datentr?ger gespeichert oder auf einen Datentr?ger kopiert werden.