[OAK-3923] Async indexing delayed by 30 minutes because stop order is incorrect

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.0.32, 1.2.11, 1.3.15, 1.4
• Component/s: core
• Assignee: Chetan Mehrotra
• Reporter: Thomas Mueller
• Created: 26/Jan/16 08:32
• Updated: 08/Oct/19 15:22
• Resolved: 29/Jan/16 10:07

Description

The stop order of Oak components is incorrect, and this can lead to an async indexing delay of 30 minutes, because the indexing lease is not removed. The problem is that the node store is stopped before the async index is stopped, so that async indexing can still be in progress, and then when async indexing is done, the lease can not be removed because the node store is not available.

From the log file:

error.log:
21.01.2016 11:53:56.898 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak-tarmk-standby BundleEvent STOPPED
21.01.2016 11:53:56.900 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak-solr-osgi Service [org.apache.jackrabbit.oak.plugins.index.solr.osgi.SolrIndexEditorProviderService,571, [org.apache.jackrabbit.oak.plugins.index.IndexEditorProvider]] ServiceEvent UNREGISTERING
...
21.01.2016 11:53:56.930 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak-lucene BundleEvent STOPPING
21.01.2016 11:53:56.930 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak-lucene BundleEvent STOPPED
21.01.2016 11:53:56.931 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak-core Service [org.apache.jackrabbit.oak.plugins.index.property.PropertyIndexProvider,405, [org.apache.jackrabbit.oak.spi.query.QueryIndexProvider]] ServiceEvent UNREGISTERING
...
21.01.2016 11:53:56.936 *INFO* [FelixStartLevel] com.adobe.granite.repository.impl.SlingRepositoryManager stop: Repository still running, forcing shutdown
...
21.01.2016 11:53:56.960 *WARN* [FelixStartLevel] org.apache.jackrabbit.oak.osgi.OsgiWhiteboard Error unregistering service: com.adobe.granite.repository.impl.SlingRepositoryManager$1@7c052458 of type java.util.concurrent.Executor
java.lang.IllegalStateException: Service already unregistered.
	at org.apache.felix.framework.ServiceRegistrationImpl.unregister(ServiceRegistrationImpl.java:136)
	at org.apache.jackrabbit.oak.osgi.OsgiWhiteboard$1.unregister(OsgiWhiteboard.java:81)
	at org.apache.jackrabbit.oak.spi.whiteboard.CompositeRegistration.unregister(CompositeRegistration.java:43)
	at org.apache.jackrabbit.oak.Oak$6.close(Oak.java:592)
...
21.01.2016 11:56:50.985 *INFO* [FelixStartLevel] org.apache.jackrabbit.oak-core Service [763, [org.apache.jackrabbit.oak.plugins.segment.SegmentStoreProvider]] ServiceEvent UNREGISTERING
 
debug.log:
21.01.2016 11:56:51.964 *WARN* [sling-default-4] org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate [async] The index update failed
java.lang.IllegalStateException: service must be activated when used
	at com.google.common.base.Preconditions.checkState(Preconditions.java:150)
	at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeStoreService.getNodeStore(SegmentNodeStoreService.java:233)
	at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeStoreService.getNodeStore(SegmentNodeStoreService.java:92)
	at org.apache.jackrabbit.oak.spi.state.ProxyNodeStore.getRoot(ProxyNodeStore.java:36)
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate$AsyncUpdateCallback.close(AsyncIndexUpdate.java:266)
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.updateIndex(AsyncIndexUpdate.java:451)
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.run(AsyncIndexUpdate.java:351)
 
error.log:
21.01.2016 11:56:51.965 *ERROR* [sling-default-4] org.apache.sling.commons.scheduler.impl.QuartzScheduler Exception during job execution of org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate@1706b18c : service must be activated when used
java.lang.IllegalStateException: service must be activated when used
	at com.google.common.base.Preconditions.checkState(Preconditions.java:150)
	at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeStoreService.getNodeStore(SegmentNodeStoreService.java:233)
	at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeStoreService.getNodeStore(SegmentNodeStoreService.java:92)
	at org.apache.jackrabbit.oak.spi.state.ProxyNodeStore.release(ProxyNodeStore.java:90)
	at org.apache.jackrabbit.oak.plugins.index.AsyncIndexUpdate.run(AsyncIndexUpdate.java:372)
	at org.apache.sling.commons.scheduler.impl.QuartzJobExecutor.execute(QuartzJobExecutor.java:115)
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
	at java.lang.Thread.run(Thread.java:745)

Issue Links

• is related to: OAK-3834 AsyncIndexUpdate default async lease timeout is (too?) long
• is related to: OAK-3952 BackgroundObserver close should wait for stop to be processed
• is related to: OAK-2108 Killing a node may stop async index update to to 30 minutes (Tar storage)
• is related to: OAK-4035 AsyncIndexUpdate should not log exception when its forcibly stopped
• relates to: OAK-3944 OsgiWhiteboard should handle multiple unregister call