log rotation error/bug

Fri Dec 18 16:43:11 EST 2015

I have similar issue on one of my IdP servers, though all of them are
similar. Everything is checked out fro SVN.
But there are few differences from your case. I use IdP 3.1.2 and only
idp-process.log is affected. The newly created log file has records only
related to the sealer key rotation.

2015-12-15 23:41:08,835 - INFO
[net.shibboleth.utilities.java.support.security.BasicKeystoreKeyStrategy:327]
- Default key version has not changed, still secret6

2015-12-15 23:56:08,834 - INFO
[net.shibboleth.utilities.java.support.security.BasicKeystoreKeyStrategy:327]
- Default key version has not changed, still secret6

Restarting Jetty/IdP solves the issue.

On Fri, Dec 18, 2015 at 4:30 PM, Jeffrey Eaton <jeaton at cmu.edu> wrote:

> 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
>
>
> --
> To unsubscribe from this list send an email to
> users-unsubscribe at shibboleth.net
>

-- 
Yavor Yanakiev
Systems Developer for Identity Services
212-992-7585
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20151218/2e9973a3/attachment.html>