log rotation error/bug

Fri Dec 18 20:16:52 EST 2015

> On Dec 18, 2015, at 6:25 PM, Cantor, Scott <cantor.2 at osu.edu> wrote:
> 
>> 18-Dec-2015 15:10:03.992 INFO [Thread-77]
>> org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResource
>> Loading Illegal access: this web application instance has been stopped
>> already. Could not load [org.ldaptive.provider.jndi.NamingExceptionUtils].
>> The following stack trace is thrown for debugging purposes as well as to
>> attempt to terminate the thread which caused the illegal access.
>> java.lang.IllegalStateException: Illegal access: this web application instance
>> has been stopped already.
> 
> I'm not sure what that means. Uncaught exception or not, I don't know how that would cause the webapp to "stop" or what that would mean. But I'm sure that in that scenario there could be issues with the log because it inits the logging config in the webapp start sequence.
> 
> Seems like maybe two copies ended up running and grabbing the same file handles or got into some kind of race condition. I would tend to point the finger at Tomcat as the main source of trouble.
> 
> Did you happen to be using some kind of JNDI resource at the container level for the LDAP connection? Not sure if we handle that or not, I only know about the JDBC case.
> 
> -- Scott
> 
> -- 
> To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net

Tomcat did not restart at all during that time.  The java process has been running since Dec 14.

The only LDAP connection I have is in attribute-resolver.xml.  I don’t have anything defined at the tomcat container level - the only thing I really configured in Tomcat was the ip.xml which only has”

<Context docBase="/opt/shibboleth-idp/war/idp.war"
         privileged="true"
         antiResourceLocking="false"
         swallowOutput="true" />

The attribute-resolver looks like:

    <resolver:DataConnector id="cmuLDAP" xsi:type="dc:LDAPDirectory"
        ldapURL="%{idp.attribute.resolver.LDAP.ldapURL}"
        baseDN="%{idp.attribute.resolver.LDAP.baseDN}"
        principal="%{idp.attribute.resolver.LDAP.bindDN}"
        principalCredential="%{idp.attribute.resolver.LDAP.bindDNCredential}"
        useStartTLS="%{idp.attribute.resolver.LDAP.useStartTLS:true}"
        noResultIsError="%{idp.attribute.resolver.LDAP.noResultsIsError:false}"
        multipleResultsIsError="%{idp.attribute.resolver.LDAP.multipleResultsIsError:true}">
        <dc:FilterTemplate>
            <![CDATA[
                %{idp.attribute.resolver.LDAP.searchFilter}
            ]]>
        </dc:FilterTemplate>
        <dc:StartTLSTrustCredential id="LDAPtoIdPCredential" xsi:type="sec:X509ResourceBacked">
            <sec:Certificate>%{idp.attribute.resolver.LDAP.trustCertificates}</sec:Certificate>
        </dc:StartTLSTrustCredential>
        <dc:ConnectionPool
            minPoolSize="%{idp.pool.LDAP.minSize}"
            maxPoolSize="%{idp.pool.LDAP.maxSize}"
            blockWaitTime="%{idp.pool.LDAP.blockWaitTime}"
            expirationTime="%{idp.pool.LDAP.expirationTime}"
            validatePeriodically="%{idp.pool.LDAP.validatePeriodically}"
            validateTimerPeriod="%{idp.pool.LDAP.validatePeriod}"
            validateDN="%{idp.pool.LDAP.validateDN}"
            validateFilter="%{idp.pool.LDAP.validateFilter}"
            failFastInitialize="%{idp.pool.LDAP.failFastInitialize}"/>
        <dc:ResultCache
            elementTimeToLive="%{idp.cache.LDAP.timeToLive}"
            maximumCachedElements="%{idp.cache.LDAP.cacheSize}"/>
    </resolver:DataConnector>

and ldap.properties has:

idp.authn.LDAP.ldapURL                          = ldaps://ldap.cmu.edu:636
idp.authn.LDAP.useStartTLS                      = false
idp.authn.LDAP.trustCertificates                = %{idp.home}/credentials/ldap-server.crt
idp.authn.LDAP.baseDN                            = ou=andrewperson,dc=andrew,dc=cmu,dc=edu
idp.authn.LDAP.bindDN                           = uid=XXX,ou=specials,dc=cmu,dc=edu
idp.authn.LDAP.bindDNCredential                 = XXX
idp.attribute.resolver.LDAP.ldapURL             = %{idp.authn.LDAP.ldapURL}
idp.attribute.resolver.LDAP.baseDN              = %{idp.authn.LDAP.baseDN}
idp.attribute.resolver.LDAP.bindDN              = %{idp.authn.LDAP.bindDN}
idp.attribute.resolver.LDAP.bindDNCredential    = %{idp.authn.LDAP.bindDNCredential}
idp.attribute.resolver.LDAP.useStartTLS         = %{idp.authn.LDAP.useStartTLS}
idp.attribute.resolver.LDAP.trustCertificates   = %{idp.authn.LDAP.trustCertificates}
idp.attribute.resolver.LDAP.searchFilter        = (uid=$requestContext.principalName)
idp.pool.LDAP.minSize                           = 3
idp.pool.LDAP.maxSize                           = 10
idp.pool.LDAP.blockWhenEmpty                    = true
idp.pool.LDAP.blockWaitTime                     = PT5M
idp.pool.LDAP.validatePeriodically              = true
idp.pool.LDAP.validatePeriod                    = PT30M
idp.pool.LDAP.validateDN                        = dc=cmu,dc=edu
idp.pool.LDAP.validateFilter                    = objectClass=*
idp.pool.LDAP.expirationTime                    = PT10M
idp.pool.LDAP.failFastInitialize                = true
idp.cache.LDAP.timeToLive                       = PT1H
idp.cache.LDAP.cacheSize                        = 1000

The errors logged by tomcat were (in order):

18-Dec-2015 15:05:27.974 INFO [Thread-56] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [org.ldaptive.provider.jndi.NamingExceptionUtils]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.

18-Dec-2015 15:05:27.976 INFO [Thread-56] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [ch.qos.logback.core.rolling.helper.AsynchronousCompressor]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.

18-Dec-2015 15:05:27.977 INFO [Thread-56] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [ch.qos.logback.core.status.ErrorStatus]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal 
access.

18-Dec-2015 15:05:27.978 INFO [Thread-56] org.apache.catalina.loader.WebappClassLoaderBase.checkStateForResourceLoading Illegal access: this web application instance has been stopped already. Could not load [ch.qos.logback.core.status.ErrorStatus]. The following stack trace is thrown for debugging purposes as well as to attempt to terminate the thread which caused the illegal access.

The second error, about ch.qos.logback.core.rolling.helper.AsynchronousCompressor looks like the culprit for the log file mess.  I have no idea why it would have been doing any rotation at 15:05, though. Maybe the first thread crash/termination somehow caused the later errors.  

-jeaton