dovecot - Mar 2007 - "ldap_result() failed: Can't contact LDAP server" log messages

Greetings -

I', continuing to build a test system that, at present, only I have  
access to.  It is running Dovecot 1.0rc24.  Here's the output of a  
"dovecot-n"...

# /usr/local/etc/dovecot.conf
log_path: /logfiles/mail/live/dovecot
protocols: imap
ssl_cert_file: /usr/local/etc/ssl/certs/imapservice-bundle.crt
ssl_key_file: /usr/local/etc/ssl/private/imapservice-private.key
disable_plaintext_auth: no
login_dir: /var/run/dovecot/login
login_executable: /usr/local/libexec/dovecot/imap-login
login_process_per_connection: no
login_greeting_capability: yes
mail_location: maildir:/mailstore/%1u/%u/Maildir:INDEX=/var/dovecot/ 
index/%1u/%u:CONTROL=/var/dovecot/control/%1u/%u
mail_debug: yes
mmap_disable: yes
maildir_copy_with_hardlinks: yes
mail_log_prefix: %Us(%u)[%p]:
imap_client_workarounds: delay-newmail outlook-idle
namespace:
   type: private
   separator: /
   inbox: yes
auth default:
   mechanisms: plain login
   cache_size: 1024
   cache_ttl: 600
   username_chars:  
abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890
   username_format: %Lu
   passdb:
     driver: ldap
     args: /usr/local/etc/dovecot-ldap-passdb.conf
   userdb:
     driver: ldap
     args: /usr/local/etc/dovecot-ldap-userdb.conf

We are using LDAP for the passdb and userdb.

The oddity is that even on a quiescent system (Dovecot started from  
scratch, but no connections being made to it) we are seeing these  
messages being logged, apparently every 5 minutes:

dovecot: Mar 09 11:09:44 Error: auth(default): LDAP: ldap_result()  
failed: Can't contact LDAP server
dovecot: Mar 09 11:09:44 Error: auth(default): LDAP: ldap_result()  
failed: Can't contact LDAP server
dovecot: Mar 09 11:14:45 Error: auth(default): LDAP: ldap_result()  
failed: Can't contact LDAP server
dovecot: Mar 09 11:14:45 Error: auth(default): LDAP: ldap_result()  
failed: Can't contact LDAP server
dovecot: Mar 09 11:19:45 Error: auth(default): LDAP: ldap_result()  
failed: Can't contact LDAP server
dovecot: Mar 09 11:19:45 Error: auth(default): LDAP: ldap_result()  
failed: Can't contact LDAP server

I'm guessing there are two log entries each time because of separate  
connections being used for the passdb and userdb.

The LDAP server *is* available throughout.

I'm wondering if Dovecot is trying to hold the connection open but,  
after a timeout of 5 minutes of inactivity, the LDAP server is  
closing it and causing Dovecot to log this message.

If this is indeed the case then I guess on a production server these  
message will be rarely if ever seen.

Obviously I'd prefer not to have such worrying-sounding log entries  
appearing.  (And if my guess is right then they're slightly  
misleading: the LDAP server *can* be contacted!)

Any thoughts?

Cheers,
Mike B-)

-- 
The Computing Service, University of York, Heslington, York Yo10 5DD, UK
Tel:+44-1904-433811  FAX:+44-1904-433740

* Unsolicited commercial e-mail is NOT welcome at this e-mail address. *

On Fri, 2007-03-09 at 11:57 +0000, Mike Brudenell wrote:
>    passdb:
>      driver: ldap
>      args: /usr/local/etc/dovecot-ldap-passdb.conf
>    userdb:
>      driver: ldap
>      args: /usr/local/etc/dovecot-ldap-userdb.conf
Is there a reason why these config files are separate? That causes it to
create two LDAP connections. If you used the same config file it would
create only one LDAP connection.
> The oddity is that even on a quiescent system (Dovecot started from  
> scratch, but no connections being made to it) we are seeing these  
> messages being logged, apparently every 5 minutes:
> 
> dovecot: Mar 09 11:09:44 Error: auth(default): LDAP: ldap_result()  
> failed: Can't contact LDAP server
..
> I'm wondering if Dovecot is trying to hold the connection open but,  
> after a timeout of 5 minutes of inactivity, the LDAP server is  
> closing it and causing Dovecot to log this message.
I guess it's that. But I think it's invisible to users? Dovecot should
reconnect to the server and retry the request instead of giving some
"internal authentication failure".
> Obviously I'd prefer not to have such worrying-sounding log entries  
> appearing.  (And if my guess is right then they're slightly  
> misleading: the LDAP server *can* be contacted!)
That's the error that LDAP library gives. I'm not sure if it would be a
good idea to just hide the error. Of course one possibility would be
that Dovecot itself disconnects the LDAP connection after a configured
amount of idle time.

