Bug 676666

Summary: DS pipe log script is executed as many times as the dirsrv service is restarted
Product: Red Hat Enterprise Linux 6 Reporter: Rich Megginson <rmeggins>
Component: 389-ds-baseAssignee: Rich Megginson <rmeggins>
Status: CLOSED ERRATA QA Contact: Chandrasekar Kannan <ckannan>
Severity: medium Docs Contact:
Priority: high    
Version: 6.1CC: benl, dpal, jgalipea, rmeggins, shaines, sramling, syeghiay
Target Milestone: rcKeywords: screened
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: 389-ds-base-1.2.8-0.9.rc4.el6 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 668385 Environment:
Last Closed: 2011-05-19 12:41:28 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Bug Depends On: 668385    
Bug Blocks: 639035, 656390, 676871    

Description Rich Megginson 2011-02-10 16:48:04 UTC 
+++ This bug was initially created as a clone of Bug #668385 +++

Description of problem: 
DS pipe log script is getting executed as many times as the service is restarted.
This happens when you place the ds-logpipe.py script in the /etc/sysconfig/dirsrv-$inst_name file to start the DS pipelog script when the instance is started.


Version-Release number of selected component (if applicable): DS90


How reproducible: Consistently


Steps to Reproduce:
1. Configure access logs for named pipe. Set these access log attributes using
ldapmodify.
    nsslapd-accesslog-maxlogsperdir: 1
    nsslapd-accesslog-logexpirationtime: -1
    nsslapd-accesslog-logrotationtime: -1
    nsslapd-accesslog: /var/log/dirsrv/slapd-$inst_name/access.pipe
    nsslapd-accesslog-logbuffering: off

2. Append the below line into the /etc/sysconfig/dirsrv-$inst_name file.
    /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-inst/access.pipe
--plugin=/usr/share/dirsrv/data/logregex.py logregex.regex="err=32" >
/tmp/test_access &
3. Restart the DS instance using the "service restart dirsrv" command
4. Make sure the ds-logpipe.py script is started after running the above command.
5. Restart the dirsrv service one more time.
6. ds-logpipe.py is being executed everytime the service restarted.  

Actual results:
DS pipe log script is getting executed as many times as the service is restarted.

Expected results: It is expected to run only one instance of the DS pipe log script.

--- Additional comment from rmeggins on 2011-02-07 22:11:42 EST ---

Created attachment 477547 [details]
0001-Bug-668385-DS-pipe-log-script-is-executed-as-many-ti.patch

--- Additional comment from rmeggins on 2011-02-10 11:47:37 EST ---

To ssh://git.fedorahosted.org/git/389/ds.git
   30cb812..1132e09  master -> master
commit 1132e09752c8f9aba7a963bfc91a8941000012ca
Author: Rich Megginson <rmeggins>
Date:   Thu Feb 3 18:42:37 2011 -0700
    Reviewed by: nkinder (Thanks!)
    Branch: master
    Fix Description: The main thing was adding a pid file for the script itself,
    so it can know if it is running or not.  This is the new '-i' argument.
    The other tricky part was figuring out, when reading the pipe, it is hard to
    know if the server has really exited or not, and therefore, if the script
    can exit.  When the server is starting up, when it daemonizes, it will close
    and reopen the log file descriptors.  We can detect this as reading just
    an eof (line == None) from the pipe and nothing else.  In this case, we
    can just reopen the log.
    When we open the log file, if reading from a server, we always set a timer
    because the open will block until something writes to the pipe.  However,
    readline() will always return and will never block.  Even at eof, if the
    other side has closed the pipe, readline() will just return None.
    The documentation on the wiki has been updated with the new information
    about how to set up the init scripts to use the logpipe.
    Platforms tested: RHEL6 x86_64
    Flag Day: no
    Doc impact: no
To ssh://git.fedorahosted.org/git/389/ds.git
   f0e39fd..ceec7ba  389-ds-base-1.2.8 -> 389-ds-base-1.2.8
