Mailing-List: contact solr-user-help@lucene.apache.org; run by ezmlm
Precedence: bulk
Reply-To: solr-user@lucene.apache.org
MIME-Version: 1.0
In-Reply-To: <MWHPR02MB2366ADD9114A1686C49715C4F0210@MWHPR02MB2366.namprd02.prod.outlook.com>
References: <MWHPR02MB2366FD5CAA69038ECADD9C7FF02E0@MWHPR02MB2366.namprd02.prod.outlook.com>
 <CAEFAe-ECzoCeqe+7qez=jNLSFs9H=aaoudvzY64Np9EmFau8kQ@mail.gmail.com> <MWHPR02MB2366ADD9114A1686C49715C4F0210@MWHPR02MB2366.namprd02.prod.outlook.com>
From: Alexandre Rafalovitch <arafalov@gmail.com>
Date: Thu, 9 Mar 2017 10:24:28 -0500
Message-ID: <CAEFAe-H+GiOjjM7E_AJ9bd23pf-x=3eTPYF97dp68YPGZd9LgQ@mail.gmail.com>
Subject: Re: DIH Full Index Issue
To: solr-user <solr-user@lucene.apache.org>
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: quoted-printable
archived-at: Thu, 09 Mar 2017 15:25:15 -0000

I am not super familiar with what happens with DIH in the SolrCloud
and I was talking about HTTP access.log (which admittedly needs custom
configuration). However, I do see this in the logs:

2017-03-09 13:40:00.356 INFO  (qtp2080166188-41928) [c:collectionXXX
s:shard1 r:core_node1 x:collectionXXX_shard1_replica2]
o.a.s.c.S.Request [collectionXXX_shard1_replica2]  webapp=3D/solr
path=3D/dataimport
params=3D{optimize=3Dtrue&commit=3Dtrue&clean=3Dtrue&command=3Dfull-import}
status=3D0 QTime=3D3
....
2017-03-09 13:40:26.115 INFO  (qtp2080166188-39334) [c:collectionXXX
s:shard1 r:core_node1 x:collectionXXX_shard1_replica2]
o.a.s.u.p.LogUpdateProcessorFactory [collectionXXX_shard1_replica2]
webapp=3D/solr path=3D/update
params=3D{update.distrib=3DTOLEADER&distrib.from=3Dhttp://XXX.XXX.XXX.189:8=
080/solr/collectionXXX_shard1_replica1/&wt=3Djavabin&version=3D2}{}
0 0
....
2017-03-09 13:40:26.131 INFO  (qtp2080166188-34463) [c:collectionXXX
s:shard1 r:core_node1 x:collectionXXX_shard1_replica2]
o.a.s.u.DirectUpdateHandler2 start
commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue,expungeDel=
etes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse}

It seems like there is a DIH start at 13:40:00, but then at 13:40:26
there is an update hit to another shard which propogates to this one
and causes the commit making DIH changes at that point visible.
Interestingly, there seem to be an error in that distributed update as
I see "missing required field: adtype", which may mean the actual
incoming records from other shards did not get into the index.

So, to me, my theory stands so far and I would look for something
sending - invalid - documents to shard1_replica1 at the same time as
you are running DIH on shard1_replica2.

Regards,
  Alex.
----
http://www.solr-start.com/ - Resources for Solr users, new and experienced


On 9 March 2017 at 10:13, AJ Lemke <aj.lemke@securitylabs.com> wrote:
> Thanks for the tip Alex.
>
> I forgot to mention that we are using Solr in cloud mode.
>
> I have checked the logs and I am seeing the following lines (this is an a=
bridged snippet):
>
> 2017-03-09 13:40:00.356 INFO  (qtp2080166188-41928) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.h.d.DataImporter L=
oading DIH Configuration: data-config.xml
> 2017-03-09 13:40:00.356 INFO  (qtp2080166188-41928) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.h.d.DataImporter D=
ata Configuration loaded successfully
> 2017-03-09 13:40:00.356 INFO  (Thread-17768) [c:collectionXXX s:shard1 r:=
core_node1 x:collectionXXX_shard1_replica2] o.a.s.h.d.DataImporter Starting=
 Full Import
