[
https://issues.apache.org/jira/browse/OAK-3923?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15123261#comment-15123261
]
Chetan Mehrotra commented on OAK-3923:
--------------------------------------
Thanks Alex for the review!
bq. one thing I'm worried about is the verbosity of logging in the patch. Given
the frequency of the indexer(s) I imagine this will happen a lot
No the logs should come only 1-2 times in a given start stop cycle as they are
done from close method. Remember that AsyncIndexUpdate job is unscheduled first
via the close of CompositeRegistration of job reg in Oak#close and then only
the task is closed. So that should avoid the case where close is signalled and
run is being attempted
bq. My suggestion is to minimize the noise as much as possible and set all logs
from run and close to debug.
Makes sense. The logs were more for aiding the testcase to assert and also to
help us analyze such situations where close is being done forcibly
> Async indexing delayed by 30 minutes because stop order is incorrect
> --------------------------------------------------------------------
>
> Key: OAK-3923
> URL: https://issues.apache.org/jira/browse/OAK-3923
> Project: Jackrabbit Oak
> Issue Type: Bug
> Components: core
> Reporter: Thomas Mueller
> Assignee: Chetan Mehrotra
> Fix For: 1.4
>
> Attachments: OAK-3923-v1.patch
>
>
> 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:
> {noformat}
> 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)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
