906663 - Thunderbird's address book cannot connect to LDAP server but doesn't show any error message. Reports "No contacts"

Status: UNCONFIRMED

(MailNews Core :: LDAP Integration, defect)

Description

[Alain Knaff]

After attempting to set up my thunderbird to connect to our corporate LDAP server for address completion, it just doesn't work (addresses don't complete even though they exist), but thunderbird doesn't show any error messages either (such as "connection refused", "authentication failed", "bad base DN" or anything similar...)

Trying to doubleclick on the addressbook, and then doing Offline->DownloadNow just says "Replication failed" but without saying why.

Even Thunderbird's error console (Tools->ErrorConsole) stays empty.

If thunderbird doesn't succeed doing something it should say why. If the connection to the server fails, it should say why ("connection refused", "network timeout", ...), and if the server returned an error, it should just forward this error to the user ("authentication failed", ...), maybe prepending some suitable explanatory boilerplate if you think you have to...

Just letting the user guess (or have him use tcpdump) is not an option. Some corporate environments don't allow users to install or use tcpdump, or the connection might be SSL anyways. Not to mention that it isn't exactly "user friendly" to ask the user to use network tracing tools...

Comment 1

[Moreia]

I'm using 24.1.1 and experiencing the same frustration. 

I added my school LDAP credential. When I start typing a name ('d-a-v') all of Thunderbird freezes for 10 seconds, presumably while it tries to connect to the LDAP server. 

If I go to "Directory Server Properties > Offline > Download Now" I get "replication failed" but no explanation of what failed and there's no new information in the error log.

Comment 2

[WADA:World Anti-bad-Duping Agency]

First of all, please rule out problem like bug 391263(double booking of abook.mab file). Problem of that bug is generated by Tb, but add-on may generate similar double booking of abook.mab or abook-N.mab file.
If there is no double booking of *.mab file, see bug 402793 comment #28 and get LDAP log to see Tb's LDAP server access.
> Win example : SET NSPR_LOG_MODULES=timestamp,ldap:5
Log file is text file, so you can view and check log file content by yourself using Text Editor.

Comment 3

[Moreia]

