You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/06/24 05:18:16 UTC
[JENKINS] Lucene-Solr-NightlyTests-4.x - Build # 295 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-4.x/295/
1 tests failed.
REGRESSION: org.apache.solr.cloud.RecoveryZkTest.testDistribSearch
Error Message:
expected:<2143> but was:<86>
Stack Trace:
java.lang.AssertionError: expected:<2143> but was:<86>
at __randomizedtesting.SeedInfo.seed([165080780D09E20C:97B60E607A568230]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.junit.Assert.assertEquals(Assert.java:456)
at org.apache.solr.cloud.RecoveryZkTest.doTest(RecoveryZkTest.java:108)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:679)
Build Log:
[...truncated 8842 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.RecoveryZkTest
[junit4:junit4] 2> 624598 T1937 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 624603 T1937 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./solrtest-RecoveryZkTest-1372041343016
[junit4:junit4] 2> 624605 T1937 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 624606 T1938 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 624706 T1937 oasc.ZkTestServer.run start zk server on port:26432
[junit4:junit4] 2> 624707 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 624712 T1944 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7038d7c7 name:ZooKeeperConnection Watcher:127.0.0.1:26432 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 624712 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 624712 T1937 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 624754 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 624756 T1946 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a6ef0a9 name:ZooKeeperConnection Watcher:127.0.0.1:26432/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 624756 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 624757 T1937 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 624825 T1937 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 624828 T1937 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 624876 T1937 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 624879 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 624880 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 624893 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 624894 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 624899 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 624900 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 624903 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 624904 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 624907 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 624908 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 624911 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 624911 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 624914 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 624915 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 624918 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 624919 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 624927 T1937 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 624927 T1937 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 625231 T1937 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 625236 T1937 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:54251
[junit4:junit4] 2> 625237 T1937 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 625237 T1937 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 625238 T1937 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343
[junit4:junit4] 2> 625238 T1937 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343/solr.xml
[junit4:junit4] 2> 625239 T1937 oasc.CoreContainer.<init> New CoreContainer 1593458812
[junit4:junit4] 2> 625239 T1937 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343/'
[junit4:junit4] 2> 625240 T1937 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343/'
[junit4:junit4] 2> 625354 T1937 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 625355 T1937 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 625355 T1937 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 625356 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 625356 T1937 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 625357 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 625357 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 625358 T1937 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 625358 T1937 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 625359 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 625376 T1937 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 625377 T1937 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:26432/solr
[junit4:junit4] 2> 625377 T1937 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 625379 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 625406 T1957 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@50590aeb name:ZooKeeperConnection Watcher:127.0.0.1:26432 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 625407 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 625416 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 625428 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 625430 T1959 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@64ddc9f4 name:ZooKeeperConnection Watcher:127.0.0.1:26432/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 625430 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 625433 T1937 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 625443 T1937 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 625446 T1937 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 625454 T1937 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54251_
[junit4:junit4] 2> 625456 T1937 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54251_
[junit4:junit4] 2> 625460 T1937 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 625478 T1937 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 625481 T1937 oasc.Overseer.start Overseer (id=89918101456420867-127.0.0.1:54251_-n_0000000000) starting
[junit4:junit4] 2> 625491 T1937 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 625503 T1961 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 625504 T1937 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 625506 T1937 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 625508 T1937 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 625511 T1960 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 625514 T1962 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 625515 T1962 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 627014 T1960 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 627015 T1960 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54251_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54251"}
[junit4:junit4] 2> 627015 T1960 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 627016 T1960 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 627031 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 627518 T1962 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343/collection1
[junit4:junit4] 2> 627518 T1962 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 627520 T1962 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 627520 T1962 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 627521 T1962 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343/collection1/'
[junit4:junit4] 2> 627523 T1962 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 627523 T1962 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343/collection1/lib/README' to classloader
[junit4:junit4] 2> 627580 T1962 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 627638 T1962 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 627640 T1962 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 627646 T1962 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 628298 T1962 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 628298 T1962 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 628299 T1962 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 628311 T1962 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 628316 T1962 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 628330 T1962 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 628335 T1962 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 628339 T1962 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 628341 T1962 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 628341 T1962 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 628341 T1962 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 628342 T1962 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 628342 T1962 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 628343 T1962 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 628343 T1962 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-controljetty-1372041343343/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/control/data/
[junit4:junit4] 2> 628343 T1962 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7f702c48
[junit4:junit4] 2> 628344 T1962 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 628344 T1962 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/control/data
[junit4:junit4] 2> 628345 T1962 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/control/data/index/
[junit4:junit4] 2> 628345 T1962 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1372041343016/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 628345 T1962 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/control/data/index
[junit4:junit4] 2> 628350 T1962 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@3b854a44 lockFactory=org.apache.lucene.store.NativeFSLockFactory@45770447),segFN=segments_1,generation=1}
[junit4:junit4] 2> 628350 T1962 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 628353 T1962 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 628353 T1962 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 628354 T1962 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 628354 T1962 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 628355 T1962 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 628355 T1962 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 628355 T1962 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 628356 T1962 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 628356 T1962 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 628366 T1962 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 628374 T1962 oass.SolrIndexSearcher.<init> Opening Searcher@78f2850f main
[junit4:junit4] 2> 628374 T1962 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/control/data/tlog
[junit4:junit4] 2> 628376 T1962 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 628376 T1962 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 628379 T1963 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@78f2850f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 628381 T1962 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 628381 T1962 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54251 collection:control_collection shard:shard1
[junit4:junit4] 2> 628382 T1962 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 628406 T1962 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 628409 T1962 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 628409 T1962 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 628409 T1962 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54251/collection1/
[junit4:junit4] 2> 628409 T1962 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 628410 T1962 oasc.SyncStrategy.syncToMe http://127.0.0.1:54251/collection1/ has no replicas
[junit4:junit4] 2> 628410 T1962 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54251/collection1/
[junit4:junit4] 2> 628410 T1962 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 628535 T1960 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 628552 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 628569 T1962 oasc.ZkController.register We are http://127.0.0.1:54251/collection1/ and leader is http://127.0.0.1:54251/collection1/
[junit4:junit4] 2> 628569 T1962 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54251
[junit4:junit4] 2> 628569 T1962 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 628569 T1962 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 628570 T1962 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 628571 T1962 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 628572 T1937 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 628573 T1937 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 628573 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 628590 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 628592 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 628594 T1966 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@574c4e64 name:ZooKeeperConnection Watcher:127.0.0.1:26432/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 628594 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 628596 T1937 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 628598 T1937 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 628867 T1937 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 628870 T1937 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:29604
[junit4:junit4] 2> 628871 T1937 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 628871 T1937 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 628872 T1937 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010
[junit4:junit4] 2> 628872 T1937 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010/solr.xml
[junit4:junit4] 2> 628873 T1937 oasc.CoreContainer.<init> New CoreContainer 987682504
[junit4:junit4] 2> 628873 T1937 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010/'
[junit4:junit4] 2> 628874 T1937 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010/'
[junit4:junit4] 2> 628985 T1937 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 628986 T1937 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 628986 T1937 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 628986 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 628987 T1937 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 628987 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 628988 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 628988 T1937 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 628989 T1937 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 628989 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 629006 T1937 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 629007 T1937 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:26432/solr
[junit4:junit4] 2> 629007 T1937 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 629008 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 629011 T1977 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7b5fe4cb name:ZooKeeperConnection Watcher:127.0.0.1:26432 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 629012 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 629028 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 629040 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 629042 T1979 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@58dfbc6c name:ZooKeeperConnection Watcher:127.0.0.1:26432/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 629043 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 629053 T1937 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 630056 T1937 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:29604_
[junit4:junit4] 2> 630063 T1937 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:29604_
[junit4:junit4] 2> 630072 T1960 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 630073 T1966 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 630073 T1979 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 630073 T1960 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:54251_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54251"}
[junit4:junit4] 2> 630090 T1980 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 630090 T1980 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 630097 T1966 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 630097 T1979 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 630101 T1959 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 630101 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 630102 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 631602 T1960 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 631603 T1960 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:29604_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:29604"}
[junit4:junit4] 2> 631604 T1960 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 631604 T1960 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 631620 T1979 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 631620 T1966 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 631620 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 632100 T1980 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010/collection1
[junit4:junit4] 2> 632100 T1980 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 632101 T1980 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 632101 T1980 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 632103 T1980 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010/collection1/'
[junit4:junit4] 2> 632104 T1980 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 632105 T1980 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010/collection1/lib/README' to classloader
[junit4:junit4] 2> 632156 T1980 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 632214 T1980 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 632215 T1980 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 632222 T1980 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 632828 T1980 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 632829 T1980 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 632829 T1980 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 632837 T1980 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 632840 T1980 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 632852 T1980 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 632856 T1980 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 632859 T1980 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 632860 T1980 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 632860 T1980 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 632861 T1980 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 632861 T1980 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 632862 T1980 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 632862 T1980 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 632862 T1980 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty1-1372041347010/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty1/
[junit4:junit4] 2> 632862 T1980 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7f702c48
[junit4:junit4] 2> 632863 T1980 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 632863 T1980 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty1
[junit4:junit4] 2> 632863 T1980 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty1/index/
[junit4:junit4] 2> 632863 T1980 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 632864 T1980 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty1/index
[junit4:junit4] 2> 632866 T1980 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@121cec89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d0f3b57),segFN=segments_1,generation=1}
[junit4:junit4] 2> 632866 T1980 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 632868 T1980 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 632869 T1980 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 632869 T1980 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 632870 T1980 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 632870 T1980 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 632870 T1980 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 632870 T1980 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 632871 T1980 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 632871 T1980 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 632878 T1980 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 632883 T1980 oass.SolrIndexSearcher.<init> Opening Searcher@2a4e52db main
[junit4:junit4] 2> 632883 T1980 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty1/tlog
[junit4:junit4] 2> 632884 T1980 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 632884 T1980 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 632887 T1981 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2a4e52db main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 632888 T1980 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 632888 T1980 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:29604 collection:collection1 shard:shard1
[junit4:junit4] 2> 632889 T1980 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 632906 T1980 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 632909 T1980 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 632909 T1980 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 632909 T1980 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:29604/collection1/
[junit4:junit4] 2> 632909 T1980 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 632910 T1980 oasc.SyncStrategy.syncToMe http://127.0.0.1:29604/collection1/ has no replicas
[junit4:junit4] 2> 632910 T1980 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:29604/collection1/
[junit4:junit4] 2> 632910 T1980 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 633125 T1960 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 633142 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 633142 T1966 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 633142 T1979 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 633171 T1980 oasc.ZkController.register We are http://127.0.0.1:29604/collection1/ and leader is http://127.0.0.1:29604/collection1/
[junit4:junit4] 2> 633171 T1980 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:29604
[junit4:junit4] 2> 633171 T1980 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 633171 T1980 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 633172 T1980 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 633173 T1980 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 633174 T1937 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 633175 T1937 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 633175 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 633358 T1937 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 633360 T1937 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:12158
[junit4:junit4] 2> 633361 T1937 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 633361 T1937 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 633362 T1937 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598
[junit4:junit4] 2> 633362 T1937 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598/solr.xml
[junit4:junit4] 2> 633362 T1937 oasc.CoreContainer.<init> New CoreContainer 325678321
[junit4:junit4] 2> 633363 T1937 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598/'
[junit4:junit4] 2> 633363 T1937 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598/'
[junit4:junit4] 2> 633437 T1937 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 633438 T1937 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 633438 T1937 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 633438 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 633438 T1937 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 633439 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 633439 T1937 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 633439 T1937 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 633440 T1937 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 633440 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 633451 T1937 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 633452 T1937 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:26432/solr
[junit4:junit4] 2> 633452 T1937 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 633453 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 633456 T1993 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7ec95cbe name:ZooKeeperConnection Watcher:127.0.0.1:26432 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 633456 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 633473 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 633481 T1937 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 633482 T1995 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@45050562 name:ZooKeeperConnection Watcher:127.0.0.1:26432/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 633483 T1937 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 633493 T1937 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 634498 T1937 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:12158_
[junit4:junit4] 2> 634501 T1937 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:12158_
[junit4:junit4] 2> 634569 T1959 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 634569 T1995 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 634569 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 634569 T1979 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 634569 T1966 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 634570 T1979 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 634570 T1966 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 634576 T1996 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 634576 T1996 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 634647 T1960 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 634648 T1960 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:29604_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:29604"}
[junit4:junit4] 2> 634716 T1960 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12158_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12158"}
[junit4:junit4] 2> 634717 T1960 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 634717 T1960 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 634769 T1979 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 634769 T1966 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 634769 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 634769 T1995 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 635600 T1996 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598/collection1
[junit4:junit4] 2> 635600 T1996 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 635601 T1996 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 635601 T1996 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 635603 T1996 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598/collection1/'
[junit4:junit4] 2> 635604 T1996 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 635605 T1996 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598/collection1/lib/README' to classloader
[junit4:junit4] 2> 635655 T1996 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 635720 T1996 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 635722 T1996 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 635728 T1996 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 636316 T1996 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 636317 T1996 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 636317 T1996 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 636325 T1996 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 636328 T1996 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 636338 T1996 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 636341 T1996 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 636344 T1996 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 636345 T1996 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 636346 T1996 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 636346 T1996 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 636347 T1996 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 636347 T1996 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 636347 T1996 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 636347 T1996 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0/./org.apache.solr.cloud.RecoveryZkTest-jetty2-1372041351598/collection1/, dataDir=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2/
[junit4:junit4] 2> 636347 T1996 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@7f702c48
[junit4:junit4] 2> 636348 T1996 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 636348 T1996 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2
[junit4:junit4] 2> 636349 T1996 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2/index/
[junit4:junit4] 2> 636349 T1996 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 636349 T1996 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2/index
[junit4:junit4] 2> 636351 T1996 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@75973529 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e0cc098),segFN=segments_1,generation=1}
[junit4:junit4] 2> 636352 T1996 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 636354 T1996 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 636354 T1996 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 636355 T1996 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 636355 T1996 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 636355 T1996 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 636356 T1996 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 636356 T1996 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 636356 T1996 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 636357 T1996 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 636363 T1996 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 636367 T1996 oass.SolrIndexSearcher.<init> Opening Searcher@3f53bc70 main
[junit4:junit4] 2> 636368 T1996 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2/tlog
[junit4:junit4] 2> 636369 T1996 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 636369 T1996 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 636372 T1997 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f53bc70 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 636374 T1996 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 636374 T1996 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:12158 collection:collection1 shard:shard1
[junit4:junit4] 2> 636377 T1996 oasc.ZkController.register We are http://127.0.0.1:12158/collection1/ and leader is http://127.0.0.1:29604/collection1/
[junit4:junit4] 2> 636377 T1996 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:12158
[junit4:junit4] 2> 636377 T1996 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 636377 T1996 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C942 name=collection1 org.apache.solr.core.SolrCore@3c0f5c99 url=http://127.0.0.1:12158/collection1 node=127.0.0.1:12158_ C942_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:12158_, base_url=http://127.0.0.1:12158}
[junit4:junit4] 2> 636378 T1998 C942 P12158 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 636378 T1996 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 636378 T1998 C942 P12158 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 636379 T1998 C942 P12158 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 636379 T1998 C942 P12158 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 636379 T1937 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build/solr-core/test/J0
[junit4:junit4] 2> 636380 T1937 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 636380 T1937 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 636380 T1998 C942 P12158 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 636397 T1937 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 636399 T1969 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> ASYNC NEW_CORE C943 name=collection1 org.apache.solr.core.SolrCore@6314017d url=http://127.0.0.1:54251/collection1 node=127.0.0.1:54251_ C943_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:54251_, base_url=http://127.0.0.1:54251, leader=true}
[junit4:junit4] 2> 636409 T1950 C943 P54251 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@3b854a44 lockFactory=org.apache.lucene.store.NativeFSLockFactory@45770447),segFN=segments_1,generation=1}
[junit4:junit4] 2> 636410 T1950 C943 P54251 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 636412 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10001 (1438689635670687744)]} 0 5
[junit4:junit4] 2> 636412 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438689635672784896)]} 0 3
[junit4:junit4] 2> ASYNC NEW_CORE C944 name=collection1 org.apache.solr.core.SolrCore@57b73bce url=http://127.0.0.1:29604/collection1 node=127.0.0.1:29604_ C944_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:29604_, base_url=http://127.0.0.1:29604, leader=true}
[junit4:junit4] 2> 636429 T1971 C944 P29604 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@121cec89 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4d0f3b57),segFN=segments_1,generation=1}
[junit4:junit4] 2> 636429 T1971 C944 P29604 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 636431 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438689635691659264)]} 0 4
[junit4:junit4] 2> 636431 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10001 (1438689635693756416)]} 0 3
[junit4:junit4] 2> 636506 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438689635773448192)]} 0 1
[junit4:junit4] 2> 636506 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10002 (1438689635773448193)]} 0 1
[junit4:junit4] 2> 636510 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10002 (1438689635777642496)]} 0 1
[junit4:junit4] 2> 636510 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438689635777642497)]} 0 1
[junit4:junit4] 2> 636587 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10001 (-1438689635858382848)]} 0 1
[junit4:junit4] 2> 636587 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[1 (-1438689635858382849)]} 0 1
[junit4:junit4] 2> 636590 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[1 (-1438689635862577152)]} 0 0
[junit4:junit4] 2> 636591 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10001 (-1438689635862577153)]} 0 1
[junit4:junit4] 2> 636594 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10003 (1438689635865722881)]} 0 1
[junit4:junit4] 2> 636594 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438689635865722880)]} 0 1
[junit4:junit4] 2> 636598 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438689635869917184)]} 0 1
[junit4:junit4] 2> 636598 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10003 (1438689635869917185)]} 0 1
[junit4:junit4] 2> 636601 T1937 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 12158
[junit4:junit4] 2> 636601 T1937 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=325678321
[junit4:junit4] 2> 636673 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[2 (-1438689635949608960)]} 0 0
[junit4:junit4] 2> 636674 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10002 (-1438689635950657536)]} 0 0
[junit4:junit4] 2> 636676 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[2 (-1438689635952754688)]} 0 0
[junit4:junit4] 2> 636677 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10002 (-1438689635953803264)]} 0 0
[junit4:junit4] 2> 636680 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1438689635955900416)]} 0 1
[junit4:junit4] 2> 636680 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10004 (1438689635956948992)]} 0 0
[junit4:junit4] 2> 636683 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10004 (1438689635960094721)]} 0 0
[junit4:junit4] 2> 636684 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1438689635960094720)]} 0 1
[junit4:junit4] 2> 636738 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10005 (1438689636016717824)]} 0 1
[junit4:junit4] 2> 636738 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1438689636016717825)]} 0 1
[junit4:junit4] 2> 636741 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10005 (1438689636020912128)]} 0 0
[junit4:junit4] 2> 636742 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1438689636020912129)]} 0 1
[junit4:junit4] 2> 636758 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[4 (-1438689636038737920)]} 0 0
[junit4:junit4] 2> 636758 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10004 (-1438689636038737921)]} 0 0
[junit4:junit4] 2> 636761 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[4 (-1438689636041883648)]} 0 0
[junit4:junit4] 2> 636762 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10004 (-1438689636042932224)]} 0 0
[junit4:junit4] 2> 636764 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1438689636043980800)]} 0 1
[junit4:junit4] 2> 636764 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10006 (1438689636045029376)]} 0 0
[junit4:junit4] 2> 636767 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1438689636047126528)]} 0 1
[junit4:junit4] 2> 636767 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10006 (1438689636048175104)]} 0 0
[junit4:junit4] 2> 636848 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1438689636132061184)]} 0 1
[junit4:junit4] 2> 636848 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10007 (1438689636133109760)]} 0 0
[junit4:junit4] 2> 636851 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1438689636136255488)]} 0 0
[junit4:junit4] 2> 636852 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10007 (1438689636136255489)]} 0 1
[junit4:junit4] 2> 636938 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[5 (-1438689636227481600)]} 0 0
[junit4:junit4] 2> 636939 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10005 (-1438689636228530176)]} 0 0
[junit4:junit4] 2> 636941 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[5 (-1438689636230627328)]} 0 0
[junit4:junit4] 2> 636942 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10005 (-1438689636231675904)]} 0 0
[junit4:junit4] 2> 636945 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1438689636233773056)]} 0 1
[junit4:junit4] 2> 636946 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10008 (1438689636234821632)]} 0 1
[junit4:junit4] 2> 636947 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1438689636236918784)]} 0 0
[junit4:junit4] 2> 636949 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10008 (1438689636237967360)]} 0 1
[junit4:junit4] 2> 637048 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1438689636341776384)]} 0 1
[junit4:junit4] 2> 637049 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10009 (1438689636342824960)]} 0 1
[junit4:junit4] 2> 637052 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1438689636345970688)]} 0 1
[junit4:junit4] 2> 637052 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10009 (1438689636345970689)]} 0 1
[junit4:junit4] 2> 637123 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[6 (-1438689636420419584)]} 0 1
[junit4:junit4] 2> 637123 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10006 (-1438689636421468160)]} 0 0
[junit4:junit4] 2> 637126 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10006 (-1438689636424613889)]} 0 0
[junit4:junit4] 2> 637126 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[6 (-1438689636424613888)]} 0 0
[junit4:junit4] 2> 637130 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1438689636427759616)]} 0 1
[junit4:junit4] 2> 637130 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10010 (1438689636427759617)]} 0 1
[junit4:junit4] 2> 637134 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1438689636431953920)]} 0 1
[junit4:junit4] 2> 637134 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10010 (1438689636431953921)]} 0 1
[junit4:junit4] 2> 637223 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1438689636525277184)]} 0 1
[junit4:junit4] 2> 637224 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10011 (1438689636526325760)]} 0 1
[junit4:junit4] 2> 637226 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1438689636529471488)]} 0 0
[junit4:junit4] 2> 637228 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10011 (1438689636530520064)]} 0 1
[junit4:junit4] 2> 637232 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[8 (-1438689636535762944)]} 0 0
[junit4:junit4] 2> 637233 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10008 (-1438689636536811520)]} 0 0
[junit4:junit4] 2> 637235 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[8 (-1438689636538908672)]} 0 0
[junit4:junit4] 2> 637236 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10008 (-1438689636539957248)]} 0 0
[junit4:junit4] 2> 637239 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1438689636542054400)]} 0 1
[junit4:junit4] 2> 637240 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10012 (1438689636543102976)]} 0 1
[junit4:junit4] 2> 637242 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1438689636545200128)]} 0 1
[junit4:junit4] 2> 637243 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10012 (1438689636546248704)]} 0 1
[junit4:junit4] 2> 637345 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[9 (-1438689636653203456)]} 0 1
[junit4:junit4] 2> 637345 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10009 (-1438689636654252032)]} 0 0
[junit4:junit4] 2> 637348 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[9 (-1438689636657397760)]} 0 0
[junit4:junit4] 2> 637348 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10009 (-1438689636657397761)]} 0 0
[junit4:junit4] 2> 637352 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1438689636660543488)]} 0 1
[junit4:junit4] 2> 637352 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10013 (1438689636660543489)]} 0 1
[junit4:junit4] 2> 637356 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10013 (1438689636664737792)]} 0 1
[junit4:junit4] 2> 637356 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1438689636664737793)]} 0 1
[junit4:junit4] 2> 637442 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10010 (-1438689636754915328)]} 0 1
[junit4:junit4] 2> 637442 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10 (-1438689636755963904)]} 0 0
[junit4:junit4] 2> 637445 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10010 (-1438689636759109632)]} 0 0
[junit4:junit4] 2> 637445 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10 (-1438689636759109633)]} 0 0
[junit4:junit4] 2> 637449 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10014 (1438689636762255361)]} 0 1
[junit4:junit4] 2> 637449 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1438689636762255360)]} 0 1
[junit4:junit4] 2> 637452 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10014 (1438689636765401088)]} 0 1
[junit4:junit4] 2> 637453 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1438689636766449664)]} 0 1
[junit4:junit4] 2> 637552 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10015 (1438689636870258688)]} 0 1
[junit4:junit4] 2> 637554 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1438689636872355840)]} 0 1
[junit4:junit4] 2> 637556 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10015 (1438689636874452992)]} 0 1
[junit4:junit4] 2> 637557 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1438689636875501568)]} 0 1
[junit4:junit4] 2> 637603 T1937 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 637603 T1937 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 637605 T1937 oasc.RecoveryStrategy.close WARN Stopping recovery for zkNodeName=3core=collection1
[junit4:junit4] 2> 637632 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10012 (-1438689636954144769)]} 0 1
[junit4:junit4] 2> 637632 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[12 (-1438689636954144768)]} 0 1
[junit4:junit4] 2> 637634 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10012 (-1438689636957290496)]} 0 0
[junit4:junit4] 2> 637635 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[12 (-1438689636958339072)]} 0 0
[junit4:junit4] 2> 637638 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10016 (1438689636960436224)]} 0 1
[junit4:junit4] 2> 637639 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1438689636961484800)]} 0 1
[junit4:junit4] 2> 637641 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10016 (1438689636963581952)]} 0 1
[junit4:junit4] 2> 637642 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1438689636964630528)]} 0 1
[junit4:junit4] 2> 637718 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10017 (1438689637044322304)]} 0 1
[junit4:junit4] 2> 637719 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1438689637045370880)]} 0 1
[junit4:junit4] 2> 637722 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10017 (1438689637048516608)]} 0 1
[junit4:junit4] 2> 637723 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1438689637049565184)]} 0 1
[junit4:junit4] 2> 637797 T1960 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 637798 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10013 (-1438689637128208384)]} 0 1
[junit4:junit4] 2> 637798 T1960 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12158_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12158"}
[junit4:junit4] 2> 637798 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[13 (-1438689637129256960)]} 0 0
[junit4:junit4] 2> 637801 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10013 (-1438689637132402689)]} 0 0
[junit4:junit4] 2> 637801 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[13 (-1438689637132402688)]} 0 0
[junit4:junit4] 2> 637802 T1960 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:12158_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:12158"}
[junit4:junit4] 2> 637805 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1438689637135548416)]} 0 1
[junit4:junit4] 2> 637805 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10018 (1438689637135548417)]} 0 1
[junit4:junit4] 2> 637808 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1438689637138694144)]} 0 1
[junit4:junit4] 2> 637809 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10018 (1438689637139742720)]} 0 1
[junit4:junit4] 2> 637817 T1995 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 637817 T1966 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 637817 T1959 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 637817 T1979 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 637902 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1438689637237260288)]} 0 1
[junit4:junit4] 2> 637903 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10019 (1438689637238308864)]} 0 1
[junit4:junit4] 2> 637906 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1438689637241454592)]} 0 1
[junit4:junit4] 2> 637907 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10019 (1438689637242503168)]} 0 1
[junit4:junit4] 2> 637925 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[15 (-1438689637261377536)]} 0 1
[junit4:junit4] 2> 637925 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10015 (-1438689637262426112)]} 0 0
[junit4:junit4] 2> 637928 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[15 (-1438689637265571840)]} 0 0
[junit4:junit4] 2> 637928 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10015 (-1438689637265571841)]} 0 0
[junit4:junit4] 2> 637932 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10020 (1438689637268717568)]} 0 1
[junit4:junit4] 2> 637933 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1438689637268717569)]} 0 2
[junit4:junit4] 2> 637937 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1438689637273960448)]} 0 1
[junit4:junit4] 2> 637938 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10020 (1438689637273960449)]} 0 2
[junit4:junit4] 2> 638030 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1438689637371478017)]} 0 1
[junit4:junit4] 2> 638030 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10021 (1438689637371478016)]} 0 1
[junit4:junit4] 2> 638034 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1438689637375672320)]} 0 1
[junit4:junit4] 2> 638034 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10021 (1438689637375672321)]} 0 1
[junit4:junit4] 2> 638129 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[18 (-1438689637475287040)]} 0 1
[junit4:junit4] 2> 638129 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10018 (-1438689637475287041)]} 0 1
[junit4:junit4] 2> 638132 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10018 (-1438689637479481344)]} 0 0
[junit4:junit4] 2> 638132 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[18 (-1438689637479481345)]} 0 0
[junit4:junit4] 2> 638136 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10022 (1438689637482627072)]} 0 1
[junit4:junit4] 2> 638136 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1438689637482627073)]} 0 1
[junit4:junit4] 2> 638139 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10022 (1438689637485772800)]} 0 1
[junit4:junit4] 2> 638140 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1438689637486821376)]} 0 1
[junit4:junit4] 2> 638243 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[19 (-1438689637594824704)]} 0 1
[junit4:junit4] 2> 638243 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10019 (-1438689637594824705)]} 0 1
[junit4:junit4] 2> 638246 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10019 (-1438689637599019008)]} 0 0
[junit4:junit4] 2> 638246 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[19 (-1438689637599019009)]} 0 0
[junit4:junit4] 2> 638250 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1438689637602164736)]} 0 1
[junit4:junit4] 2> 638250 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10023 (1438689637602164737)]} 0 1
[junit4:junit4] 2> 638253 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1438689637605310464)]} 0 1
[junit4:junit4] 2> 638254 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10023 (1438689637606359040)]} 0 1
[junit4:junit4] 2> 638278 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1438689637631524864)]} 0 1
[junit4:junit4] 2> 638279 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10024 (1438689637632573440)]} 0 1
[junit4:junit4] 2> 638282 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10024 (1438689637635719168)]} 0 1
[junit4:junit4] 2> 638282 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1438689637635719169)]} 0 1
[junit4:junit4] 2> 638358 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10025 (1438689637715410944)]} 0 1
[junit4:junit4] 2> 638359 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1438689637716459520)]} 0 1
[junit4:junit4] 2> 638362 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10025 (1438689637719605248)]} 0 1
[junit4:junit4] 2> 638363 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1438689637720653824)]} 0 1
[junit4:junit4] 2> 638419 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10020 (-1438689637779374080)]} 0 1
[junit4:junit4] 2> 638419 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[20 (-1438689637779374081)]} 0 1
[junit4:junit4] 2> 638422 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[20 (-1438689637783568384)]} 0 0
[junit4:junit4] 2> 638422 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10020 (-1438689637783568385)]} 0 0
[junit4:junit4] 2> 638426 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1438689637786714113)]} 0 1
[junit4:junit4] 2> 638426 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10026 (1438689637786714112)]} 0 1
[junit4:junit4] 2> 638429 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1438689637789859840)]} 0 1
[junit4:junit4] 2> 638430 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10026 (1438689637790908416)]} 0 1
[junit4:junit4] 2> 638508 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1438689637872697344)]} 0 1
[junit4:junit4] 2> 638509 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10027 (1438689637873745920)]} 0 1
[junit4:junit4] 2> 638512 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1438689637876891648)]} 0 1
[junit4:junit4] 2> 638513 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10027 (1438689637877940224)]} 0 1
[junit4:junit4] 2> 638585 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10028 (1438689637954486272)]} 0 1
[junit4:junit4] 2> 638586 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1438689637954486273)]} 0 2
[junit4:junit4] 2> 638589 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10028 (1438689637957632000)]} 0 1
[junit4:junit4] 2> 638590 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1438689637958680576)]} 0 1
[junit4:junit4] 2> 638636 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10022 (-1438689638006915072)]} 0 1
[junit4:junit4] 2> 638636 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[22 (-1438689638007963648)]} 0 0
[junit4:junit4] 2> 638639 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10022 (-1438689638011109376)]} 0 0
[junit4:junit4] 2> 638639 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[22 (-1438689638011109377)]} 0 0
[junit4:junit4] 2> 638643 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1438689638014255104)]} 0 1
[junit4:junit4] 2> 638643 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10029 (1438689638014255105)]} 0 1
[junit4:junit4] 2> 638647 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1438689638018449408)]} 0 1
[junit4:junit4] 2> 638647 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10029 (1438689638018449409)]} 0 1
[junit4:junit4] 2> 638728 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1438689638103384064)]} 0 1
[junit4:junit4] 2> 638729 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10030 (1438689638104432640)]} 0 1
[junit4:junit4] 2> 638732 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1438689638107578368)]} 0 1
[junit4:junit4] 2> 638733 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10030 (1438689638108626944)]} 0 1
[junit4:junit4] 2> 638824 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[26 (-1438689638204047360)]} 0 1
[junit4:junit4] 2> 638824 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10026 (-1438689638205095936)]} 0 0
[junit4:junit4] 2> 638827 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10026 (-1438689638208241664)]} 0 0
[junit4:junit4] 2> 638827 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[26 (-1438689638208241665)]} 0 0
[junit4:junit4] 2> 638831 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10031 (1438689638211387392)]} 0 1
[junit4:junit4] 2> 638831 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1438689638211387393)]} 0 1
[junit4:junit4] 2> 638835 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10031 (1438689638215581696)]} 0 1
[junit4:junit4] 2> 638835 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1438689638215581697)]} 0 1
[junit4:junit4] 2> 638918 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10032 (1438689638302613504)]} 0 1
[junit4:junit4] 2> 638919 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1438689638303662080)]} 0 1
[junit4:junit4] 2> 638922 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10032 (1438689638306807808)]} 0 1
[junit4:junit4] 2> 638922 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1438689638306807809)]} 0 1
[junit4:junit4] 2> 638982 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10033 (1438689638369722368)]} 0 1
[junit4:junit4] 2> 638983 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1438689638370770944)]} 0 1
[junit4:junit4] 2> 638986 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10033 (1438689638373916672)]} 0 1
[junit4:junit4] 2> 638987 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1438689638374965248)]} 0 1
[junit4:junit4] 2> 639080 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10034 (1438689638472482816)]} 0 1
[junit4:junit4] 2> 639081 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1438689638473531392)]} 0 1
[junit4:junit4] 2> 639084 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10034 (1438689638476677120)]} 0 1
[junit4:junit4] 2> 639085 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1438689638477725696)]} 0 1
[junit4:junit4] 2> 639143 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[30 (-1438689638538543104)]} 0 1
[junit4:junit4] 2> 639143 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10030 (-1438689638538543105)]} 0 1
[junit4:junit4] 2> 639146 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[30 (-1438689638542737408)]} 0 0
[junit4:junit4] 2> 639146 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10030 (-1438689638542737409)]} 0 0
[junit4:junit4] 2> 639150 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1438689638545883136)]} 0 1
[junit4:junit4] 2> 639150 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10035 (1438689638545883137)]} 0 1
[junit4:junit4] 2> 639153 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1438689638549028864)]} 0 1
[junit4:junit4] 2> 639154 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10035 (1438689638550077440)]} 0 1
[junit4:junit4] 2> 639201 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1438689638599360512)]} 0 1
[junit4:junit4] 2> 639202 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10036 (1438689638600409088)]} 0 1
[junit4:junit4] 2> 639205 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1438689638603554816)]} 0 1
[junit4:junit4] 2> 639206 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10036 (1438689638604603392)]} 0 1
[junit4:junit4] 2> 639249 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[34 (-1438689638649692160)]} 0 1
[junit4:junit4] 2> 639249 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10034 (-1438689638650740736)]} 0 0
[junit4:junit4] 2> 639252 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10034 (-1438689638653886464)]} 0 0
[junit4:junit4] 2> 639252 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[34 (-1438689638653886465)]} 0 0
[junit4:junit4] 2> 639256 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10037 (1438689638657032193)]} 0 1
[junit4:junit4] 2> 639256 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1438689638657032192)]} 0 1
[junit4:junit4] 2> 639259 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10037 (1438689638660177920)]} 0 1
[junit4:junit4] 2> 639260 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1438689638661226496)]} 0 1
[junit4:junit4] 2> 639274 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10038 (1438689638675906560)]} 0 1
[junit4:junit4] 2> 639275 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1438689638678003712)]} 0 1
[junit4:junit4] 2> 639278 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10038 (1438689638680100864)]} 0 1
[junit4:junit4] 2> 639279 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1438689638681149440)]} 0 1
[junit4:junit4] 2> 639363 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10039 (1438689638769229824)]} 0 1
[junit4:junit4] 2> 639364 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1438689638770278400)]} 0 1
[junit4:junit4] 2> 639367 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10039 (1438689638773424129)]} 0 1
[junit4:junit4] 2> 639367 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1438689638773424128)]} 0 1
[junit4:junit4] 2> 639392 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10040 (1438689638799638528)]} 0 1
[junit4:junit4] 2> 639393 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1438689638800687104)]} 0 1
[junit4:junit4] 2> 639396 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1438689638803832832)]} 0 1
[junit4:junit4] 2> 639396 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10040 (1438689638803832833)]} 0 1
[junit4:junit4] 2> 639463 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[36 (-1438689638875136000)]} 0 1
[junit4:junit4] 2> 639463 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10036 (-1438689638875136001)]} 0 0
[junit4:junit4] 2> 639466 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10036 (-1438689638878281728)]} 0 0
[junit4:junit4] 2> 639466 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[36 (-1438689638878281729)]} 0 0
[junit4:junit4] 2> 639470 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10041 (1438689638881427456)]} 0 1
[junit4:junit4] 2> 639470 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1438689638881427457)]} 0 1
[junit4:junit4] 2> 639474 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10041 (1438689638885621760)]} 0 1
[junit4:junit4] 2> 639474 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1438689638885621761)]} 0 1
[junit4:junit4] 2> 639578 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1438689638994673664)]} 0 2
[junit4:junit4] 2> 639578 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10042 (1438689638994673665)]} 0 2
[junit4:junit4] 2> 639582 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10042 (1438689638998867968)]} 0 1
[junit4:junit4] 2> 639582 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1438689638998867969)]} 0 1
[junit4:junit4] 2> 639632 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10043 (1438689639051296768)]} 0 1
[junit4:junit4] 2> 639633 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1438689639052345344)]} 0 1
[junit4:junit4] 2> 639636 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10043 (1438689639055491072)]} 0 1
[junit4:junit4] 2> 639637 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1438689639056539648)]} 0 1
[junit4:junit4] 2> 639724 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10037 (-1438689639147765760)]} 0 1
[junit4:junit4] 2> 639725 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[37 (-1438689639149862912)]} 0 0
[junit4:junit4] 2> 639727 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10037 (-1438689639151960064)]} 0 0
[junit4:junit4] 2> 639728 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[37 (-1438689639153008640)]} 0 0
[junit4:junit4] 2> 639731 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10044 (1438689639155105792)]} 0 1
[junit4:junit4] 2> 639732 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1438689639156154368)]} 0 1
[junit4:junit4] 2> 639735 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10044 (1438689639159300097)]} 0 1
[junit4:junit4] 2> 639735 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1438689639159300096)]} 0 1
[junit4:junit4] 2> 639742 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10045 (1438689639166640128)]} 0 1
[junit4:junit4] 2> 639743 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1438689639167688704)]} 0 1
[junit4:junit4] 2> 639745 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10045 (1438689639169785856)]} 0 1
[junit4:junit4] 2> 639746 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1438689639170834432)]} 0 1
[junit4:junit4] 2> 639822 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10039 (-1438689639250526208)]} 0 1
[junit4:junit4] 2> 639822 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[39 (-1438689639251574784)]} 0 0
[junit4:junit4] 2> 639825 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10039 (-1438689639254720512)]} 0 0
[junit4:junit4] 2> 639825 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[39 (-1438689639254720513)]} 0 0
[junit4:junit4] 2> 639829 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1438689639257866240)]} 0 1
[junit4:junit4] 2> 639829 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10046 (1438689639257866241)]} 0 1
[junit4:junit4] 2> 639833 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1438689639262060544)]} 0 1
[junit4:junit4] 2> 639833 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10046 (1438689639262060545)]} 0 1
[junit4:junit4] 2> 639836 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1438689639265206272)]} 0 1
[junit4:junit4] 2> 639837 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10047 (1438689639266254848)]} 0 1
[junit4:junit4] 2> 639839 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1438689639268352000)]} 0 1
[junit4:junit4] 2> 639840 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10047 (1438689639269400576)]} 0 1
[junit4:junit4] 2> 639881 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1438689639312392192)]} 0 1
[junit4:junit4] 2> 639882 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10048 (1438689639313440768)]} 0 1
[junit4:junit4] 2> 639885 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1438689639316586496)]} 0 1
[junit4:junit4] 2> 639886 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10048 (1438689639317635072)]} 0 1
[junit4:junit4] 2> 639988 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[41 (-1438689639424589824)]} 0 1
[junit4:junit4] 2> 639989 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10041 (-1438689639426686976)]} 0 0
[junit4:junit4] 2> 639991 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[41 (-1438689639428784128)]} 0 0
[junit4:junit4] 2> 639992 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10041 (-1438689639429832704)]} 0 0
[junit4:junit4] 2> 639995 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1438689639431929856)]} 0 1
[junit4:junit4] 2> 639996 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10049 (1438689639432978432)]} 0 1
[junit4:junit4] 2> 639998 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1438689639435075584)]} 0 1
[junit4:junit4] 2> 639999 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10049 (1438689639436124160)]} 0 1
[junit4:junit4] 2> 640021 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1438689639459192832)]} 0 1
[junit4:junit4] 2> 640022 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10050 (1438689639460241408)]} 0 1
[junit4:junit4] 2> 640024 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1438689639462338560)]} 0 1
[junit4:junit4] 2> 640026 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10050 (1438689639464435712)]} 0 1
[junit4:junit4] 2> 640047 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[43 (-1438689639486455808)]} 0 1
[junit4:junit4] 2> 640048 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10043 (-1438689639488552960)]} 0 0
[junit4:junit4] 2> 640049 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[43 (-1438689639489601536)]} 0 0
[junit4:junit4] 2> 640051 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10043 (-1438689639491698688)]} 0 0
[junit4:junit4] 2> 640053 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1438689639492747264)]} 0 1
[junit4:junit4] 2> 640055 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10051 (1438689639494844416)]} 0 1
[junit4:junit4] 2> 640056 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1438689639495892992)]} 0 1
[junit4:junit4] 2> 640058 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10051 (1438689639497990144)]} 0 1
[junit4:junit4] 2> 640096 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1438689639537836032)]} 0 1
[junit4:junit4] 2> 640097 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10052 (1438689639538884608)]} 0 1
[junit4:junit4] 2> 640100 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10052 (1438689639542030336)]} 0 1
[junit4:junit4] 2> 640100 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1438689639542030337)]} 0 1
[junit4:junit4] 2> 640123 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1438689639566147584)]} 0 1
[junit4:junit4] 2> 640123 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10053 (1438689639566147585)]} 0 1
[junit4:junit4] 2> 640127 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1438689639570341888)]} 0 1
[junit4:junit4] 2> 640127 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10053 (1438689639570341889)]} 0 1
[junit4:junit4] 2> 640174 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1438689639619624960)]} 0 1
[junit4:junit4] 2> 640175 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10054 (1438689639620673536)]} 0 1
[junit4:junit4] 2> 640178 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1438689639623819264)]} 0 1
[junit4:junit4] 2> 640179 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10054 (1438689639624867840)]} 0 1
[junit4:junit4] 2> 640193 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10055 (1438689639639547904)]} 0 1
[junit4:junit4] 2> 640193 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1438689639639547905)]} 0 1
[junit4:junit4] 2> 640197 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1438689639643742208)]} 0 1
[junit4:junit4] 2> 640197 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10055 (1438689639643742209)]} 0 1
[junit4:junit4] 2> 640237 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[47 (-1438689639685685248)]} 0 1
[junit4:junit4] 2> 640237 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10047 (-1438689639686733824)]} 0 0
[junit4:junit4] 2> 640240 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10047 (-1438689639689879552)]} 0 0
[junit4:junit4] 2> 640240 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[47 (-1438689639689879553)]} 0 0
[junit4:junit4] 2> 640244 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10056 (1438689639693025280)]} 0 1
[junit4:junit4] 2> 640244 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1438689639693025281)]} 0 1
[junit4:junit4] 2> 640248 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1438689639697219584)]} 0 1
[junit4:junit4] 2> 640248 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10056 (1438689639697219585)]} 0 1
[junit4:junit4] 2> 640304 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[48 (-1438689639755939840)]} 0 1
[junit4:junit4] 2> 640304 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10048 (-1438689639756988416)]} 0 0
[junit4:junit4] 2> 640307 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10048 (-1438689639760134144)]} 0 0
[junit4:junit4] 2> 640307 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[48 (-1438689639760134145)]} 0 0
[junit4:junit4] 2> 640311 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1438689639763279872)]} 0 1
[junit4:junit4] 2> 640311 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10057 (1438689639763279873)]} 0 1
[junit4:junit4] 2> 640315 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1438689639767474176)]} 0 1
[junit4:junit4] 2> 640315 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10057 (1438689639767474177)]} 0 1
[junit4:junit4] 2> 640416 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[51 (-1438689639873380352)]} 0 1
[junit4:junit4] 2> 640416 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10051 (-1438689639874428928)]} 0 0
[junit4:junit4] 2> 640419 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[51 (-1438689639877574656)]} 0 0
[junit4:junit4] 2> 640419 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10051 (-1438689639877574657)]} 0 0
[junit4:junit4] 2> 640423 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10058 (1438689639880720385)]} 0 1
[junit4:junit4] 2> 640423 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1438689639880720384)]} 0 1
[junit4:junit4] 2> 640426 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10058 (1438689639883866112)]} 0 1
[junit4:junit4] 2> 640427 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1438689639884914688)]} 0 1
[junit4:junit4] 2> 640452 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10059 (1438689639911129088)]} 0 1
[junit4:junit4] 2> 640453 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1438689639912177664)]} 0 1
[junit4:junit4] 2> 640456 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10059 (1438689639915323392)]} 0 1
[junit4:junit4] 2> 640457 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1438689639916371968)]} 0 1
[junit4:junit4] 2> 640522 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10052 (-1438689639984529408)]} 0 1
[junit4:junit4] 2> 640522 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[52 (-1438689639985577984)]} 0 0
[junit4:junit4] 2> 640525 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[52 (-1438689639988723712)]} 0 0
[junit4:junit4] 2> 640525 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10052 (-1438689639988723713)]} 0 0
[junit4:junit4] 2> 640529 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10060 (1438689639991869440)]} 0 1
[junit4:junit4] 2> 640529 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1438689639991869441)]} 0 1
[junit4:junit4] 2> 640533 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1438689639996063744)]} 0 1
[junit4:junit4] 2> 640533 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10060 (1438689639996063745)]} 0 1
[junit4:junit4] 2> 640603 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[55 (-1438689640069464064)]} 0 1
[junit4:junit4] 2> 640603 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10055 (-1438689640070512640)]} 0 0
[junit4:junit4] 2> 640606 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10055 (-1438689640073658368)]} 0 0
[junit4:junit4] 2> 640606 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[55 (-1438689640073658369)]} 0 0
[junit4:junit4] 2> 640610 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10061 (1438689640076804096)]} 0 1
[junit4:junit4] 2> 640610 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1438689640076804097)]} 0 1
[junit4:junit4] 2> 640614 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1438689640080998400)]} 0 1
[junit4:junit4] 2> 640614 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10061 (1438689640080998401)]} 0 1
[junit4:junit4] 2> 640696 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1438689640166981632)]} 0 1
[junit4:junit4] 2> 640697 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10062 (1438689640168030208)]} 0 1
[junit4:junit4] 2> 640700 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1438689640171175936)]} 0 1
[junit4:junit4] 2> 640701 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10062 (1438689640172224512)]} 0 1
[junit4:junit4] 2> 640727 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1438689640199487488)]} 0 1
[junit4:junit4] 2> 640728 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10063 (1438689640200536064)]} 0 1
[junit4:junit4] 2> 640731 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1438689640203681792)]} 0 1
[junit4:junit4] 2> 640732 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10063 (1438689640204730368)]} 0 1
[junit4:junit4] 2> 640737 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[56 (-1438689640211021824)]} 0 0
[junit4:junit4] 2> 640738 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10056 (-1438689640212070400)]} 0 0
[junit4:junit4] 2> 640740 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[56 (-1438689640214167552)]} 0 0
[junit4:junit4] 2> 640741 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10056 (-1438689640215216128)]} 0 0
[junit4:junit4] 2> 640744 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1438689640217313280)]} 0 1
[junit4:junit4] 2> 640745 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10064 (1438689640218361856)]} 0 1
[junit4:junit4] 2> 640747 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1438689640220459008)]} 0 1
[junit4:junit4] 2> 640749 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10064 (1438689640222556160)]} 0 1
[junit4:junit4] 2> 640777 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1438689640251916288)]} 0 1
[junit4:junit4] 2> 640779 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10065 (1438689640254013440)]} 0 1
[junit4:junit4] 2> 640781 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1438689640256110592)]} 0 1
[junit4:junit4] 2> 640782 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10065 (1438689640257159168)]} 0 1
[junit4:junit4] 2> 640868 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1438689640347336704)]} 0 1
[junit4:junit4] 2> 640869 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10066 (1438689640348385280)]} 0 1
[junit4:junit4] 2> 640872 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1438689640351531008)]} 0 1
[junit4:junit4] 2> 640873 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10066 (1438689640352579584)]} 0 1
[junit4:junit4] 2> 640955 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1438689640438562816)]} 0 2
[junit4:junit4] 2> 640955 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10067 (1438689640438562817)]} 0 1
[junit4:junit4] 2> 640959 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10067 (1438689640442757120)]} 0 1
[junit4:junit4] 2> 640959 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1438689640442757121)]} 0 1
[junit4:junit4] 2> 641055 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10068 (1438689640543420416)]} 0 1
[junit4:junit4] 2> 641055 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1438689640543420417)]} 0 1
[junit4:junit4] 2> 641059 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10068 (1438689640547614720)]} 0 1
[junit4:junit4] 2> 641059 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1438689640547614721)]} 0 1
[junit4:junit4] 2> 641113 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10063 (-1438689640604237824)]} 0 1
[junit4:junit4] 2> 641113 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[63 (-1438689640605286400)]} 0 0
[junit4:junit4] 2> 641116 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10063 (-1438689640608432128)]} 0 0
[junit4:junit4] 2> 641116 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[63 (-1438689640608432129)]} 0 0
[junit4:junit4] 2> 641120 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10069 (1438689640611577856)]} 0 1
[junit4:junit4] 2> 641120 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1438689640611577857)]} 0 1
[junit4:junit4] 2> 641124 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10069 (1438689640615772160)]} 0 1
[junit4:junit4] 2> 641124 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1438689640615772161)]} 0 1
[junit4:junit4] 2> 641173 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10065 (-1438689640667152384)]} 0 1
[junit4:junit4] 2> 641173 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[65 (-1438689640668200960)]} 0 0
[junit4:junit4] 2> 641176 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[65 (-1438689640671346688)]} 0 0
[junit4:junit4] 2> 641176 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10065 (-1438689640671346689)]} 0 0
[junit4:junit4] 2> 641180 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1438689640674492416)]} 0 1
[junit4:junit4] 2> 641180 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10070 (1438689640674492417)]} 0 1
[junit4:junit4] 2> 641184 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1438689640678686720)]} 0 1
[junit4:junit4] 2> 641184 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10070 (1438689640678686721)]} 0 1
[junit4:junit4] 2> 641202 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1438689640697561088)]} 0 1
[junit4:junit4] 2> 641203 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10071 (1438689640698609664)]} 0 1
[junit4:junit4] 2> 641205 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1438689640700706816)]} 0 1
[junit4:junit4] 2> 641207 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10071 (1438689640702803968)]} 0 1
[junit4:junit4] 2> 641222 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[67 (-1438689640718532608)]} 0 1
[junit4:junit4] 2> 641223 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10067 (-1438689640720629760)]} 0 0
[junit4:junit4] 2> 641225 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[67 (-1438689640722726912)]} 0 0
[junit4:junit4] 2> 641226 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10067 (-1438689640723775488)]} 0 0
[junit4:junit4] 2> 641229 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1438689640725872640)]} 0 1
[junit4:junit4] 2> 641230 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10072 (1438689640726921216)]} 0 1
[junit4:junit4] 2> 641232 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1438689640729018368)]} 0 1
[junit4:junit4] 2> 641233 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10072 (1438689640730066944)]} 0 1
[junit4:junit4] 2> 641265 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[70 (-1438689640763621376)]} 0 1
[junit4:junit4] 2> 641265 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10070 (-1438689640764669952)]} 0 0
[junit4:junit4] 2> 641268 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[70 (-1438689640767815680)]} 0 0
[junit4:junit4] 2> 641268 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10070 (-1438689640767815681)]} 0 0
[junit4:junit4] 2> 641272 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73 (1438689640770961409)]} 0 1
[junit4:junit4] 2> 641272 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10073 (1438689640770961408)]} 0 1
[junit4:junit4] 2> 641275 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73 (1438689640774107136)]} 0 1
[junit4:junit4] 2> 641276 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10073 (1438689640775155712)]} 0 1
[junit4:junit4] 2> 641360 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10071 (-1438689640863236096)]} 0 1
[junit4:junit4] 2> 641364 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10071 (-1438689640867430400)]} 0 1
[junit4:junit4] 2> 641366 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[71 (-1438689640870576128)]} 0 1
[junit4:junit4] 2> 641367 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10074 (1438689640870576129)]} 0 1
[junit4:junit4] 2> 641368 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[71 (-1438689640872673280)]} 0 0
[junit4:junit4] 2> 641371 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10074 (1438689640874770432)]} 0 1
[junit4:junit4] 2> 641372 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[74 (1438689640875819008)]} 0 1
[junit4:junit4] 2> 641376 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[74 (1438689640880013312)]} 0 1
[junit4:junit4] 2> 641464 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10075 (1438689640972288000)]} 0 1
[junit4:junit4] 2> 641468 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[75 (1438689640976482304)]} 0 1
[junit4:junit4] 2> 641468 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10075 (1438689640976482304)]} 0 1
[junit4:junit4] 2> 641471 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[75 (1438689640979628032)]} 0 1
[junit4:junit4] 2> 641506 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10072 (-1438689641016328192)]} 0 1
[junit4:junit4] 2> 641507 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[72 (-1438689641018425344)]} 0 0
[junit4:junit4] 2> 641509 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10072 (-1438689641020522496)]} 0 0
[junit4:junit4] 2> 641510 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[72 (-1438689641021571072)]} 0 0
[junit4:junit4] 2> 641513 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10076 (1438689641023668224)]} 0 1
[junit4:junit4] 2> 641514 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[76 (1438689641024716800)]} 0 1
[junit4:junit4] 2> 641516 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10076 (1438689641026813952)]} 0 1
[junit4:junit4] 2> 641517 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[76 (1438689641027862528)]} 0 1
[junit4:junit4] 2> 641596 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10077 (1438689641110700032)]} 0 1
[junit4:junit4] 2> 641597 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[77 (1438689641111748608)]} 0 1
[junit4:junit4] 2> 641600 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[77 (1438689641114894337)]} 0 1
[junit4:junit4] 2> 641600 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10077 (1438689641114894336)]} 0 1
[junit4:junit4] 2> 641695 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[73 (-1438689641214509056)]} 0 1
[junit4:junit4] 2> 641695 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10073 (-1438689641215557632)]} 0 0
[junit4:junit4] 2> 641698 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10073 (-1438689641218703360)]} 0 0
[junit4:junit4] 2> 641698 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[73 (-1438689641218703361)]} 0 0
[junit4:junit4] 2> 641702 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10078 (1438689641221849088)]} 0 1
[junit4:junit4] 2> 641702 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[78 (1438689641221849089)]} 0 1
[junit4:junit4] 2> 641705 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10078 (1438689641224994816)]} 0 1
[junit4:junit4] 2> 641706 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[78 (1438689641226043392)]} 0 1
[junit4:junit4] 2> 641711 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10075 (-1438689641232334848)]} 0 0
[junit4:junit4] 2> 641712 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[75 (-1438689641233383424)]} 0 0
[junit4:junit4] 2> 641714 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10075 (-1438689641235480576)]} 0 0
[junit4:junit4] 2> 641715 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[75 (-1438689641236529152)]} 0 0
[junit4:junit4] 2> 641718 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10079 (1438689641238626304)]} 0 1
[junit4:junit4] 2> 641719 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[79 (1438689641239674880)]} 0 1
[junit4:junit4] 2> 641721 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10079 (1438689641241772032)]} 0 1
[junit4:junit4] 2> 641722 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[79 (1438689641242820608)]} 0 1
[junit4:junit4] 2> 641743 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10080 (1438689641264840704)]} 0 1
[junit4:junit4] 2> 641744 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[80 (1438689641265889280)]} 0 1
[junit4:junit4] 2> 641747 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10080 (1438689641269035008)]} 0 1
[junit4:junit4] 2> 641747 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[80 (1438689641269035009)]} 0 1
[junit4:junit4] 2> 641830 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10081 (1438689641356066816)]} 0 1
[junit4:junit4] 2> 641831 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[81 (1438689641357115392)]} 0 1
[junit4:junit4] 2> 641834 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[81 (1438689641360261120)]} 0 1
[junit4:junit4] 2> 641834 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10081 (1438689641360261121)]} 0 1
[junit4:junit4] 2> 641867 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[76 (-1438689641394864128)]} 0 1
[junit4:junit4] 2> 641867 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10076 (-1438689641395912704)]} 0 0
[junit4:junit4] 2> 641869 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[76 (-1438689641398009856)]} 0 0
[junit4:junit4] 2> 641870 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10076 (-1438689641399058432)]} 0 0
[junit4:junit4] 2> 641873 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[82 (1438689641401155584)]} 0 1
[junit4:junit4] 2> 641874 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10082 (1438689641402204160)]} 0 1
[junit4:junit4] 2> 641876 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[82 (1438689641404301312)]} 0 1
[junit4:junit4] 2> 641877 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10082 (1438689641405349888)]} 0 1
[junit4:junit4] 2> 641881 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[83 (1438689641409544192)]} 0 1
[junit4:junit4] 2> 641882 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10083 (1438689641410592768)]} 0 1
[junit4:junit4] 2> 641884 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[83 (1438689641412689920)]} 0 1
[junit4:junit4] 2> 641886 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10083 (1438689641414787072)]} 0 1
[junit4:junit4] 2> 641952 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[84 (1438689641483993088)]} 0 1
[junit4:junit4] 2> 641954 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10084 (1438689641486090240)]} 0 1
[junit4:junit4] 2> 641956 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[84 (1438689641488187392)]} 0 1
[junit4:junit4] 2> 641958 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10084 (1438689641490284544)]} 0 1
[junit4:junit4] 2> 641991 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[85 (1438689641524887552)]} 0 1
[junit4:junit4] 2> 641993 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10085 (1438689641526984704)]} 0 1
[junit4:junit4] 2> 641995 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[85 (1438689641529081856)]} 0 1
[junit4:junit4] 2> 641996 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10085 (1438689641530130432)]} 0 1
[junit4:junit4] 2> 642005 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[86 (1438689641539567616)]} 0 1
[junit4:junit4] 2> 642006 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10086 (1438689641540616192)]} 0 1
[junit4:junit4] 2> 642009 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10086 (1438689641543761920)]} 0 1
[junit4:junit4] 2> 642009 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[86 (1438689641543761921)]} 0 1
[junit4:junit4] 2> 642084 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10078 (-1438689641622405120)]} 0 1
[junit4:junit4] 2> 642084 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[78 (-1438689641623453696)]} 0 0
[junit4:junit4] 2> 642087 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[78 (-1438689641626599424)]} 0 0
[junit4:junit4] 2> 642087 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10078 (-1438689641626599425)]} 0 0
[junit4:junit4] 2> 642091 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10087 (1438689641629745153)]} 0 1
[junit4:junit4] 2> 642091 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[87 (1438689641629745152)]} 0 1
[junit4:junit4] 2> 642094 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10087 (1438689641632890880)]} 0 1
[junit4:junit4] 2> 642095 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[87 (1438689641633939456)]} 0 1
[junit4:junit4] 2> 642195 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10079 (-1438689641738797056)]} 0 1
[junit4:junit4] 2> 642195 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[79 (-1438689641739845632)]} 0 0
[junit4:junit4] 2> 642198 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10079 (-1438689641742991360)]} 0 0
[junit4:junit4] 2> 642198 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[79 (-1438689641742991361)]} 0 0
[junit4:junit4] 2> 642202 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10088 (1438689641746137088)]} 0 1
[junit4:junit4] 2> 642202 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[88 (1438689641746137089)]} 0 1
[junit4:junit4] 2> 642205 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10088 (1438689641749282816)]} 0 1
[junit4:junit4] 2> 642206 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[88 (1438689641750331392)]} 0 1
[junit4:junit4] 2> 642274 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10089 (1438689641821634560)]} 0 1
[junit4:junit4] 2> 642275 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[89 (1438689641822683136)]} 0 1
[junit4:junit4] 2> 642278 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10089 (1438689641825828864)]} 0 1
[junit4:junit4] 2> 642279 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[89 (1438689641826877440)]} 0 1
[junit4:junit4] 2> 642302 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10082 (-1438689641850994688)]} 0 1
[junit4:junit4] 2> 642302 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[82 (-1438689641852043264)]} 0 0
[junit4:junit4] 2> 642304 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10082 (-1438689641854140416)]} 0 0
[junit4:junit4] 2> 642305 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[82 (-1438689641855188992)]} 0 0
[junit4:junit4] 2> 642308 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10090 (1438689641857286144)]} 0 1
[junit4:junit4] 2> 642309 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[90 (1438689641858334720)]} 0 1
[junit4:junit4] 2> 642311 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10090 (1438689641860431872)]} 0 1
[junit4:junit4] 2> 642312 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[90 (1438689641861480448)]} 0 1
[junit4:junit4] 2> 642330 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10083 (-1438689641881403392)]} 0 0
[junit4:junit4] 2> 642331 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[83 (-1438689641882451968)]} 0 0
[junit4:junit4] 2> 642333 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10083 (-1438689641884549120)]} 0 0
[junit4:junit4] 2> 642334 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[83 (-1438689641885597696)]} 0 0
[junit4:junit4] 2> 642337 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10091 (1438689641887694848)]} 0 1
[junit4:junit4] 2> 642338 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[91 (1438689641888743424)]} 0 1
[junit4:junit4] 2> 642340 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10091 (1438689641890840576)]} 0 1
[junit4:junit4] 2> 642341 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[91 (1438689641891889152)]} 0 1
[junit4:junit4] 2> 642360 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10084 (-1438689641912860672)]} 0 1
[junit4:junit4] 2> 642361 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[84 (-1438689641912860673)]} 0 1
[junit4:junit4] 2> 642363 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10084 (-1438689641916006400)]} 0 0
[junit4:junit4] 2> 642365 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[84 (-1438689641917054976)]} 0 1
[junit4:junit4] 2> 642367 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10092 (1438689641919152128)]} 0 1
[junit4:junit4] 2> 642369 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[92 (1438689641921249280)]} 0 1
[junit4:junit4] 2> 642371 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10092 (1438689641923346432)]} 0 1
[junit4:junit4] 2> 642372 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[92 (1438689641924395008)]} 0 1
[junit4:junit4] 2> 642449 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10086 (-1438689642006183936)]} 0 0
[junit4:junit4] 2> 642450 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[86 (-1438689642007232512)]} 0 0
[junit4:junit4] 2> 642453 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10086 (-1438689642009329664)]} 0 1
[junit4:junit4] 2> 642453 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[86 (-1438689642010378240)]} 0 0
[junit4:junit4] 2> 642457 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10093 (1438689642013523968)]} 0 1
[junit4:junit4] 2> 642458 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[93 (1438689642014572544)]} 0 2
[junit4:junit4] 2> 642461 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[93 (1438689642017718272)]} 0 1
[junit4:junit4] 2> 642461 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10093 (1438689642017718273)]} 0 1
[junit4:junit4] 2> 642485 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[89 (-1438689642042884096)]} 0 1
[junit4:junit4] 2> 642485 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10089 (-1438689642043932672)]} 0 0
[junit4:junit4] 2> 642488 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10089 (-1438689642047078400)]} 0 0
[junit4:junit4] 2> 642489 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[89 (-1438689642047078401)]} 0 1
[junit4:junit4] 2> 642492 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[94 (1438689642050224128)]} 0 1
[junit4:junit4] 2> 642492 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10094 (1438689642050224129)]} 0 1
[junit4:junit4] 2> 642496 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10094 (1438689642054418432)]} 0 1
[junit4:junit4] 2> 642496 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[94 (1438689642054418433)]} 0 1
[junit4:junit4] 2> 642504 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10095 (1438689642062807040)]} 0 1
[junit4:junit4] 2> 642505 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[95 (1438689642063855616)]} 0 1
[junit4:junit4] 2> 642508 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10095 (1438689642067001344)]} 0 1
[junit4:junit4] 2> 642509 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[95 (1438689642068049920)]} 0 1
[junit4:junit4] 2> 642567 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10090 (-1438689642128867328)]} 0 1
[junit4:junit4] 2> 642568 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[90 (-1438689642130964480)]} 0 0
[junit4:junit4] 2> 642570 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10090 (-1438689642133061632)]} 0 0
[junit4:junit4] 2> 642571 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[90 (-1438689642134110208)]} 0 0
[junit4:junit4] 2> 642574 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10096 (1438689642136207360)]} 0 1
[junit4:junit4] 2> 642575 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[96 (1438689642137255936)]} 0 1
[junit4:junit4] 2> 642578 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[96 (1438689642140401664)]} 0 1
[junit4:junit4] 2> 642578 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10096 (1438689642140401665)]} 0 1
[junit4:junit4] 2> 642673 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[97 (1438689642240016384)]} 0 1
[junit4:junit4] 2> 642674 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10097 (1438689642241064960)]} 0 1
[junit4:junit4] 2> 642677 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[97 (1438689642244210688)]} 0 1
[junit4:junit4] 2> 642678 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10097 (1438689642245259264)]} 0 1
[junit4:junit4] 2> 642757 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[98 (1438689642328096768)]} 0 1
[junit4:junit4] 2> 642758 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10098 (1438689642329145344)]} 0 1
[junit4:junit4] 2> 642761 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[98 (1438689642332291072)]} 0 1
[junit4:junit4] 2> 642762 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10098 (1438689642333339648)]} 0 1
[junit4:junit4] 2> 642862 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[99 (1438689642438197248)]} 0 1
[junit4:junit4] 2> 642863 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10099 (1438689642439245824)]} 0 1
[junit4:junit4] 2> 642866 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[99 (1438689642442391552)]} 0 1
[junit4:junit4] 2> 642867 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10099 (1438689642443440128)]} 0 1
[junit4:junit4] 2> 642964 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[91 (-1438689642545152000)]} 0 1
[junit4:junit4] 2> 642964 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10091 (-1438689642546200576)]} 0 0
[junit4:junit4] 2> 642967 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10091 (-1438689642549346304)]} 0 0
[junit4:junit4] 2> 642967 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[91 (-1438689642549346305)]} 0 0
[junit4:junit4] 2> 642971 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[100 (1438689642552492032)]} 0 1
[junit4:junit4] 2> 642971 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10100 (1438689642552492033)]} 0 1
[junit4:junit4] 2> 642974 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[100 (1438689642555637760)]} 0 1
[junit4:junit4] 2> 642975 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10100 (1438689642556686336)]} 0 1
[junit4:junit4] 2> 643074 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[101 (1438689642660495360)]} 0 1
[junit4:junit4] 2> 643075 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10101 (1438689642661543936)]} 0 1
[junit4:junit4] 2> 643078 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[101 (1438689642664689664)]} 0 1
[junit4:junit4] 2> 643078 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10101 (1438689642664689665)]} 0 1
[junit4:junit4] 2> 643178 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[92 (-1438689642769547264)]} 0 1
[junit4:junit4] 2> 643178 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10092 (-1438689642770595840)]} 0 0
[junit4:junit4] 2> 643181 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[92 (-1438689642773741568)]} 0 0
[junit4:junit4] 2> 643181 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10092 (-1438689642773741569)]} 0 0
[junit4:junit4] 2> 643185 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10102 (1438689642776887296)]} 0 1
[junit4:junit4] 2> 643185 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[102 (1438689642776887297)]} 0 1
[junit4:junit4] 2> 643188 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10102 (1438689642780033024)]} 0 1
[junit4:junit4] 2> 643189 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[102 (1438689642781081600)]} 0 1
[junit4:junit4] 2> 643194 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10093 (-1438689642787373056)]} 0 0
[junit4:junit4] 2> 643195 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[93 (-1438689642788421632)]} 0 0
[junit4:junit4] 2> 643197 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10093 (-1438689642790518784)]} 0 0
[junit4:junit4] 2> 643198 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[93 (-1438689642791567360)]} 0 0
[junit4:junit4] 2> 643201 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10103 (1438689642793664512)]} 0 1
[junit4:junit4] 2> 643202 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[103 (1438689642794713088)]} 0 1
[junit4:junit4] 2> 643204 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10103 (1438689642796810240)]} 0 1
[junit4:junit4] 2> 643205 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[103 (1438689642797858816)]} 0 1
[junit4:junit4] 2> 643233 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10104 (1438689642827218944)]} 0 1
[junit4:junit4] 2> 643234 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[104 (1438689642828267520)]} 0 1
[junit4:junit4] 2> 643237 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10104 (1438689642831413248)]} 0 1
[junit4:junit4] 2> 643237 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[104 (1438689642831413249)]} 0 1
[junit4:junit4] 2> 643329 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10095 (-1438689642927882240)]} 0 1
[junit4:junit4] 2> 643329 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[95 (-1438689642928930816)]} 0 0
[junit4:junit4] 2> 643332 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[95 (-1438689642932076544)]} 0 0
[junit4:junit4] 2> 643332 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10095 (-1438689642932076545)]} 0 0
[junit4:junit4] 2> 643336 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10105 (1438689642935222272)]} 0 1
[junit4:junit4] 2> 643336 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[105 (1438689642935222273)]} 0 1
[junit4:junit4] 2> 643339 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10105 (1438689642938368000)]} 0 1
[junit4:junit4] 2> 643340 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[105 (1438689642939416576)]} 0 1
[junit4:junit4] 2> 643433 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10106 (1438689643036934144)]} 0 1
[junit4:junit4] 2> 643435 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[106 (1438689643039031296)]} 0 1
[junit4:junit4] 2> 643437 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10106 (1438689643041128448)]} 0 1
[junit4:junit4] 2> 643438 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[106 (1438689643042177024)]} 0 1
[junit4:junit4] 2> 643458 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10107 (1438689643063148544)]} 0 1
[junit4:junit4] 2> 643459 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[107 (1438689643064197120)]} 0 1
[junit4:junit4] 2> 643461 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10107 (1438689643066294272)]} 0 1
[junit4:junit4] 2> 643462 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[107 (1438689643067342848)]} 0 1
[junit4:junit4] 2> 643537 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10096 (-1438689643145986048)]} 0 1
[junit4:junit4] 2> 643537 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[96 (-1438689643145986049)]} 0 1
[junit4:junit4] 2> 643540 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10096 (-1438689643150180352)]} 0 0
[junit4:junit4] 2> 643540 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[96 (-1438689643150180353)]} 0 0
[junit4:junit4] 2> 643544 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[108 (1438689643153326080)]} 0 1
[junit4:junit4] 2> 643544 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10108 (1438689643153326081)]} 0 1
[junit4:junit4] 2> 643547 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[108 (1438689643156471808)]} 0 1
[junit4:junit4] 2> 643548 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10108 (1438689643157520384)]} 0 1
[junit4:junit4] 2> 643614 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[109 (1438689643226726400)]} 0 1
[junit4:junit4] 2> 643615 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10109 (1438689643227774976)]} 0 1
[junit4:junit4] 2> 643618 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[109 (1438689643230920704)]} 0 1
[junit4:junit4] 2> 643619 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10109 (1438689643231969280)]} 0 1
[junit4:junit4] 2> 643621 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10099 (-1438689643235115008)]} 0 0
[junit4:junit4] 2> 643621 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[99 (-1438689643235115009)]} 0 0
[junit4:junit4] 2> 643624 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[10099 (-1438689643238260736)]} 0 0
[junit4:junit4] 2> 643624 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {delete=[99 (-1438689643238260737)]} 0 0
[junit4:junit4] 2> 643628 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[110 (1438689643241406464)]} 0 1
[junit4:junit4] 2> 643628 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10110 (1438689643241406465)]} 0 1
[junit4:junit4] 2> 643631 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[110 (1438689643244552192)]} 0 1
[junit4:junit4] 2> 643632 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10110 (1438689643245600768)]} 0 1
[junit4:junit4] 2> 643700 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[111 (1438689643316903936)]} 0 1
[junit4:junit4] 2> 643701 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10111 (1438689643317952512)]} 0 1
[junit4:junit4] 2> 643704 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[111 (1438689643321098240)]} 0 1
[junit4:junit4] 2> 643705 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10111 (1438689643322146816)]} 0 1
[junit4:junit4] 2> 643729 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[112 (1438689643347312640)]} 0 1
[junit4:junit4] 2> 643731 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10112 (1438689643349409792)]} 0 1
[junit4:junit4] 2> 643733 T1970 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[112 (1438689643351506944)]} 0 1
[junit4:junit4] 2> 643734 T1971 C944 P29604 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10112 (1438689643352555520)]} 0 1
[junit4:junit4] 2> 643748 T1949 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[113 (1438689643367235584)]} 0 1
[junit4:junit4] 2> 643749 T1950 C943 P54251 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10113 (1438689643368284160)]} 0 1
[junit4:junit4] 2> 643752 T1971 C944 P29604 oasup.LogUpdate
[...truncated too long message...]
asc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 853602 T2014 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 853602 T2014 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 853603 T2014 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:12158/collection1/
[junit4:junit4] 2> 853603 T2014 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:12158 START replicas=[http://127.0.0.1:29604/collection1/] nUpdates=100
[junit4:junit4] 2> 853640 T1937 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 12158
[junit4:junit4] 2> 853640 T1937 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2056639937
[junit4:junit4] 2> 854643 T1937 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 854643 T1937 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 854694 T1937 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 854759 T1937 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 854761 T1937 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:26432 26432
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RecoveryZkTest -Dtests.method=testDistribSearch -Dtests.seed=165080780D09E20C -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/home/hudson/lucene-data/enwiki.random.lines.txt -Dtests.locale=mk_MK -Dtests.timezone=America/Mazatlan -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 230s J0 | RecoveryZkTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: expected:<2143> but was:<86>
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([165080780D09E20C:97B60E607A568230]:0)
[junit4:junit4] > at org.apache.solr.cloud.RecoveryZkTest.doTest(RecoveryZkTest.java:108)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:679)
[junit4:junit4] 2> 854879 T1937 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 854888 T1979 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 854888 T1979 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 854888 T1979 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 883605 T2014 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:12158 couldn't connect to http://127.0.0.1:29604/collection1/, counting as success
[junit4:junit4] 2> 883605 T2014 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:12158 DONE. sync succeeded
[junit4:junit4] 2> 883606 T2014 oasc.SyncStrategy.syncReplicas We have been closed, won't attempt to sync replicas back to leader
[junit4:junit4] 2> 883607 T2014 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 2> 883607 T2014 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@19d8718
[junit4:junit4] 2> 883614 T2014 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=43,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=86,cumulative_deletesById=43,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 883614 T2014 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 883615 T2014 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 883615 T2014 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 883618 T2014 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 883619 T2014 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 883619 T2014 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2;done=false>>]
[junit4:junit4] 2> 883619 T2014 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2
[junit4:junit4] 2> 883620 T2014 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2/index;done=false>>]
[junit4:junit4] 2> 883620 T2014 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.RecoveryZkTest-1372041343016/jetty2/index
[junit4:junit4] 2> 883659 T2014 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 883659 T2014 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 883660 T2014 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 883660 T2014 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=DefaultSimilarity, locale=mk_MK, timezone=America/Mazatlan
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=58848848,total=434372608
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestRandomDVFaceting, TestFaceting, PeerSyncTest, UpdateRequestProcessorFactoryTest, QueryParsingTest, SearchHandlerTest, MBeansHandlerTest, SpatialFilterTest, TestWriterPerf, DistributedQueryElevationComponentTest, PolyFieldTest, DistributedTermsComponentTest, TestStressVersions, TestSolrXmlPersistence, TestPluginEnable, ExternalFileFieldSortTest, TestCloudManagedSchemaAddField, CoreAdminHandlerTest, DocValuesTest, PrimitiveFieldTypeTest, BadCopyFieldTest, TestSchemaResource, ChaosMonkeyNothingIsSafeTest, TestCoreContainer, TestXIncludeConfig, TestFuzzyAnalyzedSuggestions, TestSerializedLuceneMatchVersion, TestSolrDeletionPolicy2, TestSolrCoreProperties, SolrIndexSplitterTest, SliceStateTest, BasicDistributedZkTest, SliceStateUpdateTest, SystemInfoHandlerTest, TermVectorComponentTest, TestFastWriter, TestRealTimeGet, RecoveryZkTest]
[junit4:junit4] Completed on J0 in 259.34s, 1 test, 1 failure <<< FAILURES!
[...truncated 709 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:399: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:372: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:1246: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-NightlyTests-4.x/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 11 ignored (5 assumptions)
Total time: 107 minutes 53 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure