[SOLR-16074] Reproducible failure TestReplicationHandler.doTestStressReplication - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Closed
Priority: Blocker
Resolution: Fixed
Affects Version/s: 9.0
Fix Version/s: 9.0
Component/s: Tests
Labels:
None

Description

Found this while testing Spotless, reproduces on a fresh pull of Solr. Reproduce with:

./gradlew :solr:core:test --tests "org.apache.solr.handler.TestReplicationHandler.doTestStressReplication" -Ptests.jvms=6 -Ptests.jvmargs=-XX:TieredStopAtLevel=1 -Ptests.seed=3608C7C46BF3C0B9 -Ptests.file.encoding=UTF-8

Stack trace:

  2> 1170 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.a.s.SolrTestCase Setting 'solr.default.confdir' system property to test-framework derived value of '/Users/Erick/apache/solr/solr/server/solr/configsets/_default/conf'
  2> 1183 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.a.s.u.ErrorLogMuter Creating ErrorLogMuter-regex-1 for ERROR logs matching regex: ignore_exception
  2> 1193 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.a.s.SolrTestCaseJ4 Created dataDir: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/data-dir-1-001
  2> 1241 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.a.s.SolrTestCaseJ4 Using TrieFields (NUMERIC_POINTS_SYSPROP=false) w/NUMERIC_DOCVALUES_SYSPROP=true
  2> 1265 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.e.j.u.log Logging initialized @1299ms to org.eclipse.jetty.util.log.Slf4jLog
  2> 1269 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl="None") w/ MAC_OS_X supressed clientAuth
  2> 1283 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
  2> 1297 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.SolrTestCaseJ4 ###Starting doTestStressReplication
  2> 1298 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.SolrTestCaseJ4 Writing core.properties file to /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1
  2> 1451 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Start Jetty (configured port=0, binding port=0)
  2> 1453 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 2 ...
  2> 1457 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.Server jetty-9.4.44.v20210927; built: 2021-09-27T23:02:44.612Z; git: 8da83308eeca865e495e53ef315a249d63ba9332; jvm 11.0.5+10
  2> 1464 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session DefaultSessionIdManager workerName=node0
  2> 1464 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session No SessionScavenger set, using defaults
  2> 1466 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session node0 Scavenging every 600000ms
  2> 1474 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4654afe3\{/solr,null,AVAILABLE}
  2> 1486 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.AbstractConnector Started ServerConnector@7997b438\{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:55414}
  2> 1487 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.Server Started @1523ms
  2> 1516 ERROR (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
  2> 1516 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
  2> 1522 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider  ___      _       Welcome to Apache Solr™ version 10.0.0
  2> 1522 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider / __| ___| |_ _   Starting in standalone mode on port null
  2> 1523 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider \__ \/ _ \ | '_|  Install dir: /Users/Erick/apache/solr/solr
  2> 1523 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider |___/\___/_|_|    Start time: 2022-03-03T15:25:43.997195Z
  2> 1523 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider Solr Home: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001 (source: servlet config: solr.solr.home)
  2> 1524 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.SolrXmlConfig Loading solr.xml from /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/solr.xml
  2> 3008 WARN  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CoreContainer Not all security plugins configured!  authentication=disabled authorization=disabled.  Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external.  See https://s.apache.org/solrsecurity for more info
  2> 3161 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001
  2> 3162 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
  2> 3165 INFO  (coreLoadExecutor-11-thread-1) [] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient core cache for max 4 cores with initial capacity of 4
  2> 3195 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Jetty properties: \{hostContext=/solr, solr.data.dir=/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1/data, hostPort=55414}
  2> 3203 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 9.0.0
  2> 3236 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.s.IndexSchema Schema name=test
  2> 3245 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
  2> 3245 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1, trusted=true
  2> 3285 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.c.SolrCore Opening new SolrCore at [/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1], dataDir=[/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1/data/]
  2> 3312 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=46, maxMergedSegmentMB=99.5498046875, floorSegmentMB=1.2705078125, forceMergeDeletesPctAllowed=27.42697661019185, segmentsPerTier=36.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.31409724782534043, deletesPctAllowed=31.056673504466776
  2> 3652 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
  2> 3652 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
  2> 3654 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=32, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.8618787730062866]
  2> 3674 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1/conf
  2> 3686 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Replication enabled for following config files: schema.xml,foo/bar.txt
  2> 3687 INFO  (coreLoadExecutor-11-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 ms
  2> 3692 INFO  (searcherExecutor-13-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 3698 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.SolrTestCaseJ4 Writing core.properties file to /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1
  2> 3702 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Start Jetty (configured port=0, binding port=0)
  2> 3702 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 2 ...
  2> 3702 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.Server jetty-9.4.44.v20210927; built: 2021-09-27T23:02:44.612Z; git: 8da83308eeca865e495e53ef315a249d63ba9332; jvm 11.0.5+10
  2> 3704 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session DefaultSessionIdManager workerName=node0
  2> 3704 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session No SessionScavenger set, using defaults
  2> 3704 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session node0 Scavenging every 660000ms
  2> 3705 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1bdfc7d8\{/solr,null,AVAILABLE}
  2> 3706 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.AbstractConnector Started ServerConnector@3cf4ff94\{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:55416}
  2> 3707 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.Server Started @3743ms
  2> 3707 ERROR (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
  2> 3707 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
  2> 3707 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider  ___      _       Welcome to Apache Solr™ version 10.0.0
  2> 3708 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider / __| ___| |_ _   Starting in standalone mode on port null
  2> 3708 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider \__ \/ _ \ | '_|  Install dir: /Users/Erick/apache/solr/solr
  2> 3708 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider |___/\___/_|_|    Start time: 2022-03-03T15:25:46.182223Z
  2> 3708 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider Solr Home: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002 (source: servlet config: solr.solr.home)
  2> 3708 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.SolrXmlConfig Loading solr.xml from /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/solr.xml
  2> 3865 WARN  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CoreContainer Not all security plugins configured!  authentication=disabled authorization=disabled.  Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external.  See https://s.apache.org/solrsecurity for more info
  2> 3904 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002
  2> 3904 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
  2> 3904 INFO  (coreLoadExecutor-26-thread-1) [] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient core cache for max 4 cores with initial capacity of 4
  2> 3906 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Jetty properties: \{hostContext=/solr, solr.data.dir=/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data, hostPort=55416}
  2> 3910 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 9.0.0
  2> 3912 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.s.IndexSchema Schema name=test
  2> 3912 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
  2> 3913 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1, trusted=true
  2> 3913 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.c.SolrCore Opening new SolrCore at [/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1], dataDir=[/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/]
  2> 3915 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=46, maxMergedSegmentMB=99.5498046875, floorSegmentMB=1.2705078125, forceMergeDeletesPctAllowed=27.42697661019185, segmentsPerTier=36.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.31409724782534043, deletesPctAllowed=31.056673504466776
  2> 3957 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
  2> 3957 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
  2> 3958 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=32, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.8618787730062866]
  2> 3960 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/conf
  2> 3965 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 1000ms
  2> 3966 INFO  (coreLoadExecutor-26-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 ms
  2> 3968 INFO  (searcherExecutor-28-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 3975 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.AbstractConnector Stopped ServerConnector@3cf4ff94\{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:0}
  2> 3976 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1bdfc7d8\{/solr,null,STOPPED}
  2> 3976 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session node0 Stopped scavenging
  2> 3977 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1942533390
  2> 3981 INFO  (coreCloseExecutor-34-thread-1) [ x:collection1] o.a.s.c.SolrCore CLOSING SolrCore org.apache.solr.core.SolrCore@25a03ea2 collection1
  2> 3981 INFO  (coreCloseExecutor-34-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1 tag=SolrCore@25a03ea2
  2> 4004 INFO  (coreCloseExecutor-34-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 Committing on IndexWriter.close()  ... SKIPPED (unnecessary).
  2> 4007 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node tag=null
  2> 4014 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm tag=null
  2> 4020 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty tag=null
  2> 4025 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Start Jetty (configured port=0, binding port=0)
  2> 4025 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 2 ...
  2> 4025 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.Server jetty-9.4.44.v20210927; built: 2021-09-27T23:02:44.612Z; git: 8da83308eeca865e495e53ef315a249d63ba9332; jvm 11.0.5+10
  2> 4026 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session DefaultSessionIdManager workerName=node0
  2> 4026 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session No SessionScavenger set, using defaults
  2> 4027 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session node0 Scavenging every 660000ms
  2> 4027 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@675189b8\{/solr,null,AVAILABLE}
  2> 4029 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.AbstractConnector Started ServerConnector@421864dc\{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:55417}
  2> 4029 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.Server Started @4066ms
  2> 4029 ERROR (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
  2> 4029 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
  2> 4030 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider  ___      _       Welcome to Apache Solr™ version 10.0.0
  2> 4030 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider / __| ___| |_ _   Starting in standalone mode on port null
  2> 4030 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider \__ \/ _ \ | '_|  Install dir: /Users/Erick/apache/solr/solr
  2> 4030 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider |___/\___/_|_|    Start time: 2022-03-03T15:25:46.504330Z
  2> 4030 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider Solr Home: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002 (source: servlet config: solr.solr.home)
  2> 4030 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.SolrXmlConfig Loading solr.xml from /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/solr.xml
  2> 4286 WARN  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CoreContainer Not all security plugins configured!  authentication=disabled authorization=disabled.  Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external.  See https://s.apache.org/solrsecurity for more info
  2> 4321 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002
  2> 4321 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
  2> 4322 INFO  (coreLoadExecutor-45-thread-1) [] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient core cache for max 4 cores with initial capacity of 4
  2> 4323 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Jetty properties: \{hostContext=/solr, solr.data.dir=/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data, hostPort=55417}
  2> 4326 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 9.0.0
  2> 4329 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.s.IndexSchema Schema name=test
  2> 4329 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
  2> 4329 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1, trusted=true
  2> 4331 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.c.SolrCore Opening new SolrCore at [/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1], dataDir=[/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/]
  2> 4338 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=18, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
  2> 4466 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
  2> 4466 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
  2> 4467 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=16, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.4874934082984129]
  2> 4471 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/conf
  2> 4472 INFO  (coreLoadExecutor-45-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 ms
  2> 4473 INFO  (searcherExecutor-47-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 4476 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.AbstractConnector Stopped ServerConnector@7997b438\{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:0}
  2> 4476 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@4654afe3\{/solr,null,STOPPED}
  2> 4476 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session node0 Stopped scavenging
  2> 4482 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1356896889
  2> 4483 INFO  (coreCloseExecutor-52-thread-1) [ x:collection1] o.a.s.c.SolrCore CLOSING SolrCore org.apache.solr.core.SolrCore@4becd7d9 collection1
  2> 4483 INFO  (coreCloseExecutor-52-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1 tag=SolrCore@4becd7d9
  2> 4495 INFO  (coreCloseExecutor-52-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 Committing on IndexWriter.close()  ... SKIPPED (unnecessary).
  2> 4497 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node tag=null
  2> 4501 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm tag=null
  2> 4504 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty tag=null
  2> 4506 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Start Jetty (configured port=0, binding port=0)
  2> 4506 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 2 ...
  2> 4506 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.Server jetty-9.4.44.v20210927; built: 2021-09-27T23:02:44.612Z; git: 8da83308eeca865e495e53ef315a249d63ba9332; jvm 11.0.5+10
  2> 4507 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session DefaultSessionIdManager workerName=node0
  2> 4507 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session No SessionScavenger set, using defaults
  2> 4508 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session node0 Scavenging every 660000ms
  2> 4508 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@724509b2\{/solr,null,AVAILABLE}
  2> 4510 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.AbstractConnector Started ServerConnector@55ce1fae\{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:55418}
  2> 4510 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.Server Started @4547ms
  2> 4511 ERROR (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
  2> 4511 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
  2> 4511 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider  ___      _       Welcome to Apache Solr™ version 10.0.0
  2> 4511 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider / __| ___| |_ _   Starting in standalone mode on port null
  2> 4511 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider \__ \/ _ \ | '_|  Install dir: /Users/Erick/apache/solr/solr
  2> 4511 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider |___/\___/_|_|    Start time: 2022-03-03T15:25:46.985679Z
  2> 4511 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.s.CoreContainerProvider Solr Home: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001 (source: servlet config: solr.solr.home)
  2> 4511 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.SolrXmlConfig Loading solr.xml from /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/solr.xml
  2> 6070 WARN  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CoreContainer Not all security plugins configured!  authentication=disabled authorization=disabled.  Solr is only as secure as you make it. Consider configuring authentication/authorization before exposing Solr to users internal or external.  See https://s.apache.org/solrsecurity for more info
  2> 6099 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001
  2> 6099 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
  2> 6100 INFO  (coreLoadExecutor-63-thread-1) [] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient core cache for max 4 cores with initial capacity of 4
  2> 6105 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 9.0.0
  2> 6104 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.s.e.JettySolrRunner Jetty properties: \{hostContext=/solr, solr.data.dir=/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1/data, hostPort=55418}
  2> 6107 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.s.IndexSchema Schema name=test
  2> 6107 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
  2> 6107 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1, trusted=true
  2> 6108 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.c.SolrCore Opening new SolrCore at [/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1], dataDir=[/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1/data/]
  2> 6110 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=18, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
  2> 6220 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
  2> 6221 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
  2> 6222 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=16, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.4874934082984129]
  2> 6224 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-001/collection1/conf
  2> 6224 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Replication enabled for following config files: schema.xml
  2> 6224 INFO  (coreLoadExecutor-63-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 ms
  2> 6226 INFO  (searcherExecutor-65-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 6349 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.DirectUpdateHandler2 REMOVING ALL DOCUMENTS FROM INDEX
  2> 6351 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{deleteByQuery=*:*} 0 29
  2> 6366 INFO  (qtp892828690-70) [ x:collection1] o.a.s.u.DirectUpdateHandler2 REMOVING ALL DOCUMENTS FROM INDEX
  2> 6367 INFO  (qtp892828690-70) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{deleteByQuery=*:*} 0 0
  2> 6445 INFO  (searcherExecutor-47-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 6446 INFO  (qtp892828690-70) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 76
  2> 6487 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[0]} 0 38
  2> 6489 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[1]} 0 0
  2> 6491 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[2]} 0 0
  2> 6492 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[3]} 0 0
  2> 6494 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[4]} 0 0
  2> 6495 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[5]} 0 0
  2> 6497 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[6]} 0 0
  2> 6499 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[7]} 0 0
  2> 6500 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[8]} 0 0
  2> 6502 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[9]} 0 0
  2> 6503 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[10]} 0 0
  2> 6505 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[11]} 0 0
  2> 6506 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[12]} 0 0
  2> 6508 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[13]} 0 0
  2> 6509 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[14]} 0 0
  2> 6511 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[15]} 0 0
  2> 6512 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[16]} 0 0
  2> 6514 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[17]} 0 0
  2> 6515 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[18]} 0 0
  2> 6517 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[19]} 0 0
  2> 6518 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[20]} 0 0
  2> 6519 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[21]} 0 0
  2> 6521 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[22]} 0 0
  2> 6522 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[23]} 0 0
  2> 6524 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[24]} 0 0
  2> 6525 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[25]} 0 0
  2> 6527 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[26]} 0 0
  2> 6528 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[27]} 0 0
  2> 6529 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[28]} 0 0
  2> 6531 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[29]} 0 0
  2> 6532 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[30]} 0 0
  2> 6533 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[31]} 0 0
  2> 6535 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[32]} 0 0
  2> 6536 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[33]} 0 0
  2> 6721 INFO  (searcherExecutor-65-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 6721 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 184
  2> 6759 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/select params=\{q=*:*&sort=id+desc&wt=javabin&version=2} hits=34 status=0 QTime=31
  2> 6772 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.h.TestReplicationHandler Waited for 0ms and found 34 docs
  2> 6779 INFO  (qtp892828690-70) [] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params=\{core=collection1&action=status&wt=javabin&version=2} status=0 QTime=4
  2> 6797 WARN  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher 'leaderUrl' must be specified without the /replication suffix
  2> 6801 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
  2> 6802 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Leader's generation: 2
  2> 6802 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Leader's version: 1646321149011
  2> 6802 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Follower's generation: 2
  2> 6802 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Follower's version: 1646321148844
  2> 6802 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Starting replication process
  2> 6809 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=2&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=6
  2> 6810 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Number of files in latest index in leader: 4
  2> 6812 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Starting download (fullCopy=true) to NRTCachingDirectory(MMapDirectory@/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549285 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4cd3ce33; maxCacheMB=48.0 maxMergeSizeMB=4.0)
  2> 6812 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher tmpIndexDir_type  : class org.apache.lucene.store.NRTCachingDirectory , MMapDirectory@/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549285 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4cd3ce33
  2> 6821 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=2&qt=/replication&file=_0.cfe&checksum=true&wt=filestream&command=filecontent} status=0 QTime=2
  2> 6826 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=2&qt=/replication&file=_0.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
  2> 6849 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=2&qt=/replication&file=_0.cfs&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
  2> 6869 WARN  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher File segments_2 did not match. expected checksum is 538973631 and actual is checksum 2555868324. expected length is 202 and actual length is 117
  2> 6872 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=2&qt=/replication&file=segments_2&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
  2> 6892 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Bytes downloaded: 2821, Bytes skipped downloading: 0
  2> 6893 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=true,bytesDownloaded=2821) : 0 secs (null bytes/sec) to NRTCachingDirectory(MMapDirectory@/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549285 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4cd3ce33; maxCacheMB=48.0 maxMergeSizeMB=4.0)
  2> 6914 INFO  (explicit-fetchindex-cmd) [] o.a.s.c.SolrCore Updating index properties... index=index.20220303082549285
  2> 6964 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher removing old index directory NRTCachingDirectory(MMapDirectory@/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@3d6e7ed0; maxCacheMB=48.0 maxMergeSizeMB=4.0)
  2> 6966 INFO  (explicit-fetchindex-cmd) [] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=18, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
  2> 6970 INFO  (explicit-fetchindex-cmd) [] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
  2> 6974 INFO  (searcherExecutor-47-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 6974 INFO  (qtp892828690-108) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{wait=true&leaderUrl=http://127.0.0.1:55418/solr/collection1/replication&command=fetchindex} status=0 QTime=179
  2> 6992 INFO  (qtp892828690-70) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/select params=\{q=*:*&sort=id+desc&wt=javabin&version=2} hits=34 status=0 QTime=1
  2> 6994 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.h.TestReplicationHandler Waited for 0ms and found 34 docs
  2> 7001 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=2
  2> 7003 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=1
  2> 7008 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{follower=false&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=1
  2> 7009 INFO  (qtp892828690-108) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=4
  2> 7010 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
  2> 7011 INFO  (qtp892828690-70) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
  1> [snapshot_metadata, index]
  1> [index.20220303082549285, index.properties, snapshot_metadata, replication.properties]
  2> 7020 INFO  (qtp892828690-108) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[34]} 0 2
  2> 7022 INFO  (qtp892828690-70) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[35]} 0 0
  2> 7023 INFO  (qtp892828690-108) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[36]} 0 0
  2> 7131 INFO  (searcherExecutor-47-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 7132 INFO  (qtp892828690-70) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 107
  2> 7137 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[37]} 0 2
  2> 7139 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[38]} 0 0
  2> 7141 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[39]} 0 0
  2> 7142 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[40]} 0 0
  2> 7143 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[41]} 0 0
  2> 7145 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[42]} 0 0
  2> 7146 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[43]} 0 0
  2> 7148 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[44]} 0 0
  2> 7149 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[45]} 0 0
  2> 7151 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[46]} 0 0
  2> 7152 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[47]} 0 0
  2> 7153 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[48]} 0 0
  2> 7155 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[49]} 0 0
  2> 7156 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[50]} 0 0
  2> 7157 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[51]} 0 0
  2> 7159 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[52]} 0 0
  2> 7160 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[53]} 0 0
  2> 7161 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[54]} 0 0
  2> 7162 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[55]} 0 0
  2> 7163 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[56]} 0 0
  2> 7165 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[57]} 0 0
  2> 7166 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[58]} 0 0
  2> 7167 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[59]} 0 0
  2> 7168 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[60]} 0 0
  2> 7169 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[61]} 0 0
  2> 7170 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[62]} 0 0
  2> 7172 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[63]} 0 0
  2> 7173 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[64]} 0 0
  2> 7174 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[65]} 0 0
  2> 7175 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[66]} 0 0
  2> 7176 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[67]} 0 0
  2> 7177 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[68]} 0 0
  2> 7178 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[69]} 0 0
  2> 7179 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[70]} 0 0
  2> 7180 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[71]} 0 0
  2> 7181 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[72]} 0 0
  2> 7182 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[73]} 0 0
  2> 7183 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[74]} 0 0
  2> 7184 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[75]} 0 0
  2> 7185 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[76]} 0 0
  2> 7187 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[77]} 0 0
  2> 7188 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[78]} 0 0
  2> 7189 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[79]} 0 0
  2> 7190 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[80]} 0 0
  2> 7191 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[81]} 0 0
  2> 7192 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[82]} 0 0
  2> 7193 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[83]} 0 0
  2> 7194 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[84]} 0 0
  2> 7195 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[85]} 0 0
  2> 7196 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[86]} 0 0
  2> 7198 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[87]} 0 0
  2> 7199 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[88]} 0 0
  2> 7200 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[89]} 0 0
  2> 7202 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[90]} 0 0
  2> 7203 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[91]} 0 0
  2> 7204 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[92]} 0 0
  2> 7205 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[93]} 0 0
  2> 7213 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[94]} 0 0
  2> 7215 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[95]} 0 0
  2> 7216 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[96]} 0 0
  2> 7217 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[97]} 0 0
  2> 7219 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[98]} 0 0
  2> 7326 INFO  (searcherExecutor-65-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 7327 INFO  (qtp898021229-93) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 106
  2> 7329 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/select params=\{q=*:*&sort=id+desc&wt=javabin&version=2} hits=96 status=0 QTime=1
  2> 7331 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.h.TestReplicationHandler Waited for 0ms and found 96 docs
  2> 7334 INFO  (qtp892828690-70) [] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params=\{core=collection1&action=status&wt=javabin&version=2} status=0 QTime=1
  2> 7337 WARN  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher 'leaderUrl' must be specified without the /replication suffix
  2> 7338 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
  2> 7338 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Leader's generation: 3
  2> 7339 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Leader's version: 1646321149694
  2> 7339 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Follower's generation: 3
  2> 7339 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Follower's version: 1646321149498
  2> 7339 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Starting replication process
  2> 7343 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=3&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=4
  2> 7344 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Number of files in latest index in leader: 7
  2> 7345 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Starting download (fullCopy=true) to NRTCachingDirectory(MMapDirectory@/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@646865b2; maxCacheMB=48.0 maxMergeSizeMB=4.0)
  2> 7345 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher tmpIndexDir_type  : class org.apache.lucene.store.NRTCachingDirectory , MMapDirectory@/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@646865b2
  2> 7345 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Don't need to download this file. Local file's path is: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549285/_0.cfe, checksum is: 841580380
  2> 7347 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Don't need to download this file. Local file's path is: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549285/_0.si, checksum is: 1125430291
  2> 7347 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Don't need to download this file. Local file's path is: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549285/_0.cfs, checksum is: 2151762433
  2> 7348 WARN  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher File _1.cfs did not match. expected checksum is 3875326707 and actual is checksum 1015361674. expected length is 2285 and actual length is 1412
  2> 7349 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=3&qt=/replication&file=_1.cfs&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
  2> 7351 WARN  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher File _1.cfe did not match. expected checksum is 4114852705 and actual is checksum 115616999. expected length is 320 and actual length is 320
  2> 7352 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=3&qt=/replication&file=_1.cfe&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
  2> 7372 WARN  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher File _1.si did not match. expected checksum is 149287138 and actual is checksum 995242766. expected length is 368 and actual length is 368
  2> 7395 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=3&qt=/replication&file=_1.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
  2> 7397 WARN  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher File segments_3 did not match. expected checksum is 3705891129 and actual is checksum 2799505042. expected length is 284 and actual length is 284
  2> 7419 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=3&qt=/replication&file=segments_3&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
  2> 7421 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Bytes downloaded: 3257, Bytes skipped downloading: 2619
  2> 7421 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=true,bytesDownloaded=3257) : 0 secs (null bytes/sec) to NRTCachingDirectory(MMapDirectory@/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@646865b2; maxCacheMB=48.0 maxMergeSizeMB=4.0)
  2> 7422 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Starting download of configuration files from leader: [\{size=1530, name=schema.xml, checksum=1508380349}]
  2> 7447 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{generation=3&qt=/replication&cf=schema.xml&checksum=true&wt=filestream&command=filecontent} status=0 QTime=1
  2> 7453 INFO  (explicit-fetchindex-cmd) [] o.a.s.c.SolrCore Updating index properties... index=index.20220303082549818
  2> 7476 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Configuration files are modified, core will be reloaded
  2> 7500 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher Reloading SolrCore collection1
  2> 7510 INFO  (CoreReload) [] o.a.s.c.SolrConfig Using Lucene MatchVersion: 9.0.0
  2> 7513 INFO  (CoreReload) [] o.a.s.s.IndexSchema Schema name=test
  2> 7513 INFO  (CoreReload) [] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
  2> 7513 INFO  (CoreReload) [] o.a.s.c.CoreContainer Reloading SolrCore 'collection1' using configuration from instancedir /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1
  2> 7558 INFO  (CoreReload) [] o.a.s.c.SolrCore Opening new SolrCore at [/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1], dataDir=[/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/]
  2> 7565 INFO  (OldIndexDirectoryCleanupThreadForCore-collection1) [] o.a.s.c.DirectoryFactory Will not remove most recent old directory after reload /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549285
  2> 7565 INFO  (OldIndexDirectoryCleanupThreadForCore-collection1) [] o.a.s.c.DirectoryFactory Found 0 old index directories to clean-up under /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/ afterReload=true
  2> 7608 INFO  (CoreReload) [] o.a.s.u.CommitTracker Hard AutoCommit: disabled
  2> 7608 INFO  (CoreReload) [] o.a.s.u.CommitTracker Soft AutoCommit: disabled
  2> 7610 INFO  (CoreReload) [] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/conf
  2> 7610 INFO  (CoreReload) [] o.a.s.h.ReplicationHandler Commits will be reserved for 10000 ms
  2> 7612 INFO  (CoreReload) [] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=18, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
  2> 7614 INFO  (searcherExecutor-72-thread-1) [] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 7616 INFO  (CoreReload) [] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
  2> 7619 INFO  (explicit-fetchindex-cmd) [] o.a.s.h.IndexFetcher removing old index directory NRTCachingDirectory(MMapDirectory@/Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549285 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@4cd3ce33; maxCacheMB=48.0 maxMergeSizeMB=4.0)
  2> 7621 INFO  (explicit-fetchindex-cmd) [] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=18, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
  2> 7623 INFO  (searcherExecutor-72-thread-1) [] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 7625 INFO  (explicit-fetchindex-cmd) [] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
  2> 7631 INFO  (searcherExecutor-72-thread-1-processing-collection1) [ x:collection1] o.a.s.c.SolrCore Registered new searcher autowarm time: 0 ms
  2> 7633 INFO  (qtp892828690-108) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{wait=true&leaderUrl=http://127.0.0.1:55418/solr/collection1/replication&command=fetchindex} status=0 QTime=296
  2> 7633 INFO  (qtp892828690-108) [ x:collection1] o.a.s.c.SolrCore CLOSING SolrCore org.apache.solr.core.SolrCore@72b874ff collection1
  2> 7633 INFO  (qtp892828690-108) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1 tag=SolrCore@72b874ff
  2> 7656 INFO  (qtp892828690-108) [] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params=\{core=collection1&action=status&wt=javabin&version=2} status=0 QTime=1
  2> 7658 INFO  (qtp892828690-70) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/select params=\{q=*:*&sort=id+desc&wt=javabin&version=2} hits=96 status=0 QTime=1
  2> 7659 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.h.TestReplicationHandler Waited for 0ms and found 96 docs
  2> 7661 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=1
  2> 7663 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=1
  2> 7665 INFO  (qtp892828690-108) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=1
  2> 7667 INFO  (qtp898021229-93) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
  2> 7668 INFO  (qtp892828690-70) [ x:collection1] o.a.s.c.S.Request webapp=/solr path=/replication params=\{_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
  1> [snapshot_metadata, index]
  1> [index.properties, snapshot_metadata, replication.properties, index.20220303082549818]
  2> 7673 INFO  (qtp892828690-108) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[99]} 0 1
  2> 7674 INFO  (qtp892828690-70) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[100]} 0 0
  2> 7675 INFO  (qtp892828690-108) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{wt=javabin&version=2}{add=[101]} 0 0
  2> 7750 INFO  (qtp892828690-70) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory webapp=/solr path=/update params=\{waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{} 0 74
  2> 7751 ERROR (qtp892828690-70) [ x:collection1] o.a.s.h.RequestHandlerBase java.nio.file.AccessDeniedException: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
  2>           => java.nio.file.AccessDeniedException: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
  2>     at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:90)
  2> java.nio.file.AccessDeniedException: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
  2>     at sun.nio.fs.UnixException.translateToIOException(UnixException.java:90) ~[?:?]
  2>     at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111) ~[?:?]
  2>     at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116) ~[?:?]
  2>     at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:182) ~[?:?]
  2>     at java.nio.channels.FileChannel.open(FileChannel.java:292) ~[?:?]
  2>     at java.nio.channels.FileChannel.open(FileChannel.java:345) ~[?:?]
  2>     at org.apache.lucene.util.IOUtils.fsync(IOUtils.java:439) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.FSDirectory.fsync(FSDirectory.java:301) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.FSDirectory.sync(FSDirectory.java:255) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.NRTCachingDirectory.sync(NRTCachingDirectory.java:172) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.LockValidatingDirectoryWrapper.sync(LockValidatingDirectoryWrapper.java:68) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:5339) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:3534) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3863) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3825) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:661) ~[main/:?]
  2>     at org.apache.solr.update.processor.RunUpdateProcessorFactory$RunUpdateProcessor.processCommit(RunUpdateProcessorFactory.java:97) ~[main/:?]
  2>     at org.apache.solr.update.processor.UpdateRequestProcessor.processCommit(UpdateRequestProcessor.java:70) ~[main/:?]
  2>     at org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalCommit(DistributedUpdateProcessor.java:1098) ~[main/:?]
  2>     at org.apache.solr.update.processor.DistributedUpdateProcessor.processCommit(DistributedUpdateProcessor.java:1085) ~[main/:?]
  2>     at org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor.processCommit(LogUpdateProcessorFactory.java:169) ~[main/:?]
  2>     at org.apache.solr.handler.RequestHandlerUtils.handleCommit(RequestHandlerUtils.java:69) ~[main/:?]
  2>     at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:76) ~[main/:?]
  2>     at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:214) [main/:?]
  2>     at org.apache.solr.core.SolrCore.execute(SolrCore.java:2638) [main/:?]
  2>     at org.apache.solr.servlet.HttpSolrCall.execute(HttpSolrCall.java:825) [main/:?]
  2>     at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:565) [main/:?]
  2>     at org.apache.solr.servlet.SolrDispatchFilter.dispatch(SolrDispatchFilter.java:218) [main/:?]
  2>     at org.apache.solr.servlet.SolrDispatchFilter.lambda$doFilter$0(SolrDispatchFilter.java:189) [main/:?]
  2>     at org.apache.solr.servlet.ServletUtils.traceHttpRequestExecution2(ServletUtils.java:232) [main/:?]
  2>     at org.apache.solr.servlet.ServletUtils.rateLimitRequest(ServletUtils.java:208) [main/:?]
  2>     at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:187) [main/:?]
  2>     at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:171) [main/:?]
  2>     at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:189) [main/:?]
  2>     at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:322) [jetty-rewrite-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:713) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.Server.handle(Server.java:516) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:400) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:645) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:392) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at java.lang.Thread.run(Thread.java:834) [?:?]
  2> 7760 ERROR (qtp892828690-70) [ x:collection1] o.a.s.s.HttpSolrCall java.nio.file.AccessDeniedException: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
  2>           => java.nio.file.AccessDeniedException: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
  2>     at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:90)
  2> java.nio.file.AccessDeniedException: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
  2>     at sun.nio.fs.UnixException.translateToIOException(UnixException.java:90) ~[?:?]
  2>     at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111) ~[?:?]
  2>     at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116) ~[?:?]
  2>     at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:182) ~[?:?]
  2>     at java.nio.channels.FileChannel.open(FileChannel.java:292) ~[?:?]
  2>     at java.nio.channels.FileChannel.open(FileChannel.java:345) ~[?:?]
  2>     at org.apache.lucene.util.IOUtils.fsync(IOUtils.java:439) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.FSDirectory.fsync(FSDirectory.java:301) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.FSDirectory.sync(FSDirectory.java:255) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.NRTCachingDirectory.sync(NRTCachingDirectory.java:172) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.LockValidatingDirectoryWrapper.sync(LockValidatingDirectoryWrapper.java:68) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:5339) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:3534) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3863) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.commit(IndexWriter.java:3825) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandler2.java:661) ~[main/:?]
  2>     at org.apache.solr.update.processor.RunUpdateProcessorFactory$RunUpdateProcessor.processCommit(RunUpdateProcessorFactory.java:97) ~[main/:?]
  2>     at org.apache.solr.update.processor.UpdateRequestProcessor.processCommit(UpdateRequestProcessor.java:70) ~[main/:?]
  2>     at org.apache.solr.update.processor.DistributedUpdateProcessor.doLocalCommit(DistributedUpdateProcessor.java:1098) ~[main/:?]
  2>     at org.apache.solr.update.processor.DistributedUpdateProcessor.processCommit(DistributedUpdateProcessor.java:1085) ~[main/:?]
  2>     at org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor.processCommit(LogUpdateProcessorFactory.java:169) ~[main/:?]
  2>     at org.apache.solr.handler.RequestHandlerUtils.handleCommit(RequestHandlerUtils.java:69) ~[main/:?]
  2>     at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:76) ~[main/:?]
  2>     at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:214) ~[main/:?]
  2>     at org.apache.solr.core.SolrCore.execute(SolrCore.java:2638) ~[main/:?]
  2>     at org.apache.solr.servlet.HttpSolrCall.execute(HttpSolrCall.java:825) [main/:?]
  2>     at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:565) [main/:?]
  2>     at org.apache.solr.servlet.SolrDispatchFilter.dispatch(SolrDispatchFilter.java:218) [main/:?]
  2>     at org.apache.solr.servlet.SolrDispatchFilter.lambda$doFilter$0(SolrDispatchFilter.java:189) [main/:?]
  2>     at org.apache.solr.servlet.ServletUtils.traceHttpRequestExecution2(ServletUtils.java:232) [main/:?]
  2>     at org.apache.solr.servlet.ServletUtils.rateLimitRequest(ServletUtils.java:208) [main/:?]
  2>     at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:187) [main/:?]
  2>     at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:171) [main/:?]
  2>     at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:189) [main/:?]
  2>     at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:322) [jetty-rewrite-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:713) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.Server.handle(Server.java:516) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:400) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:645) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:392) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
  2>     at java.lang.Thread.run(Thread.java:834) [?:?]
  2> 7763 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.SolrTestCaseJ4 ###Ending doTestStressReplication
  2> 7765 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.AbstractConnector Stopped ServerConnector@55ce1fae\{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:0}
  2> 7766 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@724509b2\{/solr,null,STOPPED}
  2> 7766 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session node0 Stopped scavenging
  2> 7773 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1473968402
  2> 7773 INFO  (coreCloseExecutor-77-thread-1) [ x:collection1] o.a.s.c.SolrCore CLOSING SolrCore org.apache.solr.core.SolrCore@364b9fc0 collection1
  2> 7774 INFO  (coreCloseExecutor-77-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1 tag=SolrCore@364b9fc0
  2> 7784 INFO  (coreCloseExecutor-77-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 Committing on IndexWriter.close()  ... SKIPPED (unnecessary).
  2> 7787 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node tag=null
  2> 7793 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm tag=null
  2> 7796 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty tag=null
  2> 7798 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.AbstractConnector Stopped ServerConnector@421864dc\{HTTP/1.1, (http/1.1, h2c)}{127.0.0.1:0}
  2> 7799 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@675189b8\{/solr,null,STOPPED}
  2> 7799 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.e.j.s.session node0 Stopped scavenging
  2> 7799 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1209840064
  2> 7800 INFO  (coreCloseExecutor-80-thread-1) [ x:collection1] o.a.s.c.SolrCore CLOSING SolrCore org.apache.solr.core.SolrCore@2f4db96f collection1
  2> 7800 INFO  (coreCloseExecutor-80-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1 tag=SolrCore@2f4db96f
  2> 7812 INFO  (coreCloseExecutor-80-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 Committing on IndexWriter.close()  ... SKIPPED (unnecessary).
  2> 7860 ERROR (coreCloseExecutor-80-thread-1) [ x:collection1] o.a.s.u.SolrIndexWriter Error closing IndexWriter
  2>           => java.nio.file.AccessDeniedException: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
  2>     at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:90)
  2> java.nio.file.AccessDeniedException: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
  2>     at sun.nio.fs.UnixException.translateToIOException(UnixException.java:90) ~[?:?]
  2>     at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111) ~[?:?]
  2>     at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:116) ~[?:?]
  2>     at sun.nio.fs.UnixFileSystemProvider.newFileChannel(UnixFileSystemProvider.java:182) ~[?:?]
  2>     at java.nio.channels.FileChannel.open(FileChannel.java:292) ~[?:?]
  2>     at java.nio.channels.FileChannel.open(FileChannel.java:345) ~[?:?]
  2>     at org.apache.lucene.util.IOUtils.fsync(IOUtils.java:439) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.FSDirectory.fsync(FSDirectory.java:301) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.FSDirectory.sync(FSDirectory.java:255) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.NRTCachingDirectory.sync(NRTCachingDirectory.java:172) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.store.LockValidatingDirectoryWrapper.sync(LockValidatingDirectoryWrapper.java:68) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:5339) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:3534) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3863) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1322) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1360) ~[lucene-core-9.0.0.jar:9.0.0 0b18b3b965cedaf5eb129aa41243a44c83ca826d - jpountz - 2021-12-01 14:23:49]
  2>     at org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:298) [main/:?]
  2>     at org.apache.solr.update.DirectUpdateHandler2.closeWriter(DirectUpdateHandler2.java:895) [main/:?]
  2>     at org.apache.solr.update.DefaultSolrCoreState.closeIndexWriter(DefaultSolrCoreState.java:96) [main/:?]
  2>     at org.apache.solr.update.DefaultSolrCoreState.close(DefaultSolrCoreState.java:393) [main/:?]
  2>     at org.apache.solr.update.SolrCoreState.decrefSolrCoreState(SolrCoreState.java:112) [main/:?]
  2>     at org.apache.solr.core.SolrCore.doClose(SolrCore.java:1639) [main/:?]
  2>     at org.apache.solr.core.SolrCore.close(SolrCore.java:1582) [main/:?]
  2>     at org.apache.solr.core.SolrCores.lambda$close$0(SolrCores.java:123) [main/:?]
  2>     at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
  2>     at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:259) [solr-solrj-10.0.0-SNAPSHOT.jar:10.0.0-SNAPSHOT b7424bd1b33848b6732dd194607644f6baf1c90b [snapshot build, details omitted]]
  2>     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
  2>     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
  2>     at java.lang.Thread.run(Thread.java:834) [?:?]
  2> 7863 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node tag=null
  2> 7865 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm tag=null
  2> 7866 INFO  (TEST-TestReplicationHandler.doTestStressReplication-seed#[3608C7C46BF3C0B9]) [] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty tag=null
   >     org.apache.solr.client.solrj.impl.BaseHttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:55417/solr/collection1: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003/solr-instance-002/collection1/data/index.20220303082549818/_0.cfe
   >         at __randomizedtesting.SeedInfo.seed([3608C7C46BF3C0B9:EDA3C7026EDBA90A]:0)
   >         at app//org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:710)
   >         at app//org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:228)
   >         at app//org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:209)
   >         at app//org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:223)
   >         at app//org.apache.solr.client.solrj.SolrClient.commit(SolrClient.java:466)
   >         at app//org.apache.solr.client.solrj.SolrClient.commit(SolrClient.java:442)
   >         at app//org.apache.solr.handler.TestReplicationHandler.doTestStressReplication(TestReplicationHandler.java:1039)
   >         at java.base@11.0.5/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
   >         at java.base@11.0.5/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
   >         at java.base@11.0.5/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
   >         at java.base@11.0.5/java.lang.reflect.Method.invoke(Method.java:566)
   >         at app//com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1754)
   >         at app//com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:942)
   >         at app//com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:978)
   >         at app//com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:992)
   >         at app//com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
   >         at app//org.junit.rules.RunRules.evaluate(RunRules.java:20)
   >         at app//org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:44)
   >         at app//org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
   >         at app//org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:45)
   >         at app//org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
   >         at app//org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
   >         at app//org.junit.rules.RunRules.evaluate(RunRules.java:20)
   >         at app//com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   >         at app//com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:370)
   >         at app//com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:819)
   >         at app//com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:470)
   >         at app//com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:951)
   >         at app//com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:836)
   >         at app//com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:887)
   >         at app//com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:898)
   >         at app//com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   >         at app//org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
   >         at app//org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
   >         at app//com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
   >         at app//org.junit.rules.RunRules.evaluate(RunRules.java:20)
   >         at app//org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
   >         at app//com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   >         at app//org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:38)
   >         at app//com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
   >         at app//com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
   >         at app//com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   >         at app//com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   >         at app//org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
   >         at app//org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:43)
   >         at app//org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:44)
   >         at app//org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:60)
   >         at app//org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:47)
   >         at app//org.junit.rules.RunRules.evaluate(RunRules.java:20)
   >         at app//com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
   >         at app//com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:370)
   >         at app//com.carrotsearch.randomizedtesting.ThreadLeakControl.lambda$forkTimeoutingTask$0(ThreadLeakControl.java:826)
   >         at java.base@11.0.5/java.lang.Thread.run(Thread.java:834)
  2> NOTE: reproduce with: gradlew test --tests TestReplicationHandler.doTestStressReplication -Dtests.seed=3608C7C46BF3C0B9 -Dtests.slow=true -Dtests.badapples=true -Dtests.locale=to -Dtests.timezone=PNT -Dtests.asserts=true -Dtests.file.encoding=UTF-8
  2> 7873 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.a.s.u.ErrorLogMuter Closing ErrorLogMuter-regex-1 after mutting 0 log messages
  2> 7873 INFO  (SUITE-TestReplicationHandler-seed#[3608C7C46BF3C0B9]-worker) [] o.a.s.u.ErrorLogMuter Creating ErrorLogMuter-regex-2 for ERROR logs matching regex: ignore_exception
  2> NOTE: leaving temporary files on disk at: /Users/Erick/apache/solr/solr/core/build/tmp/tests-tmp/solr.handler.TestReplicationHandler_3608C7C46BF3C0B9-003
  2> NOTE: test params are: codec=Lucene90, sim=Asserting(RandomSimilarity(queryNorm=false): {}), locale=to, timezone=PNT
  2> NOTE: Mac OS X 10.16 x86_64/AdoptOpenJDK 11.0.5 (64-bit)/cpus=12,threads=1,free=158604912,total=268435456
  2> NOTE: All tests run in this JVM: [TestReplicationHandler]

Attachments

Issue Links

causes

SOLR-16866 CachingDirectoryFactory Throwing Error When Closing

Resolved

is broken by

SOLR-15989 Upgrade to Tika 1.28.1

Closed

links to

GitHub Pull Request #728

GitHub Pull Request #729

Activity

People

Assignee:: Kevin Risden

Reporter:: Erick Erickson

Votes:: 0 Vote for this issue

Watchers:: 6 Start watching this issue

Dates

Created:: 03/Mar/22 15:37

Updated:: 07/Mar/24 19:09

Resolved:: 07/Mar/22 16:44

Time Tracking

Estimated:

Not Specified

Remaining:

Logged:

2h 50m