Rulit it out with Comment 5
https://bugzilla.mozilla.org/show_bug.cgi?id=391263#c5 
(In reply to WADA from comment #5)
> > Sometimes the addresses defined in a personal catalog in the address book disappears.
> 
> Does "the address book" mean local address book? Or LDAP directory?
> What do you mean by "a personal catalog"? One called "List(Mailing List)" by
> Thunderbird? 
> 
> Following is questions when "local address book".
> What address books are defined?
> What files for address books exist in your pfofile?
> (1) Go Tools/Options/Advanced/General/Config Editor

Note: this is Edit/Preferences/Advanced/General/Config Editor on linux versions. 

I see 4 listed. ldap.mab, eds.mab, history.mab and abook.mab 

I'm actually not sure where eds.mab is coming from.

>     Put .filename in filter field
>     LDAP_2.servers.XXX.filename will appear where XXX is;
>       default, pab, history, <added_abook_name(may be part of name)>  
> (2) Check Thunderbird's profile directory
>     Is there any yyyy.mab file other than listed at step (1)?

I actually only see three .mab files: 

.thunderbird/md24zdij.default/abook.mab
.thunderbird/md24zdij.default/history.mab
.thunderbird/md24zdij.default/ldap.mab

So it seems like bug 391263(double booking of abook.mab file) isn't the issue, at least for me.

Comment 4

[Moreia]

And, I did this: 

   $ export NSPR_LOG_MODULES=ldap:5
   $ export NSPR_LOG_FIlE=/tmp/ldap.log
   $ printenv | grep LOG
   NSPR_LOG_FIlE=/tmp/ldap.log
   NSPR_LOG_MODULES=ldap:5

Nothing gets written to `/tmp/ldap.log` but I thought that might be becuase I needed to run Thunderbird from the command line so I tried that and when I try to add to the "to" field from an identity that uses the LDAP addressbook I see this: 

  -1465329856[7f99a7755370]: nsLDAPOperation::SimpleBind(): called; bindName = ''; 
  -1465329856[7f99a7755370]: nsLDAPSSLConnect(): standard connect() function returned -1 
  -1465329856[7f99a7755370]: unbinding
  -1465329856[7f99a7755370]: unbound

And I get the same behavior described -- Thunderbird freezes after a few letters, goes gray and then lets me keep typing but may freeze again. Each time it freezes that stack of errors writes to the terminal. But nothing ends up in ldap.log.

Comment 5

[Moreia]

Note: the logging is per https://wiki.mozilla.org/MailNews:Logging and https://bugzilla.mozilla.org/show_bug.cgi?id=402793#c28

Comment 6

[Moreia]

Doing some additional research based on the suspiciously empty "bindName" above, I copied the basename settings to bindname and it does now ask for my password, but then it still freezes up and doesn't find address on the LDAP server. 

Nothing is written to ldap.log.

Comment 7

[cordes.ben]

@Moreia, your problem is that you have a lower-case "L" in the environment variable NSPR_LOG_FI"l"E. Try again with NSPR_LOG_FILE and it should work.

Comment 8

[Moreia]

(In reply to cordes.ben from comment #7)
> @Moreia, your problem is that you have a lower-case "L" in the environment
> variable NSPR_LOG_FI"l"E. Try again with NSPR_LOG_FILE and it should work.

Thanks. Logging is now working, but ... nothing else has changed. The errors write to /tmp/ldap.log instead of the screen, but the error is the same:

-1446025408[7fcca8955370]: nsLDAPOperation::SimpleBind(): called; bindName = '[e-mail]'; 
-1446025408[7fcca8955370]: unbinding
-1446025408[7fcca8955370]: unbound

And Thunderbird continues to freeze when I type recipient addresses under the identity that is configured to use the LDAP server for addressing.

Comment 9

[Philip Chee]

Possibly related Bug 931482 - nsILDAPOperation.simpleBind should be async

Comment 10

[Q]

I don't even get nsLDAPOperation lines ( how do I enable these? )

After update, with Thunderbird 31.5.0,  LDAP feature stopped working entirely: yesterday it was asking me for an authentication password, and then sort of worked; now it just fails silently. I suppose bug #833971 ( https://bugzilla.mozilla.org/show_bug.cgi?id=833971 ) has been fixed too well.

So I set
NSPR_LOG_MODULES="ldap:5,timestamp"

, and then after an attempt to get an offline copy of an address book I get no password prompt with "Replication failed" in the GUI and these two lines in the log:
===
2015-03-08 06:47:59.638217 UTC - -809519232[7f14ce817580]: unbinding
2015-03-08 06:47:59.638287 UTC - -809519232[7f14ce817580]: unbound
===

If I'm trying to look up a name on any ldap server ( yes we have several ), I get "no matches found" and no messages in the log entirely.

Needless to say, the ldapsearch utility works fine.

So basically there are two questions: 
(1) how do we get some info to the log when it fails
and
(2) where do I look to configure the LDAP connection ( any chance there would be any text config files so one does not have to compile ) ?

Comment 12

[Kent James (:rkent)]

Bug 1135265 wants to add an easy capability to log errors discovers in C++ to the error console. It was supposed to land in Bug 1119529 but I got some flak (https://bugzilla.mozilla.org/show_bug.cgi?id=1119529#c49) so I separated into a separate bug that is now going nowhere.

Comment 13

[Wayne Mery (:wsmwk)]

Alain,
Does this still reproduce for you?

ldap has changed significantly in the past couple years

Comment 14

[Alain Knaff]

(In reply to Wayne Mery (:wsmwk) from comment #13)

Alain,
Does this still reproduce for you?

ldap has changed significantly in the past couple years

Still an issue.

Searching in Adressbook says "No contacts" without any other explanation.

Comment 15

[Wayne Mery (:wsmwk)]

Sören, can you reproduce this?

Comment 16

[Sören Hentzschel]

Sören, can you reproduce this?

How can I test this? I don't use LDAP.

Comment 17

[Wayne Mery (:wsmwk)]

You would need an ldap server, for example https://www.hostmyapple.com/blog/10-easy-steps-to-setup-openldap

But I think we really need an ldap log from the reporter, Alain. For version 102 and 115 the logging instructions are https://wiki.mozilla.org/MailNews:Logging#Thunderbird_Logging (different from earlier)

Comment 18

[Alain Knaff]

In 115, the behavior improved slightly. Connection refused errors to LDAP servers are now at least logged as such into the error console. However, there is still no obvious feedback to the user that something is amiss (no popup, no triangular warning sign), the UI just pretends that the address isn't there.

For an LDAP server which is unreachable, we no longer have a freeze, which is good.

Comment 19

[Alain Knaff]

In case you need the debug log:

mailnews.ldap: Connecting to ldap://localhost:1389 3 LDAPClient.jsm:49:18

mailnews.ldap: Connected LDAPClient.jsm:161:18
mailnews.ldap: Binding gouv.etat.lu\NQO344 LDAPClient.jsm:71:18
mailnews.ldap: C: [1] BindRequest LDAPClient.jsm:281:18
mailnews.ldap: S: [1] BindResponse resultCode=0 message="" LDAPClient.jsm:209:20
mailnews.ldap: Searching dn="ou=people" filter="(|(cn=*paul.)(mail=paul.)(givenName=paul.)(sn=paul.))" LDAPClient.jsm:140:18
mailnews.ldap: C: [2] SearchRequest LDAPClient.jsm:281:18
mailnews.ldap: S: [2] SearchResultEntry <empty string> 100 LDAPClient.jsm:209:20
mailnews.ldap: S: [2] SearchResultDone resultCode=4 message="" LDAPClient.jsm:209:20
mailnews.ldap: C: [3] UnbindRequest LDAPClient.jsm:281:18
mailnews.ldap: Connected LDAPClient.jsm:161:18
mailnews.ldap: Binding gouv.etat.lu\NQO344 LDAPClient.jsm:71:18
mailnews.ldap: C: [4] BindRequest LDAPClient.jsm:281:18
mailnews.ldap: S: [4] BindResponse resultCode=0 message="" LDAPClient.jsm:209:20
mailnews.ldap: Searching dn="ou=people" filter="(|(cn=*paul.)(mail=paul.)(givenName=paul.)(sn=paul.))" LDAPClient.jsm:140:18
mailnews.ldap: C: [5] SearchRequest LDAPClient.jsm:281:18
mailnews.ldap: Connected LDAPClient.jsm:161:18
mailnews.ldap: Binding gouv.etat.lu\NQO344 LDAPClient.jsm:71:18
mailnews.ldap: C: [6] BindRequest LDAPClient.jsm:281:18
mailnews.ldap: S: [6] BindResponse resultCode=0 message="" LDAPClient.jsm:209:20
mailnews.ldap: Searching dn="ou=people" filter="(|(cn=*paul.**)(mail=paul.)(givenName=paul.)(sn=paul.))" LDAPClient.jsm:140:18
mailnews.ldap: C: [7] SearchRequest LDAPClient.jsm:281:18
mailnews.ldap: S: [5] SearchResultEntry <empty string> 100 LDAPClient.jsm:209:20
mailnews.ldap: S: [5] SearchResultDone resultCode=4 message="" LDAPClient.jsm:209:20
mailnews.ldap: C: [8] UnbindRequest LDAPClient.jsm:281:18

(When testing with iptables dropping packets to simulate a network outage, there was a long delay between the first line, and the rest, which only followed after I removed the drop rule again).

N.B. Without setting mailnews.ldap.loglevel to All, there is nothing at all in the error log for this failure case!

Comment 20

[Alain Knaff]

Didn't wait long enough. Here's another trace with the blocking iptables rule left in place

mailnews.ldap: Connecting to ldap://localhost:1389 5 LDAPClient.jsm:49:18

mailnews.ldap: Connection closed 2 LDAPClient.jsm:253:18
mailnews.ldap: Connected LDAPClient.jsm:161:18
mailnews.ldap: Binding gouv.etat.lu\NQO344 LDAPClient.jsm:71:18
mailnews.ldap: C: [1] BindRequest LDAPClient.jsm:281:18
mailnews.ldap: Connected LDAPClient.jsm:161:18
mailnews.ldap: Binding gouv.etat.lu\NQO344 LDAPClient.jsm:71:18
mailnews.ldap: C: [1] BindRequest LDAPClient.jsm:281:18
mailnews.ldap: Connected LDAPClient.jsm:161:18
mailnews.ldap: Binding gouv.etat.lu\NQO344 LDAPClient.jsm:71:18
mailnews.ldap: C: [1] BindRequest LDAPClient.jsm:281:18
mailnews.ldap: Connected LDAPClient.jsm:161:18
mailnews.ldap: Binding gouv.etat.lu\NQO344 LDAPClient.jsm:71:18
mailnews.ldap: C: [1] BindRequest LDAPClient.jsm:281:18
mailnews.ldap: Connected LDAPClient.jsm:161:18
mailnews.ldap: Binding gouv.etat.lu\NQO344 LDAPClient.jsm:71:18
mailnews.ldap: C: [1] BindRequest LDAPClient.jsm:281:18
mailnews.ldap: S: [1] BindResponse resultCode=0 message="" LDAPClient.jsm:209:20
mailnews.ldap: Searching dn="ou=people" filter="(|(cn=xavier.b*)(mail=xavier.b)(givenName=xavier.b)(sn=xavier.b))" LDAPClient.jsm:140:18
mailnews.ldap: C: [2] SearchRequest LDAPClient.jsm:281:18
mailnews.ldap: S: [2] SearchResultEntry <empty string> 5 LDAPClient.jsm:209:20
mailnews.ldap: S: [2] SearchResultDone resultCode=0 message="" LDAPClient.jsm:209:20
mailnews.ldap: C: [3] UnbindRequest LDAPClient.jsm:281:18

=> so, after the timeout, it just continues like nothing happened, and sends its LDAP search request onto a socket which is not actually connected!