It also happens on add records.
Putting a proxy in between client and server, revealed that the server writes
zero bytes back on the update, so what the client says is correct. So guess I
have to dig into the server code.
Limiting to fewer updates before commit does seem to make the change of success
higher.
Any input will greatly appreciated.
cheers,
:-Dennis
On 17/05/2011, at 14.43, Dennis Schafroth wrote:
> Hi
>
> I can see others is having same issue but haven't seen any fixes or work
> around.
>
>
> I am adding and delete records mixed. I do bulks up till 1000 records. On the
> commit I see the following in the client:
>
> 2011-05-17 13:42:41 ERROR - harvester
> [main/com.indexdata.masterkey.localindices.harvest.storage.SolrRecordStorage]
> - Commit failed when adding 39900 and deleting 11666.
> org.apache.solr.client.solrj.SolrServerException:
> java.net.SocketTimeoutException: Read timed out
> at
> org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:483)
> 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.commit(SolrServer.java:86)
> at org.apache.solr.client.solrj.SolrServer.commit(SolrServer.java:75)
> at
> com.indexdata.masterkey.localindices.harvest.storage.SolrRecordStorage.commit(SolrRecordStorage.java:47)
> at
> com.indexdata.masterkey.localindices.harvest.storage.BulkSolrRecordStorage.commit(BulkSolrRecordStorage.java:101)
> at
> com.indexdata.masterkey.localindices.harvest.job.OAIRecordHarvestJob.run(OAIRecordHarvestJob.java:146)
> at
> com.indexdata.masterkey.localindices.harvest.job.TestOAIRecordHarvestJob.TestCleanFullBulkHarvestJob(TestOAIRecordHarvestJob.java:65)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at junit.framework.TestCase.runTest(TestCase.java:164)
> at junit.framework.TestCase.runBare(TestCase.java:130)
> at junit.framework.TestResult$1.protect(TestResult.java:106)
> at junit.framework.TestResult.runProtected(TestResult.java:124)
> at junit.framework.TestResult.run(TestResult.java:109)
> at junit.framework.TestCase.run(TestCase.java:120)
> at
> org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)
> at
> org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
> at
> org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
> at
> org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
> at
> org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
> at
> org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
> Caused by: java.net.SocketTimeoutException: Read timed out
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.read(SocketInputStream.java:129)
> at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
> at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
> at
> org.apache.commons.httpclient.HttpParser.readRawLine(HttpParser.java:78)
> at
> org.apache.commons.httpclient.HttpParser.readLine(HttpParser.java:106)
> at
> org.apache.commons.httpclient.HttpConnection.readLine(HttpConnection.java:1116)
> at
> org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpConnectionAdapter.readLine(MultiThreadedHttpConnectionManager.java:1413)
> at
> org.apache.commons.httpclient.HttpMethodBase.readStatusLine(HttpMethodBase.java:1973)
> at
> org.apache.commons.httpclient.HttpMethodBase.readResponse(HttpMethodBase.java:1735)
> at
> org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1098)
> at
> org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398)
> at
> org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171)
> at
> org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397)
> at
> org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323)
> at
> org.apache.solr.client.solrj.impl.CommonsHttpSolrServer.request(CommonsHttpSolrServer.java:427)
> ... 24 more
>
>
> But the server seems pretty happy anyway:
>
> 17-05-2011 13:42:40 org.apache.solr.update.DirectUpdateHandler2 commit
> INFO: start
> commit(optimize=false,waitFlush=true,waitSearcher=true,expungeDeletes=false)
> 17-05-2011 13:42:41 org.apache.solr.core.SolrDeletionPolicy onCommit
> INFO: SolrDeletionPolicy.onCommit: commits:num=2
>
> commit{dir=/Users/dennis/solr/solr/data/index,segFN=segments_28,version=1303911462910,generation=80,filenames=[_26.frq,
> _2c.nrm, _26.fnm, _2c.fdx, _2c.prx, _2b.fnm, _2c.fdt, _2d.tis, _2e.frq,
> _2e.prx, _2b.frq, _2b_1.del, _2a.tii, _2c.fnm, _2e.nrm, _2b.prx, _2a.tis,
> _2a.nrm, _2a.fdx, _2c.tis, _2e.tii, _2c.frq, _2e.fdx, _2e.fdt, _2a.fdt,
> _2b.tis, _2a.prx, _2a.frq, _2c.tii, _2d.prx, _2d.fnm, _2b.tii, _2e.tis,
> _26.prx, _2b.nrm, _2d.frq, _2b.fdt, _26.fdx, _26.fdt, _2d.fdx, _2a_1.del,
> segments_28, _2b.fdx, _2d.fdt, _26.nrm, _26.tii, _26_2.del, _2d.tii, _2d.nrm,
> _26.tis, _2e.fnm, _2a.fnm]
>
> commit{dir=/Users/dennis/solr/solr/data/index,segFN=segments_29,version=1303911462925,generation=81,filenames=[_2k.fnm,
> _2j.nrm, _2k.nrm, _2j_1.del, _2j.tis, _2k.tii, _2j.fdx, _2j.fdt, _2k.fdx,
> _2k.prx, _2j.prx, _2j.tii, _2j.fnm, _2k.fdt, segments_29, _2k.tis, _2k.frq,
> _2j.frq]
> 17-05-2011 13:42:41 org.apache.solr.core.SolrDeletionPolicy updateCommits
> INFO: newest commit = 1303911462925
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher <init>
> INFO: Opening Searcher@74a32a82 main
> 17-05-2011 13:42:41 org.apache.solr.update.DirectUpdateHandler2 commit
> INFO: end_commit_flush
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming Searcher@74a32a82 main from Searcher@4171e599 main
>
> fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming result for Searcher@74a32a82 main
>
> fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming Searcher@74a32a82 main from Searcher@4171e599 main
>
> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming result for Searcher@74a32a82 main
>
> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming Searcher@74a32a82 main from Searcher@4171e599 main
>
> queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming result for Searcher@74a32a82 main
>
> queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming Searcher@74a32a82 main from Searcher@4171e599 main
>
> documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher warm
> INFO: autowarming result for Searcher@74a32a82 main
>
> documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.core.QuerySenderListener newSearcher
> INFO: QuerySenderListener sending requests to Searcher@74a32a82 main
> 17-05-2011 13:42:41 org.apache.solr.core.QuerySenderListener newSearcher
> INFO: QuerySenderListener done.
> 17-05-2011 13:42:41 org.apache.solr.core.SolrCore registerSearcher
> INFO: [] Registered new searcher Searcher@74a32a82 main
> 17-05-2011 13:42:41 org.apache.solr.search.SolrIndexSearcher close
> INFO: Closing Searcher@4171e599 main
>
> fieldValueCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>
> filterCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>
> queryResultCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
>
> documentCache{lookups=0,hits=0,hitratio=0.00,inserts=0,evictions=0,size=0,warmupTime=0,cumulative_lookups=0,cumulative_hits=0,cumulative_hitratio=0.00,cumulative_inserts=0,cumulative_evictions=0}
> 17-05-2011 13:42:41 org.apache.solr.update.processor.LogUpdateProcessor finish
> INFO: {commit=} 0 1027
> 17-05-2011 13:42:41 org.apache.solr.core.SolrCore execute
> INFO: [] webapp=/solr path=/update
> params={waitSearcher=true&commit=true&waitFlush=true&wt=xml&version=2.2}
> status=0 QTime=1027
> ---------------------------------------
>
> The client and server is running on same machine, so I cannot believe it's
> network issue. The solr server runs in a tomcat 6 container. The solrj is a
> junit test in eclipse.
> Both client and server is version 3.1.0, but it also happens with client
> 1.4.1
>
> I do not see that there is any "long" wait, so wonder what this can be? It
> doesnt happen every time but most.
>
> cheers,
> :-Dennis
>