Maybe you could also configure the LDAP server to not disconnect
Dovecot's connection?
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20070309/fdb7b610/attachment.bin>

Greetings -

On 9 Mar 2007, at 12:15, Timo Sirainen wrote:
> Is there a reason why these config files are separate? That causes  
> it to
> create two LDAP connections. If you used the same config file it would
> create only one LDAP connection.
Yes: you tell us to!  :-)  ...

1.  We are using "auth_bind = yes" to validate passwords, and

2.  Our LDAP server does not allow anonymous searches, so I am  
setting auth_bind_userdn to login with appropriate credentials.

The comment in dovecot-ldap.conf says this:

# If authentication binding is used, you can save one LDAP request  
per login
# if users' DN can be specified with a common template. The template  
can use
# the standard %variables (see user_filter). Note that you can't
# use any pass_attrs if you use this setting.
#
# If you use this setting, it's a good idea to use a different
# dovecot-ldap.conf for userdb (it can even be a symlink, just as  
long as the
# filename is different in userdb's args). That way one connection is  
used only
# for LDAP binds and another connection is used for user lookups.  
Otherwise
# the binding is changed to the default DN before each user lookup.

>> I'm wondering if Dovecot is trying to hold the connection open but,
>> after a timeout of 5 minutes of inactivity, the LDAP server is
>> closing it and causing Dovecot to log this message.
>
> I guess it's that. But I think it's invisible to users? Dovecot
should
> reconnect to the server and retry the request instead of giving some
> "internal authentication failure".
I've just spoken to our LDAP Guru who runs the servers and he tells  
me that the system is indeed set up to close the connection after it  
has been idle for 300 seconds (5 minutes).  :-)

I don't actually know at present: but so far I've not noticed any  
problems authenticating myself.  I'm guessing Dovecot finds the  
connection closed (logs the 'inappropriate' error message :-) and  
then reconnects?

> Maybe you could also configure the LDAP server to not disconnect
> Dovecot's connection?
Unfortunately I don't have control of the LDAP servers: that's  
another group's territory.  :-)


Cheers,
Mike B-)

-- 
The Computing Service, University of York, Heslington, York Yo10 5DD, UK
Tel:+44-1904-433811  FAX:+44-1904-433740

* Unsolicited commercial e-mail is NOT welcome at this e-mail address. *

Hi,

I'm also getting some of these;  exactly, I get one everytime I reconnect.
For
example, yesterday I closed my kmail and shutted down my PC:

Mar  8 18:49:02 imap-server dovecot: IMAP(myself): Disconnected: Logged out

And this morning I reconnect:

Mar  9 08:06:02 imap-server dovecot: auth(default): LDAP: ldap_result() 
failed: Can't contact LDAP server
Mar  9 08:06:02 imap-server dovecot: imap-login: Login: user=<myself>, 
method=PLAIN, rip=10.0.4.25, lip=10.0.2.30, TLS

El Viernes, 9 de Marzo de 2007 13:15, Timo Sirainen
escribi?:
> On Fri, 2007-03-09 at 11:57 +0000, Mike Brudenell wrote:
> >    passdb:
> >      driver: ldap
> >      args: /usr/local/etc/dovecot-ldap-passdb.conf
> >    userdb:
> >      driver: ldap
> >      args: /usr/local/etc/dovecot-ldap-userdb.conf
>
> Is there a reason why these config files are separate? That causes it to
> create two LDAP connections. If you used the same config file it would
> create only one LDAP connection.
I suppose he read this from the example dovecot-ldap.conf:

# If authentication binding is used, you can save one LDAP request per login
# if users' DN can be specified with a common template. The template can use
# the standard %variables (see user_filter). Note that you can't
# use any pass_attrs if you use this setting.
#
# If you use this setting, it's a good idea to use a different
# dovecot-ldap.conf for userdb (it can even be a symlink, just as long as the
# filename is different in userdb's args). That way one connection is used 
only
# for LDAP binds and another connection is used for user lookups. Otherwise
# the binding is changed to the default DN before each user lookup.

I think this is a bit misleading; in most cases, one single file and one 
single connection would be a better idea IMHO.


Aaaaaaaaaagur.
-- 
Joseba Torre. CIDIR Bizkaia.