[daisy] [JIRA] Commented: (DSY-457) Automatic shutdown of Daisy repository service does not clean up write lock (and prevents startup)

Geoffrey De Smet (JIRA) issues at cocoondev.org
Thu May 3 02:18:20 CDT 2007 

    [ http://issues.cocoondev.org//browse/DSY-457?page=comments#action_13148 ] 

Geoffrey De Smet commented on DSY-457:
--------------------------------------

Yesterday evening the lock was apparently cleaned up ok. I hadn't used the repo in the last hour before closing it though.
Nevertheless, this exception occured:

[INFO   ] <2007-05-02 17:18:12,709> (daisy.jcl.net.sf.ehcache.CacheManager): VM shutting down with the CacheManager still active. Calling shutdown.
[INFO   ] <2007-05-02 17:18:12,944> (daisy.emailer.emailer): Waiting for emailer thread to end.
[INFO   ] <2007-05-02 17:18:12,975> (daisy.emailer.emailer): Emailer thread ended.
[INFO   ] <2007-05-02 17:18:13,554> (daisy.extensions.doctaskmanager.documentTaskManager): Waiting for document task janitor thread to end.
[INFO   ] <2007-05-02 17:18:13,788> (daisy.extensions.doctaskmanager.documentTaskManager): Document task janitor thread ended.
[INFO   ] <2007-05-02 17:18:18,275> (daisy.jcl.org.jbpm.job.executor.JobExecutorThread): inactivated job executor thread 'JbpmJobExector:193.74.194.93:1' got interrupted
[INFO   ] <2007-05-02 17:18:18,275> (daisy.jcl.org.jbpm.job.executor.JobExecutorThread): JbpmJobExector:193.74.194.93:1 leaves cyberspace
[INFO   ] <2007-05-02 17:18:18,275> (daisy.repository.httpconnector): Stopping Acceptor ServerSocket[addr=0.0.0.0/0.0.0.0,port=0,localport=9263]
[INFO   ] <2007-05-02 17:18:18,385> (daisy.repository.httpconnector): Stopped SocketListener on 0.0.0.0:9263
[INFO   ] <2007-05-02 17:18:18,604> (daisy.repository.httpconnector): Stopped HttpContext[/,/]
[INFO   ] <2007-05-02 17:18:18,604> (daisy.repository.httpconnector): Stopped org.mortbay.http.HttpServer at 1b7edd3
[INFO   ] <2007-05-02 17:18:19,683> (daisy.repository.repository-manager): Waiting for expired lock janitor thread to end.
[INFO   ] <2007-05-02 17:18:19,683> (daisy.repository.repository-manager): Expired lock janitor thread ended.
[INFO   ] <2007-05-02 17:18:19,683> (daisy.repository.fullTextIndex): Waiting for index flush thread to end.
[INFO   ] <2007-05-02 17:18:19,683> (daisy.repository.fullTextIndex): Index flush thread ended.
[ERROR  ] <2007-05-02 17:18:20,636> (daisy.repository.eventdispatcher): Exception in event dispatcher.
com.mysql.jdbc.CommunicationsException: Communications link failure due to underlying exception: 

** BEGIN NESTED EXCEPTION ** 

java.net.SocketException
MESSAGE: java.net.ConnectException: Connection refused: connect

STACKTRACE:

java.net.SocketException: java.net.ConnectException: Connection refused: connect
	at com.mysql.jdbc.StandardSocketFactory.connect(StandardSocketFactory.java:156)
	at com.mysql.jdbc.MysqlIO.<init>(MysqlIO.java:284)
	at com.mysql.jdbc.Connection.createNewIO(Connection.java:2555)
	at com.mysql.jdbc.Connection.<init>(Connection.java:1485)
	at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
	at org.outerj.daisy.jdbcutil.DriverLoader$DriverShim.connect(DriverLoader.java:77)
	at org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:37)
	at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290)
	at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771)
	at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
	at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:544)
	at org.outerj.daisy.datasource.JdbcDataSource.getConnection(JdbcDataSource.java:142)
	at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.apache.avalon.activation.impl.ApplianceInvocationHandler.invoke(ApplianceInvocationHandler.java:129)
	at $Proxy3.getConnection(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.apache.avalon.activation.impl.BlockInvocationHandler.invoke(BlockInvocationHandler.java:108)
	at $Proxy3.getConnection(Unknown Source)
	at org.outerj.daisy.event.EventDispatcherImpl$EventDispatchThread.run(EventDispatcherImpl.java:101)


** END NESTED EXCEPTION **



Last packet sent to the server was 0 ms ago.
	at com.mysql.jdbc.Connection.createNewIO(Connection.java:2621)
	at com.mysql.jdbc.Connection.<init>(Connection.java:1485)
	at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:266)
	at org.outerj.daisy.jdbcutil.DriverLoader$DriverShim.connect(DriverLoader.java:77)
	at org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:37)
	at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290)
	at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771)
	at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95)
	at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:544)
	at org.outerj.daisy.datasource.JdbcDataSource.getConnection(JdbcDataSource.java:142)
	at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.apache.avalon.activation.impl.ApplianceInvocationHandler.invoke(ApplianceInvocationHandler.java:129)
	at $Proxy3.getConnection(Unknown Source)
	at sun.reflect.GeneratedMethodAccessor3.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.apache.avalon.activation.impl.BlockInvocationHandler.invoke(BlockInvocationHandler.java:108)
	at $Proxy3.getConnection(Unknown Source)
	at org.outerj.daisy.event.EventDispatcherImpl$EventDispatchThread.run(EventDispatcherImpl.java:101)
