mulgara warning on startup

we seem to get this one on start up as well:

2007-07-27 05:02:46,953 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock [Finalizer org.mulgara.st
ore.xa.LockFile]

let me know if these are okay, and i'll document in our wiki...

Milestone Bugs deleted

These should be harmless - I remember seeing them too. But let me know if they still appear in the new 0.8 release.

planning on testing this once we receive final 0.8 rpms

i'm not seeing these so far on 0.8.

i'd like to test again on the production server after the upgrade, once we have a week of data or so.

yes, these are still appearing in 0.8

2007-09-24 09:46:17,903 INFO  DatabaseSession> Trying to obtain write lock.  [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
--
java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.mulgara.resolver.Database.setHostnameAliases(Database.java:1247)
        at org.mulgara.resolver.Database.<init>(Database.java:568)
        at org.mulgara.resolver.Database.<init>(Database.java:317)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:494)
        at org.mulgara.server.SessionFactoryFactory.getTripleStoreImplementation(SessionFactoryFactory.java:182)
        at org.mulgara.server.SessionFactoryFactory.newSessionFactory(SessionFactoryFactory.java:234)
        at org.mulgara.server.local.LocalSessionFactory.newSession(LocalSessionFactory.java:195)
        at org.topazproject.mulgara.ws.ItqlInterpreterBeanWrapper.getInterpreter(ItqlInterpreterBeanWrapper.java:65)
        at org.topazproject.mulgara.ws.ItqlInterpreterBeanWrapper.executeUpdate(ItqlInterpreterBeanWrapper.java:192)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.apache.axis.providers.java.RPCProvider.invokeMethod(RPCProvider.java:397)
        at org.apache.axis.providers.java.RPCProvider.processMessage(RPCProvider.java:186)
        at org.apache.axis.providers.java.JavaProvider.invoke(JavaProvider.java:323)
        at org.apache.axis.strategies.InvocationStrategy.visit(InvocationStrategy.java:32)
        at org.apache.axis.SimpleChain.doVisiting(SimpleChain.java:118)
        at org.apache.axis.SimpleChain.invoke(SimpleChain.java:83)
        at org.apache.axis.handlers.soap.SOAPService.invoke(SOAPService.java:454)
        at org.apache.axis.server.AxisServer.invoke(AxisServer.java:281)
        at org.apache.axis.transport.http.AxisServlet.doPost(AxisServlet.java:699)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:710)
        at org.apache.axis.transport.http.AxisServletBase.service(AxisServletBase.java:327)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:803)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:870)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)
        at java.lang.Thread.run(Thread.java:595)
Caused by: java.lang.IllegalStateException: Host names have already been set
        at org.mulgara.server.ServerInfo.setHostnameAliases(ServerInfo.java:168)
        ... 46 more

2007-09-24 09:46:18,835 INFO  DatabaseSession> Constructing DatabaseSession: externalResolverFactoryMap={jar=org.mulgara.resolver.jar.JarResolverFactory@7023d08b, https=org.mulgara.resolver.http.HttpResolverFactory@303ec561, http=org.mulgara.resolver.http.HttpResolverFactory@303ec561, file=org.mulgara.resolver.file.FileResolverFactory@127e5130} internalResolverFactoryMap={http://mulgara.org/mulgara#XMLSchemaModel=org.mulgara.resolver.InternalResolverFactory@7d59ea8e, http://mulgara.org/mulgara#Model=org.mulgara.resolver.InternalSystemResolverFactory@438d460, http://mulgara.org/mulgara#PrefixModel=org.mulgara.resolver.InternalResolverFactory@2bf8f8c8, http://mulgara.org/mulgara#LuceneModel=org.mulgara.resolver.InternalResolverFactory@61b59919, http://topazproject.org/models#filter=org.mulgara.resolver.InternalResolverFactory@48f81402, http://mulgara.org/mulgara#RelationalModel=org.mulgara.resolver.InternalResolverFactory@16e9b4bb, http://topazproject.org/models#StringCompare=org.mulgara.resolver.InternalResolverFactory@49586cbd, http://mulgara.org/mulgara#TypeModel=org.mulgara.resolver.InternalResolverFactory@2691f0de, http://mulgara.org/mulgara#FileSystemModel=org.mulgara.resolver.InternalResolverFactory@67e2c841, http://mulgara.org/mulgara#ViewModel=org.mulgara.resolver.InternalResolverFactory@4b0e18ba} metadata=org.mulgara.resolver.DatabaseMetadataImpl@ffeef1 [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,835 INFO  DatabaseSession> Starting Transactional Operation [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,835 INFO  DatabaseSession> Beginning transactional block: autocommit = true [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,835 INFO  DatabaseSession> Trying to obtain write lock.  [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,835 INFO  DatabaseSession> Obtained write lock.  [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,835 INFO  DatabaseSession> BEGIN new transaction. [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,842 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock [Finalizer org.mulgara.store.xa.LockFile]
2007-09-24 09:46:18,843 INFO  DatabaseSession> Finishing Transactional Operation [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,843 INFO  DatabaseSession> End Transactional Block autocommit=true transaction status=ACTIVE [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,882 INFO  DatabaseSession> Releasing write lock [http-9091-Processor25 org.mulgara.resolver.DatabaseSession]
2007-09-24 09:46:18,883 INFO  DatabaseSes

The IllegalStateExceptions (and the associated InvocationTargetException) can be freely ignored.

The lock-file ones: they seem to occur not just at startup, right? Are they always <foo>.np.lock? If so, that would indicate the node-pool lock, which would indicate some node-pool instance are not always close()'d as they should (though the finalizer makes sure they do get closed in the end). Not sure this is a problem worth chasing down at this point.

looks like they are only occuring on shutdown or startup...

today's log has a bunch that correspond to the daily backup restart, but none corresponding to the rc3 upgrade (mulgara was up and down 3 times i think).

[root@ploskow01 0.8-rc3]# grep 'WARN  LockFile' /var/log/topaz/mulgara.log | more
2007-09-28 05:02:51,051 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,108 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,109 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,109 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,109 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,109 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,109 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,109 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,109 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:51,109 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:53,415 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:53,415 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:53,415 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:53,415 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:53,416 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:53,416 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]
2007-09-28 05:02:53,416 WARN  LockFile> In finalize.  Lock file was not released: /var/lib/topaz/data/mulgara/xaNodePool/xa.np.lock
 [Finalizer org.mulgara.store.xa.LockFile]

looks like mulgara didn't die easily this AM and was killed by the backup script:

...ploskow01
Stopping mulgara (23202)
Stopping mulgara ()

feel free to close if it's no big deal. i will add these to my list of ignorable errors.

I had a quick look at the logs, and these are only occurring shortly after startup. I don't see that they're doing any harm, so I'm lowering the priority of this.

Closing ticket per Russ.