OpenLDAP / slapd dies sporadically

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Hi,

I'm using LDAP on my FreeBSD 10.0-RELEASE-p7 for user authentication. Unfortunately slapd keeps on dying sporadically. Best of all is, that I'm unable to debug the cause of this - all I see is this in /var/log/messages:
Code:
Aug 15 09:57:27 Storage-03 kernel: pid 1051 (slapd), uid 389: exited on signal 11
My research through Google didn't result in much success; it seems like I'm alone here which makes me think, that I may have a misconfiguration which could cause this?

So I rather share my /usr/local/etc/openldap/slapd.conf as well ;)
Code:
#======================================#
#              slapd.conf              #
#======================================#

# LDAP Attribut Schema Definitions:
include     /usr/local/etc/openldap/schema/core.schema
include     /usr/local/etc/openldap/schema/cosine.schema
include     /usr/local/etc/openldap/schema/inetorgperson.schema
include     /usr/local/etc/openldap/schema/nis.schema
include     /usr/local/etc/openldap/schema/ldapab.schema


# Logging
loglevel 256


# Important Files
pidfile     /var/run/openldap/slapd.pid
argsfile    /var/run/openldap/slapd.args


# Allow LDAPv2 client connections. This is required for iOS suppoprt via SSL.
#allow bind_v2

# Time limits
#idletimeout    0
#writetimeout   0
#timelimit      3600


# Dynamic Modules:
modulepath  /usr/local/libexec/openldap
moduleload  back_mdb
moduleload  back_monitor


# Access from 127.0.0.1 without encryption
access to dn.subtree="dc=mydomain,dc=local"
    by peername.ip=127.0.0.1 write
    by *                     none   break

# Access from other than 127.0.0.1 requires TLS
# encryption with min. 128 bit encryption
access to dn.subtree="dc=mydomain,dc=local"
    by ssf=128  write
    by *        none

# TLS-Certificate
TLSCACertificateFile  /etc/ssl/RootCA/cacert.pem
TLSCertificateFile    /etc/ssl/RootCA/certs/192.168.10.50.pem
TLSCertificateKeyFile /etc/ssl/RootCA/certs/192.168.10.50.key
TLSVerifyClient       allow


# Restrict write access for password attributes to root user only
access to attrs=userPassword
       by self      write
       by anonymous auth
       by *         none

# All the other atributes can be read by everyone else
access to *
       by *         read


# ================================== #
#        Internal Monitoring         #
# ================================== #

# DB type
database    monitor

# Name of Administrator
rootdn      "cn=monitoring,cn=Monitor"

# Password of Administrators
rootpw      {SSHA}[...]

# ACL for moitoring
access to dn.subtree="cn=Monitor"
    by dn.exact="cn=admin,dc=mydomain,dc=local"  write
    by peername.ip=127.0.0.1                    read
    by users                                    read
    by *                                        none



# ================================== #
#  Lightning Memory-Mapped Database  #
# ================================== #

# Datenbanktyp
database    mdb

# DB location on FS
directory   /var/db/openLDAP

# Datenbank-Pfad
suffix      "dc=mydomain,dc=local"

# Name of Administrator
rootdn      "cn=admin,dc=mydomain,dc=local"

# Password of Administrators
rootpw      {SSHA}[...]

# Max size of DB in Byte [ 5368709120 Byte => 5 GB ]
maxsize     5368709120

# Index search related attributes
index objectClass  eq
index uid          eq
index uidNumber    eq
index uniqueMember eq
index gidNumber    eq
index cn           eq
index memberUid    eq

