lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jan Høydahl <jan....@cominvent.com>
Subject Re: [JENKINS] Lucene-Solr-Tests-8.x - Build # 173 - Unstable
Date Thu, 02 May 2019 20:56:43 GMT
I have nailed this AuditLoggerIntegrationTest.testAsyncQueueDrain() test failure.
It is actually a real bug, not a problem with the test :)
The AuditLogger plugin was supposed to continue logging events on the async queue for up to 30 seconds, but once the last event was pulled from the queue, the wait loop would end and shut down the thread, causing shutdown to happen before the last event on the queue was logged.

Will commit a fix to master soon.

--
Jan Høydahl, search solution architect
Cominvent AS - www.cominvent.com

> 29. apr. 2019 kl. 23:02 skrev Jan Høydahl <jan.asf@cominvent.com>:
> 
> This test is still unstable after hardening attempt, will probably bad-apple it if I cannot spot what's wrong soon.
> 
> --
> Jan Høydahl, search solution architect
> Cominvent AS - www.cominvent.com <http://www.cominvent.com/>
> 
>> 29. apr. 2019 kl. 01:09 skrev Apache Jenkins Server <jenkins@builds.apache.org <mailto:jenkins@builds.apache.org>>:
>> 
>> Build: https://builds.apache.org/job/Lucene-Solr-Tests-8.x/173/ <https://builds.apache.org/job/Lucene-Solr-Tests-8.x/173/>
>> 
>> 1 tests failed.
>> FAILED:  org.apache.solr.security.AuditLoggerIntegrationTest.testAsyncQueueDrain
>> 
>> Error Message:
>> Failed waiting for 3 callbacks after 30 seconds
>> 
>> Stack Trace:
>> java.lang.AssertionError: Failed waiting for 3 callbacks after 30 seconds
>> 	at __randomizedtesting.SeedInfo.seed([F4F92CA55A0CAED9:45E6D381EACF3D06]:0)
>> 	at org.junit.Assert.fail(Assert.java:88)
>> 	at org.apache.solr.security.AuditLoggerIntegrationTest.waitForAuditEventCallbacks(AuditLoggerIntegrationTest.java:229)
>> 	at org.apache.solr.security.AuditLoggerIntegrationTest.waitForAuditEventCallbacks(AuditLoggerIntegrationTest.java:221)
>> 	at org.apache.solr.security.AuditLoggerIntegrationTest.assertThreeAdminEvents(AuditLoggerIntegrationTest.java:252)
>> 	at org.apache.solr.security.AuditLoggerIntegrationTest.testAsyncQueueDrain(AuditLoggerIntegrationTest.java:132)
>> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>> 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
>> 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
>> 	at java.lang.reflect.Method.invoke(Method.java:498)
>> 	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1750)
>> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:938)
>> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:974)
>> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:988)
>> 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
>> 	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
>> 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
>> 	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
>> 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
>> 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
>> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
>> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
>> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
>> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
>> 	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:947)
>> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:832)
>> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:883)
>> 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:894)
>> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
>> 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
>> 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
>> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
>> 	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
>> 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
>> 	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
>> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
>> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
>> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
>> 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
>> 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
>> 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
>> 	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
>> 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
>> 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
>> 	at java.lang.Thread.run(Thread.java:748)
>> 
>> 
>> 
>> 
>> Build Log:
>> [...truncated 14418 lines...]
>>   [junit4] Suite: org.apache.solr.security.AuditLoggerIntegrationTest
>>   [junit4]   2> Creating dataDir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/init-core-data-001
>>   [junit4]   2> 2937130 WARN  (SUITE-AuditLoggerIntegrationTest-seed#[F4F92CA55A0CAED9]-worker) [    ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=17 numCloses=17
>>   [junit4]   2> 2937130 INFO  (SUITE-AuditLoggerIntegrationTest-seed#[F4F92CA55A0CAED9]-worker) [    ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true
>>   [junit4]   2> 2937144 INFO  (SUITE-AuditLoggerIntegrationTest-seed#[F4F92CA55A0CAED9]-worker) [    ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl=None)
>>   [junit4]   2> 2937144 INFO  (SUITE-AuditLoggerIntegrationTest-seed#[F4F92CA55A0CAED9]-worker) [    ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
>>   [junit4]   2> 2937367 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Starting testQueuedTimeMetric
>>   [junit4]   2> 2937403 INFO  (auditTestCallback-6365-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Listening for audit callbacks on on port 42505
>>   [junit4]   2> 2937404 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1 servers in /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-001
>>   [junit4]   2> 2937404 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
>>   [junit4]   2> 2937439 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
>>   [junit4]   2> 2937439 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Starting server
>>   [junit4]   2> 2937569 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer start zk server on port:37324
>>   [junit4]   2> 2937569 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:37324
>>   [junit4]   2> 2937569 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 37324
>>   [junit4]   2> 2937966 INFO  (zkConnectionManagerCallback-8789-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2937990 INFO  (zkConnectionManagerCallback-8791-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2938003 INFO  (zkConnectionManagerCallback-8793-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2938064 WARN  (jetty-launcher-8794-thread-1) [    ] o.e.j.s.AbstractConnector Ignoring deprecated socket close linger time
>>   [junit4]   2> 2938064 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Start Jetty (original configured port=0)
>>   [junit4]   2> 2938064 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 1 ...
>>   [junit4]   2> 2938064 INFO  (jetty-launcher-8794-thread-1) [    ] o.e.j.s.Server jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 1.8.0_191-b12
>>   [junit4]   2> 2938128 INFO  (jetty-launcher-8794-thread-1) [    ] o.e.j.s.session DefaultSessionIdManager workerName=node0
>>   [junit4]   2> 2938128 INFO  (jetty-launcher-8794-thread-1) [    ] o.e.j.s.session No SessionScavenger set, using defaults
>>   [junit4]   2> 2938128 INFO  (jetty-launcher-8794-thread-1) [    ] o.e.j.s.session node0 Scavenging every 600000ms
>>   [junit4]   2> 2938149 INFO  (jetty-launcher-8794-thread-1) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2ad4c0b3{/solr,null,AVAILABLE}
>>   [junit4]   2> 2938396 INFO  (jetty-launcher-8794-thread-1) [    ] o.e.j.s.AbstractConnector Started ServerConnector@5f4d1142{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:45424}
>>   [junit4]   2> 2938396 INFO  (jetty-launcher-8794-thread-1) [    ] o.e.j.s.Server Started @2938576ms
>>   [junit4]   2> 2938396 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=45424}
>>   [junit4]   2> 2938396 ERROR (jetty-launcher-8794-thread-1) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
>>   [junit4]   2> 2938396 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
>>   [junit4]   2> 2938396 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr™ version 8.1.0
>>   [junit4]   2> 2938396 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
>>   [junit4]   2> 2938396 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null
>>   [junit4]   2> 2938396 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2019-04-28T21:38:41.585Z
>>   [junit4]   2> 2938449 INFO  (zkConnectionManagerCallback-8796-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2938449 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
>>   [junit4]   2> 2940612 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=true]
>>   [junit4]   2> 2940629 WARN  (jetty-launcher-8794-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@58020f7d[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2940688 WARN  (jetty-launcher-8794-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@67f2073e[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2940703 INFO  (jetty-launcher-8794-thread-1) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37324/solr
>>   [junit4]   2> 2940758 INFO  (zkConnectionManagerCallback-8803-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2940777 INFO  (zkConnectionManagerCallback-8805-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2941476 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:45424_solr
>>   [junit4]   2> 2941477 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.c.Overseer Overseer (id=74602024098988037-127.0.0.1:45424_solr-n_0000000000) starting
>>   [junit4]   2> 2941493 INFO  (zkConnectionManagerCallback-8812-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2941495 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:37324/solr ready
>>   [junit4]   2> 2941512 INFO  (OverseerStateUpdate-74602024098988037-127.0.0.1:45424_solr-n_0000000000) [n:127.0.0.1:45424_solr    ] o.a.s.c.Overseer Starting to work on the main queue : 127.0.0.1:45424_solr
>>   [junit4]   2> 2941513 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45424_solr
>>   [junit4]   2> 2941528 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.c.CoreContainer Initializing auditlogger plugin: solr.CallbackAuditLoggerPlugin
>>   [junit4]   2> 2941548 INFO  (zkCallback-8811-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2941549 INFO  (zkCallback-8804-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2941998 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
>>   [junit4]   2> 2942366 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_45424.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2942438 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_45424.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2942439 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_45424.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2942452 INFO  (jetty-launcher-8794-thread-1) [n:127.0.0.1:45424_solr    ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-001/node1/.
>>   [junit4]   2> 2942914 INFO  (zkConnectionManagerCallback-8819-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2943007 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2943080 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:37324/solr ready
>>   [junit4]   2> 2943219 INFO  (qtp964655037-20098) [n:127.0.0.1:45424_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2943219 INFO  (qtp964655037-20098) [n:127.0.0.1:45424_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
>>   [junit4]   2> 2943348 INFO  (audit-8813-thread-1-processing-n:127.0.0.1:45424_solr) [n:127.0.0.1:45424_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sleeping for 100ms before sending callback
>>   [junit4]   2> 2943349 INFO  (qtp964655037-20098) [n:127.0.0.1:45424_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :clusterstatus with params action=CLUSTERSTATUS&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2943420 INFO  (qtp964655037-20098) [n:127.0.0.1:45424_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=CLUSTERSTATUS&wt=javabin&version=2} status=0 QTime=71
>>   [junit4]   2> 2943421 INFO  (qtp964655037-20099) [n:127.0.0.1:45424_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :overseerstatus with params action=OVERSEERSTATUS&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2943730 INFO  (qtp964655037-20099) [n:127.0.0.1:45424_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=OVERSEERSTATUS&wt=javabin&version=2} status=0 QTime=308
>>   [junit4]   2> 2944096 INFO  (audit-8813-thread-1-processing-n:127.0.0.1:45424_solr) [n:127.0.0.1:45424_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:45424/solr/admin/collections <http://127.0.0.1:45424/solr/admin/collections>","nodeName":"n:127.0.0.1:45424_solr","message":"Completed","level":"INFO","date":1556487526408,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:45424"},"solrParams":{"action":["LIST"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":45424,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=LIST&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":0.0} to localhost:42505
>>   [junit4]   2> 2944096 INFO  (audit-8813-thread-1-processing-n:127.0.0.1:45424_solr) [n:127.0.0.1:45424_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sleeping for 100ms before sending callback
>>   [junit4]   2> 2944315 INFO  (audit-8813-thread-1-processing-n:127.0.0.1:45424_solr) [n:127.0.0.1:45424_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:45424/solr/admin/collections <http://127.0.0.1:45424/solr/admin/collections>","nodeName":"n:127.0.0.1:45424_solr","message":"Completed","level":"INFO","date":1556487526609,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:45424"},"solrParams":{"action":["CLUSTERSTATUS"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":45424,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=CLUSTERSTATUS&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":71.0} to localhost:42505
>>   [junit4]   2> 2944315 INFO  (audit-8813-thread-1-processing-n:127.0.0.1:45424_solr) [n:127.0.0.1:45424_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sleeping for 100ms before sending callback
>>   [junit4]   2> 2944607 INFO  (audit-8813-thread-1-processing-n:127.0.0.1:45424_solr) [n:127.0.0.1:45424_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:45424/solr/admin/collections <http://127.0.0.1:45424/solr/admin/collections>","nodeName":"n:127.0.0.1:45424_solr","message":"Completed","level":"INFO","date":1556487526919,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:45424"},"solrParams":{"action":["OVERSEERSTATUS"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":45424,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=OVERSEERSTATUS&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":308.0} to localhost:42505
>>   [junit4]   2> 2945636 INFO  (auditTestCallback-6365-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2945705 INFO  (OverseerCollectionConfigSetProcessor-74602024098988037-127.0.0.1:45424_solr-n_0000000000) [n:127.0.0.1:45424_solr    ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist.  Requestor may have disconnected from ZooKeeper
>>   [junit4]   2> 2945710 INFO  (auditTestCallback-6365-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2945769 INFO  (auditTestCallback-6365-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2945892 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1948034237
>>   [junit4]   2> 2945892 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:45424_solr
>>   [junit4]   2> 2945893 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.c.ZkController Publish this node as DOWN...
>>   [junit4]   2> 2945893 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.c.ZkController Publish node=127.0.0.1:45424_solr as DOWN
>>   [junit4]   2> 2946074 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
>>   [junit4]   2> 2946114 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
>>   [junit4]   2> 2946114 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@5cba5cb7: rootName = solr_45424, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@5696f07f
>>   [junit4]   2> 2946131 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
>>   [junit4]   2> 2946131 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@509b7314: rootName = solr_45424, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@bed605b
>>   [junit4]   2> 2946133 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
>>   [junit4]   2> 2946133 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@10ad156a: rootName = solr_45424, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@2a405f
>>   [junit4]   2> 2946133 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
>>   [junit4]   2> 2946199 INFO  (closeThreadPool-8824-thread-1) [    ] o.a.s.c.Overseer Overseer (id=74602024098988037-127.0.0.1:45424_solr-n_0000000000) closing
>>   [junit4]   2> 2946199 INFO  (OverseerStateUpdate-74602024098988037-127.0.0.1:45424_solr-n_0000000000) [n:127.0.0.1:45424_solr    ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:45424_solr
>>   [junit4]   2> 2946329 INFO  (OverseerAutoScalingTriggerThread-74602024098988037-127.0.0.1:45424_solr-n_0000000000) [    ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
>>   [junit4]   2> 2946422 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.c.Overseer Overseer (id=74602024098988037-127.0.0.1:45424_solr-n_0000000000) closing
>>   [junit4]   2> 2946422 INFO  (closeThreadPool-8824-thread-2) [    ] o.a.s.c.Overseer Overseer (id=74602024098988037-127.0.0.1:45424_solr-n_0000000000) closing
>>   [junit4]   2> 2946435 INFO  (jetty-closer-8820-thread-1) [    ] o.a.s.s.AuditLoggerPlugin Shutting down async Auditlogger background thread(s)
>>   [junit4]   2> 2946436 WARN  (audit-8813-thread-1-processing-n:127.0.0.1:45424_solr) [n:127.0.0.1:45424_solr    ] o.a.s.s.AuditLoggerPlugin Interrupted while waiting for next audit log event
>>   [junit4]   2> 2946629 INFO  (jetty-closer-8820-thread-1) [    ] o.e.j.s.AbstractConnector Stopped ServerConnector@5f4d1142{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:0}
>>   [junit4]   2> 2946827 INFO  (jetty-closer-8820-thread-1) [    ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@2ad4c0b3{/solr,null,UNAVAILABLE}
>>   [junit4]   2> 2946858 INFO  (jetty-closer-8820-thread-1) [    ] o.e.j.s.session node0 Stopped scavenging
>>   [junit4]   2> 2946892 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer Shutting down ZkTestServer.
>>   [junit4]   2> 2946994 WARN  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Watch limit violations: 
>>   [junit4]   2> Maximum concurrent create/delete watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/aliases.json
>>   [junit4]   2> 	3	/solr/clusterprops.json
>>   [junit4]   2> 
>>   [junit4]   2> Maximum concurrent data watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/clusterstate.json
>>   [junit4]   2> 
>>   [junit4]   2> Maximum concurrent children watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/live_nodes
>>   [junit4]   2> 	3	/solr/collections
>>   [junit4]   2> 
>>   [junit4]   2> 2947419 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:37324
>>   [junit4]   2> 2947419 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 37324
>>   [junit4]   2> 2947420 INFO  (TEST-AuditLoggerIntegrationTest.testQueuedTimeMetric-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Ending testQueuedTimeMetric
>>   [junit4]   2> 2947472 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Starting testMuteAdminListCollections
>>   [junit4]   2> 2947492 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1 servers in /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-002
>>   [junit4]   2> 2947492 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
>>   [junit4]   2> 2947493 INFO  (auditTestCallback-6380-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Listening for audit callbacks on on port 33079
>>   [junit4]   2> 2947512 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
>>   [junit4]   2> 2947512 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Starting server
>>   [junit4]   2> 2947621 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer start zk server on port:46623
>>   [junit4]   2> 2947621 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:46623
>>   [junit4]   2> 2947621 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 46623
>>   [junit4]   2> 2947690 INFO  (zkConnectionManagerCallback-8826-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2947767 INFO  (zkConnectionManagerCallback-8828-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2947787 INFO  (zkConnectionManagerCallback-8830-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2947822 WARN  (jetty-launcher-8831-thread-1) [    ] o.e.j.s.AbstractConnector Ignoring deprecated socket close linger time
>>   [junit4]   2> 2947822 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Start Jetty (original configured port=0)
>>   [junit4]   2> 2947822 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 1 ...
>>   [junit4]   2> 2947822 INFO  (jetty-launcher-8831-thread-1) [    ] o.e.j.s.Server jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 1.8.0_191-b12
>>   [junit4]   2> 2947965 INFO  (jetty-launcher-8831-thread-1) [    ] o.e.j.s.session DefaultSessionIdManager workerName=node0
>>   [junit4]   2> 2947965 INFO  (jetty-launcher-8831-thread-1) [    ] o.e.j.s.session No SessionScavenger set, using defaults
>>   [junit4]   2> 2947965 INFO  (jetty-launcher-8831-thread-1) [    ] o.e.j.s.session node0 Scavenging every 660000ms
>>   [junit4]   2> 2947982 INFO  (jetty-launcher-8831-thread-1) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@5cad5c17{/solr,null,AVAILABLE}
>>   [junit4]   2> 2948002 INFO  (jetty-launcher-8831-thread-1) [    ] o.e.j.s.AbstractConnector Started ServerConnector@1d092fc{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:33110}
>>   [junit4]   2> 2948002 INFO  (jetty-launcher-8831-thread-1) [    ] o.e.j.s.Server Started @2948182ms
>>   [junit4]   2> 2948002 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=33110}
>>   [junit4]   2> 2948002 ERROR (jetty-launcher-8831-thread-1) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
>>   [junit4]   2> 2948002 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
>>   [junit4]   2> 2948002 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr™ version 8.1.0
>>   [junit4]   2> 2948002 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
>>   [junit4]   2> 2948002 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null
>>   [junit4]   2> 2948002 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2019-04-28T21:38:51.191Z
>>   [junit4]   2> 2948091 INFO  (zkConnectionManagerCallback-8833-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2948092 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
>>   [junit4]   2> 2949248 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=true]
>>   [junit4]   2> 2949259 WARN  (jetty-launcher-8831-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@6ba51d62[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2949281 WARN  (jetty-launcher-8831-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@4927529e[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2949282 INFO  (jetty-launcher-8831-thread-1) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:46623/solr
>>   [junit4]   2> 2949298 INFO  (zkConnectionManagerCallback-8840-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2949312 INFO  (zkConnectionManagerCallback-8842-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2949727 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:33110_solr
>>   [junit4]   2> 2949727 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.c.Overseer Overseer (id=74602024758804485-127.0.0.1:33110_solr-n_0000000000) starting
>>   [junit4]   2> 2949741 INFO  (zkConnectionManagerCallback-8849-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2949742 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:46623/solr ready
>>   [junit4]   2> 2949765 INFO  (OverseerStateUpdate-74602024758804485-127.0.0.1:33110_solr-n_0000000000) [n:127.0.0.1:33110_solr    ] o.a.s.c.Overseer Starting to work on the main queue : 127.0.0.1:33110_solr
>>   [junit4]   2> 2949781 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33110_solr
>>   [junit4]   2> 2949784 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.c.CoreContainer Initializing auditlogger plugin: solr.CallbackAuditLoggerPlugin
>>   [junit4]   2> 2949817 INFO  (zkCallback-8848-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2949829 INFO  (zkCallback-8841-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2949889 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
>>   [junit4]   2> 2949961 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_33110.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2950033 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_33110.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2950052 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_33110.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2950053 INFO  (jetty-launcher-8831-thread-1) [n:127.0.0.1:33110_solr    ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-002/node1/.
>>   [junit4]   2> 2950186 INFO  (zkConnectionManagerCallback-8855-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2950187 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2950188 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:46623/solr ready
>>   [junit4]   2> 2950239 INFO  (qtp102589823-20171) [n:127.0.0.1:33110_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2950239 INFO  (qtp102589823-20171) [n:127.0.0.1:33110_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
>>   [junit4]   2> 2950267 INFO  (qtp102589823-20172) [n:127.0.0.1:33110_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :clusterstatus with params action=CLUSTERSTATUS&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2950268 INFO  (qtp102589823-20172) [n:127.0.0.1:33110_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=CLUSTERSTATUS&wt=javabin&version=2} status=0 QTime=0
>>   [junit4]   2> 2950463 INFO  (qtp102589823-20172) [n:127.0.0.1:33110_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:33110/solr/admin/collections <http://127.0.0.1:33110/solr/admin/collections>","nodeName":"n:127.0.0.1:33110_solr","message":"Completed","level":"INFO","date":1556487533457,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:33110"},"solrParams":{"action":["CLUSTERSTATUS"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":33110,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=CLUSTERSTATUS&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":0.0} to localhost:33079
>>   [junit4]   2> 2950465 INFO  (qtp102589823-20173) [n:127.0.0.1:33110_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :overseerstatus with params action=OVERSEERSTATUS&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2950820 INFO  (auditTestCallback-6380-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2950928 INFO  (qtp102589823-20173) [n:127.0.0.1:33110_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=OVERSEERSTATUS&wt=javabin&version=2} status=0 QTime=462
>>   [junit4]   2> 2951259 INFO  (qtp102589823-20173) [n:127.0.0.1:33110_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:33110/solr/admin/collections <http://127.0.0.1:33110/solr/admin/collections>","nodeName":"n:127.0.0.1:33110_solr","message":"Completed","level":"INFO","date":1556487534117,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:33110"},"solrParams":{"action":["OVERSEERSTATUS"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":33110,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=OVERSEERSTATUS&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":462.0} to localhost:33079
>>   [junit4]   2> 2951339 INFO  (auditTestCallback-6380-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2951471 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=277853560
>>   [junit4]   2> 2951471 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:33110_solr
>>   [junit4]   2> 2951507 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.c.ZkController Publish this node as DOWN...
>>   [junit4]   2> 2951507 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.c.ZkController Publish node=127.0.0.1:33110_solr as DOWN
>>   [junit4]   2> 2951799 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
>>   [junit4]   2> 2951855 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
>>   [junit4]   2> 2951855 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@75690a4e: rootName = solr_33110, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@20d09551
>>   [junit4]   2> 2951858 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
>>   [junit4]   2> 2951858 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@2d7f9379: rootName = solr_33110, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@bed605b
>>   [junit4]   2> 2951893 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
>>   [junit4]   2> 2951893 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@481a4331: rootName = solr_33110, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@2a405f
>>   [junit4]   2> 2951893 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
>>   [junit4]   2> 2951940 INFO  (closeThreadPool-8860-thread-2) [    ] o.a.s.c.Overseer Overseer (id=74602024758804485-127.0.0.1:33110_solr-n_0000000000) closing
>>   [junit4]   2> 2951955 INFO  (zkCallback-8848-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
>>   [junit4]   2> 2952110 INFO  (OverseerStateUpdate-74602024758804485-127.0.0.1:33110_solr-n_0000000000) [n:127.0.0.1:33110_solr    ] o.a.s.c.Overseer According to ZK I (id=74602024758804485-127.0.0.1:33110_solr-n_0000000000) am no longer a leader. propsId=null
>>   [junit4]   2> 2952110 INFO  (OverseerStateUpdate-74602024758804485-127.0.0.1:33110_solr-n_0000000000) [n:127.0.0.1:33110_solr    ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:33110_solr
>>   [junit4]   2> 2952146 INFO  (OverseerAutoScalingTriggerThread-74602024758804485-127.0.0.1:33110_solr-n_0000000000) [    ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
>>   [junit4]   2> 2952349 INFO  (closeThreadPool-8860-thread-1) [    ] o.a.s.c.Overseer Overseer (id=74602024758804485-127.0.0.1:33110_solr-n_0000000000) closing
>>   [junit4]   2> 2952365 INFO  (jetty-closer-8856-thread-1) [    ] o.a.s.c.Overseer Overseer (id=74602024758804485-127.0.0.1:33110_solr-n_0000000000) closing
>>   [junit4]   2> 2952511 INFO  (jetty-closer-8856-thread-1) [    ] o.e.j.s.AbstractConnector Stopped ServerConnector@1d092fc{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:0}
>>   [junit4]   2> 2952640 INFO  (jetty-closer-8856-thread-1) [    ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@5cad5c17{/solr,null,UNAVAILABLE}
>>   [junit4]   2> 2952718 INFO  (jetty-closer-8856-thread-1) [    ] o.e.j.s.session node0 Stopped scavenging
>>   [junit4]   2> 2952823 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer Shutting down ZkTestServer.
>>   [junit4]   2> 2952824 WARN  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Watch limit violations: 
>>   [junit4]   2> Maximum concurrent create/delete watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/aliases.json
>>   [junit4]   2> 	3	/solr/clusterprops.json
>>   [junit4]   2> 
>>   [junit4]   2> Maximum concurrent data watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/clusterstate.json
>>   [junit4]   2> 
>>   [junit4]   2> Maximum concurrent children watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/live_nodes
>>   [junit4]   2> 	3	/solr/collections
>>   [junit4]   2> 
>>   [junit4]   2> 2952934 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:46623
>>   [junit4]   2> 2952934 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 46623
>>   [junit4]   2> 2952935 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer Shutting down ZkTestServer.
>>   [junit4]   2> 2952935 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:46623
>>   [junit4]   2> 2952935 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 46623
>>   [junit4]   2> 2952935 INFO  (TEST-AuditLoggerIntegrationTest.testMuteAdminListCollections-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Ending testMuteAdminListCollections
>>   [junit4]   2> 2953151 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Starting auth
>>   [junit4]   2> 2953184 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1 servers in /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-003
>>   [junit4]   2> 2953185 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
>>   [junit4]   2> 2953185 INFO  (auditTestCallback-6395-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Listening for audit callbacks on on port 36650
>>   [junit4]   2> 2953205 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
>>   [junit4]   2> 2953205 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Starting server
>>   [junit4]   2> 2953293 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer start zk server on port:46132
>>   [junit4]   2> 2953293 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:46132
>>   [junit4]   2> 2953293 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 46132
>>   [junit4]   2> 2953422 INFO  (zkConnectionManagerCallback-8863-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2953479 INFO  (zkConnectionManagerCallback-8865-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2953481 INFO  (zkConnectionManagerCallback-8867-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2953496 WARN  (jetty-launcher-8868-thread-1) [    ] o.e.j.s.AbstractConnector Ignoring deprecated socket close linger time
>>   [junit4]   2> 2953496 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Start Jetty (original configured port=0)
>>   [junit4]   2> 2953497 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 1 ...
>>   [junit4]   2> 2953497 INFO  (jetty-launcher-8868-thread-1) [    ] o.e.j.s.Server jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 1.8.0_191-b12
>>   [junit4]   2> 2953584 INFO  (jetty-launcher-8868-thread-1) [    ] o.e.j.s.session DefaultSessionIdManager workerName=node0
>>   [junit4]   2> 2953584 INFO  (jetty-launcher-8868-thread-1) [    ] o.e.j.s.session No SessionScavenger set, using defaults
>>   [junit4]   2> 2953584 INFO  (jetty-launcher-8868-thread-1) [    ] o.e.j.s.session node0 Scavenging every 600000ms
>>   [junit4]   2> 2953585 INFO  (jetty-launcher-8868-thread-1) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2c166ff9{/solr,null,AVAILABLE}
>>   [junit4]   2> 2953585 INFO  (jetty-launcher-8868-thread-1) [    ] o.e.j.s.AbstractConnector Started ServerConnector@17a50bf9{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:34190}
>>   [junit4]   2> 2953585 INFO  (jetty-launcher-8868-thread-1) [    ] o.e.j.s.Server Started @2953765ms
>>   [junit4]   2> 2953585 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34190}
>>   [junit4]   2> 2953585 ERROR (jetty-launcher-8868-thread-1) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
>>   [junit4]   2> 2953585 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
>>   [junit4]   2> 2953585 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr™ version 8.1.0
>>   [junit4]   2> 2953586 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
>>   [junit4]   2> 2953586 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null
>>   [junit4]   2> 2953586 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2019-04-28T21:38:56.775Z
>>   [junit4]   2> 2953600 INFO  (zkConnectionManagerCallback-8870-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2953605 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
>>   [junit4]   2> 2954708 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=true]
>>   [junit4]   2> 2954740 WARN  (jetty-launcher-8868-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@569997e4[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2954773 WARN  (jetty-launcher-8868-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@2695a349[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2954774 INFO  (jetty-launcher-8868-thread-1) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:46132/solr
>>   [junit4]   2> 2954840 INFO  (zkConnectionManagerCallback-8877-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2954884 INFO  (zkConnectionManagerCallback-8879-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2955280 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:34190_solr
>>   [junit4]   2> 2955280 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.c.Overseer Overseer (id=74602025133146117-127.0.0.1:34190_solr-n_0000000000) starting
>>   [junit4]   2> 2955314 INFO  (zkConnectionManagerCallback-8886-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2955315 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:46132/solr ready
>>   [junit4]   2> 2955316 INFO  (OverseerStateUpdate-74602025133146117-127.0.0.1:34190_solr-n_0000000000) [n:127.0.0.1:34190_solr    ] o.a.s.c.Overseer Starting to work on the main queue : 127.0.0.1:34190_solr
>>   [junit4]   2> 2955330 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34190_solr
>>   [junit4]   2> 2955351 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.c.CoreContainer Initializing authorization plugin: solr.RuleBasedAuthorizationPlugin
>>   [junit4]   2> 2955351 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.c.CoreContainer Initializing authentication plugin: solr.BasicAuthPlugin
>>   [junit4]   2> 2955351 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.c.CoreContainer Initializing auditlogger plugin: solr.CallbackAuditLoggerPlugin
>>   [junit4]   2> 2955389 INFO  (zkCallback-8885-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2955424 INFO  (zkCallback-8878-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2955715 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
>>   [junit4]   2> 2955991 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34190.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2956096 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34190.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2956097 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34190.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2956098 INFO  (jetty-launcher-8868-thread-1) [n:127.0.0.1:34190_solr    ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-003/node1/.
>>   [junit4]   2> 2956440 INFO  (zkConnectionManagerCallback-8892-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2956482 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2956497 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:46132/solr ready
>>   [junit4]   2> 2956518 INFO  (qtp1249881293-20243) [n:127.0.0.1:34190_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2956518 INFO  (qtp1249881293-20243) [n:127.0.0.1:34190_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
>>   [junit4]   2> 2956683 INFO  (auditTestCallback-6395-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2956686 INFO  (qtp1249881293-20243) [n:127.0.0.1:34190_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:34190/solr/admin/collections <http://127.0.0.1:34190/solr/admin/collections>","nodeName":"n:127.0.0.1:34190_solr","message":"Completed","level":"INFO","date":1556487539707,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:34190"},"solrParams":{"action":["LIST"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":34190,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=LIST&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":0.0} to localhost:36650
>>   [junit4]   2> 2956700 INFO  (qtp1249881293-20244) [n:127.0.0.1:34190_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2956700 INFO  (qtp1249881293-20244) [n:127.0.0.1:34190_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
>>   [junit4]   2> 2956902 INFO  (qtp1249881293-20244) [n:127.0.0.1:34190_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:34190/solr/admin/collections <http://127.0.0.1:34190/solr/admin/collections>","nodeName":"n:127.0.0.1:34190_solr","message":"Completed","level":"INFO","date":1556487539889,"username":"solr","clientIp":"127.0.0.1","collections":[],"headers":{"Authorization":"Basic c29scjpTb2xyUm9ja3M=","User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:34190"},"solrParams":{"action":["LIST"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":34190,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=LIST&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":0.0} to localhost:36650
>>   [junit4]   2> 2956903 INFO  (qtp1249881293-20244) [n:127.0.0.1:34190_solr    ] o.a.s.s.RuleBasedAuthorizationPlugin request has come without principal. failed permission {
>>   [junit4]   2>   "name":"collection-admin-edit",
>>   [junit4]   2>   "role":"admin"} 
>>   [junit4]   2> 2956956 INFO  (auditTestCallback-6395-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2956974 INFO  (auditTestCallback-6395-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2957143 INFO  (qtp1249881293-20244) [n:127.0.0.1:34190_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:34190/solr/admin/collections <http://127.0.0.1:34190/solr/admin/collections>","nodeName":"n:127.0.0.1:34190_solr","message":"Rejected","level":"WARN","date":1556487540092,"clientIp":"127.0.0.1","collections":["test"],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:34190"},"solrParams":{"pullReplicas":["0"],"name":["test"],"nrtReplicas":["1"],"action":["CREATE"],"numShards":["1"],"tlogReplicas":["0"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":34190,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=CREATE&name=test&numShards=1&nrtReplicas=1&pullReplicas=0&tlogReplicas=0&wt=javabin&version=2","eventType":"REJECTED","requestType":"ADMIN","status":401,"qtime":-1.0} to localhost:36650
>>   [junit4]   2> 2957143 INFO  (qtp1249881293-20244) [n:127.0.0.1:34190_solr    ] o.a.s.s.HttpSolrCall USER_REQUIRED auth header null context : userPrincipal: [null] type: [ADMIN], collections: [test,], Path: [/admin/collections] path : /admin/collections params :pullReplicas=0&name=test&nrtReplicas=1&action=CREATE&numShards=1&tlogReplicas=0&wt=javabin&version=2 
>>   [junit4]   2> 2957233 INFO  (qtp1249881293-20244) [n:127.0.0.1:34190_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:34190/solr/admin/collections <http://127.0.0.1:34190/solr/admin/collections>","nodeName":"n:127.0.0.1:34190_solr","message":"Unauthorized","level":"WARN","date":1556487540332,"clientIp":"127.0.0.1","collections":["test"],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:34190"},"solrParams":{"pullReplicas":["0"],"name":["test"],"nrtReplicas":["1"],"action":["CREATE"],"numShards":["1"],"tlogReplicas":["0"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":34190,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=CREATE&name=test&numShards=1&nrtReplicas=1&pullReplicas=0&tlogReplicas=0&wt=javabin&version=2","eventType":"UNAUTHORIZED","requestType":"ADMIN","status":403,"qtime":-1.0} to localhost:36650
>>   [junit4]   1> {"requestUrl":"http://127.0.0.1:34190/solr/admin/collections <http://127.0.0.1:34190/solr/admin/collections>","nodeName":"n:127.0.0.1:34190_solr","message":"Completed","level":"INFO","date":1556487539889,"username":"solr","clientIp":"127.0.0.1","collections":[],"headers":{"Authorization":"Basic c29scjpTb2xyUm9ja3M=","User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:34190"},"solrParams":{"action":["LIST"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":34190,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=LIST&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":0.0}
>>   [junit4]   2> 2957344 INFO  (qtp1249881293-20245) [    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:34190/solr/admin/collections <http://127.0.0.1:34190/solr/admin/collections>","message":"Rejected","level":"WARN","date":1556487540497,"clientIp":"127.0.0.1","headers":{"Authorization":"Basic c29scjp3cm9uZ1BX","User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:34190"},"solrParams":{},"solrHost":"127.0.0.1","solrPort":34190,"solrIp":"127.0.0.1","resource":"/solr","httpMethod":"GET","httpQueryString":"action=CREATE&name=test&numShards=1&nrtReplicas=1&pullReplicas=0&tlogReplicas=0&wt=javabin&version=2","eventType":"REJECTED","requestType":"UNKNOWN","status":401,"qtime":-1.0} to localhost:36650
>>   [junit4]   2> 2957347 INFO  (auditTestCallback-6395-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2957442 INFO  (auditTestCallback-6395-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /solr
>>   [junit4]   2> 2957543 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1135288726
>>   [junit4]   2> 2957543 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:34190_solr
>>   [junit4]   2> 2957563 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.c.ZkController Publish this node as DOWN...
>>   [junit4]   2> 2957563 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.c.ZkController Publish node=127.0.0.1:34190_solr as DOWN
>>   [junit4]   2> 2957697 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
>>   [junit4]   2> 2957733 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
>>   [junit4]   2> 2957733 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@38df0c3a: rootName = solr_34190, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@12028acd
>>   [junit4]   2> 2957737 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
>>   [junit4]   2> 2957737 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1a45a3e3: rootName = solr_34190, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@bed605b
>>   [junit4]   2> 2957738 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
>>   [junit4]   2> 2957738 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1c6a21b3: rootName = solr_34190, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@2a405f
>>   [junit4]   2> 2957738 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
>>   [junit4]   2> 2957754 INFO  (jetty-closer-8893-thread-1) [    ] o.a.s.c.Overseer Overseer (id=74602025133146117-127.0.0.1:34190_solr-n_0000000000) closing
>>   [junit4]   2> 2957755 INFO  (OverseerStateUpdate-74602025133146117-127.0.0.1:34190_solr-n_0000000000) [n:127.0.0.1:34190_solr    ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:34190_solr
>>   [junit4]   2> 2957769 INFO  (OverseerAutoScalingTriggerThread-74602025133146117-127.0.0.1:34190_solr-n_0000000000) [    ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
>>   [junit4]   2> 2957859 INFO  (zkCallback-8885-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
>>   [junit4]   2> 2957917 INFO  (closeThreadPool-8897-thread-1) [    ] o.a.s.c.Overseer Overseer (id=74602025133146117-127.0.0.1:34190_solr-n_0000000000) closing
>>   [junit4]   2> 2957917 INFO  (closeThreadPool-8897-thread-2) [    ] o.a.s.c.Overseer Overseer (id=74602025133146117-127.0.0.1:34190_solr-n_0000000000) closing
>>   [junit4]   2> 2958130 INFO  (jetty-closer-8893-thread-1) [    ] o.e.j.s.AbstractConnector Stopped ServerConnector@17a50bf9{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:0}
>>   [junit4]   2> 2958130 INFO  (jetty-closer-8893-thread-1) [    ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@2c166ff9{/solr,null,UNAVAILABLE}
>>   [junit4]   2> 2958131 INFO  (jetty-closer-8893-thread-1) [    ] o.e.j.s.session node0 Stopped scavenging
>>   [junit4]   2> 2958163 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer Shutting down ZkTestServer.
>>   [junit4]   2> 2958184 WARN  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Watch limit violations: 
>>   [junit4]   2> Maximum concurrent create/delete watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/aliases.json
>>   [junit4]   2> 	3	/solr/clusterprops.json
>>   [junit4]   2> 
>>   [junit4]   2> Maximum concurrent data watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/clusterstate.json
>>   [junit4]   2> 
>>   [junit4]   2> Maximum concurrent children watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/live_nodes
>>   [junit4]   2> 	3	/solr/collections
>>   [junit4]   2> 
>>   [junit4]   2> 2958186 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:46132
>>   [junit4]   2> 2958186 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 46132
>>   [junit4]   2> 2958219 INFO  (TEST-AuditLoggerIntegrationTest.auth-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Ending auth
>>   [junit4]   2> 2958347 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Starting testAsync
>>   [junit4]   2> 2958353 INFO  (auditTestCallback-6410-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Listening for audit callbacks on on port 38508
>>   [junit4]   2> 2958354 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1 servers in /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-004
>>   [junit4]   2> 2958354 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
>>   [junit4]   2> 2958354 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
>>   [junit4]   2> 2958354 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Starting server
>>   [junit4]   2> 2958466 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer start zk server on port:46436
>>   [junit4]   2> 2958466 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:46436
>>   [junit4]   2> 2958466 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 46436
>>   [junit4]   2> 2958571 INFO  (zkConnectionManagerCallback-8899-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2958608 INFO  (zkConnectionManagerCallback-8901-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2958628 INFO  (zkConnectionManagerCallback-8903-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2958630 WARN  (jetty-launcher-8904-thread-1) [    ] o.e.j.s.AbstractConnector Ignoring deprecated socket close linger time
>>   [junit4]   2> 2958631 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Start Jetty (original configured port=0)
>>   [junit4]   2> 2958631 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 1 ...
>>   [junit4]   2> 2958631 INFO  (jetty-launcher-8904-thread-1) [    ] o.e.j.s.Server jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 1.8.0_191-b12
>>   [junit4]   2> 2958671 INFO  (jetty-launcher-8904-thread-1) [    ] o.e.j.s.session DefaultSessionIdManager workerName=node0
>>   [junit4]   2> 2958671 INFO  (jetty-launcher-8904-thread-1) [    ] o.e.j.s.session No SessionScavenger set, using defaults
>>   [junit4]   2> 2958671 INFO  (jetty-launcher-8904-thread-1) [    ] o.e.j.s.session node0 Scavenging every 660000ms
>>   [junit4]   2> 2958671 INFO  (jetty-launcher-8904-thread-1) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@20ac2cc2{/solr,null,AVAILABLE}
>>   [junit4]   2> 2958681 INFO  (jetty-launcher-8904-thread-1) [    ] o.e.j.s.AbstractConnector Started ServerConnector@3c04b9c8{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:40835}
>>   [junit4]   2> 2958681 INFO  (jetty-launcher-8904-thread-1) [    ] o.e.j.s.Server Started @2958861ms
>>   [junit4]   2> 2958681 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=40835}
>>   [junit4]   2> 2958681 ERROR (jetty-launcher-8904-thread-1) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
>>   [junit4]   2> 2958681 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
>>   [junit4]   2> 2958681 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr™ version 8.1.0
>>   [junit4]   2> 2958681 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
>>   [junit4]   2> 2958682 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null
>>   [junit4]   2> 2958682 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2019-04-28T21:39:01.871Z
>>   [junit4]   2> 2958701 INFO  (zkConnectionManagerCallback-8906-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2958701 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
>>   [junit4]   2> 2959120 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=true]
>>   [junit4]   2> 2959156 WARN  (jetty-launcher-8904-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@59400247[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2959200 WARN  (jetty-launcher-8904-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@6e6efc07[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2959201 INFO  (jetty-launcher-8904-thread-1) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:46436/solr
>>   [junit4]   2> 2959220 INFO  (zkConnectionManagerCallback-8913-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2959256 INFO  (zkConnectionManagerCallback-8915-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2960150 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:40835_solr
>>   [junit4]   2> 2960150 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.c.Overseer Overseer (id=74602025468362757-127.0.0.1:40835_solr-n_0000000000) starting
>>   [junit4]   2> 2960213 INFO  (zkConnectionManagerCallback-8922-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2960270 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:46436/solr ready
>>   [junit4]   2> 2960322 INFO  (OverseerStateUpdate-74602025468362757-127.0.0.1:40835_solr-n_0000000000) [n:127.0.0.1:40835_solr    ] o.a.s.c.Overseer Starting to work on the main queue : 127.0.0.1:40835_solr
>>   [junit4]   2> 2960346 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40835_solr
>>   [junit4]   2> 2960380 INFO  (zkCallback-8914-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2960380 INFO  (zkCallback-8921-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2960435 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.c.CoreContainer Initializing auditlogger plugin: solr.CallbackAuditLoggerPlugin
>>   [junit4]   2> 2960614 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
>>   [junit4]   2> 2960833 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40835.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2960942 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40835.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2960942 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40835.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@74ed8068
>>   [junit4]   2> 2960943 INFO  (jetty-launcher-8904-thread-1) [n:127.0.0.1:40835_solr    ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-004/node1/.
>>   [junit4]   2> 2961088 INFO  (zkConnectionManagerCallback-8929-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2961089 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
>>   [junit4]   2> 2961090 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:46436/solr ready
>>   [junit4]   2> 2961181 INFO  (qtp448790952-20315) [n:127.0.0.1:40835_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2961181 INFO  (qtp448790952-20315) [n:127.0.0.1:40835_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
>>   [junit4]   2> 2961290 INFO  (qtp448790952-20316) [n:127.0.0.1:40835_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :clusterstatus with params action=CLUSTERSTATUS&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2961343 INFO  (qtp448790952-20316) [n:127.0.0.1:40835_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=CLUSTERSTATUS&wt=javabin&version=2} status=0 QTime=53
>>   [junit4]   2> 2961355 INFO  (qtp448790952-20317) [n:127.0.0.1:40835_solr    ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :overseerstatus with params action=OVERSEERSTATUS&wt=javabin&version=2 and sendToOCPQueue=true
>>   [junit4]   2> 2961520 INFO  (audit-8923-thread-1-processing-n:127.0.0.1:40835_solr) [n:127.0.0.1:40835_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:40835/solr/admin/collections <http://127.0.0.1:40835/solr/admin/collections>","nodeName":"n:127.0.0.1:40835_solr","message":"Completed","level":"INFO","date":1556487544370,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:40835"},"solrParams":{"action":["LIST"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":40835,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=LIST&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":0.0} to localhost:38508
>>   [junit4]   2> 2961675 INFO  (auditTestCallback-6410-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2961716 INFO  (auditTestCallback-6410-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2961845 INFO  (audit-8923-thread-1-processing-n:127.0.0.1:40835_solr) [n:127.0.0.1:40835_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:40835/solr/admin/collections <http://127.0.0.1:40835/solr/admin/collections>","nodeName":"n:127.0.0.1:40835_solr","message":"Completed","level":"INFO","date":1556487544533,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:40835"},"solrParams":{"action":["CLUSTERSTATUS"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":40835,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=CLUSTERSTATUS&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":53.0} to localhost:38508
>>   [junit4]   2> 2962019 INFO  (qtp448790952-20317) [n:127.0.0.1:40835_solr    ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=OVERSEERSTATUS&wt=javabin&version=2} status=0 QTime=664
>>   [junit4]   2> 2962225 INFO  (auditTestCallback-6410-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Received audit event for path /admin/collections
>>   [junit4]   2> 2962254 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.SolrCloudAuthTestCase First metrics count assert failed, pausing 2s before re-attempt
>>   [junit4]   2> 2962275 INFO  (audit-8923-thread-1-processing-n:127.0.0.1:40835_solr) [n:127.0.0.1:40835_solr    ] o.a.s.s.CallbackAuditLoggerPlugin Sent audit callback {"requestUrl":"http://127.0.0.1:40835/solr/admin/collections <http://127.0.0.1:40835/solr/admin/collections>","nodeName":"n:127.0.0.1:40835_solr","message":"Completed","level":"INFO","date":1556487545208,"clientIp":"127.0.0.1","collections":[],"headers":{"User-Agent":"Solr[org.apache.solr.client.solrj.impl.HttpSolrClient] 1.0","Connection":"keep-alive","Host":"127.0.0.1:40835"},"solrParams":{"action":["OVERSEERSTATUS"],"wt":["javabin"],"version":["2"]},"solrHost":"127.0.0.1","solrPort":40835,"solrIp":"127.0.0.1","resource":"/admin/collections","httpMethod":"GET","httpQueryString":"action=OVERSEERSTATUS&wt=javabin&version=2","eventType":"COMPLETED","requestType":"ADMIN","status":200,"qtime":664.0} to localhost:38508
>>   [junit4]   2> 2963737 INFO  (OverseerCollectionConfigSetProcessor-74602025468362757-127.0.0.1:40835_solr-n_0000000000) [n:127.0.0.1:40835_solr    ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist.  Requestor may have disconnected from ZooKeeper
>>   [junit4]   2> 2964313 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1874412241
>>   [junit4]   2> 2964313 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:40835_solr
>>   [junit4]   2> 2964313 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.c.ZkController Publish this node as DOWN...
>>   [junit4]   2> 2964313 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.c.ZkController Publish node=127.0.0.1:40835_solr as DOWN
>>   [junit4]   2> 2964385 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
>>   [junit4]   2> 2964386 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
>>   [junit4]   2> 2964386 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@5e185b41: rootName = solr_40835, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@eb47b27
>>   [junit4]   2> 2964423 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
>>   [junit4]   2> 2964423 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1747fcab: rootName = solr_40835, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@bed605b
>>   [junit4]   2> 2964480 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
>>   [junit4]   2> 2964480 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@524facf3: rootName = solr_40835, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@2a405f
>>   [junit4]   2> 2964480 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
>>   [junit4]   2> 2964569 INFO  (closeThreadPool-8934-thread-1) [    ] o.a.s.c.Overseer Overseer (id=74602025468362757-127.0.0.1:40835_solr-n_0000000000) closing
>>   [junit4]   2> 2964569 INFO  (OverseerStateUpdate-74602025468362757-127.0.0.1:40835_solr-n_0000000000) [n:127.0.0.1:40835_solr    ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:40835_solr
>>   [junit4]   2> 2964575 INFO  (OverseerAutoScalingTriggerThread-74602025468362757-127.0.0.1:40835_solr-n_0000000000) [    ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
>>   [junit4]   2> 2964814 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.c.Overseer Overseer (id=74602025468362757-127.0.0.1:40835_solr-n_0000000000) closing
>>   [junit4]   2> 2964814 INFO  (closeThreadPool-8934-thread-2) [    ] o.a.s.c.Overseer Overseer (id=74602025468362757-127.0.0.1:40835_solr-n_0000000000) closing
>>   [junit4]   2> 2964891 INFO  (zkCallback-8921-thread-1) [    ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
>>   [junit4]   2> 2964892 INFO  (jetty-closer-8930-thread-1) [    ] o.a.s.s.AuditLoggerPlugin Shutting down async Auditlogger background thread(s)
>>   [junit4]   2> 2964924 WARN  (audit-8923-thread-1-processing-n:127.0.0.1:40835_solr) [n:127.0.0.1:40835_solr    ] o.a.s.s.AuditLoggerPlugin Interrupted while waiting for next audit log event
>>   [junit4]   2> 2964985 INFO  (jetty-closer-8930-thread-1) [    ] o.e.j.s.AbstractConnector Stopped ServerConnector@3c04b9c8{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:0}
>>   [junit4]   2> 2964985 INFO  (jetty-closer-8930-thread-1) [    ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@20ac2cc2{/solr,null,UNAVAILABLE}
>>   [junit4]   2> 2964986 INFO  (jetty-closer-8930-thread-1) [    ] o.e.j.s.session node0 Stopped scavenging
>>   [junit4]   2> 2965057 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer Shutting down ZkTestServer.
>>   [junit4]   2> 2965179 WARN  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Watch limit violations: 
>>   [junit4]   2> Maximum concurrent create/delete watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/aliases.json
>>   [junit4]   2> 	3	/solr/clusterprops.json
>>   [junit4]   2> 
>>   [junit4]   2> Maximum concurrent data watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/clusterstate.json
>>   [junit4]   2> 
>>   [junit4]   2> Maximum concurrent children watches above limit:
>>   [junit4]   2> 
>>   [junit4]   2> 	3	/solr/live_nodes
>>   [junit4]   2> 	3	/solr/collections
>>   [junit4]   2> 
>>   [junit4]   2> 2965192 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:46436
>>   [junit4]   2> 2965192 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 46436
>>   [junit4]   2> 2965192 INFO  (TEST-AuditLoggerIntegrationTest.testAsync-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Ending testAsync
>>   [junit4]   2> 2965221 INFO  (TEST-AuditLoggerIntegrationTest.searchWithException-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.SolrTestCaseJ4 ###Starting searchWithException
>>   [junit4]   2> 2965222 INFO  (TEST-AuditLoggerIntegrationTest.searchWithException-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 1 servers in /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/build/solr-core/test/J1/temp/solr.security.AuditLoggerIntegrationTest_F4F92CA55A0CAED9-001/tempDir-005
>>   [junit4]   2> 2965222 INFO  (TEST-AuditLoggerIntegrationTest.searchWithException-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
>>   [junit4]   2> 2965223 INFO  (auditTestCallback-6425-thread-1) [    ] o.a.s.s.AuditLoggerIntegrationTest Listening for audit callbacks on on port 45325
>>   [junit4]   2> 2965236 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
>>   [junit4]   2> 2965236 INFO  (ZkTestServer Run Thread) [    ] o.a.s.c.ZkTestServer Starting server
>>   [junit4]   2> 2965336 INFO  (TEST-AuditLoggerIntegrationTest.searchWithException-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer start zk server on port:37398
>>   [junit4]   2> 2965336 INFO  (TEST-AuditLoggerIntegrationTest.searchWithException-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer parse host and port list: 127.0.0.1:37398
>>   [junit4]   2> 2965336 INFO  (TEST-AuditLoggerIntegrationTest.searchWithException-seed#[F4F92CA55A0CAED9]) [    ] o.a.s.c.ZkTestServer connecting to 127.0.0.1 37398
>>   [junit4]   2> 2965612 INFO  (zkConnectionManagerCallback-8936-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2965629 INFO  (zkConnectionManagerCallback-8938-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2965632 INFO  (zkConnectionManagerCallback-8940-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2965644 WARN  (jetty-launcher-8941-thread-1) [    ] o.e.j.s.AbstractConnector Ignoring deprecated socket close linger time
>>   [junit4]   2> 2965644 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Start Jetty (original configured port=0)
>>   [junit4]   2> 2965644 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Trying to start Jetty on port 0 try number 1 ...
>>   [junit4]   2> 2965644 INFO  (jetty-launcher-8941-thread-1) [    ] o.e.j.s.Server jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 1.8.0_191-b12
>>   [junit4]   2> 2965645 INFO  (jetty-launcher-8941-thread-1) [    ] o.e.j.s.session DefaultSessionIdManager workerName=node0
>>   [junit4]   2> 2965645 INFO  (jetty-launcher-8941-thread-1) [    ] o.e.j.s.session No SessionScavenger set, using defaults
>>   [junit4]   2> 2965645 INFO  (jetty-launcher-8941-thread-1) [    ] o.e.j.s.session node0 Scavenging every 660000ms
>>   [junit4]   2> 2965645 INFO  (jetty-launcher-8941-thread-1) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@252f3630{/solr,null,AVAILABLE}
>>   [junit4]   2> 2965645 INFO  (jetty-launcher-8941-thread-1) [    ] o.e.j.s.AbstractConnector Started ServerConnector@7ed08014{HTTP/1.1,[http/1.1, h2c]}{127.0.0.1:35542}
>>   [junit4]   2> 2965645 INFO  (jetty-launcher-8941-thread-1) [    ] o.e.j.s.Server Started @2965825ms
>>   [junit4]   2> 2965645 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=35542}
>>   [junit4]   2> 2965646 ERROR (jetty-launcher-8941-thread-1) [    ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
>>   [junit4]   2> 2965646 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
>>   [junit4]   2> 2965646 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.s.SolrDispatchFilter  ___      _       Welcome to Apache Solr™ version 8.1.0
>>   [junit4]   2> 2965646 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _   Starting in cloud mode on port null
>>   [junit4]   2> 2965646 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_|  Install dir: null
>>   [junit4]   2> 2965646 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.s.SolrDispatchFilter |___/\___/_|_|    Start time: 2019-04-28T21:39:08.835Z
>>   [junit4]   2> 2965647 INFO  (zkConnectionManagerCallback-8943-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2965648 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
>>   [junit4]   2> 2966129 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.h.c.HttpShardHandlerFactory Host whitelist initialized: WhitelistHostChecker [whitelistHosts=null, whitelistHostCheckingEnabled=true]
>>   [junit4]   2> 2966130 WARN  (jetty-launcher-8941-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@28bce952[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2966133 WARN  (jetty-launcher-8941-thread-1) [    ] o.e.j.u.s.S.config No Client EndPointIdentificationAlgorithm configured for SslContextFactory@67f1c12[provider=null,keyStore=null,trustStore=null]
>>   [junit4]   2> 2966134 INFO  (jetty-launcher-8941-thread-1) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:37398/solr
>>   [junit4]   2> 2966159 INFO  (zkConnectionManagerCallback-8950-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2966161 INFO  (zkConnectionManagerCallback-8952-thread-1) [    ] o.a.s.c.c.ConnectionManager zkClient has connected
>>   [junit4]   2> 2966381 INFO  (jetty-launcher-8941-thread-1) [n:127.0.0.1:35542_solr    ] o.a.s.c.OverseerElectionContext I am going to be the lea
>> 
>> [...truncated too long message...]
>> 
>> s :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> ivy-availability-check:
>> [loadresource] Do not set property disallowed.ivy.jars.list as its length is 0.
>> 
>> -ivy-fail-disallowed-ivy-version:
>> 
>> ivy-fail:
>> 
>> ivy-fail:
>> 
>> ivy-configure:
>> [ivy:configure] :: loading settings :: file = /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/lucene/top-level-ivy-settings.xml
>> 
>> resolve:
>> 
>> jar-checksums:
>>    [mkdir] Created dir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/null1920764231
>>     [copy] Copying 239 files to /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/null1920764231
>>   [delete] Deleting directory /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-8.x/solr/null1920764231
>> 
>> check-working-copy:
>> [ivy:cachepath] :: resolving dependencies :: #;working@lucene2-us-west.apache.org <mailto:working@lucene2-us-west.apache.org>
>> [ivy:cachepath] 	confs: [default]
>> [ivy:cachepath] 	found org.eclipse.jgit#org.eclipse.jgit;5.3.0.201903130848-r in public
>> [ivy:cachepath] 	found com.jcraft#jsch;0.1.54 in public
>> [ivy:cachepath] 	found com.jcraft#jzlib;1.1.1 in public
>> [ivy:cachepath] 	found com.googlecode.javaewah#JavaEWAH;1.1.6 in public
>> [ivy:cachepath] 	found org.slf4j#slf4j-api;1.7.2 in public
>> [ivy:cachepath] 	found org.bouncycastle#bcpg-jdk15on;1.60 in public
>> [ivy:cachepath] 	found org.bouncycastle#bcprov-jdk15on;1.60 in public
>> [ivy:cachepath] 	found org.bouncycastle#bcpkix-jdk15on;1.60 in public
>> [ivy:cachepath] 	found org.slf4j#slf4j-nop;1.7.2 in public
>> [ivy:cachepath] :: resolution report :: resolve 93ms :: artifacts dl 17ms
>> 	---------------------------------------------------------------------
>> 	|                  |            modules            ||   artifacts   |
>> 	|       conf       | number| search|dwnlded|evicted|| number|dwnlded|
>> 	---------------------------------------------------------------------
>> 	|      default     |   9   |   0   |   0   |   0   ||   9   |   0   |
>> 	---------------------------------------------------------------------
>> [wc-checker] Initializing working copy...
>> [wc-checker] Checking working copy status...
>> 
>> -jenkins-base:
>> 
>> BUILD SUCCESSFUL
>> Total time: 229 minutes 13 seconds
>> Archiving artifacts
>> java.lang.InterruptedException: no matches found within 10000
>> 	at hudson.FilePath$ValidateAntFileMask.hasMatch(FilePath.java:2847)
>> 	at hudson.FilePath$ValidateAntFileMask.invoke(FilePath.java:2726)
>> 	at hudson.FilePath$ValidateAntFileMask.invoke(FilePath.java:2707)
>> 	at hudson.FilePath$FileCallableWrapper.call(FilePath.java:3086)
>> Also:   hudson.remoting.Channel$CallSiteStackTrace: Remote call to lucene2
>> 		at hudson.remoting.Channel.attachCallSiteStackTrace(Channel.java:1741)
>> 		at hudson.remoting.UserRequest$ExceptionResponse.retrieve(UserRequest.java:357)
>> 		at hudson.remoting.Channel.call(Channel.java:955)
>> 		at hudson.FilePath.act(FilePath.java:1072)
>> 		at hudson.FilePath.act(FilePath.java:1061)
>> 		at hudson.FilePath.validateAntFileMask(FilePath.java:2705)
>> 		at hudson.tasks.ArtifactArchiver.perform(ArtifactArchiver.java:243)
>> 		at hudson.tasks.BuildStepCompatibilityLayer.perform(BuildStepCompatibilityLayer.java:81)
>> 		at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
>> 		at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:744)
>> 		at hudson.model.AbstractBuild$AbstractBuildExecution.performAllBuildSteps(AbstractBuild.java:690)
>> 		at hudson.model.Build$BuildExecution.post2(Build.java:186)
>> 		at hudson.model.AbstractBuild$AbstractBuildExecution.post(AbstractBuild.java:635)
>> 		at hudson.model.Run.execute(Run.java:1835)
>> 		at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
>> 		at hudson.model.ResourceController.execute(ResourceController.java:97)
>> 		at hudson.model.Executor.run(Executor.java:429)
>> Caused: hudson.FilePath$TunneledInterruptedException
>> 	at hudson.FilePath$FileCallableWrapper.call(FilePath.java:3088)
>> 	at hudson.remoting.UserRequest.perform(UserRequest.java:212)
>> 	at hudson.remoting.UserRequest.perform(UserRequest.java:54)
>> 	at hudson.remoting.Request$2.run(Request.java:369)
>> 	at hudson.remoting.InterceptingExecutorService$1.call(InterceptingExecutorService.java:72)
>> 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
>> 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>> 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>> 	at java.lang.Thread.run(Thread.java:748)
>> Caused: java.lang.InterruptedException: java.lang.InterruptedException: no matches found within 10000
>> 	at hudson.FilePath.act(FilePath.java:1074)
>> 	at hudson.FilePath.act(FilePath.java:1061)
>> 	at hudson.FilePath.validateAntFileMask(FilePath.java:2705)
>> 	at hudson.tasks.ArtifactArchiver.perform(ArtifactArchiver.java:243)
>> 	at hudson.tasks.BuildStepCompatibilityLayer.perform(BuildStepCompatibilityLayer.java:81)
>> 	at hudson.tasks.BuildStepMonitor$1.perform(BuildStepMonitor.java:20)
>> 	at hudson.model.AbstractBuild$AbstractBuildExecution.perform(AbstractBuild.java:744)
>> 	at hudson.model.AbstractBuild$AbstractBuildExecution.performAllBuildSteps(AbstractBuild.java:690)
>> 	at hudson.model.Build$BuildExecution.post2(Build.java:186)
>> 	at hudson.model.AbstractBuild$AbstractBuildExecution.post(AbstractBuild.java:635)
>> 	at hudson.model.Run.execute(Run.java:1835)
>> 	at hudson.model.FreeStyleBuild.run(FreeStyleBuild.java:43)
>> 	at hudson.model.ResourceController.execute(ResourceController.java:97)
>> 	at hudson.model.Executor.run(Executor.java:429)
>> No artifacts found that match the file pattern "**/*.events,heapdumps/**,**/hs_err_pid*". Configuration error?
>> Recording test results
>> Build step 'Publish JUnit test result report' changed build result to UNSTABLE
>> Email was triggered for: Unstable (Test Failures)
>> Sending email for trigger: Unstable (Test Failures)
>> 
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org <mailto:dev-unsubscribe@lucene.apache.org>
>> For additional commands, e-mail: dev-help@lucene.apache.org <mailto:dev-help@lucene.apache.org>


Mime
View raw message