You are viewing a plain text version of this content. The canonical link for it is here.
Posted to solr-dev@lucene.apache.org by Chantal Ackermann <ch...@btelligent.de> on 2009/11/05 17:27:35 UTC
SEVERE: SolrIndexWriter was not closed prior to finalize
Hi all,
just wanted to post this log output because it has 3 exclamation marks
which makes it sound important. ;-)
It has happened after an index process on one core was rolled back. The
select request in between was issued on a different core.
I have seen this message before but also only after some exception
happened. I just reindexed successfully (no rollback) and no SEVERE
reappeared.
Otherwise everything works fine, so I suppose it's more a matter of log
message placement / log level choice etc.
Cheers,
Chantal
05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
INFO: start rollback
05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
INFO: end_rollback
05.11.2009 16:14:33 org.apache.solr.core.SolrCore execute
INFO: [sei] webapp=/solr path=/dataimport params={} status=0 QTime=9
05.11.2009 16:43:38 org.apache.solr.core.SolrCore execute
INFO: [epg] webapp=/solr path=/select
params={sort=start_date+asc,start_date+asc&start=0&q=%2Bstart_date:[*+TO+NOW]+%2Bend_date:[NOW+TO+*]+%2Bruntime:[5+TO+300]&wt=javabin&rows=20&version=1}
hits=8 status=0 QTime=297
05.11.2009 17:10:25 org.apache.solr.update.SolrIndexWriter finalize
SEVERE: SolrIndexWriter was not closed prior to finalize(), indicates a
bug -- POSSIBLE RESOURCE LEAK!!!
Re: SEVERE: SolrIndexWriter was not closed prior to finalize
Posted by Chris Hostetter <ho...@fucit.org>.
On Mon, 9 Nov 2009, Chantal Ackermann wrote:
: > common pattern? ... do all of the people noticing these "POSSIBLE RESOURCE
: > LEAK" messages use rollback? is there any correlation between how much
: > you use rollback and how often you get one of these messages? (even if
: > they don't happen at/near the same times)
: I just noticed that it appeared after a rollback and did not reappear when the
: index went fine. I can set up some test to make sure that (in my case) this is
: a reproducible pattern.
Chantal: any update on this ... were you able to observe a definite
corrolation between rollbacks and these warnings?
I've opened SOLR-1596 to track this even if it falls off of everyones
email radar.
-Hoss
Re: SEVERE: SolrIndexWriter was not closed prior to finalize
Posted by Chantal Ackermann <ch...@btelligent.de>.
> It would be really helpful if people seeing these messages frequently in
> their logs could elaborate a little bit more on...
>
> 1) exactly which version/build of Solr they are using
1.4.0 RC from 30th of October.
Changes.txt contains the line:
$Id: CHANGES.txt 831168 2009-10-30 00:28:25Z yonik $
> 2) whether they have any custom plugins loaded (either that they developed
> on their own, or from a third party, or even from solr/contrib)
Custom EntityProcessor (single class) for handling multiple rows per
document. I've overridden getRow(). Other resources that would need
releasing etc. are not used.
> 3) what types of funtionality of Solr they use when dealing with
> indexing (ie: DIH, CSV loading, Solr Cell, SignatureUpdateProcessor,
> etc...)
DIH: loading from SQL DB, including RegexTransformer, ScriptTransformer,
DateFormatTransformer.
> The one thing i do notice in particular about the log messages that were
> posted in this thread is that the rollback feature was used ... is this a
> common pattern? ... do all of the people noticing these "POSSIBLE RESOURCE
> LEAK" messages use rollback? is there any correlation between how much
> you use rollback and how often you get one of these messages? (even if
> they don't happen at/near the same times)
I just noticed that it appeared after a rollback and did not reappear
when the index went fine. I can set up some test to make sure that (in
my case) this is a reproducible pattern.
> (solr isn't running perfectly, and something is goig wrong, but luckily
> it's going wrong in a way that solr can recover from ... it could just as
> easily go wrong in a way that solr can't recover from)
Thanks a lot for clarifying this, Chris!
Chantal
Re: SEVERE: SolrIndexWriter was not closed prior to finalize
Posted by Chris Hostetter <ho...@fucit.org>.
: that's what I thought because I didn't experience any problems. But doesn't
: that indicate that there is a missing cleanup?
yes, it does.
: And if it is not worth checking / changing then maybe the log level should be
: decreased to adjust in comparison to other SEVERE warnings?
it really is an indication of a severe problem -- but unfortunately it's
an indication of a problem detected during GC, which was was dealt with.
the reason it's classified as SEVERE is because it's possible whatever
caused this problem may be resulting in a resource leak which is *not*
being detected.
It would be really helpful if people seeing these messages frequently in
their logs could elaborate a little bit more on...
1) exactly which version/build of Solr they are using
2) whether they have any custom plugins loaded (either that they developed
on their own, or from a third party, or even from solr/contrib)
3) what types of funtionality of Solr they use when dealing with
indexing (ie: DIH, CSV loading, Solr Cell, SignatureUpdateProcessor,
etc...)
Because this problem is only detected during GC, the log messages arround
when it happens are probably not directly helpful, but a better picture of
the *pattern* of behaviors that trigger this would be very helpful.
The one thing i do notice in particular about the log messages that were
posted in this thread is that the rollback feature was used ... is this a
common pattern? ... do all of the people noticing these "POSSIBLE RESOURCE
LEAK" messages use rollback? is there any correlation between how much
you use rollback and how often you get one of these messages? (even if
they don't happen at/near the same times)
: It's just that monitoring systems will of course raise an alarm on SEVERE
: messages. And even if SOLR runs perfect these messages would give the
: impression that something's going wrong.
(solr isn't running perfectly, and something is goig wrong, but luckily
it's going wrong in a way that solr can recover from ... it could just as
easily go wrong in a way that solr can't recover from)
-Hoss
Re: SEVERE: SolrIndexWriter was not closed prior to finalize
Posted by Noble Paul നോബിള് नोब्ळ् <no...@corp.aol.com>.
On Fri, Nov 6, 2009 at 2:15 PM, Chantal Ackermann
<ch...@btelligent.de> wrote:
>
>
> Noble Paul നോബിള് नोब्ळ् schrieb:
>>
>> These logs were added to warn us developers on some missing cleanups.
>> Doing cleanups in finalize() is not considered clean.
>>
>> It should not cause any harm other than those nasty messages.
>>
>
> that's what I thought because I didn't experience any problems. But doesn't
> that indicate that there is a missing cleanup?
cleanup stil happens. But we did not wish to to happen in finalize().
> And if it is not worth checking / changing then maybe the log level should
> be decreased to adjust in comparison to other SEVERE warnings?
>
> It's just that monitoring systems will of course raise an alarm on SEVERE
> messages. And even if SOLR runs perfect these messages would give the
> impression that something's going wrong.
This was a bug in Solr and there was a consensus to put it in as a
SEVERE one. It is a code problem .
I guess the message should be in WARNING level
>
> Cheers,
> Chantal
>
>
>
>> On Fri, Nov 6, 2009 at 4:59 AM, markwaddle <ma...@markwaddle.com> wrote:
>>>
>>> For what it's worth, I have encountered this error in the logs nearly
>>> once a
>>> day for the last 3 weeks. It appears so often, yet so inconsistently that
>>> it
>>> does not seem to occur while performing a specific operation or near a
>>> specific error.
>>>
>>> Mark
>>>
>>>
>>> Chantal Ackermann wrote:
>>>>
>>>> Hi all,
>>>>
>>>> just wanted to post this log output because it has 3 exclamation marks
>>>> which makes it sound important. ;-)
>>>>
>>>> It has happened after an index process on one core was rolled back. The
>>>> select request in between was issued on a different core.
>>>> I have seen this message before but also only after some exception
>>>> happened. I just reindexed successfully (no rollback) and no SEVERE
>>>> reappeared.
>>>>
>>>> Otherwise everything works fine, so I suppose it's more a matter of log
>>>> message placement / log level choice etc.
>>>>
>>>> Cheers,
>>>> Chantal
>>>>
>>>> 05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
>>>> INFO: start rollback
>>>> 05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
>>>> INFO: end_rollback
>>>> 05.11.2009 16:14:33 org.apache.solr.core.SolrCore execute
>>>> INFO: [sei] webapp=/solr path=/dataimport params={} status=0 QTime=9
>>>> 05.11.2009 16:43:38 org.apache.solr.core.SolrCore execute
>>>> INFO: [epg] webapp=/solr path=/select
>>>>
>>>> params={sort=start_date+asc,start_date+asc&start=0&q=%2Bstart_date:[*+TO+NOW]+%2Bend_date:[NOW+TO+*]+%2Bruntime:[5+TO+300]&wt=javabin&rows=20&version=1}
>>>> hits=8 status=0 QTime=297
>>>> 05.11.2009 17:10:25 org.apache.solr.update.SolrIndexWriter finalize
>>>> SEVERE: SolrIndexWriter was not closed prior to finalize(), indicates a
>>>> bug -- POSSIBLE RESOURCE LEAK!!!
>>>>
>>>>
>>> --
>>> View this message in context:
>>> http://old.nabble.com/SEVERE%3A-SolrIndexWriter-was-not-closed-prior-to-finalize-tp26217896p26224126.html
>>> Sent from the Solr - Dev mailing list archive at Nabble.com.
>>>
>>>
>
--
-----------------------------------------------------
Noble Paul | Principal Engineer| AOL | http://aol.com
Re: SEVERE: SolrIndexWriter was not closed prior to finalize
Posted by Chantal Ackermann <ch...@btelligent.de>.
Noble Paul നോബിള് नोब्ळ् schrieb:
> These logs were added to warn us developers on some missing cleanups.
> Doing cleanups in finalize() is not considered clean.
>
> It should not cause any harm other than those nasty messages.
>
that's what I thought because I didn't experience any problems. But
doesn't that indicate that there is a missing cleanup?
And if it is not worth checking / changing then maybe the log level
should be decreased to adjust in comparison to other SEVERE warnings?
It's just that monitoring systems will of course raise an alarm on
SEVERE messages. And even if SOLR runs perfect these messages would give
the impression that something's going wrong.
Cheers,
Chantal
> On Fri, Nov 6, 2009 at 4:59 AM, markwaddle <ma...@markwaddle.com> wrote:
>> For what it's worth, I have encountered this error in the logs nearly once a
>> day for the last 3 weeks. It appears so often, yet so inconsistently that it
>> does not seem to occur while performing a specific operation or near a
>> specific error.
>>
>> Mark
>>
>>
>> Chantal Ackermann wrote:
>>> Hi all,
>>>
>>> just wanted to post this log output because it has 3 exclamation marks
>>> which makes it sound important. ;-)
>>>
>>> It has happened after an index process on one core was rolled back. The
>>> select request in between was issued on a different core.
>>> I have seen this message before but also only after some exception
>>> happened. I just reindexed successfully (no rollback) and no SEVERE
>>> reappeared.
>>>
>>> Otherwise everything works fine, so I suppose it's more a matter of log
>>> message placement / log level choice etc.
>>>
>>> Cheers,
>>> Chantal
>>>
>>> 05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
>>> INFO: start rollback
>>> 05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
>>> INFO: end_rollback
>>> 05.11.2009 16:14:33 org.apache.solr.core.SolrCore execute
>>> INFO: [sei] webapp=/solr path=/dataimport params={} status=0 QTime=9
>>> 05.11.2009 16:43:38 org.apache.solr.core.SolrCore execute
>>> INFO: [epg] webapp=/solr path=/select
>>> params={sort=start_date+asc,start_date+asc&start=0&q=%2Bstart_date:[*+TO+NOW]+%2Bend_date:[NOW+TO+*]+%2Bruntime:[5+TO+300]&wt=javabin&rows=20&version=1}
>>> hits=8 status=0 QTime=297
>>> 05.11.2009 17:10:25 org.apache.solr.update.SolrIndexWriter finalize
>>> SEVERE: SolrIndexWriter was not closed prior to finalize(), indicates a
>>> bug -- POSSIBLE RESOURCE LEAK!!!
>>>
>>>
>> --
>> View this message in context: http://old.nabble.com/SEVERE%3A-SolrIndexWriter-was-not-closed-prior-to-finalize-tp26217896p26224126.html
>> Sent from the Solr - Dev mailing list archive at Nabble.com.
>>
>>
Re: SEVERE: SolrIndexWriter was not closed prior to finalize
Posted by Noble Paul നോബിള് नोब्ळ् <no...@corp.aol.com>.
These logs were added to warn us developers on some missing cleanups.
Doing cleanups in finalize() is not considered clean.
It should not cause any harm other than those nasty messages.
On Fri, Nov 6, 2009 at 4:59 AM, markwaddle <ma...@markwaddle.com> wrote:
>
> For what it's worth, I have encountered this error in the logs nearly once a
> day for the last 3 weeks. It appears so often, yet so inconsistently that it
> does not seem to occur while performing a specific operation or near a
> specific error.
>
> Mark
>
>
> Chantal Ackermann wrote:
>>
>> Hi all,
>>
>> just wanted to post this log output because it has 3 exclamation marks
>> which makes it sound important. ;-)
>>
>> It has happened after an index process on one core was rolled back. The
>> select request in between was issued on a different core.
>> I have seen this message before but also only after some exception
>> happened. I just reindexed successfully (no rollback) and no SEVERE
>> reappeared.
>>
>> Otherwise everything works fine, so I suppose it's more a matter of log
>> message placement / log level choice etc.
>>
>> Cheers,
>> Chantal
>>
>> 05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
>> INFO: start rollback
>> 05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
>> INFO: end_rollback
>> 05.11.2009 16:14:33 org.apache.solr.core.SolrCore execute
>> INFO: [sei] webapp=/solr path=/dataimport params={} status=0 QTime=9
>> 05.11.2009 16:43:38 org.apache.solr.core.SolrCore execute
>> INFO: [epg] webapp=/solr path=/select
>> params={sort=start_date+asc,start_date+asc&start=0&q=%2Bstart_date:[*+TO+NOW]+%2Bend_date:[NOW+TO+*]+%2Bruntime:[5+TO+300]&wt=javabin&rows=20&version=1}
>> hits=8 status=0 QTime=297
>> 05.11.2009 17:10:25 org.apache.solr.update.SolrIndexWriter finalize
>> SEVERE: SolrIndexWriter was not closed prior to finalize(), indicates a
>> bug -- POSSIBLE RESOURCE LEAK!!!
>>
>>
>
> --
> View this message in context: http://old.nabble.com/SEVERE%3A-SolrIndexWriter-was-not-closed-prior-to-finalize-tp26217896p26224126.html
> Sent from the Solr - Dev mailing list archive at Nabble.com.
>
>
--
-----------------------------------------------------
Noble Paul | Principal Engineer| AOL | http://aol.com
Re: SEVERE: SolrIndexWriter was not closed prior to finalize
Posted by markwaddle <ma...@markwaddle.com>.
For what it's worth, I have encountered this error in the logs nearly once a
day for the last 3 weeks. It appears so often, yet so inconsistently that it
does not seem to occur while performing a specific operation or near a
specific error.
Mark
Chantal Ackermann wrote:
>
> Hi all,
>
> just wanted to post this log output because it has 3 exclamation marks
> which makes it sound important. ;-)
>
> It has happened after an index process on one core was rolled back. The
> select request in between was issued on a different core.
> I have seen this message before but also only after some exception
> happened. I just reindexed successfully (no rollback) and no SEVERE
> reappeared.
>
> Otherwise everything works fine, so I suppose it's more a matter of log
> message placement / log level choice etc.
>
> Cheers,
> Chantal
>
> 05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
> INFO: start rollback
> 05.11.2009 16:13:23 org.apache.solr.update.DirectUpdateHandler2 rollback
> INFO: end_rollback
> 05.11.2009 16:14:33 org.apache.solr.core.SolrCore execute
> INFO: [sei] webapp=/solr path=/dataimport params={} status=0 QTime=9
> 05.11.2009 16:43:38 org.apache.solr.core.SolrCore execute
> INFO: [epg] webapp=/solr path=/select
> params={sort=start_date+asc,start_date+asc&start=0&q=%2Bstart_date:[*+TO+NOW]+%2Bend_date:[NOW+TO+*]+%2Bruntime:[5+TO+300]&wt=javabin&rows=20&version=1}
> hits=8 status=0 QTime=297
> 05.11.2009 17:10:25 org.apache.solr.update.SolrIndexWriter finalize
> SEVERE: SolrIndexWriter was not closed prior to finalize(), indicates a
> bug -- POSSIBLE RESOURCE LEAK!!!
>
>
--
View this message in context: http://old.nabble.com/SEVERE%3A-SolrIndexWriter-was-not-closed-prior-to-finalize-tp26217896p26224126.html
Sent from the Solr - Dev mailing list archive at Nabble.com.