commit ceec7ba4e3b9d8baadf2a34591658484606fab9b
Author: Rich Megginson <rmeggins>
Date:   Thu Feb 3 18:42:37 2011 -0700
Comment 3 Rich Megginson 2011-03-29 21:29:59 UTC 
Checking in 0009-bump-version-to-1.2.8.rc3.patch;
/cvs/dist/rpms/389-ds-base/RHEL-6/0009-bump-version-to-1.2.8.rc3.patch,v  <--  0009-bump-version-to-1.2.8.rc3.patch
initial revision: 1.1
done
RCS file: /cvs/dist/rpms/389-ds-base/RHEL-6/0010-Bug-668385-DS-pipe-log-script-is-executed-as-many-ti.patch,v
done
Checking in 0010-Bug-668385-DS-pipe-log-script-is-executed-as-many-ti.patch;
/cvs/dist/rpms/389-ds-base/RHEL-6/0010-Bug-668385-DS-pipe-log-script-is-executed-as-many-ti.patch,v  <--  0010-Bug-668385-DS-pipe-log-script-is-executed-as-many-ti.patch
initial revision: 1.1
done
RCS file: /cvs/dist/rpms/389-ds-base/RHEL-6/0011-bump-version-to-1.2.8.rc4-bump-ds-console-version-to.patch,v
done
Checking in 0011-bump-version-to-1.2.8.rc4-bump-ds-console-version-to.patch;
/cvs/dist/rpms/389-ds-base/RHEL-6/0011-bump-version-to-1.2.8.rc4-bump-ds-console-version-to.patch,v  <--  0011-bump-version-to-1.2.8.rc4-bump-ds-console-version-to.patch
initial revision: 1.1
done
Checking in 389-ds-base-git.sh;
/cvs/dist/rpms/389-ds-base/RHEL-6/389-ds-base-git.sh,v  <--  389-ds-base-git.sh
new revision: 1.11; previous revision: 1.10
done
Checking in 389-ds-base.spec;
/cvs/dist/rpms/389-ds-base/RHEL-6/389-ds-base.spec,v  <--  389-ds-base.spec
new revision: 1.20; previous revision: 1.19
done
Comment 5 Chandrasekar Kannan 2011-04-17 18:47:37 UTC 
Tested with the latest 389-ds-base and it fails. 

[root@ds90-rhel6-32vm slapd-ds90]# rpm -qi 389-ds-base
Name        : 389-ds-base                  Relocations: (not relocatable)
Version     : 1.2.8.2                           Vendor: Red Hat, Inc.
Release     : 1.el6                         Build Date: Thu 14 Apr 2011 06:53:22 PM EDT
Install Date: Sun 17 Apr 2011 01:33:14 PM EDT      Build Host: x86-003.build.bos.redhat.com
Group       : System Environment/Daemons    Source RPM: 389-ds-base-1.2.8.2-1.el6.src.rpm
Size        : 4094342                          License: GPLv2 with exceptions
Signature   : (none)
Packager    : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>
URL         : http://port389.org/
Summary     : 389 Directory Server (base)
Description :
389 Directory Server is an LDAPv3 compliant server.  The base package includes
the LDAP server and command line utilities for server administration.
[root@ds90-rhel6-32vm slapd-ds90]# 


[root@ds90-rhel6-32vm slapd-ds90]# cat /etc/sysconfig/dirsrv-ds90
# This file is sourced by dirsrv upon startup to set
# the default environment for a single specific  directory
# server instances.  To set defaults for all instances, edit
# the file in the same directory called dirsrv.

# These settings are used by the start-dirsrv and
# start-slapd scripts (as well as their associates stop
# and restart scripts).  Do not edit them unless you know
# what you are doing.
SERVER_DIR=/usr/lib/dirsrv ; export SERVER_DIR
SERVERBIN_DIR=/usr/sbin ; export SERVERBIN_DIR
CONFIG_DIR=/etc/dirsrv/slapd-ds90 ; export CONFIG_DIR
INST_DIR=/usr/lib/dirsrv/slapd-ds90 ; export INST_DIR
RUN_DIR=/var/run/dirsrv ; export RUN_DIR
DS_ROOT= ; export DS_ROOT
PRODUCT_NAME=slapd ; export PRODUCT_NAME

