SolrIndexWriter was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE LEAK!!!

[Ravi Kiran]

Hello,
While reloading a core I got this following error, when does this
occur ? Prior to this exception I do not see anything wrong in the logs.

[#|2011-02-01T13:02:36.697-0500|SEVERE|sun-appserver2.1|org.apache.solr.servlet.SolrDispatchFilter|_ThreadID=25;_ThreadName=httpWorkerThread-9001-5;_RequestID=450f6337-1f5c-42bc-a572-f0924de36b56;|org.apache.lucene.store.LockObtainFailedException:
Lock obtain timed out: NativeFSLock@
/data/solr/core/solr-data/index/lucene-7dc773a074342fa21d7d5ba09fc80678-write.lock
at org.apache.lucene.store.Lock.obtain(Lock.java:85)
at org.apache.lucene.index.IndexWriter.init(IndexWriter.java:1565)
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.addDoc(DirectUpdateHandler2.java:220)
at
org.apache.solr.update.processor.RunUpdateProcessor.processAdd(RunUpdateProcessorFactory.java:61)
at
org.apache.solr.handler.XMLLoader.processUpdate(XMLLoader.java:139)
at org.apache.solr.handler.XMLLoader.load(XMLLoader.java:69)
at
org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:54)
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(ApplicationFilterChain.java:246)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:313)
at
org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:287)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:218)
at
org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:648)
at
org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:593)
at com.sun.enterprise.web.WebPipeline.invoke(WebPipeline.java:94)
at
com.sun.enterprise.web.PESessionLockingStandardPipeline.invoke(PESessionLockingStandardPipeline.java:98)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:222)
at
org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:648)
at
org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:593)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:587)
at
org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:1096)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:166)
at
org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:648)
at
org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:593)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:587)
at
org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:1096)
at
org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:290)
at
com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.invokeAdapter(DefaultProcessorTask.java:647)
at
com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.doProcess(DefaultProcessorTask.java:579)
at
com.sun.enterprise.web.connector.grizzly.DefaultProcessorTask.process(DefaultProcessorTask.java:831)
at
com.sun.enterprise.web.connector.grizzly.DefaultReadTask.executeProcessorTask(DefaultReadTask.java:341)
at
com.sun.enterprise.web.connector.grizzly.DefaultReadTask.doTask(DefaultReadTask.java:263)
at
com.sun.enterprise.web.connector.grizzly.DefaultReadTask.doTask(DefaultReadTask.java:214)
at
com.sun.enterprise.web.connector.grizzly.TaskBase.run(TaskBase.java:265)
at
com.sun.enterprise.web.connector.grizzly.WorkerThreadImpl.run(WorkerThreadImpl.java:116)
|#]