[INFO   ] <2007-05-02 17:18:23,435> (daisy.repository.eventdispatcher): Waiting for event dispatcher thread to end.
[INFO   ] <2007-05-02 17:18:23,435> (daisy.repository.eventdispatcher): Event dispatcher thread ended.


Could be my service scripts are corrupted, I 'll clean them. Still windows services show that daisy repo depends on mysql.

> Automatic shutdown of Daisy repository service does not clean up write lock (and prevents startup)
> --------------------------------------------------------------------------------------------------
>
>          Key: DSY-457
>          URL: http://issues.cocoondev.org//browse/DSY-457
>      Project: Daisy
>         Type: Bug
>   Components: Repository
>     Versions: 2.0.1
>  Environment: Windows XP SP2
>     Reporter: Geoffrey De Smet

>
> When I directly call the repo service shutdown, it cleans up the write lock.
> When windows calls it when I turn off my machine, it doesn't clean up write lock (see the log below).
> This prevents the repo from starting up when I turn on my machine.
> And windows's services properties show that the repo is dependend on MySQL, so it should shutdown before mysql.
> Here's the service.log:
> INFO   | jvm 1    | 2007/04/20 12:32:19 | org.jbpm.persistence.JbpmPersistenceException: hibernate close session failed
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:240)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.jbpm.svc.Services.close(Services.java:222)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.jbpm.JbpmContext.close(JbpmContext.java:139)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.jbpm.job.executor.JobExecutorThread.acquireJobs(JobExecutorThread.java:141)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.jbpm.job.executor.JobExecutorThread.run(JobExecutorThread.java:56)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.jbpm.job.executor.DaisyJobExecutorThread.run(DaisyJobExecutorThread.java:48)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | Caused by: org.hibernate.exception.GenericJDBCException: Cannot release connection
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.jdbc.ConnectionManager.closeConnection(ConnectionManager.java:449)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.jdbc.ConnectionManager.aggressiveRelease(ConnectionManager.java:400)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.jdbc.ConnectionManager.afterTransaction(ConnectionManager.java:287)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.jdbc.JDBCContext.afterTransactionCompletion(JDBCContext.java:221)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.jdbc.JDBCContext.connectionCleanedUp(JDBCContext.java:97)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.jdbc.ConnectionManager.cleanup(ConnectionManager.java:388)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.jdbc.ConnectionManager.close(ConnectionManager.java:318)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.impl.SessionImpl.close(SessionImpl.java:298)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.jbpm.persistence.db.DbPersistenceService.closeSession(DbPersistenceService.java:310)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.jbpm.persistence.db.DbPersistenceService.close(DbPersistenceService.java:237)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	... 5 more
> INFO   | jvm 1    | 2007/04/20 12:32:24 | Caused by: java.sql.SQLException: Already closed.
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.apache.commons.dbcp.PoolableConnection.close(PoolableConnection.java:66)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.apache.commons.dbcp.PoolingDataSource$PoolGuardConnectionWrapper.close(PoolingDataSource.java:180)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.outerj.daisy.workflow.serverimpl.DaisyConnectionProvider.closeConnection(DaisyConnectionProvider.java:49)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	at org.hibernate.jdbc.ConnectionManager.closeConnection(ConnectionManager.java:445)
> INFO   | jvm 1    | 2007/04/20 12:32:24 | 	... 14 more
> ERROR  | wrapper  | 2007/04/20 12:32:26 | Shutdown failed: Timed out waiting for the JVM to terminate.
> ERROR  | wrapper  | 2007/04/20 12:32:26 | JVM did not exit on request, terminated
> STATUS | wrapper  | 2007/04/20 12:32:27 | <-- Wrapper Stopped
> STATUS | wrapper  | 2007/04/23 08:26:08 | --> Wrapper Started as Service
> STATUS | wrapper  | 2007/04/23 08:26:08 | Launching a JVM...
> INFO   | jvm 1    | 2007/04/23 08:26:09 | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
> INFO   | jvm 1    | 2007/04/23 08:26:09 |   Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.
> INFO   | jvm 1    | 2007/04/23 08:26:09 | 
> INFO   | jvm 1    | 2007/04/23 08:26:15 | ---- exception report ----------------------------------------------------------
> INFO   | jvm 1    | 2007/04/23 08:26:15 | Exception: org.apache.avalon.merlin.KernelException
> INFO   | jvm 1    | 2007/04/23 08:26:15 | Message: Kernel startup failure.
> INFO   | jvm 1    | 2007/04/23 08:26:15 | ---- cause ---------------------------------------------------------------------
> INFO   | jvm 1    | 2007/04/23 08:26:15 | Exception: org.apache.avalon.merlin.KernelException
> INFO   | jvm 1    | 2007/04/23 08:26:15 | Message: Cannot deploy application.
> INFO   | jvm 1    | 2007/04/23 08:26:15 | ---- cause ---------------------------------------------------------------------
> INFO   | jvm 1    | 2007/04/23 08:26:15 | Exception: org.apache.avalon.activation.LifecycleException
> INFO   | jvm 1    | 2007/04/23 08:26:15 | Message: Unable to create a new component instance in appliance [/daisy/repository/fullTextIndex] due to a component deployment failure.
> INFO   | jvm 1    | 2007/04/23 08:26:15 | ---- cause ---------------------------------------------------------------------
> INFO   | jvm 1    | 2007/04/23 08:26:15 | Exception: java.io.IOException
> INFO   | jvm 1    | 2007/04/23 08:26:15 | Message: Lock obtain timed out: SimpleFSLock at C:\app\cms\daisy-2.0.1\data\indexstore\write.lock
> INFO   | jvm 1    | 2007/04/23 08:26:15 | ---- stack trace ---------------------------------------------------------------
> INFO   | jvm 1    | 2007/04/23 08:26:15 | java.io.IOException: Lock obtain timed out: SimpleFSLock at C:\app\cms\daisy-2.0.1\data\indexstore\write.lock
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.lucene.store.Lock.obtain(Lock.java:69)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.lucene.index.IndexWriter.init(IndexWriter.java:367)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.lucene.index.IndexWriter.init(IndexWriter.java:352)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:314)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.outerj.daisy.ftindex.FullTextIndexImpl.constructIndexWriter(FullTextIndexImpl.java:307)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.outerj.daisy.ftindex.FullTextIndexImpl.updateWriter(FullTextIndexImpl.java:303)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.outerj.daisy.ftindex.FullTextIndexImpl.initialize(FullTextIndexImpl.java:109)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.framework.container.ContainerUtil.initialize(ContainerUtil.java:244)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.activation.impl.DefaultComponentFactory.incarnation(DefaultComponentFactory.java:402)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.activation.impl.DefaultComponentFactory.incarnate(DefaultComponentFactory.java:130)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.activation.impl.SingletonLifestyleManager.refreshReference(SingletonLifestyleManager.java:144)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.activation.impl.SingletonLifestyleManager.commission(SingletonLifestyleManager.java:60)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.activation.impl.DefaultAppliance.commission(DefaultAppliance.java:94)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.activation.impl.DefaultRuntime.commission(DefaultRuntime.java:86)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.composition.model.impl.DefaultSystemContext.commission(DefaultSystemContext.java:362)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.composition.model.impl.DefaultDeploymentModel.commission(DefaultDeploymentModel.java:122)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | org.apache.avalon.composition.model.impl.Commissioner.run(Commissioner.java:185)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | java.lang.Thread.run(Unknown Source)
> INFO   | jvm 1    | 2007/04/23 08:26:15 | --------------------------------------------------------------------------------

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators:
   http://issues.cocoondev.org//secure/Administrators.jspa
-
For more information on JIRA, see:
   http://www.atlassian.com/software/jira

More information about the daisy mailing list