And here is what /var/log/slapd.log tells me during the crash time:
Code:
[...]
Aug 15 09:56:52 Storage-03 slapd[1051]: conn=3988 op=3 UNBIND
Aug 15 09:56:52 Storage-03 slapd[1051]: conn=3988 fd=12 closed
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 fd=12 ACCEPT from IP=127.0.0.1:58836 (IP=0.0.0.0:389)
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 op=0 EXT oid=1.3.6.1.4.1.1466.20037
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 op=0 STARTTLS
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 op=0 RESULT oid= err=0 text=
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 fd=12 TLS established tls_ssf=256 ssf=256
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 op=1 BIND dn="cn=admin,dc=mydomain,dc=local" method=128
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 op=1 BIND dn="cn=admin,dc=mydomain,dc=local" mech=SIMPLE ssf=0
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 op=1 RESULT tag=97 err=0 text=
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 op=2 SRCH base="dc=mydomain,dc=local" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uid=leander))"
Aug 15 09:57:27 Storage-03 slapd[1051]: conn=4000 op=2 SRCH attr=loginShell cn gidNumber uidNumber objectClass homeDirectory gecos uid
Aug 15 09:57:52 Storage-03 slapd[68331]: @(#) $OpenLDAP: slapd 2.4.39 (Jul 27 2014 01:51:05) $  root@Storage-03.mydomain.Local:/usr/ports/net/openldap24-server/work/openldap-2.4.39/servers/slapd
Aug 15 09:57:52 Storage-03 slapd[68332]: slapd starting
Aug 15 09:58:01 Storage-03 slapd[68332]: conn=1000 fd=12 ACCEPT from IP=127.0.0.1:18417 (IP=0.0.0.0:389)
Aug 15 09:58:01 Storage-03 slapd[68332]: conn=1000 op=0 EXT oid=1.3.6.1.4.1.1466.20037
Aug 15 09:58:01 Storage-03 slapd[68332]: conn=1000 op=0 STARTTLS
[...]
I also see plenty of those once, since the server is down:
Code:
[...]
Aug 15 09:57:36 Storage-03 nslcd[1034]: [671964] <passwd="leander"> no available LDAP server found: Server is unavailable: Operation timed out
Aug 15 09:57:36 Storage-03 nslcd[1034]: [b46aeb] <passwd="LEANDER"> no available LDAP server found: Server is unavailable: Resource temporarily unavailable
[...]
Any ideas what could cause this or how and where I could start debugging? Because this is really not good on those production servers ;(
I even already wrote scripts in order for a workaround to monitor the daemon and restart it in case it died - but this is definitely not a long term solution.

Thanks.
 
Last edited by a moderator:

w5plt

Member

Reaction score: 4
Messages: 29

Leander,

At a brief glance, I don't see anything misconfigured in your slapd.conf file.

Questions:

  • Can you possibly increase the loglevel in slapd.conf to provide additional logging information and post the results?
  • How long does slapd stay running before it stops?
  • Can you post the nslcd.conf file?
  • Is it possible to run the OpenLDAP Server without the ldapab.schema for a while since it is not a schema provided by a default installation of OpenLDAP?

Regards

Scott
 
Last edited by a moderator:
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Hi Scott

Thanks for your reply.
w5plt said:
Can you possible increase the loglevel in slapd.conf to provide additional logging information and post the results?
To what would you like me to increase the loglevel to?
Code:
loglevel trace packets args conns BER filter config ACL stats stats2 shell parse sync
w5plt said:
How long does slapd stay running before it stops?
It differs a lot. I currently have two OpenLDAP Servers running - for the very same purpose. The only difference between the two of them is the underlying DB format they use. Also, they run in a total different, geologically separated network
  • Storage-01 uses OpenLDAP with Berkeley DB (BDB)
  • Storage-03 uses OpenLDAP with Memory-Mapped Database (MDB)

Details of Storage-01 (BDB):
  • It keeps on dieing several times a day. At least 5 to 15 times
  • up to 7 clients authenticate several times a day

Details of Storage-03 (MDB):
  • This one is more stable. It only dies like once or twice a week.
  • also, there is only one to two clients authenticating several times a day.

w5plt said:
Can you post the nslcd.conf file?
Code:
# ============================================ #
#                  nslcd.conf                  #
# ============================================ #


# The user and group nslcd should run as.
uid nslcd
gid nslcd

# The uri pointing to the LDAP server to use for name lookups.
# Multiple entries may be specified. The address that is used
# here should be resolvable without using LDAP (obviously).
#uri ldap://127.0.0.1/
#uri ldaps://127.0.0.1/
#uri ldapi://%2fvar%2frun%2fldapi_sock/
# Note: %2f encodes the '/' used as directory separator
uri ldap://127.0.0.1/

# The distinguished name of the search base.
base dc=mydomain,dc=local

# The distinguished name to bind to the server with.
# Optional: default is to bind anonymously.
binddn cn=admin,dc=mydomain,dc=local

# The credentials to bind with.
# Optional: default is no credentials.
# Note that if you set a bindpw you should check the permissions of this file.
bindpw [MyTopSecretPW]

# The distinguished name to perform password modifications by root by.
rootpwmoddn cn=admin,dc=mydomain,dc=local

# Bind/connect timelimit.
bind_timelimit 3

# Search timelimit.
timelimit 5

# When is remote slapd considered dead
reconnect_retrytime 3

# Idle timelimit. nslcd will close connections if the
# server has not been contacted for the number of seconds.
idle_timelimit 300

# Use StartTLS without verifying the server certificate.
ssl start_tls
tls_reqcert allow

# SSL cipher suite
# See man ciphers for syntax
tls_ciphers TLSv1+HIGH:!SSLv2:!aNULL:!eNULL:!3DES:@STRENGTH

# Ignore Users
#nss_initgroups_ignoreusers root
nss_initgroups_ignoreusers ALLLOCAL

# Requests for users with a lower user id are ignored
nss_min_uid 2000

# Enable username case insensitive Logins
ignorecase yes

# How user and group names are verified within the system
# This is maybe interfering with cn=Monitor account
validnames /^[a-z0-9._@]([a-z0-9._@ \~-]*[a-z0-9._@~-])?$/i

# Limit Users for System logins
pam_authz_search (&(objectClass=posixGroup)(cn=storage-03)(memberUid=$username))

w5plt said:
Is it possible to run the OpenLDAP Server without the ldapab.schema for a while since it is not a schema provided by a default installation of OpenLDAP?
Good question ;)
  • Storage-01 is already running without ldapab.schema
  • while Storage-03 runs with ldapab.schema
I just recently implemented it into the Storage-03 slapd.config. I've had the same problems before and after the implementation - so I can tell, that it unfortunately won't make a difference.


I remember having exactly the same trouble years ago when I tried to setup a Samba Active Directory server (without nslcd) .. it also kept on crashing sporadically - that's why I stopped using it and did not bring it further into production usage. But this time OpenLDAP doesn't even act as a direct Samba Backend - yet same trouble.
 

w5plt

Member

Reaction score: 4
Messages: 29

Leander,

To what would you like me to increase the loglevel to?
loglevel trace

Let's see what the log files show when slapd restarts sporadically. Also, see if there are any corresponding entries in /var/log/messages at the same time.

Depending on what the log files show at log level trace, it might be a good idea to start simplifying slapd.conf in an effort to isolate the issue. I suggest to temporarily disable monitoring in the slapd.conf and see if that has any effect on this issue.

By the way, can you post the slapd entries in /etc/rc.conf?

I'm very interested in this issue, since I have a very similar setup in a pre-production environment.

I look forward to see if the log files yield any additional information...

Regards,

Scott
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Hi Scott,

Thanks for your reply. loglevel is now changed to trace on both machines. The /etc/rc.conf of both machines has the following identical slapd(8) relevant lines:
Code:
### OpenLDAP Daemon
slapd_enable="YES"
slapd_sockets="/var/run/openldap/ldapi"
slapd_flags='-h "ldapi://%2fvar%2frun%2fopenldap%2fldapi/ ldap:/// ldaps:///"'
I also temporary disabled monitoring on both servers. I guess with Sotrage-01 we'll have a result quite soon (even though most of the people are currently on vacancy)
With Sotrage-03 it could take a couple of days - but I know it won't be too long ;)

I'll inform you as soon as possible. Otherwhise I would be interested if there is any official tool to supervise daemons on FreeBSD. I used to manually change the rc script of slapd in order to monitor itself an restart itself in case it died. But unfortuntely the rc script is going to be overwritten on each OpenLDAP update ... so this is not a quite clean workaround for such issues. As far as I know nslcd has a supervisor built in?!


For anyone who is interested - this is my little trick to supervice it's not a 100% clean - but it does the job ;) You can simply copy and paste it into your shell (assumed you run bash otherwhise create the file yourself and copy it into the editor of your choice) and do a service slapd restart. Then watch ps aux | grep slap and you'll notice slapd_watcher process. To see if it does the job simply do a kill [PID of slapd]. slapd_watcher will notice that it isn't running any longer and restart it again.
Code:
#
# Create slapd_watcher script
#

(
cat <<'EOF'
#!/usr/local/bin/bash
#
# This Script checks whether slapd is running.
# If slapd is not running then it will be
# started by this script.
#
# ================================================ #

# Get initial PID
sleep 10 # Wait untill slapd is online (when service slapd start is issued)

daemon_watcher() {
    STATUS="$(ps -U ldap | tail -n+2 2>&1)"

    if [ -z "$(echo "${STATUS}" | grep 'libexec/slapd ')" ]; then
        RC_INFO="$(service slapd start 2>&1 &)"
        SUBJECT="$(hostname -s) - OpenLDAP watcher"
        CONTENT="OpenLDAP was shutdown.\n\n${RC_INFO}"
        echo -e "${CONTENT}" | mail -s "${SUBJECT}" root
        sleep 10 # Wait untill slapd is online (when service slapd start is issued)
    fi
}

while true; do
    daemon_watcher
    sleep 3
done

exit

EOF
) >              /usr/local/bin/slapd_watcher
chmod 0755       /usr/local/bin/slapd_watcher
chown root:wheel /usr/local/bin/slapd_watcher




#
# Modify slapd rc script
#


# Create or restore backup
if [ -f /usr/local/etc/rc.d/slapd_ORIG ]; then
    cp -a /usr/local/etc/rc.d/slapd_ORIG /usr/local/etc/rc.d/slapd
else
    cp -a /usr/local/etc/rc.d/slapd /usr/local/etc/rc.d/slapd_ORIG
fi


# Modify rc.d START script
cat /usr/local/etc/rc.d/slapd | sed '
/local socket seconds/ a\
\  if [ ! -f /var/run/slapd_watcher.pid ]; then\
\    echo '' >  /var/run/slapd_watcher.pid\
\  fi\
\  if [ -z "$(cat /var/run/slapd_watcher.pid)" ]; then\
\    /usr/local/bin/slapd_watcher &\
\    echo "${!}" > /var/run/slapd_watcher.pid\
\    chmod 0755    /var/run/slapd_watcher.pid\
\  fi\
' > /tmp/output
[[ -f /tmp/output ]] && [[ ! -z "$(cat /tmp/output)" ]] && \
cat /tmp/output > /usr/local/etc/rc.d/slapd && rm /tmp/output

sleep 0.5

# Modify rc.d STOP script
cat /usr/local/etc/rc.d/slapd | sed '
/start_postcmd=start_postcmd/ a\
stop_precmd=stop_precmd\
\
stop_precmd() {\
\  if [ -f /var/run/slapd_watcher.pid ]; then\
\    kill "$(cat /var/run/slapd_watcher.pid)"\
\    echo "" > /var/run/slapd_watcher.pid\
\  fi\
}\
' > /tmp/output
[[ -f /tmp/output ]] && [[ ! -z "$(cat /tmp/output)" ]] && \
cat /tmp/output > /usr/local/etc/rc.d/slapd && rm /tmp/output

Best regards
Leander
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Hi again,

So here is the first /var/log/slapd.log output of another sporadic and silent crash of slapd(8) on Storage-01. It's the one Server which still has the DBD setup (as described in the previous posts). The slapd_watcher bash script informed me via email, that it restarted slapd(8) on Sep 18 10:56:03 after it recognized, that the slapd(8) service was down.

Code:
[...]
Sep 18 10:56:02 Storage-01 slapd[56523]: connection_get(20): got connid=1244
Sep 18 10:56:02 Storage-01 slapd[56523]: connection_read(20): checking for input on id=1244
Sep 18 10:56:02 Storage-01 slapd[56523]: op tag 0x63, time 1411030562
Sep 18 10:56:02 Storage-01 slapd[56523]: conn=1244 op=11 do_search
Sep 18 10:56:02 Storage-01 slapd[56523]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 10:56:02 Storage-01 slapd[56523]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 10:56:02 Storage-01 slapd[56523]: => bdb_search
Sep 18 10:56:02 Storage-01 slapd[56523]: bdb_dn2entry("dc=mydomain,dc=local")
Sep 18 10:56:02 Storage-01 slapd[56523]: search_candidates: base="dc=mydomain,dc=local" (0x00000001) scope=2
Sep 18 10:56:02 Storage-01 slapd[56523]: => bdb_dn2idl("dc=mydomain,dc=local")
Sep 18 10:56:02 Storage-01 slapd[56523]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:02 Storage-01 slapd[56523]: => key_read


==> slapd just died. My slapd_watcher shell script noticed it and started it again.


Sep 18 10:56:03 Storage-01 slapd[47199]: @(#) $OpenLDAP: slapd 2.4.39 (Aug 31 2014 12:59:44) $ 	root@Storage-01.mydomain.Local:/usr/ports/net/openldap24-server/work/openldap-2.4.39/servers/slapd
Sep 18 10:56:04 Storage-01 slapd[47199]: bdb_back_initialize: initialize BDB backend
Sep 18 10:56:04 Storage-01 slapd[47199]: bdb_back_initialize: Berkeley DB 4.8.30: (April  9, 2010)
Sep 18 10:56:04 Storage-01 slapd[47199]: >>> dnNormalize: <dc=mydomain,dc=local>
Sep 18 10:56:04 Storage-01 slapd[47199]: <<< dnNormalize: <dc=mydomain,dc=local>
Sep 18 10:56:04 Storage-01 slapd[47199]: >>> dnNormalize: <dc=mydomain,dc=local>
Sep 18 10:56:04 Storage-01 slapd[47199]: <<< dnNormalize: <dc=mydomain,dc=local>
Sep 18 10:56:04 Storage-01 slapd[47199]: bdb_db_init: Initializing BDB database
Sep 18 10:56:04 Storage-01 slapd[47199]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 10:56:04 Storage-01 slapd[47199]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 10:56:04 Storage-01 slapd[47199]: >>> dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>
Sep 18 10:56:04 Storage-01 slapd[47199]: <<< dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>, <cn=admin,dc=mydomain,dc=local>
Sep 18 10:56:04 Storage-01 slapd[47199]: >>> dnNormalize: <cn=Subschema>
Sep 18 10:56:04 Storage-01 slapd[47199]: <<< dnNormalize: <cn=subschema>
Sep 18 10:56:04 Storage-01 slapd[47199]: matching_rule_use_init
Sep 18 10:56:04 Storage-01 slapd[47199]:     1.2.840.113556.1.4.804 (integerBitOrMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 1.2.840.113556.1.4.804 NAME 'integerBitOrMatch' APPLIES ( supportedLDAPVersion $ entryTtl $ uidNumber $ gidNumber $ olcConcurrency $ olcConnMaxPending $ olcConnMaxPendingAuth $ olcIdleTimeout $ olcIndexSubstrIfMinLen $ olcIndexSubstrIfMaxLen $ olcIndexSubstrAnyLen $ olcIndexSubstrAnyStep $ olcIndexIntLen $ olcListenerThreads $ olcLocalSSF $ olcMaxDerefDepth $ olcReplicationInterval $ olcSockbufMaxIncoming $ olcSockbufMaxIncomingAuth $ olcThreads $ olcToolThreads $ olcWriteTimeout $ olcSpSessionlog $ olcDbCacheFree $ olcDbCacheSize $ olcDbDNcacheSize $ olcDbIDLcacheSize $ olcDbSearchStack $ olcDbShmKey $ mailPreferenceOption $ shadowLastChange $ shadowMin $ shadowMax $ shadowWarning $ shadowInactive $ shadowExpire $ shadowFlag $ ipServicePort $ ipProtocolNumber $ oncRpcNumber ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     1.2.840.113556.1.4.803 (integerBitAndMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 1.2.840.113556.1.4.803 NAME 'integerBitAndMatch' APPLIES ( supportedLDAPVersion $ entryTtl $ uidNumber $ gidNumber $ olcConcurrency $ olcConnMaxPending $ olcConnMaxPendingAuth $ olcIdleTimeout $ olcIndexSubstrIfMinLen $ olcIndexSubstrIfMaxLen $ olcIndexSubstrAnyLen $ olcIndexSubstrAnyStep $ olcIndexIntLen $ olcListenerThreads $ olcLocalSSF $ olcMaxDerefDepth $ olcReplicationInterval $ olcSockbufMaxIncoming $ olcSockbufMaxIncomingAuth $ olcThreads $ olcToolThreads $ olcWriteTimeout $ olcSpSessionlog $ olcDbCacheFree $ olcDbCacheSize $ olcDbDNcacheSize $ olcDbIDLcacheSize $ olcDbSearchStack $ olcDbShmKey $ mailPreferenceOption $ shadowLastChange $ shadowMin $ shadowMax $ shadowWarning $ shadowInactive $ shadowExpire $ shadowFlag $ ipServicePort $ ipProtocolNumber $ oncRpcNumber ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     1.3.6.1.4.1.1466.109.114.2 (caseIgnoreIA5Match): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 1.3.6.1.4.1.1466.109.114.2 NAME 'caseIgnoreIA5Match' APPLIES ( altServer $ olcDbConfig $ c $ mail $ dc $ associatedDomain $ email $ aRecord $ mDRecord $ mXRecord $ nSRecord $ sOARecord $ cNAMERecord $ janetMailbox $ gecos $ homeDirectory $ loginShell $ memberUid $ memberNisNetgroup $ ipHostNumber $ ipNetworkNumber $ ipNetmaskNumber $ macAddress $ bootFile $ nisMapEntry ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     1.3.6.1.4.1.1466.109.114.1 (caseExactIA5Match): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 1.3.6.1.4.1.1466.109.114.1 NAME 'caseExactIA5Match' APPLIES ( altServer $ olcDbConfig $ c $ mail $ dc $ associatedDomain $ email $ aRecord $ mDRecord $ mXRecord $ nSRecord $ sOARecord $ cNAMERecord $ janetMailbox $ gecos $ homeDirectory $ loginShell $ memberUid $ memberNisNetgroup $ ipHostNumber $ ipNetworkNumber $ ipNetmaskNumber $ macAddress $ bootFile $ nisMapEntry ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.39 (certificateListMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.38 (certificateListExactMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.38 NAME 'certificateListExactMatch' APPLIES ( authorityRevocationList $ certificateRevocationList $ deltaRevocationList ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.35 (certificateMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.34 (certificateExactMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.34 NAME 'certificateExactMatch' APPLIES ( userCertificate $ cACertificate ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.30 (objectIdentifierFirstComponentMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.30 NAME 'objectIdentifierFirstComponentMatch' APPLIES ( supportedControl $ supportedExtension $ supportedFeatures $ ldapSyntaxes $ supportedApplicationContext ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.29 (integerFirstComponentMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.29 NAME 'integerFirstComponentMatch' APPLIES ( supportedLDAPVersion $ entryTtl $ uidNumber $ gidNumber $ olcConcurrency $ olcConnMaxPending $ olcConnMaxPendingAuth $ olcIdleTimeout $ olcIndexSubstrIfMinLen $ olcIndexSubstrIfMaxLen $ olcIndexSubstrAnyLen $ olcIndexSubstrAnyStep $ olcIndexIntLen $ olcListenerThreads $ olcLocalSSF $ olcMaxDerefDepth $ olcReplicationInterval $ olcSockbufMaxIncoming $ olcSockbufMaxIncomingAuth $ olcThreads $ olcToolThreads $ olcWriteTimeout $ olcSpSessionlog $ olcDbCacheFree $ olcDbCacheSize $ olcDbDNcacheSize $ olcDbIDLcacheSize $ olcDbSearchStack $ olcDbShmKey $ mailPreferenceOption $ shadowLastChange $ shadowMin $ shadowMax $ shadowWarning $ shadowInactive $ shadowExpire $ shadowFlag $ ipServicePort $ ipProtocolNumber $ oncRpcNumber ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.28 (generalizedTimeOrderingMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.28 NAME 'generalizedTimeOrderingMatch' APPLIES ( createTimestamp $ modifyTimestamp ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.27 (generalizedTimeMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.27 NAME 'generalizedTimeMatch' APPLIES ( createTimestamp $ modifyTimestamp ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.24 (protocolInformationMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.24 NAME 'protocolInformationMatch' APPLIES protocolInformation )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.23 (uniqueMemberMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.23 NAME 'uniqueMemberMatch' APPLIES uniqueMember )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.22 (presentationAddressMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.22 NAME 'presentationAddressMatch' APPLIES presentationAddress )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.20 (telephoneNumberMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.20 NAME 'telephoneNumberMatch' APPLIES ( telephoneNumber $ homePhone $ mobile $ pager ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.18 (octetStringOrderingMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.17 NAME 'octetStringMatch' APPLIES ( userPassword $ olcDbCryptKey ) )
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.16 NAME 'bitStringMatch' APPLIES x500UniqueIdentifier )
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.15 NAME 'integerOrderingMatch' APPLIES ( supportedLDAPVersion $ entryTtl $ uidNumber $ gidNumber $ olcConcurrency $ olcConnMaxPending $ olcConnMaxPendingAuth $ olcIdleTimeout $ olcIndexSubstrIfMinLen $ olcIndexSubstrIfMaxLen $ olcIndexSubstrAnyLen $ olcIndexSubstrAnyStep $ olcIndexIntLen $ olcListenerThreads $ olcLocalSSF $ olcMaxDerefDepth $ olcReplicationInterval $ olcSockbufMaxIncoming $ olcSockbufMaxIncomingAuth $ olcThreads $ olcToolThreads $ olcWriteTimeout $ olcSpSessionlog $ olcDbCacheFree $ olcDbCacheSize $ olcDbDNcacheSize $ olcDbIDLcacheSize $ olcDbSearchStack $ olcDbShmKey $ mailPreferenceOption $ shadowLastChange $ shadowMin $ shadowMax $ shadowWarning $ shadowInactive $ shadowExpire $ shadowFlag $ ipServicePort $ ipProtocolNumber $ oncRpcNumber ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.14 (integerMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.14 NAME 'integerMatch' APPLIES ( supportedLDAPVersion $ entryTtl $ uidNumber $ gidNumber $ olcConcurrency $ olcConnMaxPending $ olcConnMaxPendingAuth $ olcIdleTimeout $ olcIndexSubstrIfMinLen $ olcIndexSubstrIfMaxLen $ olcIndexSubstrAnyLen $ olcIndexSubstrAnyStep $ olcIndexIntLen $ olcListenerThreads $ olcLocalSSF $ olcMaxDerefDepth $ olcReplicationInterval $ olcSockbufMaxIncoming $ olcSockbufMaxIncomingAuth $ olcThreads $ olcToolThreads $ olcWriteTimeout $ olcSpSessionlog $ olcDbCacheFree $ olcDbCacheSize $ olcDbDNcacheSize $ olcDbIDLcacheSize $ olcDbSearchStack $ olcDbShmKey $ mailPreferenceOption $ shadowLastChange $ shadowMin $ shadowMax $ shadowWarning $ shadowInactive $ shadowExpire $ shadowFlag $ ipServicePort $ ipProtocolNumber $ oncRpcNumber ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.13 (booleanMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.13 NAME 'booleanMatch' APPLIES ( hasSubordinates $ olcAddContentAcl $ olcGentleHUP $ olcHidden $ olcLastMod $ olcMirrorMode $ olcMonitoring $ olcReadOnly $ olcReverseLookup $ olcSyncUseSubentry $ olcSpNoPresent $ olcSpReloadHint $ olcDbChecksum $ olcDbNoSync $ olcDbDirtyRead $ olcDbLinearIndex ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.11 (caseIgnoreListMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.11 NAME 'caseIgnoreListMatch' APPLIES ( postalAddress $ registeredAddress $ homePostalAddress ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.9 (numericStringOrderingMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.9 NAME 'numericStringOrderingMatch' APPLIES ( x121Address $ internationaliSDNNumber ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.8 (numericStringMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.8 NAME 'numericStringMatch' APPLIES ( x121Address $ internationaliSDNNumber ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.7 (caseExactSubstringsMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.7 NAME 'caseExactSubstringsMatch' APPLIES ( serialNumber $ c $ telephoneNumber $ destinationIndicator $ dnQualifier $ homePhone $ mobile $ pager ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.5 (caseExactMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.5 NAME 'caseExactMatch' APPLIES ( supportedSASLMechanisms $ vendorName $ vendorVersion $ ref $ name $ cn $ uid $ labeledURI $ description $ olcConfigFile $ olcConfigDir $ olcAccess $ olcAllows $ olcArgsFile $ olcAttributeOptions $ olcAttributeTypes $ olcAuthIDRewrite $ olcAuthzPolicy $ olcAuthzRegexp $ olcBackend $ olcDatabase $ olcDisallows $ olcDitContentRules $ olcExtraAttrs $ olcInclude $ olcLdapSyntaxes $ olcLimits $ olcLogFile $ olcLogLevel $ olcModuleLoad $ olcModulePath $ olcObjectClasses $ olcObjectIdentifier $ olcOverlay $ olcPasswordCryptSaltFormat $ olcPasswordHash $ olcPidFile $ olcPlugin $ olcPluginLogFile $ olcReferral $ olcReplica $ olcReplicaArgsFile $ olcReplicaPidFile $ olcReplogFile $ olcRequires $ olcRestrict $ olcRootDSE $ olcRootPW $ olcSaslAuxprops $ olcSaslHost $ olcSaslRealm $ olcSaslSecProps $ olcSecurity $ olcServerID $ olcSizeLimit $ olcSortVals $ olcSubordinate $ olcSyncrepl $ olcTCPBuffer $ olcTimeLimit $ olcTLSCACerti
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.4 (caseIgnoreSubstringsMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.4 NAME 'caseIgnoreSubstringsMatch' APPLIES ( serialNumber $ c $ telephoneNumber $ destinationIndicator $ dnQualifier $ homePhone $ mobile $ pager ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.3 (caseIgnoreOrderingMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.2 (caseIgnoreMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.2 NAME 'caseIgnoreMatch' APPLIES ( supportedSASLMechanisms $ vendorName $ vendorVersion $ ref $ name $ cn $ uid $ labeledURI $ description $ olcConfigFile $ olcConfigDir $ olcAccess $ olcAllows $ olcArgsFile $ olcAttributeOptions $ olcAttributeTypes $ olcAuthIDRewrite $ olcAuthzPolicy $ olcAuthzRegexp $ olcBackend $ olcDatabase $ olcDisallows $ olcDitContentRules $ olcExtraAttrs $ olcInclude $ olcLdapSyntaxes $ olcLimits $ olcLogFile $ olcLogLevel $ olcModuleLoad $ olcModulePath $ olcObjectClasses $ olcObjectIdentifier $ olcOverlay $ olcPasswordCryptSaltFormat $ olcPasswordHash $ olcPidFile $ olcPlugin $ olcPluginLogFile $ olcReferral $ olcReplica $ olcReplicaArgsFile $ olcReplicaPidFile $ olcReplogFile $ olcRequires $ olcRestrict $ olcRootDSE $ olcRootPW $ olcSaslAuxprops $ olcSaslHost $ olcSaslRealm $ olcSaslSecProps $ olcSecurity $ olcServerID $ olcSizeLimit $ olcSortVals $ olcSubordinate $ olcSyncrepl $ olcTCPBuffer $ olcTimeLimit $ olcTLSCACert
Sep 18 10:56:04 Storage-01 slapd[47199]:     1.2.36.79672281.1.13.3 (rdnMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.1 (distinguishedNameMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.1 NAME 'distinguishedNameMatch' APPLIES ( creatorsName $ modifiersName $ subschemaSubentry $ entryDN $ namingContexts $ aliasedObjectName $ dynamicSubtrees $ distinguishedName $ seeAlso $ olcDefaultSearchBase $ olcRootDN $ olcSchemaDN $ olcSuffix $ olcUpdateDN $ olcRelay $ member $ owner $ roleOccupant $ manager $ documentAuthor $ secretary $ associatedName $ dITRedirect ) )
Sep 18 10:56:04 Storage-01 slapd[47199]:     2.5.13.0 (objectIdentifierMatch): 
Sep 18 10:56:04 Storage-01 slapd[47199]: matchingRuleUse: ( 2.5.13.0 NAME 'objectIdentifierMatch' APPLIES ( supportedControl $ supportedExtension $ supportedFeatures $ supportedApplicationContext ) )
Sep 18 10:56:04 Storage-01 slapd[47200]: slapd startup: initiated.
Sep 18 10:56:04 Storage-01 slapd[47200]: backend_startup_one: starting "cn=config"
Sep 18 10:56:04 Storage-01 slapd[47200]: config_back_db_open
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "cn=config"
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "cn=module{0}"
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "cn=schema"
Sep 18 10:56:04 Storage-01 slapd[47200]: >>> dnNormalize: <cn={0}core>
Sep 18 10:56:04 Storage-01 slapd[47200]: <<< dnNormalize: <cn={0}core>
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "cn={0}core"
Sep 18 10:56:04 Storage-01 slapd[47200]: >>> dnNormalize: <cn={1}cosine>
Sep 18 10:56:04 Storage-01 slapd[47200]: <<< dnNormalize: <cn={1}cosine>
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "cn={1}cosine"
Sep 18 10:56:04 Storage-01 slapd[47200]: >>> dnNormalize: <cn={2}inetorgperson>
Sep 18 10:56:04 Storage-01 slapd[47200]: <<< dnNormalize: <cn={2}inetorgperson>
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "cn={2}inetorgperson"
Sep 18 10:56:04 Storage-01 slapd[47200]: >>> dnNormalize: <cn={3}nis>
Sep 18 10:56:04 Storage-01 slapd[47200]: <<< dnNormalize: <cn={3}nis>
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "cn={3}nis"
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "olcDatabase={-1}frontend"
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "olcDatabase={0}config"
Sep 18 10:56:04 Storage-01 slapd[47200]: config_build_entry: "olcDatabase={1}bdb"
Sep 18 10:56:04 Storage-01 slapd[47200]: backend_startup_one: starting "dc=mydomain,dc=local"
Sep 18 10:56:04 Storage-01 slapd[47200]: bdb_db_open: database "dc=mydomain,dc=local": unclean shutdown detected; attempting recovery.
Sep 18 10:56:04 Storage-01 slapd[47200]: bdb_db_open: database "dc=mydomain,dc=local": dbenv_open(/var/db/openLDAP).
Sep 18 10:56:04 Storage-01 slapd[47200]: slapd starting
Sep 18 10:56:05 Storage-01 slapd[47200]: slap_listener_activate(8): 
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> slap_listener(ldap:///)
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(12): got connid=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(12): checking for input on id=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x77, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1000 op=0 do_extended
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_extended: err=0 oid= len=0
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=1 tag=120 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(12): got connid=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(12): checking for input on id=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(12): got connid=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(12): checking for input on id=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(12): unable to get TLS client DN, error=49 id=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(12): got connid=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(12): checking for input on id=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x60, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1000 op=1 do_bind
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: <<< dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>, <cn=admin,dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: do_bind: version=3 dn="cn=admin,dc=mydomain,dc=local" method=128
Sep 18 10:56:05 Storage-01 slapd[47200]: do_bind: v3 bind: "cn=admin,dc=mydomain,dc=local" to "cn=admin,dc=mydomain,dc=local"
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_result: conn=1000 op=1 p=3
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=2 tag=97 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(12): got connid=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(12): checking for input on id=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x63, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1000 op=2 do_search
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_search
Sep 18 10:56:05 Storage-01 slapd[47200]: bdb_dn2entry("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_dn2id("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_dn2id: got id=0x1
Sep 18 10:56:05 Storage-01 slapd[47200]: entry_decode: "dc=mydomain,dc=local"
Sep 18 10:56:05 Storage-01 slapd[47200]: <= entry_decode(dc=mydomain,dc=local)
Sep 18 10:56:05 Storage-01 slapd[47200]: search_candidates: base="dc=mydomain,dc=local" (0x00000001) scope=2
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_dn2idl("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read: failed (-30988)
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=0, first=0, last=0
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read 7 candidates
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=7, first=5, last=16
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (gidNumber)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read 2 candidates
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=2, first=10, last=11
Sep 18 10:56:05 Storage-01 slapd[47200]: bdb_search_candidates: id=1 first=10 last=10
Sep 18 10:56:05 Storage-01 slapd[47200]: entry_decode: "cn=corpuser,ou=groups,dc=mydomain,dc=local"
Sep 18 10:56:05 Storage-01 slapd[47200]: <= entry_decode(cn=corpuser,ou=groups,dc=mydomain,dc=local)
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_dn2id("ou=groups,dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_dn2id: got id=0x3
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_dn2id("cn=corpuser,ou=groups,dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_dn2id: got id=0xa
Sep 18 10:56:05 Storage-01 slapd[47200]: => send_search_entry: conn 1000 dn="cn=corpuser,ou=groups,dc=mydomain,dc=local"
Sep 18 10:56:05 Storage-01 slapd[47200]: <= send_search_entry: conn 1000 exit.
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_result: conn=1000 op=2 p=3
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=3 tag=101 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: slap_listener_activate(8): 
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> slap_listener(ldap:///)
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(17): got connid=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(17): checking for input on id=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x77, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1001 op=0 do_extended
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_extended: err=0 oid= len=0
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=1 tag=120 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(17): got connid=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(17): checking for input on id=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(17): got connid=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(17): checking for input on id=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(17): unable to get TLS client DN, error=49 id=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(17): got connid=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(17): checking for input on id=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x60, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1001 op=1 do_bind
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: <<< dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>, <cn=admin,dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: do_bind: version=3 dn="cn=admin,dc=mydomain,dc=local" method=128
Sep 18 10:56:05 Storage-01 slapd[47200]: do_bind: v3 bind: "cn=admin,dc=mydomain,dc=local" to "cn=admin,dc=mydomain,dc=local"
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_result: conn=1001 op=1 p=3
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=2 tag=97 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(17): got connid=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(17): checking for input on id=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x63, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1001 op=2 do_search
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_search
Sep 18 10:56:05 Storage-01 slapd[47200]: bdb_dn2entry("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: search_candidates: base="dc=mydomain,dc=local" (0x00000001) scope=2
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_dn2idl("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read: failed (-30988)
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=0, first=0, last=0
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read 7 candidates
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=7, first=5, last=16
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (gidNumber)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read 2 candidates
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=2, first=10, last=11
Sep 18 10:56:05 Storage-01 slapd[47200]: bdb_search_candidates: id=1 first=10 last=10
Sep 18 10:56:05 Storage-01 slapd[47200]: => send_search_entry: conn 1001 dn="cn=corpuser,ou=groups,dc=mydomain,dc=local"
Sep 18 10:56:05 Storage-01 slapd[47200]: <= send_search_entry: conn 1001 exit.
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_result: conn=1001 op=2 p=3
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=3 tag=101 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(12): got connid=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(12): checking for input on id=1000
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x63, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1000 op=3 do_search
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_search
Sep 18 10:56:05 Storage-01 slapd[47200]: bdb_dn2entry("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: search_candidates: base="dc=mydomain,dc=local" (0x00000001) scope=2
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_dn2idl("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read: failed (-30988)
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=0, first=0, last=0
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read 7 candidates
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=7, first=5, last=16
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (gidNumber)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read 2 candidates
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=2, first=10, last=11
Sep 18 10:56:05 Storage-01 slapd[47200]: bdb_search_candidates: id=1 first=10 last=10
Sep 18 10:56:05 Storage-01 slapd[47200]: => send_search_entry: conn 1000 dn="cn=corpuser,ou=groups,dc=mydomain,dc=local"
Sep 18 10:56:05 Storage-01 slapd[47200]: <= send_search_entry: conn 1000 exit.
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_result: conn=1000 op=3 p=3
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=4 tag=101 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(17): got connid=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(17): checking for input on id=1001
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x63, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1001 op=3 do_search
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_search
Sep 18 10:56:05 Storage-01 slapd[47200]: bdb_dn2entry("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: search_candidates: base="dc=mydomain,dc=local" (0x00000001) scope=2
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_dn2idl("dc=mydomain,dc=local")
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read: failed (-30988)
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=0, first=0, last=0
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read 7 candidates
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=7, first=5, last=16
Sep 18 10:56:05 Storage-01 slapd[47200]: => bdb_equality_candidates (gidNumber)
Sep 18 10:56:05 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_index_read 2 candidates
Sep 18 10:56:05 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=2, first=10, last=11
Sep 18 10:56:05 Storage-01 slapd[47200]: bdb_search_candidates: id=1 first=10 last=10
Sep 18 10:56:05 Storage-01 slapd[47200]: => send_search_entry: conn 1001 dn="cn=corpuser,ou=groups,dc=mydomain,dc=local"
Sep 18 10:56:05 Storage-01 slapd[47200]: <= send_search_entry: conn 1001 exit.
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_result: conn=1001 op=3 p=3
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=4 tag=101 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: slap_listener_activate(8): 
Sep 18 10:56:05 Storage-01 slapd[47200]: >>> slap_listener(ldap:///)
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(18): got connid=1002
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(18): checking for input on id=1002
Sep 18 10:56:05 Storage-01 slapd[47200]: op tag 0x77, time 1411030565
Sep 18 10:56:05 Storage-01 slapd[47200]: conn=1002 op=0 do_extended
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_extended: err=0 oid= len=0
Sep 18 10:56:05 Storage-01 slapd[47200]: send_ldap_response: msgid=1 tag=120 err=0
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(18): got connid=1002
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(18): checking for input on id=1002
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_get(18): got connid=1002
Sep 18 10:56:05 Storage-01 slapd[47200]: connection_read(18): checking for input on id=1002
Sep 18 10:56:06 Storage-01 slapd[47200]: connection_read(18): unable to get TLS client DN, error=49 id=1002
Sep 18 10:56:06 Storage-01 slapd[47200]: connection_get(18): got connid=1002
Sep 18 10:56:06 Storage-01 slapd[47200]: connection_read(18): checking for input on id=1002
Sep 18 10:56:06 Storage-01 slapd[47200]: op tag 0x60, time 1411030566
Sep 18 10:56:06 Storage-01 slapd[47200]: conn=1002 op=1 do_bind
Sep 18 10:56:06 Storage-01 slapd[47200]: >>> dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>
Sep 18 10:56:06 Storage-01 slapd[47200]: <<< dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>, <cn=admin,dc=mydomain,dc=local>
Sep 18 10:56:06 Storage-01 slapd[47200]: do_bind: version=3 dn="cn=admin,dc=mydomain,dc=local" method=128
Sep 18 10:56:06 Storage-01 slapd[47200]: do_bind: v3 bind: "cn=admin,dc=mydomain,dc=local" to "cn=admin,dc=mydomain,dc=local"
Sep 18 10:56:06 Storage-01 slapd[47200]: send_ldap_result: conn=1002 op=1 p=3
Sep 18 10:56:06 Storage-01 slapd[47200]: send_ldap_response: msgid=2 tag=97 err=0
Sep 18 10:56:06 Storage-01 slapd[47200]: connection_get(18): got connid=1002
Sep 18 10:56:06 Storage-01 slapd[47200]: connection_read(18): checking for input on id=1002
Sep 18 10:56:06 Storage-01 slapd[47200]: op tag 0x63, time 1411030566
Sep 18 10:56:06 Storage-01 slapd[47200]: conn=1002 op=2 do_search
Sep 18 10:56:06 Storage-01 slapd[47200]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 10:56:06 Storage-01 slapd[47200]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 10:56:06 Storage-01 slapd[47200]: => bdb_search
Sep 18 10:56:06 Storage-01 slapd[47200]: bdb_dn2entry("dc=mydomain,dc=local")
Sep 18 10:56:06 Storage-01 slapd[47200]: search_candidates: base="dc=mydomain,dc=local" (0x00000001) scope=2
Sep 18 10:56:06 Storage-01 slapd[47200]: => bdb_dn2idl("dc=mydomain,dc=local")
Sep 18 10:56:06 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:06 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:06 Storage-01 slapd[47200]: <= bdb_index_read: failed (-30988)
Sep 18 10:56:06 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=0, first=0, last=0
Sep 18 10:56:06 Storage-01 slapd[47200]: => bdb_equality_candidates (objectClass)
Sep 18 10:56:06 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:06 Storage-01 slapd[47200]: <= bdb_index_read 7 candidates
Sep 18 10:56:06 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=7, first=5, last=16
Sep 18 10:56:06 Storage-01 slapd[47200]: => bdb_equality_candidates (gidNumber)
Sep 18 10:56:06 Storage-01 slapd[47200]: => key_read
Sep 18 10:56:06 Storage-01 slapd[47200]: <= bdb_index_read 2 candidates
Sep 18 10:56:06 Storage-01 slapd[47200]: <= bdb_equality_candidates: id=2, first=10, last=11
Sep 18 10:56:06 Storage-01 slapd[47200]: bdb_search_candidates: id=1 first=10 last=10
Sep 18 10:56:06 Storage-01 slapd[47200]: => send_search_entry: conn 1002 dn="cn=corpuser,ou=groups,dc=mydomain,dc=local"
Sep 18 10:56:06 Storage-01 slapd[47200]: <= send_search_entry: conn 1002 exit.
Sep 18 10:56:06 Storage-01 slapd[47200]: send_ldap_result: conn=1002 op=2 p=3
Sep 18 10:56:06 Storage-01 slapd[47200]: send_ldap_response: msgid=3 tag=101 err=0
[...]
Meanwhile /var/log/messages holds following information:
Code:
[...]
Sep 18 10:56:02 Storage-01 nslcd[1392]: [3fd8cb] <group=2003> ldap_result() failed: Can't contact LDAP server
Sep 18 10:56:02 Storage-01 kernel: pid 56523 (slapd), uid 389: exited on signal 11
Sep 18 10:56:05 Storage-01 nslcd[1392]: [3fd8cb] <group=2003> ldap_start_tls_s() failed (uri=ldap://127.0.0.1/): Can't contact LDAP server: Operation timed out
Sep 18 10:56:05 Storage-01 nslcd[1392]: [3fd8cb] <group=2003> failed to bind to LDAP server ldap://127.0.0.1/: Can't contact LDAP server: Operation timed out
Sep 18 10:56:05 Storage-01 nslcd[1392]: [3fd8cb] <group=2003> no available LDAP server found: Can't contact LDAP server: Operation timed out
Sep 18 10:56:05 Storage-01 nslcd[1392]: [270949] <group=2003> ldap_result() failed: Can't contact LDAP server: Connection reset by peer
Sep 18 10:56:05 Storage-01 nslcd[1392]: [270949] <group=2003> ldap_abandon() failed to abandon search: Can't contact LDAP server: Connection reset by peer
Sep 18 10:56:05 Storage-01 nslcd[1392]: [d2f612] <group=2003> ldap_result() failed: Can't contact LDAP server
Sep 18 10:56:05 Storage-01 nslcd[1392]: [d2f612] <group=2003> ldap_abandon() failed to abandon search: Can't contact LDAP server: Connection reset by peer
Sep 18 10:56:05 Storage-01 nslcd[1392]: [ea1ae1] <group=2003> ldap_result() failed: Can't contact LDAP server
Sep 18 10:56:05 Storage-01 nslcd[1392]: [ea1ae1] <group=2003> ldap_abandon() failed to abandon search: Can't contact LDAP server: Connection reset by peer
[...]
In the meanwhile Storage-03 also had a couple of sporadic crashes ... but I was to slow to save the logs and newsyslog(8) deleted them. I'll still try to catch a new crash of Storage-03's slapd(8) and post them. According to my experience the logs of Storage-03 won't throw out more information than the logs of Storage-01 already do ... there is not really an error or so ... it just silently dies ;(
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Here is another crash of Storage-01 ... this is how sporadically this hapens ... ;(
Unfortunately there isn't really more to see than in the logs before:
Code:
[...]
Sep 18 18:50:44 Storage-01 slapd[12842]: send_ldap_response: msgid=2 tag=101 err=32
Sep 18 18:50:44 Storage-01 slapd[12842]: connection_get(19): got connid=1074
Sep 18 18:50:44 Storage-01 slapd[12842]: connection_read(19): checking for input on id=1074
Sep 18 18:50:44 Storage-01 slapd[12842]: ber_get_next on fd 19 failed errno=0 (No error: 0)
Sep 18 18:50:44 Storage-01 slapd[12842]: connection_close: conn=1074 sd=19
Sep 18 18:50:56 Storage-01 slapd[12842]: slap_listener_activate(8): 
Sep 18 18:50:56 Storage-01 slapd[12842]: >>> slap_listener(ldap:///)
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_get(19): got connid=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_read(19): checking for input on id=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: op tag 0x77, time 1411059056
Sep 18 18:50:56 Storage-01 slapd[12842]: conn=1075 op=0 do_extended
Sep 18 18:50:56 Storage-01 slapd[12842]: send_ldap_extended: err=0 oid= len=0
Sep 18 18:50:56 Storage-01 slapd[12842]: send_ldap_response: msgid=1 tag=120 err=0
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_get(19): got connid=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_read(19): checking for input on id=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_get(19): got connid=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_read(19): checking for input on id=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_read(19): unable to get TLS client DN, error=49 id=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_get(19): got connid=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_read(19): checking for input on id=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: op tag 0x60, time 1411059056
Sep 18 18:50:56 Storage-01 slapd[12842]: conn=1075 op=1 do_bind
Sep 18 18:50:56 Storage-01 slapd[12842]: >>> dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>
Sep 18 18:50:56 Storage-01 slapd[12842]: <<< dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>, <cn=admin,dc=mydomain,dc=local>
Sep 18 18:50:56 Storage-01 slapd[12842]: do_bind: version=3 dn="cn=admin,dc=mydomain,dc=local" method=128
Sep 18 18:50:56 Storage-01 slapd[12842]: do_bind: v3 bind: "cn=admin,dc=mydomain,dc=local" to "cn=admin,dc=mydomain,dc=local"
Sep 18 18:50:56 Storage-01 slapd[12842]: send_ldap_result: conn=1075 op=1 p=3
Sep 18 18:50:56 Storage-01 slapd[12842]: send_ldap_response: msgid=2 tag=97 err=0
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_get(19): got connid=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: connection_read(19): checking for input on id=1075
Sep 18 18:50:56 Storage-01 slapd[12842]: op tag 0x63, time 1411059056
Sep 18 18:50:56 Storage-01 slapd[12842]: conn=1075 op=2 do_search
Sep 18 18:50:56 Storage-01 slapd[12842]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 18:50:56 Storage-01 slapd[12842]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 18:50:56 Storage-01 slapd[12842]: => bdb_search
Sep 18 18:50:56 Storage-01 slapd[12842]: bdb_dn2entry("dc=mydomain,dc=local")
Sep 18 18:50:56 Storage-01 slapd[12842]: search_candidates: base="dc=mydomain,dc=local" (0x00000001) scope=2
Sep 18 18:50:56 Storage-01 slapd[12842]: => bdb_dn2idl("dc=mydomain,dc=local")
Sep 18 18:50:56 Storage-01 slapd[12842]: => bdb_equality_candidates (objectClass)
Sep 18 18:50:56 Storage-01 slapd[12842]: => key_read


==> Here it crashed and has been restarted by slapd_watcher


Sep 18 18:50:57 Storage-01 slapd[14097]: @(#) $OpenLDAP: slapd 2.4.39 (Aug 31 2014 12:59:44) $ 	root@Storage-01.mydomain.Local:/usr/ports/net/openldap24-server/work/openldap-2.4.39/servers/slapd
Sep 18 18:50:57 Storage-01 slapd[14097]: bdb_back_initialize: initialize BDB backend
Sep 18 18:50:57 Storage-01 slapd[14097]: bdb_back_initialize: Berkeley DB 4.8.30: (April  9, 2010)
Sep 18 18:50:57 Storage-01 slapd[14097]: >>> dnNormalize: <dc=mydomain,dc=local>
Sep 18 18:50:57 Storage-01 slapd[14097]: <<< dnNormalize: <dc=mydomain,dc=local>
Sep 18 18:50:57 Storage-01 slapd[14097]: >>> dnNormalize: <dc=mydomain,dc=local>
Sep 18 18:50:57 Storage-01 slapd[14097]: <<< dnNormalize: <dc=mydomain,dc=local>
Sep 18 18:50:57 Storage-01 slapd[14097]: bdb_db_init: Initializing BDB database
Sep 18 18:50:57 Storage-01 slapd[14097]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 18 18:50:57 Storage-01 slapd[14097]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 18 18:50:57 Storage-01 slapd[14097]: >>> dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>
Sep 18 18:50:57 Storage-01 slapd[14097]: <<< dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>, <cn=admin,dc=mydomain,dc=local>
Sep 18 18:50:57 Storage-01 slapd[14097]: >>> dnNormalize: <cn=Subschema>
Sep 18 18:50:57 Storage-01 slapd[14097]: <<< dnNormalize: <cn=subschema>
Sep 18 18:50:57 Storage-01 slapd[14097]: matching_rule_use_init
[...]
 

w5plt

Member

Reaction score: 4
Messages: 29

Leander,

Are you rotating your logs with newsyslog in a separate file outside of /var/log/messages. I have experienced similar behavior with OpenLDAP when I was testing several methods of rotating OpenLDAP Logs in a stand alone file separate from /var/log/messages.

Regards,

Scott
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Hi Scott,

Yes, I'm purposly logging slapd(8) specific traffic into /var/log/slapd.log via newsyslog. Is this a problem? Is slapd(8) dieing because it's logfile gets pulled away while it is running? Do I need to tell newsyslog something like path_to_pid_cmd_file and signal_number at the correlating slapd.conf line

Best Regards
Leander
 

w5plt

Member

Reaction score: 4
Messages: 29

Leander,

Can you post the contents of your /etc/syslog.conf and /etc/newsyslog.conf. Does any of the crashes of OpenLDAP correspond to the timing of the log file rotation?

Regards,

Scott
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Hi Scott,

Here is the /etc/syslog.conf
Code:
#==========================================#
#                syslog.conf               #
#==========================================#

*.err;kern.warning;auth.notice;mail.crit                        /dev/console
*.notice;authpriv.none;kern.debug;lpr.info;mail.crit;news.err   /var/log/messages
security.*                                      /var/log/security
auth.info;authpriv.info                         /var/log/auth.log
mail.info                                       /var/log/maillog
lpr.info                                        /var/log/lpd-errs
ftp.info                                        /var/log/xferlog
cron.*                                          /var/log/cron
!-devd
*.=debug                                        /var/log/debug.log
*.emerg                                         *

# uncomment this to log all writes to /dev/console to /var/log/console.log
# touch /var/log/console.log and chmod it to mode 600 before it will work
#console.info                                   /var/log/console.log

# uncomment this to enable logging of all log messages to /var/log/all.log
# touch /var/log/all.log and chmod it to mode 600 before it will work
#*.*                                            /var/log/all.log

# uncomment this to enable logging to a remote loghost named loghost
#*.*                                            @loghost

# uncomment these if you're running inn
# news.crit                                     /var/log/news/news.crit
# news.err                                      /var/log/news/news.err
# news.notice                                   /var/log/news/news.notice

# Uncomment this if you wish to see messages produced by devd
# !devd
# *.>=info                                       /var/log/devd.log

!ppp
*.*                                             /var/log/ppp.log
!*

# Log all OpenLDAP Messages
!slapd
*.*                                             /var/log/slapd.log

local3.*                                        /var/log/smartd.log
and here is the /etc/newsyslog.conf
Code:
# logfilename          [owner]    mode count size when  flags [/pid_file] [sig_num]
/var/log/all.log                        600  7     *    @T00  J
/var/log/amd.log                        644  7     100  *     J
/var/log/auth.log                       644  7     100  @0101T JC
/var/log/console.log                    600  5     100  *     J
/var/log/cron                           600  3     100  *     JC
/var/log/daily.log                      640  7     *    @T00  JN
/var/log/debug.log                      600  7     100  *     JC
/var/log/init.log                       644  3     100  *     J
/var/log/kerberos.log                   600  7     100  *     J
/var/log/lpd-errs                       644  7     100  *     JC
/var/log/maillog                        640  7     *    @T00  JC
/var/log/messages                       644  5     100  @0101T JC
/var/log/monthly.log                    640  12    *    $M1D0 JN
/var/log/pflog                          600  3     100  *     JB    /var/run/pflogd.pid
/var/log/ppp.log        root:network    640  3     100  *     JC
/var/log/devd.log                       644  3     100  *     JC
/var/log/security                       600  10    100  *     JC
/var/log/sendmail.st                    644  10    *    168   BN
/var/log/utx.log                        644  3     *    @01T05 B
/var/log/weekly.log                     640  5     *    $W6D0 JN
/var/log/xferlog                        600  7     100  *     JC
/var/log/ntp/ntpd.log  root:wheel       644  2     500  *     JNC
/var/log/userlog       root:wheel       600  3     500  *     JC
/var/log/slapd.log     root:wheel       600  5     500  *     JC
/var/log/modsec_audit.log root:wheel    640  5     800  *     JC
/var/log/samba4/log.nmbd                root:wheel  644  2     500  *     JC
/var/log/samba4/log.smbd                root:wheel  644  2     500  *     JC
/var/log/samba4/log.wb-BUILTIN          root:wheel  644  2     500  *     JC
/var/log/samba4/log.wb-STORAGE-03       root:wheel  644  2     500  *     JC
/var/log/samba4/log.winbindd            root:wheel  644  2     500  *     JC
/var/log/samba4/log.winbindd-idmap      root:wheel  644  2     500  *     JC
/var/log/smartd.log                     root:wheel  755  2     500  *     JC
/var/log/rsyncd.log                     644  2     500  *     CJN
/var/log/munin/munin-*.log                  root:wheel 644  7     1024 *     GJ /var/run/munin/munin-node.pid
/usr/local/www/munin.storage-03.mydomain.local/logs/munin/munin-*.log    admin:munin 770  2     1024 *     GJ /var/run/munin/munin-node.pid
/usr/local/www/*/logs/httpd-*.log    :    755    9    1024    *    GB    /var/run/httpd.pid 30
/var/log/munin/*.log munin:munin        644  7     *    @T00  GNWZ
/var/log/munin/munin-node.log                   644  7     *    @T00  Z /var/run/munin/munin-node.pid
w5plt said:
Does any of the crashes of OpenLDAP correspond to the timing of the log file rotation?
No, not that I know of. newsyslog rotates either way before or way afterwards ... Otherwhise I would see something like newsyslog[13193]: logfile turned over due to size>500K right before or after the crash in /var/log/slapd.log.
Otherwhise, I have to admit, I never understood syslogd(8) a 100%. I always had the hope I can put each logging clients like slapd(8) on a separate individually defined channel. Theses days I figured, that there only exist channels like local1-7 ... and a expression filter like I used with slapd(8). Nevertheless, I have my doubts that newsyslog(8) or syslogd(8) is the reason for the sporadic crashes. What do you think?

Best Regards,
Leander
 

w5plt

Member

Reaction score: 4
Messages: 29

Leander,

I had my configuration setup almost exactly the way you do now and I experienced the same issue. I did change my newsyslog entry to utilize the "R" Flag to execute a script which restarts the daemon slapd when the log file rotates. Since I have a N-way Multi-Master configuration I set the log rotation at different times to not affect availability of the service to clients.

Over the weekend, I'm will revert my /etc/newsyslog.conf, on my development servers, back to a configuration similar to yours and see if I can duplicate the issue.

In any event, we need to explore using different tools to determine what is affecting your system - perhaps others can chime in with some suggestions.

Regards,

Scott
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Seems like we're really not alone with this issue

Thread 29370

The newsyslog(8) "R"-flag is still an ugly solution though ;)

At first it sounds like mentioning the "N"-flag should solve the problem, since no signals will be send out any more. But then again: did newsyslog send out any signals to slapd before? How? Did it do a kind of lsof and kill the according file-holding process which is slapd(8)? This sounds a bit too automatic for my experience - can you confirm this?

I did some testing.I did a rm() /var/log/slapd.log while [pman=s]slapd[/pman] was still running. Expected test results:
  • slapd(8) dies right away or when it tries to log something the very next time
  • slapd(8) continious running happily and re-creates /var/log/slapd.log when next log is in query.

My result thus far is, that is continious running. Unfortunately /var/log/slapd.log has not been re-created automatically by slapd(8) yet.




[EDIT]

This sounds like it refers further to syslogd() in order to kill slapd ... ?!

man newsyslog.conf

[...]
path_to_pid_cmd_file
This optional field specifies the file name containing a daemon's
process ID or to find a group process ID if the U flag was speci‐
fied. If this field is present, a signal_number is sent to the
process ID contained in this file. If this field is not present
and the N flag has not been specified, then a SIGHUP signal will
be sent to syslogd(8) or to the process id found in the file
specified by newsyslog(8)'s -S switch. This field must start
with ‘/’ in order to be recognized properly. When used with the
R flag, the file is treated as a path to a binary to be executed
by the newsyslog(8) after rotation instead of sending the signal
out.
[...]
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Eventually I also caught the logs of Storage-03 (==> the one with the MDB backend) as described in the first post. It looks pretty much the same as the one of Storage-01 (==> the one with the BDB backend). I highlighted the part of the log where slapd(8) died with "==> slapd(8) died"

Code:
[...]
Sep 21 17:01:47 Storage-03 slapd[15046]: >>> slap_listener(ldap:///)
Sep 21 17:01:47 Storage-03 slapd[15046]: connection_get(19): got connid=6658
Sep 21 17:01:47 Storage-03 slapd[15046]: connection_read(19): checking for input on id=6658
Sep 21 17:01:47 Storage-03 slapd[15046]: op tag 0x60, time 1411311707
Sep 21 17:01:47 Storage-03 slapd[15046]: conn=6658 op=0 do_bind
Sep 21 17:01:47 Storage-03 slapd[15046]: >>> dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>
Sep 21 17:01:47 Storage-03 slapd[15046]: <<< dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>, <cn=admin,dc=mydomain,dc=local>
Sep 21 17:01:47 Storage-03 slapd[15046]: do_bind: version=3 dn="cn=admin,dc=mydomain,dc=local" method=128
Sep 21 17:01:47 Storage-03 slapd[15046]: do_bind: v3 bind: "cn=admin,dc=mydomain,dc=local" to "cn=admin,dc=mydomain,dc=local"
Sep 21 17:01:47 Storage-03 slapd[15046]: send_ldap_result: conn=6658 op=0 p=3
Sep 21 17:01:47 Storage-03 slapd[15046]: send_ldap_response: msgid=1 tag=97 err=0
Sep 21 17:01:47 Storage-03 slapd[15046]: connection_get(19): got connid=6658
Sep 21 17:01:47 Storage-03 slapd[15046]: connection_read(19): checking for input on id=6658
Sep 21 17:01:47 Storage-03 slapd[15046]: op tag 0x63, time 1411311707
Sep 21 17:01:47 Storage-03 slapd[15046]: conn=6658 op=1 do_search
Sep 21 17:01:47 Storage-03 slapd[15046]: >>> dnPrettyNormal: <cn=PDU,cn=Statistics,cn=Monitor>
Sep 21 17:01:47 Storage-03 slapd[15046]: <<< dnPrettyNormal: <cn=PDU,cn=Statistics,cn=Monitor>, <cn=pdu,cn=statistics,cn=monitor>
Sep 21 17:01:47 Storage-03 slapd[15046]: send_ldap_result: conn=6658 op=1 p=3
Sep 21 17:01:47 Storage-03 slapd[15046]: send_ldap_response: msgid=2 tag=101 err=32
Sep 21 17:01:47 Storage-03 slapd[15046]: connection_get(19): got connid=6658
Sep 21 17:01:47 Storage-03 slapd[15046]: connection_read(19): checking for input on id=6658
Sep 21 17:01:47 Storage-03 slapd[15046]: ber_get_next on fd 19 failed errno=0 (No error: 0)
Sep 21 17:01:47 Storage-03 slapd[15046]: connection_close: conn=6658 sd=19
Sep 21 17:04:40 Storage-03 slapd[15046]: connection_get(16): got connid=6636
Sep 21 17:04:40 Storage-03 slapd[15046]: connection_read(16): checking for input on id=6636
Sep 21 17:04:40 Storage-03 slapd[15046]: op tag 0x63, time 1411311880
Sep 21 17:04:40 Storage-03 slapd[15046]: conn=6636 op=13 do_search
Sep 21 17:04:40 Storage-03 slapd[15046]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 21 17:04:40 Storage-03 slapd[15046]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>


==> slapd(8) died


Sep 21 17:04:42 Storage-03 slapd[12593]: @(#) $OpenLDAP: slapd 2.4.39 (Aug 31 2014 12:58:38) $ 	root@Storage-03.mydomain.Local:/usr/ports/net/openldap24-server/work/openldap-2.4.39/servers/slapd
Sep 21 17:04:42 Storage-03 slapd[12593]: mdb_back_initialize: initialize MDB backend
Sep 21 17:04:42 Storage-03 slapd[12593]: mdb_back_initialize: MDB 0.9.11: (January 15, 2014)
Sep 21 17:04:42 Storage-03 slapd[12593]: >>> dnNormalize: <dc=mydomain,dc=local>
Sep 21 17:04:42 Storage-03 slapd[12593]: <<< dnNormalize: <dc=mydomain,dc=local>
Sep 21 17:04:42 Storage-03 slapd[12593]: >>> dnNormalize: <dc=mydomain,dc=local>
Sep 21 17:04:42 Storage-03 slapd[12593]: <<< dnNormalize: <dc=mydomain,dc=local>
Sep 21 17:04:42 Storage-03 slapd[12593]: mdb_db_init: Initializing mdb database
Sep 21 17:04:42 Storage-03 slapd[12593]: >>> dnPrettyNormal: <dc=mydomain,dc=local>
Sep 21 17:04:42 Storage-03 slapd[12593]: <<< dnPrettyNormal: <dc=mydomain,dc=local>, <dc=mydomain,dc=local>
Sep 21 17:04:42 Storage-03 slapd[12593]: >>> dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>
Sep 21 17:04:42 Storage-03 slapd[12593]: <<< dnPrettyNormal: <cn=admin,dc=mydomain,dc=local>, <cn=admin,dc=mydomain,dc=local>
Sep 21 17:04:42 Storage-03 slapd[12593]: >>> dnNormalize: <cn=Subschema>
Sep 21 17:04:42 Storage-03 slapd[12593]: <<< dnNormalize: <cn=subschema>
Sep 21 17:04:42 Storage-03 slapd[12593]: matching_rule_use_init
Sep 21 17:04:42 Storage-03 slapd[12593]:     1.2.840.113556.1.4.804 (integerBitOrMatch): 
Sep 21 17:04:42 Storage-03 slapd[12593]: matchingRuleUse: ( 1.2.840.113556.1.4.804 NAME 'integerBitOrMatch' APPLIES ( supportedLDAPVersion $ entryTtl $ uidNumber $ gidNumber $ olcConcurrency $ olcConnMaxPending $ olcConnMaxPendingAuth $ olcIdleTimeout $ olcIndexSubstrIfMinLen $ olcIndexSubstrIfMaxLen $ olcIndexSubstrAnyLen $ olcIndexSubstrAnyStep $ olcIndexIntLen $ olcListenerThreads $ olcLocalSSF $ olcMaxDerefDepth $ olcReplicationInterval $ olcSockbufMaxIncoming $ olcSockbufMaxIncomingAuth $ olcThreads $ olcToolThreads $ olcWriteTimeout $ olcSpSessionlog $ olcDbMaxReaders $ olcDbMaxSize $ olcDbSearchStack $ mailPreferenceOption $ shadowLastChange $ shadowMin $ shadowMax $ shadowWarning $ shadowInactive $ shadowExpire $ shadowFlag $ ipServicePort $ ipProtocolNumber $ oncRpcNumber ) )
Sep 21 17:04:42 Storage-03 slapd[12593]:     1.2.840.113556.1.4.803 (integerBitAndMatch): 
Sep 21 17:04:42 Storage-03 slapd[12593]: matchingRuleUse: ( 1.2.840.113556.1.4.803 NAME 'integerBitAndMatch' APPLIES ( supportedLDAPVersion $ entryTtl $ uidNumber $ gidNumber $ olcConcurrency $ olcConnMaxPending $ olcConnMaxPendingAuth $ olcIdleTimeout $ olcIndexSubstrIfMinLen $ olcIndexSubstrIfMaxLen $ olcIndexSubstrAnyLen $ olcIndexSubstrAnyStep $ olcIndexIntLen $ olcListenerThreads $ olcLocalSSF $ olcMaxDerefDepth $ olcReplicationInterval $ olcSockbufMaxIncoming $ olcSockbufMaxIncomingAuth $ olcThreads $ olcToolThreads $ olcWriteTimeout $ olcSpSessionlog $ olcDbMaxReaders $ olcDbMaxSize $ olcDbSearchStack $ mailPreferenceOption $ shadowLastChange $ shadowMin $ shadowMax $ shadowWarning $ shadowInactive $ shadowExpire $ shadowFlag $ ipServicePort $ ipProtocolNumber $ oncRpcNumber ) )
Sep 21 17:04:42 Storage-03 slapd[12593]:     1.3.6.1.4.1.1466.109.114.2 (caseIgnoreIA5Match): 
Sep 21 17:04:42 Storage-03 slapd[12593]: matchingRuleUse: ( 1.3.6.1.4.1.1466.109.114.2 NAME 'caseIgnoreIA5Match' APPLIES ( altServer $ c $ mail $ dc $ associatedDomain $ email $ aRecord $ mDRecord $ mXRecord $ nSRecord $ sOARecord $ cNAMERecord $ janetMailbox $ gecos $ homeDirectory $ loginShell $ memberUid $ memberNisNetgroup $ ipHostNumber $ ipNetworkNumber $ ipNetmaskNumber $ macAddress $ bootFile $ nisMapEntry ) )
Sep 21 17:04:42 Storage-03 slapd[12593]:     1.3.6.1.4.1.1466.109.114.1 (caseExactIA5Match): 
Sep 21 17:04:42 Storage-03 slapd[12593]: matchingRuleUse: ( 1.3.6.1.4.1.1466.109.114.1 NAME 'caseExactIA5Match' APPLIES ( altServer $ c $ mail $ dc $ associatedDomain $ email $ aRecord $ mDRecord $ mXRecord $ nSRecord $ sOARecord $ cNAMERecord $ janetMailbox $ gecos $ homeDirectory $ loginShell $ memberUid $ memberNisNetgroup $ ipHostNumber $ ipNetworkNumber $ ipNetmaskNumber $ macAddress $ bootFile $ nisMapEntry ) )
Sep 21 17:04:42 Storage-03 slapd[12593]:     2.5.13.39 (certificateListMatch): 
Sep 21 17:04:42 Storage-03 slapd[12593]:     2.5.13.38 (certificateListExactMatch): 
Sep 21 17:04:42 Storage-03 slapd[12593]: matchingRuleUse: ( 2.5.13.38 NAME 'certificateListExactMatch' APPLIES ( authorityRevocationList $ certificateRevocationList $ deltaRevocationList ) )
Sep 21 17:04:42 Storage-03 slapd[12593]:     2.5.13.35 (certificateMatch): 
Sep 21 17:04:42 Storage-03 slapd[12593]:     2.5.13.34 (certificateExactMatch): 
[...]
Best Regards
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Does anyone know where it is set, when / in what period of time newsyslog(8) is executed by default?

Here is a little history snippet, of when my slapd_watcher script had to start slapd(8), since it died.

OpenLDAP_Watcher.png


It informs me via mail(1) everytime it had to re-start slapd again. The slapd_watcher scans ps(1) in a 3 second interval or slapd(8) existency. If slapd(8) doesn't exist in ps(1) than slapd_watcher starts slapd(8). As you can see, most of the time it was an even hour when slapd(8) died ... only rarely on an odd time as highlighted.

My interpretation thus far is:
  • The odd ones are confusing me. I don't know what could have caused them?
  • The restarts on an even hour are an indicator to newsyslog(8). This is mainly a guess because the rotated logfiles all have a even timestamp as well.
I wanted to confirm my interpretation of the even hours by having a look into
Code:
cat /etc/defaults/rc.conf | grep 'newsyslog'
newsyslog_enable="YES"  # Run newsyslog at startup.
newsyslog_flags="-CN"  # Newsyslog flags to create marked files
and
Code:
cat /etc/rc.d/newsyslog
#!/bin/sh
#
# $FreeBSD: release/10.0.0/etc/rc.d/newsyslog 240336 2012-09-11 05:04:59Z obrien $
#

# PROVIDE: newsyslog
# REQUIRE: FILESYSTEMS mountcritremote

. /etc/rc.subr

name="newsyslog"
rcvar="newsyslog_enable"
required_files="/etc/newsyslog.conf"
command="/usr/sbin/${name}"
start_cmd="newsyslog_start"
stop_cmd=":"

newsyslog_start()
{
  check_startmsgs && echo -n 'Creating and/or trimming log files'
  ${command} ${rc_flags}
  check_startmsgs && echo '.'
}

load_rc_config $name
run_rc_command "$1"

Unfortunately I wasn't able to read out a periodical call of newsyslog(8) on every even hour. the man of newsyslog(8) states:

The newsyslog utility should be scheduled to run periodically by cron(8). When it is executed it archives log files if necessary.
But I also couldn't find any according cronjobs:
Code:
while read USERNAME; do
  echo -e "${EMY}\nGet crontab of ${USERNAME}${NONE}\n"
  echo -e "${W}$(su -m ${USERNAME} -c 'crontab -l')${NONE}\n"
done <<< "$(getent passwd | awk -F ':' '{print $1}')"
So again - does anyone know where it is set, when / in what period of time newsyslog is executed by default? I know for fact, that is not run as deamon - so something must have control over it - something like cron - but it's not cron. What is it? ;)

Thanks
 

DutchDaemon

Administrator
Staff member
Administrator
Moderator
Developer

Reaction score: 2,786
Messages: 11,279

/etc/crontab (that is the system crontab, not a user crontab):
Code:
# Rotate log files every hour, if necessary.
0    *    *    *    *    root    newsyslog
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Thanks - this makes totally sense with my assumption. I haven't thought of /etc/crontab. So where do the odd ones come from?

But what I don't understand is the setting in /etc/defaults/rc.conf. What's the use of enabling it there since it will anyway be called by cron(8)?
 
Last edited by a moderator:

DutchDaemon

Administrator
Staff member
Administrator
Moderator
Developer

Reaction score: 2,786
Messages: 11,279

Code:
newsyslog_enable="YES"  # Run newsyslog at startup.
"At startup". That's all.
 
OP
OP
Leander

Leander

Well-Known Member

Reaction score: 3
Messages: 262

Just as an update: newsyslog(8) is NOT the root cause for the sporadic deaths of slapd(8). Up to today and several new versions of FreeBSD and OpenLDAP nothing has changed. I always try to update as soon as new versions are available via freebsd-update(8) or ports tree.
 
Top