User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.9.1.6) Gecko/20091201 Firefox/3.5.6 (.NET CLR 3.5.30729) When activating ldapi (and autobind) the access log line containing the information about ip source and destination is corrupted. Reproducible: Always Steps to Reproduce: 1. Activate ldapi : dn: cn=config changetype: modify replace: nsslapd-ldapilisten nsslapd-ldapilisten: on - replace: nsslapd-ldapiautobind nsslapd-ldapiautobind: on 2. Make an ldap search /usr/bin/ldapsearch -Y EXTERNAL -H ldapi://%2fvar%2frun%2fslapd-dmz.socket -b 'dc=example,dc=com' cn=* 3. Observe the access log Actual Results: [29/Dec/2009:11:57:14 +0100] conn=1380 fd=138 slot=138 connection from ^G to 192.168.1.1 [29/Dec/2009:11:57:14 +0100] conn=1380 AUTOBIND dn="cn=Directory Manager" [29/Dec/2009:11:57:14 +0100] conn=1380 op=0 BIND dn="cn=Directory Manager" method=sasl version=3 mech=EXTERNAL ... The first line (conn=1380 fd=138 slot=138 connection from ...) varies over time and from machine to machine. Sometimes non-printable characters appear after "from" : [29/Dec/2009:12:25:01 +0100] conn=419 fd=128 slot=128 connection from to { [29/Dec/2009:12:25:01 +0100] conn=419 AUTOBIND dn="cn=Directory Manager" conn=3 fd=128 slot=128 connection from ^G to \l<E6><98> conn=12 fd=128 slot=128 connection from ^G to ^N conn=14 fd=128 slot=128 connection from ^G to Expected Results: the "fd .. slot ... connection from .. to .." string should display something reasonable and anyway th code should avoid logging non-printable characters. The important thing is that these are multi-IP multi-network card servers, the 389 is listening on all IP addresses. Another strange thing - cannot reproduce this bug in a virtual machine - happens only on real hardware servers (tested on three different HP ProLiant DL380 G5 with Intel(R) Xeon(R) CPU X5355 @ 2.66GHz)
I am now able to reproduce it in virtual machines. The thing is that in production we disable ipv6: echo "alias net-pf-10 off" >> /etc/modprobe.conf echo "alias ipv6 off" >> /etc/modprobe.conf reboot When ipv6 is disabled in this way the bug appears immediately after reboot. If i don't disable ipv6 the logs appear to be correct (smth like "conn=36 fd=128 slot=128 connection from localhost to localhost").
Created attachment 397221 [details] patch
To ssh://git.fedorahosted.org/git/389/ds.git 9aec0f1..142900b master -> master commit 142900b2757378bfbff34e3f390fcb1a292eea91 Author: Rich Megginson <rmeggins> Date: Mon Mar 1 15:03:30 2010 -0700 Reviewed by: nkinder (Thanks!) Branch: HEAD Fix Description: The connection logging code was not ldapi/unix socket aware. Now we check for the socket type, and check to see if there is a proper path name in the path field. The "server" side of the socket seems not to get the path name set correctly - not sure why, but it doesn' really matter, since the client side path name does seem to be set correctly. The access log will contain the server side path and the clien side path, so something like "from local to /var/run/slapd-foo.socket" Platforms tested: RHEL5 x86_64, Fedora 11 x86_64 Flag Day: no Doc impact: no
After compiling the latest version (389-ds-base-1.2.6.a2.tar.bz2) i have the following : [03/Mar/2010:10:11:48 +0100] conn=12 fd=129 slot=129 connection from o /Local/dirsrv/var/run/slapd-dmz.socket I thin that "o" is a part from "to" and the previous symbols must be backspaces or something like that, so that the "t" is "eaten" by these backspaces...
or i have this : conn=20 fd=128 slot=128 connection from W to /Local/dirsrv/var/run/slapd-dmz.socket Clearly, the "from" part may contain some binary garbage that contaminates the logs.
Yep, looks bad. In my tests, the from always had zeros as the first bytes of the value - looks like in your case it doesn't, which makes it very difficult to tell if it is bogus or not. I could not find any information about why the accept() system call does not properly fill in the socket path for the server side. I think I'm just going to have to use "localhost" or something like that for the server side, and just ignore the return value from accept(). I don't think it matters anyway, as long as the "to" part is filled in correctly with the path used by the client.
I am using CentOS 5.4 x86_64 with disabled ipv6: echo "alias net-pf-10 off" >> /etc/modprobe.conf echo "alias ipv6 off" >> /etc/modprobe.conf reboot Maybe the disabled ipv6 has some side effect - if i don't disable it the logs are just ok...
Created attachment 397932 [details] patch 2
Andrey, can you try my latest patch?
Yep, your second patch makes the logs clean : [05/Mar/2010:12:57:41 +0100] conn=68 fd=128 slot=128 connection from local to /Local/dirsrv/var/run/slapd-dmz.socket
To ssh://git.fedorahosted.org/git/389/ds.git 64db787..d66eb3d master -> master commit d66eb3dd9fdb9648b5058161bf8a7740a16fb2d8 Author: Rich Megginson <rmeggins> Date: Thu Mar 4 14:50:38 2010 -0700 Reviewed by: andrey.ivanov (Thanks!) Branch: HEAD Fix Description: Initialize the from PRNetAddr to nulls. That way, if PR_Accept doesn't fill in the local fields, we can see that they are empty and set the printed from field to "local". Platforms tested: RHEL5 x86_64 Flag Day: no Doc impact: no
Hi Rich, Few observation while testing this bug : [root@amitesthost amsharma]# ldapsearch -Y EXTERNAL -LLL -b "dc=example,dc=com" cn=* This gives me the below error ---- SASL/EXTERNAL authentication started ldap_sasl_interactive_bind_s: Unknown authentication method (-6) additional info: SASL(-4): no mechanism available: [root@amitesthost amsharma]# ldapsearch -x -Y EXTERNAL -LLL -b "dc=example,dc=com" cn=* It gives me ------ ldapsearch: incompatible with authentication choice And this one works for me [root@amitesthost amsharma]# ldapsearch -x EXTERNAL -LLL -b "dc=example,dc=com" cn=* Though I did not see any weird characters in the Access logs, but want to understand the above behaviours. Please help. Thanks, Amita
(In reply to comment #13) > Hi Rich, > > Few observation while testing this bug : > [root@amitesthost amsharma]# ldapsearch -Y EXTERNAL -LLL -b "dc=example,dc=com" > cn=* > > This gives me the below error ---- > SASL/EXTERNAL authentication started > ldap_sasl_interactive_bind_s: Unknown authentication method (-6) > additional info: SASL(-4): no mechanism available: Right. You did not specify the ldapi url with -H as in the original bug report. > > [root@amitesthost amsharma]# ldapsearch -x -Y EXTERNAL -LLL -b > "dc=example,dc=com" cn=* > It gives me ------ > ldapsearch: incompatible with authentication choice You can't mix -x and -Y > > And this one works for me > [root@amitesthost amsharma]# ldapsearch -x EXTERNAL -LLL -b "dc=example,dc=com" > cn=* Not sure why this works - you can't specify EXTERNAL with -x > > Though I did not see any weird characters in the Access logs, but want to > understand the above behaviours. > Please help. > > Thanks, > Amita