# Put custom instance specific settings below here.
/usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe --plugin=/usr/share/dirsrv/data/logregex.py logregex.regex="err=32" > /tmp/test_access &
[root@ds90-rhel6-32vm slapd-ds90]# 
[root@ds90-rhel6-32vm slapd-ds90]# ls -al /var/log/dirsrv/slapd-ds90
total 32
drwxrwx---. 2 nobody nobody 4096 Apr 17 14:39 .
drwxr-xr-x. 4 root   root   4096 Apr 17 13:46 ..
-rw-------. 1 nobody nobody    0 Apr 17 13:46 access
prw-------. 1 nobody nobody    0 Apr 17 14:37 access.pipe
-rw-------. 1 nobody nobody   63 Apr 17 14:39 access.pipe.rotationinfo
-rw-------. 1 nobody nobody   63 Apr 17 13:46 access.rotationinfo
-rw-------. 1 nobody nobody    0 Apr 17 13:46 audit
-rw-------. 1 nobody nobody   63 Apr 17 13:46 audit.rotationinfo
-rw-------. 1 nobody nobody 7159 Apr 17 14:39 errors
-rw-------. 1 nobody nobody   63 Apr 17 13:46 errors.rotationinfo
[root@ds90-rhel6-32vm slapd-ds90]# ps -ef |grep log
root      1121     1  0 Apr10 ?        00:01:02 /sbin/rsyslogd -c 4
gdm       1783  1745  0 Apr10 ?        00:00:00 plymouth-log-viewer --icon
gdm       1798     1  0 Apr10 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog
root     17841     1  0 14:39 pts/1    00:00:00 python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe --plugin=/usr/share/dirsrv/data/logregex.py logregex.regex=err=32
root     17935 16232  0 14:43 pts/1    00:00:00 grep log
[root@ds90-rhel6-32vm slapd-ds90]# service  dirsrv restart ds90
Shutting down dirsrv: 
    ds90...                                                [  OK  ]
Starting dirsrv: 
    ds90...                                                [  OK  ]
[root@ds90-rhel6-32vm slapd-ds90]# ps -ef |grep log
root      1121     1  0 Apr10 ?        00:01:02 /sbin/rsyslogd -c 4
gdm       1783  1745  0 Apr10 ?        00:00:00 plymouth-log-viewer --icon
gdm       1798     1  0 Apr10 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog
root     17841     1  0 14:39 pts/1    00:00:00 python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe --plugin=/usr/share/dirsrv/data/logregex.py logregex.regex=err=32
root     17969     1  0 14:43 pts/1    00:00:00 python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe --plugin=/usr/share/dirsrv/data/logregex.py logregex.regex=err=32
root     18038 16232  0 14:44 pts/1    00:00:00 grep log
[root@ds90-rhel6-32vm slapd-ds90]# service  dirsrv restart ds90
Shutting down dirsrv: 
    ds90...                                                [  OK  ]
Starting dirsrv: 
    ds90...                                                [  OK  ]
[root@ds90-rhel6-32vm slapd-ds90]# ps -ef |grep log
root      1121     1  0 Apr10 ?        00:01:02 /sbin/rsyslogd -c 4
gdm       1783  1745  0 Apr10 ?        00:00:00 plymouth-log-viewer --icon
gdm       1798     1  0 Apr10 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog
root     17841     1  0 14:39 pts/1    00:00:00 python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe --plugin=/usr/share/dirsrv/data/logregex.py logregex.regex=err=32
root     17969     1  0 14:43 pts/1    00:00:00 python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe --plugin=/usr/share/dirsrv/data/logregex.py logregex.regex=err=32
root     18070     1  2 14:44 pts/1    00:00:00 python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe --plugin=/usr/share/dirsrv/data/logregex.py logregex.regex=err=32
root     18138 16232  0 14:44 pts/1    00:00:00 grep log
[root@ds90-rhel6-32vm slapd-ds90]#
Comment 6 Chandrasekar Kannan 2011-04-17 19:04:52 UTC 
The steps to reproduce the bug were old. I have now tested with updated documentation from the wiki... and it passes.

[root@ds90-rhel6-32vm sysconfig]# cat /etc/sysconfig/dirsrv-ds90
# This file is sourced by dirsrv upon startup to set
# the default environment for a single specific  directory
# server instances.  To set defaults for all instances, edit
# the file in the same directory called dirsrv.

