676666 – DS pipe log script is executed as many times as the dirsrv service is restarted

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 676666 - DS pipe log script is executed as many times as the dirsrv service is restarted

Summary: DS pipe log script is executed as many times as the dirsrv service is restarted

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	389-ds-base
Sub Component:
Version:	6.1
Hardware:	All
OS:	Linux
Priority:	high
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	Rich Megginson
QA Contact:	Chandrasekar Kannan
Docs Contact:
URL:
Whiteboard:
Depends On:	668385
Blocks:	639035 389_1.2.8 676871
TreeView+	depends on / blocked

Reported:	2011-02-10 16:48 UTC by Rich Megginson
Modified:	2015-01-04 23:46 UTC (History)
CC List:	7 users (show)
Fixed In Version:	389-ds-base-1.2.8-0.9.rc4.el6
Doc Type:	Bug Fix
Doc Text:
Clone Of:	668385
Environment:
Last Closed:	2011-05-19 12:41:28 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHEA-2011:0533	0	normal	SHIPPED_LIVE	new package: 389-ds-base	2011-05-18 17:57:44 UTC

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

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