[Dspace-tech] SOLR Optimize fails

[Smith, Andrew J]

Hello,

After upgrading from v1.7.2 to 3.2, our usage statistics no longer display. While tracking down the issue, I tried to run the stats-util –o command. It fails with a Internal Server Error.

SOLR Optimize -- Process Started:1391700312769

Exception: Internal Server Error

Internal Server Error

request: http://{our.site.edu}/solr/statistics/update

org.apache.solr.common.SolrException: Internal Server Error

Internal Server Error

request: http://{our.site.edu}/solr/statistics/update

at org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:435)

at org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:244)

at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:105)

at org.apache.solr.client.solrj.SolrServer.optimize(SolrServer.java:94)

at org.apache.solr.client.solrj.SolrServer.optimize(SolrServer.java:82)

at org.dspace.statistics.SolrLogger.optimizeSOLR(SolrLogger.java:939)

at org.dspace.statistics.util.StatisticsClient.main(StatisticsClient.java:90)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:606)

at org.dspace.app.launcher.ScriptLauncher.main(ScriptLauncher.java:183)

Thinking this might be a result of upgrading, I returned the site to its pre-upgrade version 1.7.2. However, running stats-util in this version fails with the same error.

Any pointers on what to look for?

Thanks,

Andy

Andy Smith

Lead Technology Analyst/Programmer

IUPUI University Library

andj...@iupui.edu

(317) 274-0482

[helix84]

This is just a generic message from DSpace that Solr returned and
error. You have to find the Solr error in the Tomcat log
(catalina.out).


Regards,
~~helix84

Compulsory reading: DSpace Mailing List Etiquette
https://wiki.duraspace.org/display/DSPACE/Mailing+List+Etiquette

[Smith, Andrew J]

Thanks for the reply.

Here is what I find in the Tomcat log:


Feb 06, 2014 11:39:45 AM org.apache.solr.core.SolrCore execute
INFO: [statistics] webapp=/ajs/isw-1.7/solr path=/select params={q=type:2+AND+id:1&wt=javabin&version=1} hits=4 status=0 QTime=1
Feb 06, 2014 11:39:45 AM org.apache.solr.update.DirectUpdateHandler2 commit
INFO: start commit(optimize=true,waitFlush=true,waitSearcher=true,expungeDeletes=false)
Feb 06, 2014 11:39:45 AM org.apache.solr.update.processor.LogUpdateProcessor finish
INFO: {} 0 1
Feb 06, 2014 11:39:45 AM org.apache.solr.common.SolrException log
SEVERE: java.lang.RuntimeException: Failed to acquire random test lock; please verify filesystem for lock directory '/home/andjsmit/dspace/isw-1.7/solr/statistics/data/index' supports locking
at org.apache.lucene.store.NativeFSLockFactory.acquireTestLock(NativeFSLockFactory.java:99)
at org.apache.lucene.store.NativeFSLockFactory.makeLock(NativeFSLockFactory.java:137)
at org.apache.lucene.store.Directory.makeLock(Directory.java:131)
at org.apache.lucene.index.IndexWriter.init(IndexWriter.java:1563)
at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1421)
at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:191)
at org.apache.solr.update.UpdateHandler.createMainIndexWriter(UpdateHandler.java:98)
at org.apache.solr.update.DirectUpdateHandler2.openWriter(DirectUpdateHandler2.java:173)
at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:402)
at org.apache.solr.update.processor.RunUpdateProcessor.processCommit(RunUpdateProcessorFactory.java:85)
at org.apache.solr.handler.RequestHandlerUtils.handleCommit(RequestHandlerUtils.java:107)
at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:48)
at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:131)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:1316)
at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:338)
at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:241)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Unknown Source)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(Unknown Source)
at org.dspace.solr.filters.LocalHostRestrictionFilter.doFilter(LocalHostRestrictionFilter.java:60)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Unknown Source)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(Unknown Source)
at org.apache.catalina.core.StandardWrapperValve.invoke(Unknown Source)
at org.apache.catalina.core.StandardContextValve.invoke(Unknown Source)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(Unknown Source)
at org.apache.catalina.core.StandardHostValve.invoke(Unknown Source)
at com.googlecode.psiprobe.Tomcat70AgentValve.invoke(Tomcat70AgentValve.java:38)
at org.apache.catalina.valves.ErrorReportValve.invoke(Unknown Source)
at org.apache.catalina.core.StandardEngineValve.invoke(Unknown Source)
at org.apache.catalina.connector.CoyoteAdapter.service(Unknown Source)
at org.apache.coyote.ajp.AjpProcessor.process(Unknown Source)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(Unknown Source)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(Unknown Source)
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:744)
Caused by: org.apache.lucene.store.LockReleaseFailedException: Cannot forcefully unlock a NativeFSLock which is held by another indexer component: /home/andjsmit/dspace/isw-1.7/solr/statistics/data/index/lucene-f8487b8bf55244e941659d24a471594b-lucene--59z8n1-test.lock
at org.apache.lucene.store.NativeFSLock.release(NativeFSLockFactory.java:321)
at org.apache.lucene.store.NativeFSLockFactory.acquireTestLock(NativeFSLockFactory.java:91)
... 34 more

