Bug #8536
Updated by Rob Nahf over 6 years ago
the checkReadinessProcessResourceMap routine consistently keeps a resourceMap update from being to be indexed.
~~~
[ERROR] 2018-04-09 21:57:24,438 (IndexTaskProcessor:checkReadinessProcessResourceMap:353) We waited for another thread to finish indexing a pid with series id packageIndexingTest_P_S_P_T_T_T_20180400.14.25_md for a while. Now we quit and can't index id packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2
[ERROR] 2018-04-09 21:57:24,438 (IndexTaskProcessor:processTask:297) Unable to process task for pid: packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2
~~~
~~~
full log related to the resouceMap.1 and .2 shown below. Perhaps it's a race condition.
~~~
[ INFO] 2018-04-09 21:55:15,098 (HZEventFilter:filter:127) HZEventFilter.filter - the system metadata for the index event shows shows packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1 having a newer version than the SOLR server. So this event should be granted for indexing.
[ INFO] 2018-04-09 21:55:16,442 (IndexTaskProcessor:saveTask:865) IndexTaskProcess.saveTask save the index task packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1
[ INFO] 2018-04-09 21:55:16,442 (IndexTaskProcessor:getNextIndexTask:610) Start of indexing pid: packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1
[ INFO] 2018-04-09 21:55:16,467 (IndexTaskProcessor:getNextIndexTask:664) the original index task - IndexTask [id=8067008, pid=packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1, formatid=http://www.openarchives.org/ore/terms, objectPath=/var/metacat/data/autogen.2018040914304929417.1, dateSysMetaModified=1523310751860, deleted=false, taskModifiedDate=1523310916438, priority=3, status=IN PROCESS]
[ INFO] 2018-04-09 21:55:16,467 (IndexTaskProcessor:getNextIndexTask:671) the new index task - IndexTask [id=8067008, pid=packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1, formatid=http://www.openarchives.org/ore/terms, objectPath=/var/metacat/data/autogen.2018040914304929417.1, dateSysMetaModified=1523310751860, deleted=false, taskModifiedDate=1523310916438, priority=3, status=IN PROCESS]
[ INFO] 2018-04-09 21:55:21,278 (IndexTaskProcessor:processTask:284) *********************start to process update index task for packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1 in thread 109
[ INFO] 2018-04-09 21:55:21,533 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:21,535 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:21,538 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=resourceMap%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=5000&indent=on
[ INFO] 2018-04-09 21:55:21,598 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:21,601 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:22,446 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1+OR+seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_data.1+OR+seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_md&start=0&rows=3&indent=on
[ INFO] 2018-04-09 21:55:22,451 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1+OR+id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_data.1+OR+id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_md&start=0&rows=3&indent=on
[ INFO] 2018-04-09 21:55:25,522 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:25,524 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:25,561 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:25,564 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:25,567 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:25,575 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:25,578 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:25,581 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:55:26,096 (IndexTaskProcessor:processTask:288) *********************end to process update index task for packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1 in thread 109
[ INFO] 2018-04-09 21:55:26,099 (IndexTaskProcessor:processTask:315) Indexing complete for pid: packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1
[ INFO] 2018-04-09 21:57:12,851 (IndexTaskProcessor:saveTask:865) IndexTaskProcess.saveTask save the index task packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1
[ INFO] 2018-04-09 21:57:12,851 (IndexTaskProcessor:getNextIndexTask:610) Start of indexing pid: packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1
[ INFO] 2018-04-09 21:57:12,867 (IndexTaskProcessor:getNextIndexTask:664) the original index task - IndexTask [id=8067004, pid=packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1, formatid=http://www.openarchives.org/ore/terms, objectPath=/var/metacat/data/autogen.2018040914304929417.1, dateSysMetaModified=1523310751860, deleted=false, taskModifiedDate=1523311032850, priority=3, status=IN PROCESS]
[ INFO] 2018-04-09 21:57:12,867 (IndexTaskProcessor:getNextIndexTask:671) the new index task - IndexTask [id=8067004, pid=packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1, formatid=http://www.openarchives.org/ore/terms, objectPath=/var/metacat/data/autogen.2018040914304929417.1, dateSysMetaModified=1523310751860, deleted=false, taskModifiedDate=1523311032850, priority=3, status=IN PROCESS]
[ INFO] 2018-04-09 21:57:15,910 (IndexTaskProcessor:saveTask:865) IndexTaskProcess.saveTask save the index task packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2
[ INFO] 2018-04-09 21:57:15,910 (IndexTaskProcessor:getNextIndexTask:610) Start of indexing pid: packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2
[ INFO] 2018-04-09 21:57:15,956 (IndexTaskProcessor:getNextIndexTask:664) the original index task - IndexTask [id=8067042, pid=packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2, formatid=http://www.openarchives.org/ore/terms, objectPath=/var/metacat/data/autogen.2018040914550540142.1, dateSysMetaModified=1523310752163, deleted=false, taskModifiedDate=1523311035906, priority=3, status=IN PROCESS]
[ INFO] 2018-04-09 21:57:15,956 (IndexTaskProcessor:getNextIndexTask:671) the new index task - IndexTask [id=8067042, pid=packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2, formatid=http://www.openarchives.org/ore/terms, objectPath=/var/metacat/data/autogen.2018040914550540142.1, dateSysMetaModified=1523310752163, deleted=false, taskModifiedDate=1523311035906, priority=3, status=IN PROCESS]
[ INFO] 2018-04-09 21:57:16,478 (IndexTaskProcessor:processTask:284) *********************start to process update index task for packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1 in thread 110
[ INFO] 2018-04-09 21:57:16,807 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:16,812 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:16,817 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=resourceMap%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=5000&indent=on
[ INFO] 2018-04-09 21:57:16,821 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:16,824 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:18,827 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1+OR+seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_data.1+OR+seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_md&start=0&rows=3&indent=on
[ INFO] 2018-04-09 21:57:18,831 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1+OR+id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_data.1+OR+id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_md&start=0&rows=3&indent=on
[ INFO] 2018-04-09 21:57:23,334 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:23,336 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:23,379 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:23,381 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:23,383 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:23,385 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:23,387 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=seriesId%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:23,389 (HTTPService:doRequest:381) REQUEST URI= http://localhost:8983/solr/search_core/select/?q=id%3ApackageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1&start=0&rows=1&indent=on
[ INFO] 2018-04-09 21:57:24,056 (IndexTaskProcessor:processTask:288) *********************end to process update index task for packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1 in thread 110
[ INFO] 2018-04-09 21:57:24,062 (IndexTaskProcessor:processTask:315) Indexing complete for pid: packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.1
[ERROR] 2018-04-09 21:57:24,438 (IndexTaskProcessor:checkReadinessProcessResourceMap:353) We waited for another thread to finish indexing a pid with series id packageIndexingTest_P_S_P_T_T_T_20180400.14.25_md for a while. Now we quit and can't index id packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2
[ERROR] 2018-04-09 21:57:24,438 (IndexTaskProcessor:processTask:297) Unable to process task for pid: packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2
java.lang.Exception: We waited for another thread to finish indexing a pid with series id packageIndexingTest_P_S_P_T_T_T_20180400.14.25_md for a while. Now we quit and can't index id packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2
[ INFO] 2018-04-09 21:57:24,442 (IndexTaskProcessor:newOrFailedIndexTaskExists:890) IndexTaskProcess.newOrFailedIndexTaskExists for id packageIndexingTest_P_S_P_T_T_T_20180400.14.25_resMap.2
~~~
