Urgh, I was hoping we could repro the "massive deletion" with
infoStream turned on.
Uh-oh: that "off by 1" corruption is very likely due to the Sun JRE
bug described here:
https://issues.apache.org/jira/browse/LUCENE-1282
Can you downgrade to 1.6.0_03, or, upgrade to the latest beta build
(b28) of Sun's 1.6 JRE, from here:
http://download.java.net/jdk6/binaries/
I agree you should stick with the older stuff to reproduce this bug,
but, do you know which svn rev of Lucene's JAR you are using? I had
committed a workaround for LUCENE-1282 to trunk.
Mike
On Aug 21, 2008, at 2:55 PM, Chris Harris wrote:
Well shoot, upon further examination it appears that this time around
there weren't actually any segment deletion problems. The "only"
problem was a "doc counts differ" error. Interestingly, the count is
only off by one.
From the CheckIndex tool:
****
Opening index @ /ssd/solr-9999/solr/exhibitcore/data/index
Segments file=segments_qc3 numSegments=31
version=FORMAT_SHARED_DOC_STORE [Lucene 2.3]
[...]
4 of 31: name=_3r docCount=23673
compound=false
numFiles=8
size (MB)=203.217
no deletions
test: open reader.........FAILED
WARNING: would remove reference to this segment (-fix was not
specified); full exception:
org.apache.lucene.index.CorruptIndexException: doc counts differ for
segment _3r: fieldsReader shows 23672 but segmentInfo shows 23673
at
org.apache.lucene.index.SegmentReader.initialize(SegmentReader.java:
315)
at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:264)
at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:199)
at org.apache.lucene.index.CheckIndex.check(CheckIndex.java:178)
at org.apache.lucene.index.CheckIndex.main(CheckIndex.java:433)
[...]
WARNING: 1 broken segments detected
WARNING: 23673 documents would be lost if -fix were specified
***
I don't know if they would still help in light of this, but I've got
12MB of infoStream data from this round here:
http://www.knowledgemosaic.com/public/infoStream.tar.gz
As for the normal Solr log (I now have a log for the whole round), the
first relevant SEVERE error was this:
<record>
<date>2008-08-20T16:42:06</date>
<millis>1219275726747</millis>
<sequence>587322</sequence>
<logger>org.apache.solr.core.SolrCore</logger>
<level>SEVERE</level>
<class>org.apache.solr.common.SolrException</class>
<method>log</method>
<thread>13</thread>
<message>java.lang.NullPointerException
</message>
</record>
Curiously there is no stack trace.
The next relevant error:
<record>
<date>2008-08-20T16:42:52</date>
<millis>1219275772073</millis>
<sequence>590946</sequence>
<logger>org.apache.solr.update.UpdateHandler</logger>
<level>SEVERE</level>
<class>org.apache.solr.update.DirectUpdateHandler2$CommitTracker</
class>
<method>run</method>
<thread>16</thread>
<message>auto commit error...</message>
</record>
Then there's another NullPointerException, now from a different logger
<record>
<date>2008-08-20T16:53:46</date>
<millis>1219276426304</millis>
<sequence>640371</sequence>
<logger>org.apache.solr.servlet.SolrDispatchFilter</logger>
<level>SEVERE</level>
<class>org.apache.solr.common.SolrException</class>
<method>log</method>
<thread>17</thread>
<message>java.lang.NullPointerException</message>
</record>
And later on the "corrupt index" fun begins:
<record>
<date>2008-08-20T17:02:18</date>
<millis>1219276938663</millis>
<sequence>731205</sequence>
<logger>org.apache.solr.core.SolrCore</logger>
<level>SEVERE</level>
<class>org.apache.solr.common.SolrException</class>
<method>log</method>
<thread>13</thread>
<message>org.apache.lucene.index.CorruptIndexException: doc counts
differ for segment _3r: fieldsReader shows 23672 but segmentInfo shows
23673
at
org.apache.lucene.index.SegmentReader.initialize(SegmentReader.java:
313)
at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:262)
at org.apache.lucene.index.SegmentReader.get(SegmentReader.java:197)
at org.apache.lucene.index.MultiSegmentReader.<init>
(MultiSegmentReader.java:55)
at org.apache.lucene.index.DirectoryIndexReader
$1.doBody(DirectoryIndexReader.java:75)
at org.apache.lucene.index.SegmentInfos
$FindSegmentsFile.run(SegmentInfos.java:636)
at
org
.apache
.lucene.index.DirectoryIndexReader.open(DirectoryIndexReader.java:63)
at org.apache.lucene.index.IndexReader.open(IndexReader.java:209)
at org.apache.lucene.index.IndexReader.open(IndexReader.java:173)
at org.apache.solr.search.SolrIndexSearcher.<init>
(SolrIndexSearcher.java:93)
at org.apache.solr.core.SolrCore.newSearcher(SolrCore.java:213)
at
org
.apache
.solr
.update.DirectUpdateHandler2.openSearcher(DirectUpdateHandler2.java:
207)
at
org
.apache
.solr
.update.DirectUpdateHandler2.doDeletions(DirectUpdateHandler2.java:
466)
at
org
.apache
.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:
295)
at
org
.apache
.solr
.handler.RichDocumentLoader.doAdd(RichDocumentRequestHandler.java:231)
at
org
.apache
.solr
.handler.RichDocumentLoader.addDoc(RichDocumentRequestHandler.java:
236)
at
org
.apache
.solr
.handler.RichDocumentLoader.load(RichDocumentRequestHandler.java:278)
at
org
.apache
.solr
.handler
.RichDocumentRequestHandler
.handleRequestBody(RichDocumentRequestHandler.java:80)
at
org
.apache
.solr
.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:125)
at org.apache.solr.core.RequestHandlers
$LazyRequestHandlerWrapper.handleRequest(RequestHandlers.java:228)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:965)
at
org
.apache
.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:339)
at
org
.apache
.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:274)
at org.mortbay.jetty.servlet.ServletHandler
$CachedChain.doFilter(ServletHandler.java:1089)
at
org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:
365)
at
org
.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:
216)
at
org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:
181)
at
org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:
712)
at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:
405)
at
org
.mortbay
.jetty
.handler
.ContextHandlerCollection.handle(ContextHandlerCollection.java:211)
at
org
.mortbay
.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
at
org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:
139)
at org.mortbay.jetty.Server.handle(Server.java:285)
at
org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:
502)
at org.mortbay.jetty.HttpConnection
$RequestHandler.content(HttpConnection.java:835)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:641)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:202)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:378)
at org.mortbay.jetty.bio.SocketConnector
$Connection.run(SocketConnector.java:226)
at org.mortbay.thread.BoundedThreadPool
$PoolThread.run(BoundedThreadPool.java:442)
</message>
</record>
I should probably reiterate that this round was not with the latest
Solr or the latest Lucene. Testing that is in the works, but I kind of
wanted to figure out why this older stuff was failing too.
Chris
On Wed, Aug 20, 2008 at 6:03 PM, Michael McCandless
<[EMAIL PROTECTED]> wrote:
Did the same FileNotFoundException / massive deletion of files occur?
Actually if you could zip them all up and post them, I'll dig
through them
to see if they give any clues...
Mike
Chris Harris wrote:
Ok, I did what you suggested, giving each SolrIndexWriter its own
"infoStream" log file, created in the init() method. The thing is, I
now have like 3400 infostream log files, I guess reflecting how solr
created like 3400 SolrIndexWriters over the course of the run.
(Hopefully this is plausible.) Could you explain what I should be
looking for in these files? (Posting the whole bunch of it doesn't
sound very useful.)
Thanks,
Chris
On Mon, Aug 18, 2008 at 10:12 AM, Michael McCandless
<[EMAIL PROTECTED]> wrote:
Alas, I think this won't actually turn on IndexWriter's infoStream.
I think you may need to modify the SolrIndexWriter.java sources,
in the
init
method, to add a call to setInfoStream(...).
Can any Solr developers confirm this?
Mike
Chris Harris wrote:
I'm assuming that one way to do this would be to set the logging
level
to "FINEST" in the "logging" page in the solr admin tool, and
then to
make sure my logging.properties file is also set to record the
FINEST
logging level. Let me know if that won't enable to sort of
debugging
info you are talking about. (I do understand that the logging
page in
the admin tool makes temporary changes that will get reverted
when you
restart Solr.)
On Mon, Aug 18, 2008 at 3:05 AM, Michael McCandless
<[EMAIL PROTECTED]> wrote:
Since it seems reproducible, could you turn on debugging output
(IndexWriter.setInfoStream(...)), get the FileNotFoundException
to
happen
again, and post the resulting output?
Mike
