You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2018/05/13 14:13:14 UTC
[JENKINS] Lucene-Solr-7.x-Linux (32bit/jdk1.8.0_162) - Build # 1894
- Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/1894/
Java: 32bit/jdk1.8.0_162 -client -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.update.TestHdfsUpdateLog.testFSThreadSafety
Error Message:
Captured an uncaught exception in thread: Thread[id=6028, name=Thread-1475, state=RUNNABLE, group=TGRP-TestHdfsUpdateLog]
Stack Trace:
com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=6028, name=Thread-1475, state=RUNNABLE, group=TGRP-TestHdfsUpdateLog]
at __randomizedtesting.SeedInfo.seed([E7826015A99FB95:F85781FA97335366]:0)
Caused by: org.apache.solr.common.SolrException: Exception writing document id 97 to the index; possible analysis error.
at __randomizedtesting.SeedInfo.seed([E7826015A99FB95]:0)
at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:246)
at org.apache.solr.update.processor.RunUpdateProcessor.processAdd(RunUpdateProcessorFactory.java:67)
at org.apache.solr.update.processor.UpdateRequestProcessor.processAdd(UpdateRequestProcessor.java:55)
at org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalAdd(DistributedUpdateProcessor.java:950)
at org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:1163)
at org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:633)
at org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor.processAdd(LogUpdateProcessorFactory.java:103)
at org.apache.solr.handler.loader.XMLLoader.processUpdate(XMLLoader.java:261)
at org.apache.solr.handler.loader.XMLLoader.load(XMLLoader.java:188)
at org.apache.solr.handler.UpdateRequestHandler$1.load(UpdateRequestHandler.java:97)
at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:68)
at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:199)
at org.apache.solr.core.SolrCore.execute(SolrCore.java:2510)
at org.apache.solr.servlet.DirectSolrConnection.request(DirectSolrConnection.java:125)
at org.apache.solr.util.TestHarness.update(TestHarness.java:284)
at org.apache.solr.util.BaseTestHarness.checkUpdateStatus(BaseTestHarness.java:281)
at org.apache.solr.util.BaseTestHarness.validateUpdate(BaseTestHarness.java:251)
at org.apache.solr.SolrTestCaseJ4.checkUpdateU(SolrTestCaseJ4.java:863)
at org.apache.solr.SolrTestCaseJ4.assertU(SolrTestCaseJ4.java:842)
at org.apache.solr.SolrTestCaseJ4.assertU(SolrTestCaseJ4.java:836)
at org.apache.solr.update.TestHdfsUpdateLog$2.run(TestHdfsUpdateLog.java:122)
Caused by: java.lang.NullPointerException
at org.apache.solr.update.UpdateLog.getCurrentLogSizeFromStream(UpdateLog.java:299)
at org.apache.solr.update.DirectUpdateHandler2.getCurrentTLogSize(DirectUpdateHandler2.java:1007)
at org.apache.solr.update.DirectUpdateHandler2.addDoc0(DirectUpdateHandler2.java:291)
at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandler2.java:234)
... 20 more
Build Log:
[...truncated 12791 lines...]
[junit4] Suite: org.apache.solr.update.TestHdfsUpdateLog
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/init-core-data-001
[junit4] 2> 532212 WARN (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=12 numCloses=12
[junit4] 2> 532212 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true
[junit4] 2> 532214 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 532215 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> 532628 WARN (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.h.u.NativeCodeLoader Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
[junit4] 1> Formatting using clusterid: testClusterID
[junit4] 2> 533382 WARN (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.h.m.i.MetricsConfig Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
[junit4] 2> 533596 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Logging to org.apache.logging.slf4j.Log4jLogger@1e47fa0 via org.mortbay.log.Slf4jLog
[junit4] 2> 533616 WARN (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 533694 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 533745 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Extract jar:file:/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.4-tests.jar!/webapps/hdfs to ./temp/Jetty_localhost_localdomain_43029_hdfs____.9vhkzy/webapp
[junit4] 2> 534612 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost.localdomain:43029
[junit4] 2> 535792 WARN (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 535798 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 535817 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Extract jar:file:/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.4-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_38227_datanode____.6kxeav/webapp
[junit4] 2> 536351 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:38227
[junit4] 2> 536733 WARN (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 536734 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 536752 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Extract jar:file:/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.4-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_43903_datanode____.fg83gc/webapp
[junit4] 2> 537319 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:43903
[junit4] 2> 537356 ERROR (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:41711) [ ] o.a.h.h.s.d.DirectoryScanner dfs.datanode.directoryscan.throttle.limit.ms.per.sec set to value below 1 ms/sec. Assuming default value of 1000
[junit4] 2> 537503 ERROR (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data3/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data4/]] heartbeating to localhost.localdomain/127.0.0.1:41711) [ ] o.a.h.h.s.d.DirectoryScanner dfs.datanode.directoryscan.throttle.limit.ms.per.sec set to value below 1 ms/sec. Assuming default value of 1000
[junit4] 2> 537535 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x5456ea4d43c18: from storage DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966 node DatanodeRegistration(127.0.0.1:38035, datanodeUuid=f5090313-a828-4eec-aa58-2298907a5198, infoPort=39023, infoSecurePort=0, ipcPort=44465, storageInfo=lv=-56;cid=testClusterID;nsid=948681944;c=0), blocks: 0, hasStaleStorage: true, processing time: 2 msecs
[junit4] 2> 537536 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x5456ea4d43c0a: from storage DS-68938c90-9021-438f-ae24-e2f8b554fe28 node DatanodeRegistration(127.0.0.1:39761, datanodeUuid=139e3714-7cc2-4da9-9dc3-f83234131ad0, infoPort=36279, infoSecurePort=0, ipcPort=37665, storageInfo=lv=-56;cid=testClusterID;nsid=948681944;c=0), blocks: 0, hasStaleStorage: true, processing time: 1 msecs
[junit4] 2> 537536 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x5456ea4d43c18: from storage DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0 node DatanodeRegistration(127.0.0.1:38035, datanodeUuid=f5090313-a828-4eec-aa58-2298907a5198, infoPort=39023, infoSecurePort=0, ipcPort=44465, storageInfo=lv=-56;cid=testClusterID;nsid=948681944;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 537536 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x5456ea4d43c0a: from storage DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd node DatanodeRegistration(127.0.0.1:39761, datanodeUuid=139e3714-7cc2-4da9-9dc3-f83234131ad0, infoPort=36279, infoSecurePort=0, ipcPort=37665, storageInfo=lv=-56;cid=testClusterID;nsid=948681944;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 538149 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore
[junit4] 2> 538150 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/lib, /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 538242 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.4.0
[junit4] 2> 538288 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.s.IndexSchema [null] Schema name=test
[junit4] 2> 538518 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 538621 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@7022cd
[junit4] 2> 538645 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@7022cd
[junit4] 2> 538645 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@7022cd
[junit4] 2> 538649 INFO (coreLoadExecutor-1646-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 538649 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/lib, /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 538689 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.4.0
[junit4] 2> 538720 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 538868 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 538882 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1, trusted=true
[junit4] 2> 538883 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@7022cd
[junit4] 2> 538889 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost.localdomain:41711/solr_hdfs_home
[junit4] 2> 538889 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 538889 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 538889 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1], dataDir=[hdfs://localhost.localdomain:41711/solr_hdfs_home/collection1//home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/init-core-data-001/]
[junit4] 2> 538893 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:41711/solr_hdfs_home/collection1//home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/init-core-data-001/snapshot_metadata
[junit4] 2> 538909 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 538909 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [8388608] will allocate [1] slabs and use ~[8388608] bytes
[junit4] 2> 538909 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory Creating new global HDFS BlockCache
[junit4] 2> 539393 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 539398 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:41711/solr_hdfs_home/collection1//home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/init-core-data-001
[junit4] 2> 539426 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:41711/solr_hdfs_home/collection1//home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/init-core-data-001/index
[junit4] 2> 539435 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 539435 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [8388608] will allocate [1] slabs and use ~[8388608] bytes
[junit4] 2> 539440 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 539441 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=42, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 539636 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741825_1001{UCState=COMMITTED, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 69
[junit4] 2> 539636 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741825_1001 size 69
[junit4] 2> 540051 WARN (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 540122 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 540123 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=hdfs://localhost.localdomain:41711/solr/shard1 defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 540123 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=2
[junit4] 2> 540140 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 540140 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 540148 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=25, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 540242 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@159f10d[collection1] main]
[junit4] 2> 540242 WARN (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage Cannot write to config directory /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/conf; switching to use InMemory storage instead.
[junit4] 2> 540246 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 540247 INFO (searcherExecutor-1647-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@159f10d[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 540248 INFO (coreLoadExecutor-1646-thread-1) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1600355278452162560
[junit4] 2> 540251 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore end
[junit4] 2> 540277 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testFSThreadSafety
[junit4] 2> 540278 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.u.DirectUpdateHandler2 [collection1] REMOVING ALL DOCUMENTS FROM INDEX
[junit4] 2> 540281 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@9fb0ea[collection1] realtime]
[junit4] 2> 540282 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={_version_=-9223372036854775807&update.distrib=FROMLEADER&versions=true&wt=json&indent=true}{deleteByQuery=*:* (-9223372036854775807)} 0 4
[junit4] 2> 540282 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1600355278487814144,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 540282 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:1600355278487814144
[junit4] 2> 540331 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741826_1002{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540332 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741826_1002 size 135
[junit4] 2> 540336 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@6e2c64[collection1] main]
[junit4] 2> 540337 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 540339 INFO (searcherExecutor-1647-thread-1) [ ] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@6e2c64[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 540340 INFO (TEST-TestHdfsUpdateLog.testFSThreadSafety-seed#[E7826015A99FB95]) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{commit=} 0 57
[junit4] 2> 540374 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[0 (1600355278552825856)]} 0 30
[junit4] 2> 540391 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[1 (1600355278600011776)]} 0 1
[junit4] 2> 540403 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[2 (1600355278613643264)]} 0 1
[junit4] 2> 540415 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[3 (1600355278626226176)]} 0 1
[junit4] 2> 540428 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[4 (1600355278638809088)]} 0 1
[junit4] 2> 540440 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[5 (1600355278652440576)]} 0 1
[junit4] 2> 540453 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[6 (1600355278665023488)]} 0 1
[junit4] 2> 540463 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 540463 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 540483 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[7 (1600355278678654976)]} 0 19
[junit4] 2> 540484 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741828_1004{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 540484 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741828_1004 size 201
[junit4] 2> 540495 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[8 (1600355278710112256)]} 0 1
[junit4] 2> 540497 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741830_1006{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540498 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741830_1006{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540510 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[9 (1600355278724792320)]} 0 2
[junit4] 2> 540511 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741831_1007{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540512 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741831_1007 size 340
[junit4] 2> 540523 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[10 (1600355278738423808)]} 0 1
[junit4] 2> 540531 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741832_1008{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540532 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741832_1008{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540536 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[11 (1600355278752055296)]} 0 2
[junit4] 2> 540547 INFO (IPC Server handler 3 on 41711) [ ] BlockStateChange BLOCK* addToInvalidates: blk_1073741825_1001 127.0.0.1:39761 127.0.0.1:38035
[junit4] 2> 540550 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[12 (1600355278767783936)]} 0 1
[junit4] 2> 540563 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1affc7e[collection1] realtime]
[junit4] 2> 540563 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[13 (1600355278780366848)]} 0 1
[junit4] 2> 540568 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741827_1003{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 75
[junit4] 2> 540569 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741827_1003{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 75
[junit4] 2> 540570 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 540570 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 540570 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 540597 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741833_1009{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540598 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741833_1009{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540603 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[14 (1600355278795046912)]} 0 27
[junit4] 2> 540612 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741835_1011{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540612 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741835_1011{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540615 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[15 (1600355278835941376)]} 0 1
[junit4] 2> 540623 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741836_1012{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540624 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741836_1012{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540627 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[16 (1600355278848524288)]} 0 1
[junit4] 2> 540635 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741837_1013{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540636 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741837_1013{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540639 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[17 (1600355278861107200)]} 0 1
[junit4] 2> 540648 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741838_1014{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540649 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741838_1014 size 340
[junit4] 2> 540651 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[18 (1600355278873690112)]} 0 0
[junit4] 2> 540662 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741839_1015{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540662 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741839_1015{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540663 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[19 (1600355278886273024)]} 0 0
[junit4] 2> 540674 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741840_1016{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540674 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741840_1016{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540675 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[20 (1600355278898855936)]} 0 0
[junit4] 2> 540684 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1deeaba[collection1] realtime]
[junit4] 2> 540687 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741829_1005{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 75
[junit4] 2> 540688 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741829_1005{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 75
[junit4] 2> 540689 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 540689 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 540689 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 540710 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741841_1017{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540711 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[21 (1600355278911438848)]} 0 25
[junit4] 2> 540711 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741841_1017 size 525
[junit4] 2> 540721 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741843_1019{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 540721 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741843_1019{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 540723 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[22 (1600355278949187584)]} 0 1
[junit4] 2> 540737 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[23 (1600355278961770496)]} 0 2
[junit4] 2> 540738 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741844_1020{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540738 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741844_1020{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540749 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[24 (1600355278976450560)]} 0 1
[junit4] 2> 540752 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741845_1021{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540755 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741845_1021 size 289
[junit4] 2> 540763 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[25 (1600355278991130624)]} 0 1
[junit4] 2> 540763 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741846_1022{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540764 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741846_1022 size 1229
[junit4] 2> 540772 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741847_1023{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540773 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741847_1023{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540775 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[26 (1600355279003713536)]} 0 1
[junit4] 2> 540782 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741848_1024{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540783 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741848_1024 size 340
[junit4] 2> 540785 INFO (IPC Server handler 1 on 41711) [ ] BlockStateChange BLOCK* addToInvalidates: blk_1073741828_1004 127.0.0.1:39761 127.0.0.1:38035
[junit4] 2> 540788 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[27 (1600355279016296448)]} 0 1
[junit4] 2> 540798 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1d21bad[collection1] realtime]
[junit4] 2> 540801 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741834_1010{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 76
[junit4] 2> 540802 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741834_1010{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 76
[junit4] 2> 540803 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 540803 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 540803 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 540803 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[28 (1600355279029927936)]} 0 4
[junit4] 2> 540813 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741849_1025{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540814 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741849_1025{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540823 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[29 (1600355279045656576)]} 0 9
[junit4] 2> 540824 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741850_1026{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 540824 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741850_1026 size 289
[junit4] 2> 540833 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741852_1028{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540834 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741852_1028{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540835 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[30 (1600355279066628096)]} 0 0
[junit4] 2> 540845 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741853_1029{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540846 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741853_1029{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540850 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[31 (1600355279082356736)]} 0 1
[junit4] 2> 540855 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741854_1030{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 540855 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741854_1030{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540861 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[32 (1600355279094939648)]} 0 0
[junit4] 2> 540865 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741855_1031{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540866 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741855_1031 size 340
[junit4] 2> 540873 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[33 (1600355279106473984)]} 0 0
[junit4] 2> 540874 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741856_1032{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 540875 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741856_1032 size 340
[junit4] 2> 540877 INFO (IPC Server handler 9 on 41711) [ ] BlockStateChange BLOCK* addToInvalidates: blk_1073741833_1009 127.0.0.1:39761 127.0.0.1:38035
[junit4] 2> 540885 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[34 (1600355279119056896)]} 0 1
[junit4] 2> 540890 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@c16464[collection1] realtime]
[junit4] 2> 540894 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741842_1018{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW]]} size 76
[junit4] 2> 540895 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741842_1018{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW]]} size 76
[junit4] 2> 540895 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 540897 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[35 (1600355279131639808)]} 0 0
[junit4] 2> 540903 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 540903 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 540913 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741857_1033{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540914 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741857_1033{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540916 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[36 (1600355279144222720)]} 0 8
[junit4] 2> 540929 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741859_1035{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540929 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741859_1035{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540929 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[37 (1600355279165194240)]} 0 1
[junit4] 2> 540940 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741860_1036{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540941 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741860_1036{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540941 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[38 (1600355279177777152)]} 0 1
[junit4] 2> 540951 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741861_1037{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540952 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741861_1037 size 340
[junit4] 2> 540953 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[39 (1600355279190360064)]} 0 0
[junit4] 2> 540960 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741862_1038{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540960 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741862_1038{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540965 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[40 (1600355279202942976)]} 0 1
[junit4] 2> 540973 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741863_1039{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 540974 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741863_1039 size 1100
[junit4] 2> 540978 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[41 (1600355279217623040)]} 0 0
[junit4] 2> 540984 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741864_1040{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 540984 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741864_1040{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 540987 INFO (IPC Server handler 9 on 41711) [ ] BlockStateChange BLOCK* addToInvalidates: blk_1073741841_1017 127.0.0.1:38035 127.0.0.1:39761
[junit4] 2> 540990 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[42 (1600355279229157376)]} 0 1
[junit4] 2> 540997 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1d3e05f[collection1] realtime]
[junit4] 2> 541000 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741851_1027{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 76
[junit4] 2> 541001 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741851_1027{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 76
[junit4] 2> 541001 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 541002 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[43 (1600355279241740288)]} 0 0
[junit4] 2> 541011 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 541011 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 541023 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741865_1041{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541024 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741865_1041{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541027 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[44 (1600355279254323200)]} 0 14
[junit4] 2> 541036 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741867_1043{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541036 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741867_1043 size 340
[junit4] 2> 541039 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[45 (1600355279281586176)]} 0 0
[junit4] 2> 541046 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741868_1044{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 541047 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741868_1044 size 340
[junit4] 2> 541051 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[46 (1600355279293120512)]} 0 0
[junit4] 2> 541053 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741869_1045{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 541054 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741869_1045{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541060 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741870_1046{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541060 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741870_1046{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541065 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[47 (1600355279308849152)]} 0 0
[junit4] 2> 541073 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741871_1047{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541074 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741871_1047{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541077 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[48 (1600355279321432064)]} 0 0
[junit4] 2> 541081 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741872_1048{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541082 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741872_1048 size 289
[junit4] 2> 541084 INFO (IPC Server handler 8 on 41711) [ ] BlockStateChange BLOCK* addToInvalidates: blk_1073741849_1025 127.0.0.1:39761 127.0.0.1:38035
[junit4] 2> 541089 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[49 (1600355279332966400)]} 0 0
[junit4] 2> 541093 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@17b6557[collection1] realtime]
[junit4] 2> 541096 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741858_1034{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW]]} size 76
[junit4] 2> 541097 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741858_1034 size 349
[junit4] 2> 541097 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 541101 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[50 (1600355279345549312)]} 0 0
[junit4] 2> 541116 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 541116 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 541124 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[51 (1600355279362326528)]} 0 8
[junit4] 2> 541125 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741874_1050{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541125 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741874_1050{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541132 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741875_1051{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541132 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741875_1051{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541135 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[52 (1600355279382249472)]} 0 1
[junit4] 2> 541139 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741876_1052{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541139 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741876_1052{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541152 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[53 (1600355279393783808)]} 0 5
[junit4] 2> 541152 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741877_1053{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541153 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741877_1053{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541160 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741878_1054{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW]]} size 0
[junit4] 2> 541160 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741878_1054{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541164 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[54 (1600355279411609600)]} 0 0
[junit4] 2> 541170 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741879_1055{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541171 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741879_1055 size 1184
[junit4] 2> 541175 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[55 (1600355279424192512)]} 0 0
[junit4] 2> 541180 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741880_1056{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541181 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741880_1056 size 289
[junit4] 2> 541183 INFO (IPC Server handler 5 on 41711) [ ] BlockStateChange BLOCK* addToInvalidates: blk_1073741857_1033 127.0.0.1:39761 127.0.0.1:38035
[junit4] 2> 541187 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[56 (1600355279435726848)]} 0 1
[junit4] 2> 541197 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@10e0db3[collection1] realtime]
[junit4] 2> 541200 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741866_1042{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW]]} size 76
[junit4] 2> 541201 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741866_1042 size 313
[junit4] 2> 541201 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 541202 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[57 (1600355279448309760)]} 0 3
[junit4] 2> 541213 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[58 (1600355279464038400)]} 0 1
[junit4] 2> 541219 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 541219 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 541232 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741881_1057{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541232 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741881_1057{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541237 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[59 (1600355279475572736)]} 0 13
[junit4] 2> 541243 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741883_1059{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541243 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741883_1059{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 0
[junit4] 2> 541249 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[60 (1600355279500738560)]} 0 0
[junit4] 2> 541251 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741884_1060{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541251 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741884_1060{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541258 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741885_1061{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541259 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741885_1061{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541261 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[61 (1600355279513321472)]} 0 0
[junit4] 2> 541265 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741886_1062{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541266 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741886_1062 size 289
[junit4] 2> 541272 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741887_1063{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541272 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[62 (1600355279525904384)]} 0 0
[junit4] 2> 541273 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741887_1063 size 1138
[junit4] 2> 541281 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741888_1064{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541282 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741888_1064{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-056b7fd1-6d77-4ea7-aded-cda9d6199be0:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541284 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[63 (1600355279537438720)]} 0 0
[junit4] 2> 541284 INFO (IPC Server handler 7 on 41711) [ ] BlockStateChange BLOCK* addToInvalidates: blk_1073741865_1041 127.0.0.1:39761 127.0.0.1:38035
[junit4] 2> 541293 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@6ee24f[collection1] realtime]
[junit4] 2> 541296 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741873_1049{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW]]} size 76
[junit4] 2> 541297 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741873_1049 size 349
[junit4] 2> 541297 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 541298 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[64 (1600355279550021632)]} 0 3
[junit4] 2> 541310 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[65 (1600355279564701696)]} 0 1
[junit4] 2> 541322 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[66 (1600355279577284608)]} 0 1
[junit4] 2> 541330 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 541330 INFO (commitScheduler-1650-thread-1) [ ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1a821c2 commitCommandVersion:0
[junit4] 2> 541343 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741889_1065{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541343 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741889_1065{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|RBW], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541348 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[67 (1600355279588818944)]} 0 15
[junit4] 2> 541353 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:38035 is added to blk_1073741891_1067{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-68938c90-9021-438f-ae24-e2f8b554fe28:NORMAL:127.0.0.1:39761|RBW], ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED]]} size 0
[junit4] 2> 541353 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39761 is added to blk_1073741891_1067{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-6061b5e0-f4b1-4c1e-b9aa-438f8f4e6966:NORMAL:127.0.0.1:38035|FINALIZED], ReplicaUC[[DISK]DS-eb62c791-cd5c-42f7-81ab-ef4e2bf7f9dd:NORMAL:127.0.0.1:39761|FINALIZED]]} size 0
[junit4] 2> 541359 INFO (Thread-1475) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] w
[...truncated too long message...]
BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:45069 is added to blk_1073741993_1169 size 1106
[junit4] 2> 22418 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:45069 is added to blk_1073741994_1170{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-422a5ca2-270f-4ef4-8d3c-633a6b50fe2a:NORMAL:127.0.0.1:33615|RBW], ReplicaUC[[DISK]DS-bf6040c7-9598-4263-93cf-468ddf6cad68:NORMAL:127.0.0.1:45069|FINALIZED]]} size 0
[junit4] 2> 22419 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:33615 is added to blk_1073741994_1170 size 343
[junit4] 2> 22421 INFO (IPC Server handler 0 on 36861) [ ] BlockStateChange BLOCK* addToInvalidates: blk_1073741972_1148 127.0.0.1:33615 127.0.0.1:45069
[junit4] 2> 22422 ERROR (commitScheduler-10-thread-1) [ ] o.a.s.u.CommitTracker auto commit error...:org.apache.solr.common.SolrException: openNewSearcher called on closed core
[junit4] 2> at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1976)
[junit4] 2> at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:735)
[junit4] 2> at org.apache.solr.update.CommitTracker.run(CommitTracker.java:269)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
[junit4] 2> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2>
[junit4] 2> 22423 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:33615 is added to blk_1073741980_1156{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-bf6040c7-9598-4263-93cf-468ddf6cad68:NORMAL:127.0.0.1:45069|RBW], ReplicaUC[[DISK]DS-6f615ab2-9484-47d0-af12-8285ccfcaef2:NORMAL:127.0.0.1:33615|RBW]]} size 77
[junit4] 2> 22424 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:45069 is added to blk_1073741980_1156 size 1520
[junit4] 2> 22432 INFO (coreCloseExecutor-12-thread-1) [ x:collection1] o.a.s.s.h.HdfsDirectory Closing hdfs directory hdfs://localhost.localdomain:36861/solr_hdfs_home/collection1/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/init-core-data-001/snapshot_metadata
[junit4] 2> 22456 INFO (coreCloseExecutor-12-thread-1) [ x:collection1] o.a.s.s.h.HdfsDirectory Closing hdfs directory hdfs://localhost.localdomain:36861/solr_hdfs_home/collection1/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/init-core-data-001/index
[junit4] 2> 22460 INFO (coreCloseExecutor-12-thread-1) [ x:collection1] o.a.s.s.h.HdfsDirectory Closing hdfs directory hdfs://localhost.localdomain:36861/solr_hdfs_home/collection1/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/init-core-data-001
[junit4] 2> 22470 WARN (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.h.h.s.d.DirectoryScanner DirectoryScanner: shutdown has been called
[junit4] 2> 22614 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:0
[junit4] 2> 22718 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data3/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data4/]] heartbeating to localhost.localdomain/127.0.0.1:36861) [ ] o.a.h.h.s.d.IncrementalBlockReportManager IncrementalBlockReportManager interrupted
[junit4] 2> 22718 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data3/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data4/]] heartbeating to localhost.localdomain/127.0.0.1:36861) [ ] o.a.h.h.s.d.DataNode Ending block pool service for: Block pool BP-1463306385-88.99.242.108-1526220586519 (Datanode Uuid 52e6758b-63a0-4bf1-9083-bfcfbbe1d299) service to localhost.localdomain/127.0.0.1:36861
[junit4] 2> 22721 WARN (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.h.h.s.d.DirectoryScanner DirectoryScanner: shutdown has been called
[junit4] 2> 22729 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:0
[junit4] 2> 22832 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:36861) [ ] o.a.h.h.s.d.IncrementalBlockReportManager IncrementalBlockReportManager interrupted
[junit4] 2> 22832 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.update.TestHdfsUpdateLog_E7826015A99FB95-001/tempDir-001/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:36861) [ ] o.a.h.h.s.d.DataNode Ending block pool service for: Block pool BP-1463306385-88.99.242.108-1526220586519 (Datanode Uuid e3d1fa52-9afa-4c01-bf8e-233fff5159bc) service to localhost.localdomain/127.0.0.1:36861
[junit4] 2> 22846 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost.localdomain:0
[junit4] 2> 22874 INFO (SUITE-TestHdfsUpdateLog-seed#[E7826015A99FB95]-worker) [ ] o.a.s.SolrTestCaseJ4 ------------------------------------------------------- Done waiting for tracked resources to be released
[junit4] 2> May 13, 2018 2:10:05 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 66 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=DummyCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=DUMMY, chunkSize=25815, maxDocsPerChunk=1, blockSize=843), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=DUMMY, chunkSize=25815, blockSize=843)), sim=RandomSimilarity(queryNorm=false): {}, locale=en-SG, timezone=America/Indianapolis
[junit4] 2> NOTE: Linux 4.13.0-39-generic i386/Oracle Corporation 1.8.0_162 (32-bit)/cpus=8,threads=6,free=32898312,total=85655552
[junit4] 2> NOTE: All tests run in this JVM: [TestHdfsUpdateLog]
[junit4] Completed [1/5 (1!)] on J0 in 31.66s, 1 test, 1 error <<< FAILURES!
[...truncated 28 lines...]
BUILD FAILED
/home/jenkins/workspace/Lucene-Solr-7.x-Linux/lucene/common-build.xml:1568: The following error occurred while executing this line:
/home/jenkins/workspace/Lucene-Solr-7.x-Linux/lucene/common-build.xml:1092: There were test failures: 5 suites, 5 tests, 1 error [seed: E7826015A99FB95]
Total time: 1 minute 9 seconds
[repro] Setting last failure code to 256
[repro] Failures:
[repro] 1/5 failed: org.apache.solr.update.TestHdfsUpdateLog
[repro] Exiting with code 256
+ mv lucene/build lucene/build.repro
+ mv solr/build solr/build.repro
+ mv lucene/build.orig lucene/build
+ mv solr/build.orig solr/build
Archiving artifacts
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
[WARNINGS] Parsing warnings in console log with parser Java Compiler (javac)
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
<Git Blamer> Using GitBlamer to create author and commit information for all warnings.
<Git Blamer> GIT_COMMIT=92b4a935dc48d58613a158a441b701e09ccc5047, workspace=/var/lib/jenkins/workspace/Lucene-Solr-7.x-Linux
[WARNINGS] Computing warning deltas based on reference build #1893
Recording test results
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Build step 'Publish JUnit test result report' changed build result to UNSTABLE
Email was triggered for: Unstable (Test Failures)
Sending email for trigger: Unstable (Test Failures)
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2