Bug 551198 - LDAPI: incorrect logging to access log
LDAPI: incorrect logging to access log
Status: CLOSED CURRENTRELEASE
Product: 389
Classification: Community
Component: Directory Server (Show other bugs)
1.2.1
x86_64 Linux
high Severity low
: ---
: ---
Assigned To: Rich Megginson
Viktor Ashirov
:
Depends On:
Blocks: 389_1.2.6 639035
  Show dependency treegraph
 
Reported: 2009-12-29 08:10 EST by Andrey Ivanov
Modified: 2015-12-07 12:12 EST (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-12-07 12:12:19 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
patch (3.51 KB, patch)
2010-03-01 18:44 EST, Rich Megginson
nkinder: review+
Details | Diff
patch 2 (1.28 KB, patch)
2010-03-04 16:50 EST, Rich Megginson
rmeggins: review+
Details | Diff

  None (edit)
Description Andrey Ivanov 2009-12-29 08:10:29 EST
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)
Comment 1 Andrey Ivanov 2010-01-11 14:53:46 EST
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").
Comment 3 Rich Megginson 2010-03-01 18:44:54 EST
Created attachment 397221 [details]
patch
Comment 4 Rich Megginson 2010-03-01 20:46:35 EST
To ssh://git.fedorahosted.org/git/389/ds.git
   9aec0f1..142900b  master -> master

commit 142900b2757378bfbff34e3f390fcb1a292eea91
Author: Rich Megginson <rmeggins@redhat.com>
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
Comment 5 Andrey Ivanov 2010-03-03 04:16:01 EST
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...
Comment 6 Andrey Ivanov 2010-03-03 04:23:51 EST
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.
Comment 7 Rich Megginson 2010-03-03 09:13:34 EST
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.
Comment 8 Andrey Ivanov 2010-03-03 09:20:09 EST
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...
Comment 9 Rich Megginson 2010-03-04 16:50:51 EST
Created attachment 397932 [details]
patch 2
Comment 10 Rich Megginson 2010-03-04 16:51:42 EST
Andrey, can you try my latest patch?
Comment 11 Andrey Ivanov 2010-03-05 07:00:33 EST
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
Comment 12 Rich Megginson 2010-03-05 10:09:44 EST
To ssh://git.fedorahosted.org/git/389/ds.git
   64db787..d66eb3d  master -> master

commit d66eb3dd9fdb9648b5058161bf8a7740a16fb2d8
Author: Rich Megginson <rmeggins@redhat.com>
Date:   Thu Mar 4 14:50:38 2010 -0700
    Reviewed by: andrey.ivanov@polytechnique.fr (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
Comment 13 Amita Sharma 2011-04-13 09:40:01 EDT
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
Comment 14 Rich Megginson 2011-04-13 10:07:40 EDT
(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

Note You need to log in before you can comment on or make changes to this bug.