Exception when prep gets triggered to process files when shutdown is in progress

[bilalaslam]

We have a Dropwizard service that uses Skidroad to ship logs to AWS S3. When we kill the Dropwizard service (e.g. with CTRL-C), shutdown begins, the file writing worker closes, and then the prep worker gets triggered to process the file. Prep then gets clobbered by the ongoing shutdown. See partial exception trace below:

    DEBUG [2013-12-04 23:57:54,127] io.ifar.skidroad.writing.WritingWorkerManager: Stopped one. 0 remain.
    INFO  [2013-12-04 23:57:54,127] io.ifar.skidroad.writing.WritingWorkerManager: All workers stopped.
    INFO  [2013-12-04 23:57:54,127] io.ifar.skidroad.prepping.PrepWorkerManager: Stopping PrepWorkerManager.
    INFO  [2013-12-04 23:57:54,127] io.ifar.skidroad.upload.UploadWorkerManager: Stopping UploadWorkerManager.
    INFO  [2013-12-04 23:57:54,127] io.ifar.skidroad.jets3t.AbstractJetS3tStorage: Stopping Amazon S3.
    INFO  [2013-12-04 23:57:54,129] io.ifar.skidroad.jets3t.AbstractJetS3tStorage: Stopped Amazon S3.
    INFO  [2013-12-04 23:57:54,129] io.ifar.skidroad.tracking.AbstractLogFileTracker: Stopping ManagedJDBILogFileTracker.
    INFO  [2013-12-04 23:57:54,130] org.quartz.core.QuartzScheduler: Scheduler ManagedSimpleQuartzScheduler_$_1 shutting down.
    INFO  [2013-12-04 23:57:54,130] org.quartz.core.QuartzScheduler: Scheduler ManagedSimpleQuartzScheduler_$_1 paused.
    INFO  [2013-12-04 23:57:54,131] org.quartz.core.QuartzScheduler: Scheduler ManagedSimpleQuartzScheduler_$_1 shutdown complete.
    WARN  [2013-12-04 23:57:54,152] io.ifar.skidroad.prepping.AbstractPrepWorker: Preparation for 2013-12-04T23.1 failed.
    ! java.lang.IllegalStateException: Pool not open
    ! at org.apache.tomcat.dbcp.pool.BaseObjectPool.assertOpen(BaseObjectPool.java:137) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1076) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.skife.jdbi.v2.DataSourceConnectionFactory.openConnection(DataSourceConnectionFactory.java:36) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.skife.jdbi.v2.DBI.open(DBI.java:207) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.skife.jdbi.v2.sqlobject.OnDemandHandleDing.getHandle(OnDemandHandleDing.java:22) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.skife.jdbi.v2.sqlobject.OnDemandHandleDing.retain(OnDemandHandleDing.java:29) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.skife.jdbi.v2.sqlobject.SqlObject.invoke(SqlObject.java:146) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.skife.jdbi.v2.sqlobject.SqlObject$1.intercept(SqlObject.java:60) ~[my-collector.jar:0-SNAPSHOT]
    ! at org.skife.jdbi.v2.sqlobject.CloseInternalDoNotUseThisClass$$EnhancerByCGLIB$$57e70354.updateArchiveKey(<generated>) ~[my-collector.jar:0-SNAPSHOT]
    ! at io.ifar.skidroad.jdbi.JDBILogFileTracker.updateArchiveKey(JDBILogFileTracker.java:75) ~[my-collector.jar:0-SNAPSHOT]
    ! at io.ifar.skidroad.prepping.CompressPrepper.prepare(CompressPrepper.java:33) ~[my-collector.jar:0-SNAPSHOT]
    ! at io.ifar.skidroad.prepping.AbstractPrepWorker.call(AbstractPrepWorker.java:32) [my-collector.jar:0-SNAPSHOT]
    ! at io.ifar.skidroad.prepping.AbstractPrepWorker.call(AbstractPrepWorker.java:15) [my-collector.jar:0-SNAPSHOT]
    ! at io.ifar.skidroad.prepping.PrepWorkerManager$5.call(PrepWorkerManager.java:132) [my-collector.jar:0-SNAPSHOT]
    ! at io.ifar.skidroad.prepping.PrepWorkerManager$5.call(PrepWorkerManager.java:126) [my-collector.jar:0-SNAPSHOT]
    ! at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_40]
    ! at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_40]
    ! at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_40]
    ! at java.lang.Thread.run(Thread.java:724) [na:1.7.0_40]

[lorrin]

Preceding log lines. Note that graceful shutdown begins, WritingWorkerManager is stopped, which stops FileWritingWorker. But then PrepWorkerManager goes to work on the just-closed file in the middle of the shutdown.

^CINFO  [2013-12-04 23:57:52,053] org.eclipse.jetty.server.Server: Graceful shutdown [email protected]:8081
INFO  [2013-12-04 23:57:52,054] org.eclipse.jetty.server.Server: Graceful shutdown [email protected]:8080
INFO  [2013-12-04 23:57:52,054] org.eclipse.jetty.server.Server: Graceful shutdown o.e.j.s.ServletContextHandler{/,null}
INFO  [2013-12-04 23:57:52,054] org.eclipse.jetty.server.Server: Graceful shutdown o.e.j.s.ServletContextHandler{/,null}
INFO  [2013-12-04 23:57:54,110] org.eclipse.jetty.server.handler.ContextHandler: stopped o.e.j.s.ServletContextHandler{/,null}
INFO  [2013-12-04 23:57:54,110] org.eclipse.jetty.server.handler.ContextHandler: stopped o.e.j.s.ServletContextHandler{/,null}
INFO  [2013-12-04 23:57:54,111] io.ifar.skidroad.writing.WritingWorkerManager: Stopping WritingWorkerManager.
INFO  [2013-12-04 23:57:54,111] io.ifar.skidroad.writing.WritingWorkerManager: Queues drained. Stopping workers.
DEBUG [2013-12-04 23:57:54,111] io.ifar.skidroad.writing.AbstractWritingWorker: FileWritingWorker__my_proj_etl_req2013-12-04T23_1.log caught InterruptedException. Stopping...
DEBUG [2013-12-04 23:57:54,123] io.ifar.skidroad.prepping.PrepWorkerManager: Preparing 2013-12-04T23.1 from /tmp/my_proj_skidroad/d7d8c215-a019-4622-bf5f-b16caa7c96fb/my_proj_etl_req2013-12-04T23_1.log.
INFO  [2013-12-04 23:57:54,127] io.ifar.skidroad.writing.AbstractWritingWorker: Stopped worker FileWritingWorker__my_proj_etl_req2013-12-04T23_1.log for /tmp/my_proj_skidroad/d7d8c215-a019-4622-bf5f-b16caa7c96fb/my_proj_etl_req2013-12-04T23_1.log
DEBUG [2013-12-04 23:57:54,127] io.ifar.skidroad.writing.WritingWorkerManager: Stopped one. 0 remain.