Feb 06, 2014 11:39:45 AM org.apache.solr.core.SolrCore execute
INFO: [statistics] webapp=/ajs/isw-1.7/solr path=/update params={optimize=true&waitSearcher=true&maxSegments=1&waitFlush=true&wt=javabin&version=1} status=500 QTime=1
Feb 06, 2014 11:39:45 AM org.apache.solr.common.SolrException log
SEVERE: java.lang.RuntimeException: Failed to acquire random test lock; please verify filesystem for lock directory '/home/andjsmit/dspace/isw-1.7/solr/statistics/data/index' supports locking
at org.apache.lucene.store.NativeFSLockFactory.acquireTestLock(NativeFSLockFactory.java:99)
at org.apache.lucene.store.NativeFSLockFactory.makeLock(NativeFSLockFactory.java:137)
at org.apache.lucene.store.Directory.makeLock(Directory.java:131)
at org.apache.lucene.index.IndexWriter.init(IndexWriter.java:1563)
at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1421)
at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:191)
at org.apache.solr.update.UpdateHandler.createMainIndexWriter(UpdateHandler.java:98)
at org.apache.solr.update.DirectUpdateHandler2.openWriter(DirectUpdateHandler2.java:173)
at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:402)
at org.apache.solr.update.processor.RunUpdateProcessor.processCommit(RunUpdateProcessorFactory.java:85)
at org.apache.solr.handler.RequestHandlerUtils.handleCommit(RequestHandlerUtils.java:107)
at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:48)
at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:131)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:1316)
at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:338)
at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:241)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Unknown Source)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(Unknown Source)
at org.dspace.solr.filters.LocalHostRestrictionFilter.doFilter(LocalHostRestrictionFilter.java:60)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Unknown Source)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(Unknown Source)
at org.apache.catalina.core.StandardWrapperValve.invoke(Unknown Source)
at org.apache.catalina.core.StandardContextValve.invoke(Unknown Source)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(Unknown Source)
at org.apache.catalina.core.StandardHostValve.invoke(Unknown Source)
at com.googlecode.psiprobe.Tomcat70AgentValve.invoke(Tomcat70AgentValve.java:38)
at org.apache.catalina.valves.ErrorReportValve.invoke(Unknown Source)
at org.apache.catalina.core.StandardEngineValve.invoke(Unknown Source)
at org.apache.catalina.connector.CoyoteAdapter.service(Unknown Source)
at org.apache.coyote.ajp.AjpProcessor.process(Unknown Source)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(Unknown Source)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(Unknown Source)
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:744)
Caused by: org.apache.lucene.store.LockReleaseFailedException: Cannot forcefully unlock a NativeFSLock which is held by another indexer component: /home/andjsmit/dspace/isw-1.7/solr/statistics/data/index/lucene-f8487b8bf55244e941659d24a471594b-lucene--59z8n1-test.lock
at org.apache.lucene.store.NativeFSLock.release(NativeFSLockFactory.java:321)
at org.apache.lucene.store.NativeFSLockFactory.acquireTestLock(NativeFSLockFactory.java:91)
... 34 more

In the solr/statistics/data directory, I found a lock file I think (lucene-364fc85d50ed05e0eb5030f547b632b7-write.lock). Removing it did not change the error.

[helix84]

Keep a backup of the old index somewhere ([dspace]/solr). Delete all
*.lock files and try again. Restarting Tomcat won't hurt.

[Mark H. Wood]

Using 'wget' with a sample request from one of these log entries
suggests that "Found" means we got back a 302 Found HTTP response code:

mwood@savage ~ $ wget 'https://scholarworks.iupui.edu/solr/statistics/select?rows=0&q=type: 2 AND id:807&facet.mincount=1&shards=scholarworks.iupui.edu/solr/statistics&facet.field=id&facet=true&facet.limit=10&fq=-isBot:true&fq=-(bundleName:[* TO *]-bundleName:ORIGINAL)&fq=-(statistics_type:[* TO *] AND -statistics_type:view)&wt=javabin&version=2'
--2014-02-06 12:12:28-- https://scholarworks.iupui.edu/solr/statistics/select?rows=0&q=type:%202%20AND%20%20id:807&facet.mincount=1&shards=scholarworks.iupui.edu/solr/statistics&facet.field=id&facet=true&facet.limit=10&fq=-isBot:true&fq=-(bundleName:[*%20TO%20*]-bundleName:ORIGINAL)&fq=-(statistics_type:[*%20TO%20*]%20AND%20-statistics_type:view)&wt=javabin&version=2
Resolving scholarworks.iupui.edu... 2001:18e8:3:be::102, 134.68.190.85
Connecting to scholarworks.iupui.edu|2001:18e8:3:be::102|:443... connected.
HTTP request sent, awaiting response... 302 Found
Location: unspecified
ERROR: Redirection (302) without location.

So we need to figure out what is redirecting and why.

--
Mark H. Wood, Lead System Programmer mw...@IUPUI.Edu
Machines should not be friendly. Machines should be obedient.