> 2017-03-09 13:40:00.356 INFO  (qtp2080166188-41928) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.c.S.Request [colle=
ctionXXX_shard1_replica2]  webapp=3D/solr path=3D/dataimport params=3D{opti=
mize=3Dtrue&commit=3Dtrue&clean=3Dtrue&command=3Dfull-import} status=3D0 QT=
ime=3D3
> 2017-03-09 13:40:00.450 INFO  (Thread-17768) [c:collectionXXX s:shard1 r:=
core_node1 x:collectionXXX_shard1_replica2] o.a.s.s.SolrIndexSearcher Openi=
ng [Searcher@7c2e9318[collectionXXX_shard1_replica2] realtime]
> 2017-03-09 13:40:00.560 INFO  (Thread-17768) [c:collectionXXX s:shard1 r:=
core_node1 x:collectionXXX_shard1_replica2] o.a.s.h.d.JdbcDataSource Creati=
ng a connection for entity item with URL: jdbc:sqlserver://sqlX:XXX;databas=
eName=3DXXXXXX;responseBuffering=3Dadaptive;
> 2017-03-09 13:40:00.576 INFO  (Thread-17768) [c:collectionXXX s:shard1 r:=
core_node1 x:collectionXXX_shard1_replica2] o.a.s.h.d.JdbcDataSource Time t=
aken for getConnection(): 13
> 2017-03-09 13:40:26.115 INFO  (qtp2080166188-39334) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.u.p.LogUpdateProce=
ssorFactory [collectionXXX_shard1_replica2]  webapp=3D/solr path=3D/update =
params=3D{update.distrib=3DTOLEADER&distrib.from=3Dhttp://XXX.XXX.XXX.189:8=
080/solr/collectionXXX_shard1_replica1/&wt=3Djavabin&version=3D2}{} 0 0
> 2017-03-09 13:40:26.115 ERROR (qtp2080166188-39334) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.h.RequestHandlerBa=
se org.apache.solr.common.SolrException: [doc=3D11326865] missing required =
field: adtype
> 2017-03-09 13:40:26.131 INFO  (qtp2080166188-34463) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.u.DirectUpdateHand=
ler2 start commit{,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher=3Dtrue=
,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse}
> 2017-03-09 13:40:26.131 INFO  (qtp2080166188-34463) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.u.SolrIndexWriter =
Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@61db76=
c2
> 2017-03-09 13:40:28.350 INFO  (qtp2080166188-34463) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.s.SolrIndexSearche=
r Opening [Searcher@a4ed679[collectionXXX_shard1_replica2] main]
> 2017-03-09 13:40:28.350 INFO  (searcherExecutor-50-thread-1-processing-n:=
XXX.XXX.XXX.188:8080_solr x:collectionXXX_shard1_replica2 s:shard1 c:collec=
tionXXX r:core_node1) [c:collectionXXX s:shard1 r:core_node1 x:collectionXX=
X_shard1_replica2] o.a.s.c.QuerySenderListener QuerySenderListener sending =
requests to Searcher@a4ed679[collectionXXX_shard1_replica2] main{ExitableDi=
rectoryReader(UninvertingDirectoryReader(Uninverting(_oa1(6.3.0):C31847) Un=
inverting(_oa2(6.3.0):C2520)))}
> 2017-03-09 13:40:28.350 INFO  (searcherExecutor-50-thread-1-processing-n:=
XXX.XXX.XXX.188:8080_solr x:collectionXXX_shard1_replica2 s:shard1 c:collec=
tionXXX r:core_node1) [c:collectionXXX s:shard1 r:core_node1 x:collectionXX=
X_shard1_replica2] o.a.s.c.QuerySenderListener QuerySenderListener done.
> 2017-03-09 13:40:28.350 INFO  (searcherExecutor-50-thread-1-processing-n:=
XXX.XXX.XXX.188:8080_solr x:collectionXXX_shard1_replica2 s:shard1 c:collec=
tionXXX r:core_node1) [c:collectionXXX s:shard1 r:core_node1 x:collectionXX=
X_shard1_replica2] o.a.s.c.SolrCore [collectionXXX_shard1_replica2] Registe=
red new searcher Searcher@a4ed679[collectionXXX_shard1_replica2] main{Exita=
bleDirectoryReader(UninvertingDirectoryReader(Uninverting(_oa1(6.3.0):C3184=
7) Uninverting(_oa2(6.3.0):C2520)))}
> 2017-03-09 13:40:28.365 INFO  (qtp2080166188-34463) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.u.DirectUpdateHand=
ler2 end_commit_flush
> 2017-03-09 13:40:28.444 INFO  (qtp2080166188-34463) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.u.p.LogUpdateProce=
ssorFactory [collectionXXX_shard1_replica2]  webapp=3D/solr path=3D/update =
params=3D{update.distrib=3DFROMLEADER&waitSearcher=3Dtrue&openSearcher=3Dtr=
ue&commit=3Dtrue&softCommit=3Dfalse&distrib.from=3Dhttp://XXX.XXX.XXX.189:8=
080/solr/collectionXXX_shard1_replica1/&commit_end_point=3Dtrue&wt=3Djavabi=
n&version=3D2&expungeDeletes=3Dfalse}{commit=3D} 0 2309
> 2017-03-09 13:40:56.459 INFO  (qtp2080166188-40636) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.u.p.LogUpdateProce=
ssorFactory [collectionXXX_shard1_replica2]  webapp=3D/solr path=3D/update/=
json params=3D{commit=3Dtrue&wt=3Djson}{} 0 0
> 2017-03-09 13:40:56.459 ERROR (qtp2080166188-40636) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.h.RequestHandlerBa=
se org.apache.solr.common.SolrException: [doc=3D553094612] missing required=
 field: adtype
