log rotation error/bug

[Jeffrey Eaton]

I just came across an unusual log rotation bug with IDP v3.2.0.

Something happened in the IDP which caused it to create these files:

Dec 18 15:10 idp-process.log
Dec 18 16:21 idp-process.log598435536912956.tmp
Dec 18 15:10 idp-warn.log
Dec 18 11:48 idp-warn.log598435701916956.tmp


Interestingly, it looks like at 15:10, it renamed the files to the .tmp names, and opened new files.  Then, after writing a few lines to the new file, things switched back to being appended to the files with the .tmp names.  The only things in the idp-process.log and idp-warn.log files are a few entries, all in the 15:10 minute.  The .tmp files contain everything prior to, and after that minute (but nothing during the 15:10 minute itself).

Right around that moment, we had an LDAP server crash, which may be related.  The entries in the .log files contain just the errors about the LDAP pool:

2015-12-18 15:10:03,992 - WARN [org.ldaptive.pool.BlockingConnectionPool:808] - connection failed validation: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at 2f610ca4
2015-12-18 15:10:03,995 - WARN [org.ldaptive.pool.BlockingConnectionPool:808] - connection failed validation: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at 6e5e02ad
2015-12-18 15:10:04,005 - WARN [org.ldaptive.pool.BlockingConnectionPool:808] - connection failed validation: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at 5ffac6e2
2015-12-18 15:10:04,024 - ERROR [org.ldaptive.pool.BlockingConnectionPool:310] - validation task failed for [org.ldaptive.pool.BlockingConnectionPool at 1540597622::name=null, poolConfig=[org.ldaptive.pool.PoolConfig at 910152844::minPoolSize=3, maxPoolSize=10,
validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=1800], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator at 208490607::searchRequest=[org.ldaptive.SearchRequest at 1431755003::baseDn=dc=cm
,dc=edu, searchFilter=[org.ldaptive.SearchFilter at -1126260291::filter=objectClass=*, parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, se
rchEntryHandlers=null, searchReferenceHandlers=null, controls=null, followReferrals=false, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy at 46268698::prunePeriod=300, idleTime=600], connectOnCreate=true, connectionFac
ory=[org.ldaptive.DefaultConnectionFactory at 1682622213::provider=org.ldaptive.provider.jndi.JndiProvider at 16cbd173, config=[org.ldaptive.ConnectionConfig at 1427384267::ldapUrl=ldaps://ldap.cmu.edu:636, connectTimeout=-1, responseTimeout=-1, sslConfig=[org.lda
tive.ssl.SslConfig at 1906615546::credentialConfig=org.ldaptive.ssl.CredentialConfigFactory$2 at 422073a0, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInitial
zer=[org.ldaptive.BindConnectionInitializer at 1242784182::bindDn=uid=compserv-shibboleth-prod,ou=specials,dc=cmu,dc=edu, bindSaslConfig=null, bindControls=null]]], initialized=true, availableCount=0, activeCount=0]
2015-12-18 15:10:04,166 - WARN [org.ldaptive.pool.BlockingConnectionPool:808] - connection failed validation: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at 7f73f3cc
2015-12-18 15:10:04,168 - WARN [org.ldaptive.pool.BlockingConnectionPool:808] - connection failed validation: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at 3e4efe05
2015-12-18 15:10:04,175 - WARN [org.ldaptive.pool.BlockingConnectionPool:808] - connection failed validation: org.ldaptive.pool.AbstractConnectionPool$DefaultPooledConnectionProxy at f3adea8
2015-12-18 15:10:04,200 - ERROR [org.ldaptive.pool.BlockingConnectionPool:310] - validation task failed for [org.ldaptive.pool.BlockingConnectionPool at 865402979::name=null, poolConfig=[org.ldaptive.pool.PoolConfig at 1764378042::minPoolSize=3, maxPoolSize=10,
validateOnCheckIn=false, validateOnCheckOut=false, validatePeriodically=true, validatePeriod=1800], activator=null, passivator=null, validator=[org.ldaptive.pool.SearchValidator at 1168114438::searchRequest=[org.ldaptive.SearchRequest at 1431755003::baseDn=dc=c
u,dc=edu, searchFilter=[org.ldaptive.SearchFilter at -1126260291::filter=objectClass=*, parameters={}], returnAttributes=[1.1], searchScope=OBJECT, timeLimit=0, sizeLimit=1, derefAliases=null, typesOnly=false, binaryAttributes=null, sortBehavior=UNORDERED, s
archEntryHandlers=null, searchReferenceHandlers=null, controls=null, followReferrals=false, intermediateResponseHandlers=null]] pruneStrategy=[org.ldaptive.pool.IdlePruneStrategy at 1777388116::prunePeriod=300, idleTime=600], connectOnCreate=true, connection
actory=[org.ldaptive.DefaultConnectionFactory at 1929206033::provider=org.ldaptive.provider.jndi.JndiProvider at 49c1c561, config=[org.ldaptive.ConnectionConfig at 1441003144::ldapUrl=ldaps://ldap.cmu.edu:636, connectTimeout=-1, responseTimeout=-1, sslConfig=[org.
daptive.ssl.SslConfig at 1118499005::credentialConfig=org.ldaptive.ssl.CredentialConfigFactory$2 at 1d25dd6a, trustManagers=null, enabledCipherSuites=null, enabledProtocols=null, handshakeCompletedListeners=null], useSSL=false, useStartTLS=false, connectionInit
alizer=[org.ldaptive.BindConnectionInitializer at 9118940::bindDn=uid=compserv-shibboleth-prod,ou=specials,dc=cmu,dc=edu, bindSaslConfig=null, bindControls=null]]], initialized=true, availableCount=0, activeCount=0]


Both files are identical.

Could there be a bug with log handling relating to the LDAP pooling somehow?

-jeaton