[Date Prev][Date Next] [Chronological] [Thread] [Top]
Re: (ITS#4375) MOD operations not being logged

To: openldap-its@OpenLDAP.org
Subject: Re: (ITS#4375) MOD operations not being logged
From: quanah@stanford.edu
Date: Fri, 10 Feb 2006 00:25:07 GMT

--On Thursday, February 09, 2006 12:50 AM +0000 quanah@stanford.edu wrote:

> On Wednesday 08 February 2006 16:25, you wrote:
>
>> The *only* thing that has changed is the version of OpenLDAP software
>> being used.  We haven't updated the process that writes to the account
>> tree of the directory server in almost a year.
>
> Looking at my past logs where I audit the errors nightly, the correct
> logging  of MOD operations broke between 2.2.27 (the release I was
> running in  December) and 2.3.x.

Adding some debugging statements, the path taken for MOD operations between 
2.2 and 2.3 has changed significantly.

QS* are debug statements in slap_mods_check.

QX,Q# are debug statements in either do_modify (2.2) or fe_op_modify(2.3)

2.2: successful MOD

Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 347666 local4.debug] 
conn=3 op=0 BIND dn="dc=symas,dc=com" method=128
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 992945 local4.debug] 
conn=3 op=0 BIND dn="dc=symas,dc=com" mech=SIMPLE ssf=0
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 217296 local4.debug] 
conn=3 op=0 RESULT tag=97 err=0 text=
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 739320 local4.debug] 
QX:
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 674828 local4.debug] 
Q0:
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 795387 local4.debug] 
Q1:
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 177021 local4.debug] 
conn=3 op=1 MOD dn="uid=user.1,ou=peeps,dc=symas,dc=com"
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 257083 local4.debug] 
Q4:
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 324647 local4.debug] 
conn=3 op=1 MOD attr=displayName
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 901226 local4.debug] 
QS1:
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 121804 local4.debug] 
QS2:
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 909181 local4.debug] 
QS17:
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 217296 local4.debug] 
conn=3 op=1 RESULT tag=103 err=0 text=
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 338319 local4.debug] 
conn=3 op=2 UNBIND
Feb  9 15:37:22 helpus2.Stanford.EDU slapd[20407]: [ID 952275 local4.debug] 
conn=3 fd=10 closed

2.3: successful MOD

Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 848112 local4.debug] 
conn=1 fd=11 ACCEPT from IP=127.0.0.1:39369 (IP=0.0.0.0:389)
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 215403 local4.debug] 
conn=1 op=0 BIND dn="dc=symas,dc=com" method=128
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 600343 local4.debug] 
conn=1 op=0 BIND dn="dc=symas,dc=com" mech=SIMPLE ssf=0
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 588225 local4.debug] 
conn=1 op=0 RESULT tag=97 err=0 text=
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 901226 local4.debug] 
QS1:
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 121804 local4.debug] 
QS2:
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 739320 local4.debug] 
QX:
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 674828 local4.debug] 
Q0:
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 795387 local4.debug] 
Q1:
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 249368 local4.debug] 
conn=1 op=1 MOD dn="uid=user.1,ou=peeps,dc=symas,dc=com"
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 257083 local4.debug] 
Q4:
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 396994 local4.debug] 
conn=1 op=1 MOD attr=displayName
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 588225 local4.debug] 
conn=1 op=1 RESULT tag=103 err=0 text=
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 218904 local4.debug] 
conn=1 op=2 UNBIND
Feb  9 16:02:38 helpus2.Stanford.EDU slapd[20473]: [ID 952275 local4.debug] 
conn=1 fd=11 closed


2.2: failed MOD

Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 848112 local4.debug] 
conn=4 fd=10 ACCEPT from IP=127.0.0.1:39367 (IP=0.0.0.0:389)
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 347666 local4.debug] 
conn=4 op=0 BIND dn="dc=symas,dc=com" method=128
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 992945 local4.debug] 
conn=4 op=0 BIND dn="dc=symas,dc=com" mech=SIMPLE ssf=0
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 217296 local4.debug] 
conn=4 op=0 RESULT tag=97 err=0 text=
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 739320 local4.debug] 
QX:
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 674828 local4.debug] 
Q0:
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 795387 local4.debug] 
Q1:
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 177021 local4.debug] 
conn=4 op=1 MOD dn="uid=user.1,ou=peeps,dc=symas,dc=com"
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 257083 local4.debug] 
Q4:
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 324647 local4.debug] 
conn=4 op=1 MOD attr=displayName
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 901226 local4.debug] 
QS1:
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 121804 local4.debug] 
QS2:
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 306386 local4.debug] 
QS12:
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 217296 local4.debug] 
conn=4 op=1 RESULT tag=103 err=19 text=displayName: multiple values provided
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 338319 local4.debug] 
conn=4 op=2 UNBIND
Feb  9 15:37:50 helpus2.Stanford.EDU slapd[20407]: [ID 952275 local4.debug] 
conn=4 fd=10 closed

2.3: failed MOD

Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 848112 local4.debug] 
conn=2 fd=11 ACCEPT from IP=127.0.0.1:39370 (IP=0.0.0.0:389)
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 215403 local4.debug] 
conn=2 op=0 BIND dn="dc=symas,dc=com" method=128
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 600343 local4.debug] 
conn=2 op=0 BIND dn="dc=symas,dc=com" mech=SIMPLE ssf=0
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 588225 local4.debug] 
conn=2 op=0 RESULT tag=97 err=0 text=
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 901226 local4.debug] 
QS1:
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 121804 local4.debug] 
QS2:
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 965717 local4.debug] 
QS9:
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 588225 local4.debug] 
conn=2 op=1 RESULT tag=103 err=19 text=displayName: multiple values provided
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 218904 local4.debug] 
conn=2 op=2 UNBIND
Feb  9 16:03:06 helpus2.Stanford.EDU slapd[20473]: [ID 952275 local4.debug] 
conn=2 fd=11 closed


Clearly, in 2.2, the do_modify function (now replaced by fe_op_modify) was 
called *before* slap_mods_check.  Now in 2.3, it is called *after* 
slap_mods_check, which has broken the logging.  This sequence apparently 
needs to be reversed back to the 2.2 behavior.

--Quanah

--
Quanah Gibson-Mount
Principal Software Developer
ITS/Shared Application Services
Stanford University
GnuPG Public Key: http://www.stanford.edu/~quanah/pgp.html
Prev by Date: Re: (ITS#4394) Fix Segfault in auditlog.c
Next by Date: Re: (ITS#4394) Fix Segfault in auditlog.c
Index(es):
- Chronological
- Thread