You are viewing a plain text version of this content. The canonical link for it is here.
Posted to solr-user@lucene.apache.org by Eric Wilson <wi...@gmail.com> on 2012/06/22 17:46:54 UTC
Solr DataImport failing silently, intermitantly
One of our Solr indexes is failing to import successfully on occasion,
without any useful errors being reported.
This is a small index (about 15k documents) in Solr 1.4, deployed in Tomcat
7. It is updated every six minutes using the DataImportHandler. These jobs
are managed by JobScheduler.
Lately it has been failing several times a day. It will perform the "clean"
successfully, not show any errors in the logs, and fail to import any (or
most) of the data. Sometimes when this happens that index ends up with zero
documents, other times there are a handful of documents.
Here is an example of the log output of the case where it fails. This log
output is produced by Java Service Wrapper, which we use to maintain our
production Tomcat instances.
INFO | jvm 1 | 2012/06/21 17:33:28 | INFO: [] webapp=/subscription
path=/dataimport params={optimize=true&clean=true&command=full-import}
status=0 QTime=22
INFO | jvm 1 | 2012/06/21 17:33:28 | Jun 21, 2012 5:33:28 PM
org.apache.solr.core.SolrCore execute
INFO | jvm 1 | 2012/06/21 17:33:28 | INFO: [] webapp=/subscription
path=/dataimport params={} status=0 QTime=0
INFO | jvm 1 | 2012/06/21 17:33:28 | Jun 21, 2012 5:33:28 PM
org.apache.solr.handler.dataimport.DataImporter doFullImport
INFO | jvm 1 | 2012/06/21 17:33:28 | INFO: Starting Full Import
INFO | jvm 1 | 2012/06/21 17:33:28 | Jun 21, 2012 5:33:28 PM
org.apache.solr.handler.dataimport.SolrWriter readIndexerProperties
INFO | jvm 1 | 2012/06/21 17:33:28 | INFO: Read dataimport.properties
INFO | jvm 1 | 2012/06/21 17:33:28 | Jun 21, 2012 5:33:28 PM
org.apache.solr.update.DirectUpdateHandler2 deleteAll
INFO | jvm 1 | 2012/06/21 17:33:28 | INFO: [] REMOVING ALL DOCUMENTS
FROM INDEX
INFO | jvm 1 | 2012/06/21 17:33:28 | Jun 21, 2012 5:33:28 PM
org.apache.solr.core.SolrDeletionPolicy onInit
INFO | jvm 1 | 2012/06/21 17:33:28 | INFO: SolrDeletionPolicy.onInit:
commits:num=1
INFO | jvm 1 | 2012/06/21 17:33:28 |
commit{dir=/rpt/src/solr-home/mst/pbl/solr/data/index,segFN=segments_7j,version=1340212196528,generation=271,filenames=[_cj.fdt,
_cj.tii, _cj.fnm, _cj.frq, segments_7j, _cj.nrm, _cj.tis, _cj.prx, _cj.fdx]
INFO | jvm 1 | 2012/06/21 17:33:28 | Jun 21, 2012 5:33:28 PM
org.apache.solr.core.SolrDeletionPolicy updateCommits
INFO | jvm 1 | 2012/06/21 17:33:28 | INFO: newest commit =
1340212196528
INFO | jvm 1 | 2012/06/21 17:33:28 | Jun 21, 2012 5:33:28 PM
org.apache.solr.handler.dataimport.JdbcDataSource$1 call
INFO | jvm 1 | 2012/06/21 17:33:28 | INFO: Creating a connection for
entity PBL with URL: jdbc:oracle:thin:@ecnext-ecn01:1545:ecn01
STATUS | wrapper | 2012/06/21 17:33:29 | TERM trapped. Shutting down.
INFO | jvm 1 | 2012/06/21 17:33:29 | Jun 21, 2012 5:33:29 PM
org.apache.solr.handler.dataimport.JdbcDataSource$1 call
INFO | jvm 1 | 2012/06/21 17:33:29 | INFO: Time taken for
getConnection(): 1187
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.core.SolrCore close
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO: [] CLOSING SolrCore
org.apache.solr.core.SolrCore@57044c5
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.core.SolrCore closeSearcher
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO: [] Closing main searcher on
request.
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.search.SolrIndexSearcher close
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO: Closing Searcher@192425amain
INFO | jvm 1 | 2012/06/21 17:33:31 |
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}
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.update.DirectUpdateHandler2 close
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO: closing
DirectUpdateHandler2{commits=0,autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=41,adds=42,deletesById=0,deletesByQuery=1,errors=0,cumulative_adds=42,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.core.SolrDeletionPolicy onCommit
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO:
SolrDeletionPolicy.onCommit: commits:num=2
INFO | jvm 1 | 2012/06/21 17:33:31 |
commit{dir=/rpt/src/solr-home/mst/pbl/solr/data/index,segFN=segments_7j,version=1340212196528,generation=271,filenames=[_cj.fdt,
_cj.tii, _cj.fnm, _cj.frq, segments_7j, _cj.nrm, _cj.tis, _cj.prx, _cj.fdx]
INFO | jvm 1 | 2012/06/21 17:33:31 |
commit{dir=/rpt/src/solr-home/mst/pbl/solr/data/index,segFN=segments_7k,version=1340212196529,generation=272,filenames=[_ck.nrm,
_ck.prx, _ck.fdt, _ck.fnm, _ck.tis, _ck.fdx, segments_7k, _ck.tii, _ck.frq]
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.core.SolrDeletionPolicy updateCommits
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO: newest commit =
1340212196529
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.update.DirectUpdateHandler2 close
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO: closed
DirectUpdateHandler2{commits=0,autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=43,deletesById=0,deletesByQuery=1,errors=0,cumulative_adds=43,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.core.SolrDeletionPolicy onInit
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO: SolrDeletionPolicy.onInit:
commits:num=1
INFO | jvm 1 | 2012/06/21 17:33:31 |
commit{dir=/rpt/src/solr-home/mst/pbl/solr/data/index,segFN=segments_7k,version=1340212196529,generation=272,filenames=[_ck.nrm,
_ck.prx, _ck.fdt, _ck.fnm, _ck.tis, _ck.fdx, segments_7k, _ck.tii, _ck.frq]
INFO | jvm 1 | 2012/06/21 17:33:31 | Jun 21, 2012 5:33:31 PM
org.apache.solr.core.SolrDeletionPolicy updateCommits
INFO | jvm 1 | 2012/06/21 17:33:31 | INFO: newest commit =
1340212196529
STATUS | wrapper | 2012/06/21 17:33:32 | <-- Wrapper Stopped
We are confident (due to careful monitoring of the DB) that there has been
no data issue here.
I appreciate any help that anyone can provide in diagnosing this issue.
Thanks,
Eric