[#|2011-02-01T13:02:40.330-0500|SEVERE|sun-appserver2.1|org.apache.solr.update.SolrIndexWriter|_ThreadID=82;_ThreadName=Finalizer;_RequestID=121fac59-7b08-46b9-acaa-5c5462418dc7;|SolrIndexWriter
was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE
LEAK!!!|#]

[#|2011-02-01T13:02:40.330-0500|SEVERE|sun-appserver2.1|org.apache.solr.update.SolrIndexWriter|_ThreadID=82;_ThreadName=Finalizer;_RequestID=121fac59-7b08-46b9-acaa-5c5462418dc7;|SolrIndexWriter
was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE
LEAK!!!|#]


Ravi Kiran Bhaskar

[Chris Hostetter]

: While reloading a core I got this following error, when does this
: occur ? Prior to this exception I do not see anything wrong in the logs.

well, there are realy two distinct types of "errors" in your log...

: [#|2011-02-01T13:02:36.697-0500|SEVERE|sun-appserver2.1|org.apache.solr.servlet.SolrDispatchFilter|_ThreadID=25;_ThreadName=httpWorkerThread-9001-5;_RequestID=450f6337-1f5c-42bc-a572-f0924de36b56;|org.apache.lucene.store.LockObtainFailedException:
: Lock obtain timed out: NativeFSLock@
: /data/solr/core/solr-data/index/lucene-7dc773a074342fa21d7d5ba09fc80678-write.lock
: at org.apache.lucene.store.Lock.obtain(Lock.java:85)
: at org.apache.lucene.index.IndexWriter.init(IndexWriter.java:1565)
: at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1421)

...this is error #1, indicating that for some reason the IndexWriter Solr
wasn't trying to create wasn't able to get a Native Filesystem lock on
your index directory -- is it possible you have two intsances of Solr (or
two solr cores) trying to re-use the same data directory?

(diagnosing exampley why you got this error also requires knowing what
Filesystem you are using).

: [#|2011-02-01T13:02:40.330-0500|SEVERE|sun-appserver2.1|org.apache.solr.update.SolrIndexWriter|_ThreadID=82;_ThreadName=Finalizer;_RequestID=121fac59-7b08-46b9-acaa-5c5462418dc7;|SolrIndexWriter
: was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE
: LEAK!!!|#]
:
: [#|2011-02-01T13:02:40.330-0500|SEVERE|sun-appserver2.1|org.apache.solr.update.SolrIndexWriter|_ThreadID=82;_ThreadName=Finalizer;_RequestID=121fac59-7b08-46b9-acaa-5c5462418dc7;|SolrIndexWriter
: was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE
: LEAK!!!|#]

...these errors are warning you that something very unexpected was
discovered when the the Garbage Collector tried to cleanup the
SolrIndexWriter -- it found that the SolrIndexWriter had never been
formally closed.

In normal operation, this might indicate the existence of a bug in code
not managing it's resources properly --and in fact, it does indicate the
existence of a bug in that evidently a Lock timed out failure doesn't
cause the SOlrIndexWriter to be closed -- but in your case it's not really
something to be worried about -- it's just a cascading effect of the first
error.

-Hoss

[Ravi Kiran]

Thanks for the response Hoss. Sorry for replying late was on a business
trip. The server was indexing as well as searching at the same time and it
was configured for a Native file lock, could that be the issue ? I got
another server so moved it to a Master & slave configuration with file lock
being single on both machines, that solved the issue.

I would however love to know what caused that error (its never too late to
learn, right ???)

Thanks,

Ravi Kiran

Post by Chris Hostetter
: While reloading a core I got this following error, when does this
: occur ? Prior to this exception I do not see anything wrong in the logs.
well, there are realy two distinct types of "errors" in your log...
/data/solr/core/solr-data/index/lucene-7dc773a074342fa21d7d5ba09fc80678-write.lock
: at org.apache.lucene.store.Lock.obtain(Lock.java:85)
: at
org.apache.lucene.index.IndexWriter.init(IndexWriter.java:1565)
: at
org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:1421)
...this is error #1, indicating that for some reason the IndexWriter Solr
wasn't trying to create wasn't able to get a Native Filesystem lock on
your index directory -- is it possible you have two intsances of Solr (or
two solr cores) trying to re-use the same data directory?
(diagnosing exampley why you got this error also requires knowing what
Filesystem you are using).
[#|2011-02-01T13:02:40.330-0500|SEVERE|sun-appserver2.1|org.apache.solr.update.SolrIndexWriter|_ThreadID=82;_ThreadName=Finalizer;_RequestID=121fac59-7b08-46b9-acaa-5c5462418dc7;|SolrIndexWriter
: was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE
: LEAK!!!|#]
[#|2011-02-01T13:02:40.330-0500|SEVERE|sun-appserver2.1|org.apache.solr.update.SolrIndexWriter|_ThreadID=82;_ThreadName=Finalizer;_RequestID=121fac59-7b08-46b9-acaa-5c5462418dc7;|SolrIndexWriter
: was not closed prior to finalize(), indicates a bug -- POSSIBLE RESOURCE
: LEAK!!!|#]
...these errors are warning you that something very unexpected was
discovered when the the Garbage Collector tried to cleanup the
SolrIndexWriter -- it found that the SolrIndexWriter had never been
formally closed.
In normal operation, this might indicate the existence of a bug in code
not managing it's resources properly --and in fact, it does indicate the
existence of a bug in that evidently a Lock timed out failure doesn't
cause the SOlrIndexWriter to be closed -- but in your case it's not really
something to be worried about -- it's just a cascading effect of the first
error.
-Hoss