# These settings are used by the start-dirsrv and
# start-slapd scripts (as well as their associates stop
# and restart scripts).  Do not edit them unless you know
# what you are doing.
SERVER_DIR=/usr/lib/dirsrv ; export SERVER_DIR
SERVERBIN_DIR=/usr/sbin ; export SERVERBIN_DIR
CONFIG_DIR=/etc/dirsrv/slapd-ds90 ; export CONFIG_DIR
INST_DIR=/usr/lib/dirsrv/slapd-ds90 ; export INST_DIR
RUN_DIR=/var/run/dirsrv ; export RUN_DIR
DS_ROOT= ; export DS_ROOT
PRODUCT_NAME=slapd ; export PRODUCT_NAME

# Put custom instance specific settings below here.
accpidfile=$RUN_DIR/dslogpipe-ds90-acc.pid
# see if there is already a logpipe running - doing a stop or
# restart (which first calls stop) should have made the old
# one exit, but let's make sure we kill it first
if [ -f $accpidfile ] ; then
  accpid=`cat $accpidfile`
  if [ -n "$accpid" ] ; then
    kill "$accpid" > /dev/null 2>&1
  fi
fi
# only log failed binds
python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe -u nobody \
 -s $RUN_DIR/slapd-ds90.pid \
 -i $accpidfile --plugin=/usr/share/dirsrv/data/failedbinds.py \
 failedbinds.logfile=/var/log/dirsrv/slapd-ds90/access.failedbinds &
# sleep gives the script a chance to create the pipe, if necessary
sleep 1
[root@ds90-rhel6-32vm sysconfig]# 
[root@ds90-rhel6-32vm sysconfig]# 
[root@ds90-rhel6-32vm sysconfig]# ps -ef | grep log
root      1121     1  0 Apr10 ?        00:01:02 /sbin/rsyslogd -c 4
gdm       1783  1745  0 Apr10 ?        00:00:00 plymouth-log-viewer --icon
gdm       1798     1  0 Apr10 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog
root     18497 16232  0 15:02 pts/1    00:00:00 grep log
[root@ds90-rhel6-32vm sysconfig]# service  dirsrv stop ds90
Shutting down dirsrv: 
    ds90...                                                [  OK  ]
[root@ds90-rhel6-32vm sysconfig]# service  dirsrv start ds90
Starting dirsrv: 
    ds90...                                                [  OK  ]
[root@ds90-rhel6-32vm sysconfig]# 
[root@ds90-rhel6-32vm sysconfig]# 
[root@ds90-rhel6-32vm sysconfig]# ps -ef | grep log
root      1121     1  0 Apr10 ?        00:01:02 /sbin/rsyslogd -c 4
gdm       1783  1745  0 Apr10 ?        00:00:00 plymouth-log-viewer --icon
gdm       1798     1  0 Apr10 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog
nobody   18552     1  0 15:02 pts/1    00:00:00 python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe -u nobody -s /var/run/dirsrv/slapd-ds90.pid -i /var/run/dirsrv/dslogpipe-ds90-acc.pid --plugin=/usr/share/dirsrv/data/failedbinds.py failedbinds.logfile=/var/log/dirsrv/slapd-ds90/access.failedbinds
root     18621 16232  0 15:03 pts/1    00:00:00 grep log
[root@ds90-rhel6-32vm sysconfig]# service  dirsrv restart ds90
Shutting down dirsrv: 
    ds90...                                                [  OK  ]
Starting dirsrv: 
    ds90...                                                [  OK  ]
[root@ds90-rhel6-32vm sysconfig]# ps -ef | grep log
root      1121     1  0 Apr10 ?        00:01:02 /sbin/rsyslogd -c 4
gdm       1783  1745  0 Apr10 ?        00:00:00 plymouth-log-viewer --icon
gdm       1798     1  0 Apr10 ?        00:00:00 /usr/bin/pulseaudio --start --log-target=syslog
nobody   18655     1  0 15:03 pts/1    00:00:00 python /usr/bin/ds-logpipe.py /var/log/dirsrv/slapd-ds90/access.pipe -u nobody -s /var/run/dirsrv/slapd-ds90.pid -i /var/run/dirsrv/dslogpipe-ds90-acc.pid --plugin=/usr/share/dirsrv/data/failedbinds.py failedbinds.logfile=/var/log/dirsrv/slapd-ds90/access.failedbinds
root     18724 16232  0 15:03 pts/1    00:00:00 grep log
[root@ds90-rhel6-32vm sysconfig]#
Comment 7 errata-xmlrpc 2011-05-19 12:41:28 UTC 
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHEA-2011-0533.html