> 2017-03-09 13:41:00.053 INFO  (qtp2080166188-41928) [c:collectionXXX s:sh=
ard1 r:core_node1 x:collectionXXX_shard1_replica2] o.a.s.c.S.Request [colle=
ctionXXX_shard1_replica2]  webapp=3D/solr path=3D/schema params=3D{wt=3Djso=
n} status=3D0 QTime=3D0
>
>
>
> AJ
>
> -----Original Message-----
> From: Alexandre Rafalovitch [mailto:arafalov@gmail.com]
> Sent: Wednesday, March 8, 2017 9:33 AM
> To: solr-user <solr-user@lucene.apache.org>
> Subject: Re: DIH Full Index Issue
>
> Are you perhaps indexing at the same time from the source other than DIH?=
 Because the commit is global and all the changes from all the sources will=
 become visible.
>
> Check the access logs perhaps to see the requests to /update handler or s=
imilar.
>
> Regards,
>    Alex.
>
>
> ----
> http://www.solr-start.com/ - Resources for Solr users, new and experience=
d
>
>
> On 8 March 2017 at 09:27, AJ Lemke <aj.lemke@securitylabs.com> wrote:
>> Good Morning List!
>>
>> I have an issue where my DIH full index is committed after a minute of i=
ndexing.
>> My counts will fall from around 400K to 85K until the import is finished=
, usually about four (4) minutes later.
>>
>> This is problematic for us as there are 315K missing items in our search=
es.
>>
>> Versioning Info:
>> solr-spec - 6.3.0
>> solr-impl - 6.3.0 a66a44513ee8191e25b477372094bfa846450316 - shalin -
>> 2016-11-02 19:52:42 lucene-spec - 6.3.0 lucene-impl - 6.3.0
>> a66a44513ee8191e25b477372094bfa846450316 - shalin - 2016-11-02
>> 19:47:11
>>
>> solrconfig.xml snippet
>> <!-- The default high-performance update handler --> <updateHandler
>> class=3D"solr.DirectUpdateHandler2">
>>     <updateLog>
>>         <str name=3D"dir">${solr.ulog.dir:}</str>
>>     </updateLog>
>>     <autoCommit>
>>         <maxTime>-1</maxTime>
>>         <openSearcher>false</openSearcher>
>>     </autoCommit>
>>     <autoSoftCommit>
>>         <maxTime>-1</maxTime>
>>     </autoSoftCommit>
>> </updateHandler>
>>
>>
>> Any insights would be greatly appreciated.
>> Let me know if more information is required.
>>
>> AJ