temp-testng-customsuite.xml

/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/bin/java -Dvisualvm.id=63931688523892 -ea -Didea.launcher.port=7546 "-Didea.launcher.bin.path=/Applications/IntelliJ IDEA 15.app/Contents/bin" -Didea.testng.sm_runner -Dfile.encoding=UTF-8 -classpath "/Applications/IntelliJ IDEA 15.app/Contents/lib/idea_rt.jar:/Applications/IntelliJ IDEA 15.app/Contents/plugins/testng/lib/testng-plugin.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/lib/ant-javafx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/lib/dt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/lib/javafx-mx.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/lib/jconsole.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/lib/sa-jdi.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/lib/tools.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/charsets.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/deploy.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/javaws.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/jce.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/jfr.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/jfxswt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/jsse.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/management-agent.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/plugin.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/resources.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/rt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/cldrdata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/dnsns.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/jfxrt.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/localedata.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/nashorn.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/sunec.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/sunjce_provider.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/sunpkcs11.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_25.jdk/Contents/Home/jre/lib/ext/zipfs.jar:/Users/wcpan2/git/gondola/containers/jersey2-routing/target/test-classes:/Users/wcpan2/git/gondola/containers/jersey2-routing/target/classes:/Users/wcpan2/.m2/repository/org/apache/httpcomponents/httpclient/4.5.1/httpclient-4.5.1.jar:/Users/wcpan2/.m2/repository/org/apache/httpcomponents/httpcore/4.4.3/httpcore-4.4.3.jar:/Users/wcpan2/.m2/repository/commons-logging/commons-logging/1.2/commons-logging-1.2.jar:/Users/wcpan2/.m2/repository/commons-codec/commons-codec/1.9/commons-codec-1.9.jar:/Users/wcpan2/.m2/repository/org/slf4j/jcl-over-slf4j/1.7.13/jcl-over-slf4j-1.7.13.jar:/Users/wcpan2/.m2/repository/org/apache/httpcomponents/httpclient/4.5.1/httpclient-4.5.1-tests.jar:/Users/wcpan2/.m2/repository/commons-io/commons-io/2.4/commons-io-2.4.jar:/Users/wcpan2/.m2/repository/com/jcraft/jsch/0.1.53/jsch-0.1.53.jar:/Users/wcpan2/.m2/repository/com/jcraft/jsch.agentproxy.usocket-jna/0.0.9/jsch.agentproxy.usocket-jna-0.0.9.jar:/Users/wcpan2/.m2/repository/com/jcraft/jsch.agentproxy.core/0.0.9/jsch.agentproxy.core-0.0.9.jar:/Users/wcpan2/.m2/repository/net/java/dev/jna/jna/4.1.0/jna-4.1.0.jar:/Users/wcpan2/.m2/repository/net/java/dev/jna/jna-platform/4.1.0/jna-platform-4.1.0.jar:/Users/wcpan2/.m2/repository/com/jcraft/jsch.agentproxy.sshagent/0.0.9/jsch.agentproxy.sshagent-0.0.9.jar:/Users/wcpan2/.m2/repository/com/jcraft/jsch.agentproxy.connector-factory/0.0.9/jsch.agentproxy.connector-factory-0.0.9.jar:/Users/wcpan2/.m2/repository/com/jcraft/jsch.agentproxy.usocket-nc/0.0.9/jsch.agentproxy.usocket-nc-0.0.9.jar:/Users/wcpan2/.m2/repository/com/jcraft/jsch.agentproxy.pageant/0.0.9/jsch.agentproxy.pageant-0.0.9.jar:/Users/wcpan2/.m2/repository/com/jcraft/jsch.agentproxy.jsch/0.0.9/jsch.agentproxy.jsch-0.0.9.jar:/Users/wcpan2/.m2/repository/com/google/guava/guava/18.0/guava-18.0.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/containers/jersey-container-servlet/2.22.1/jersey-container-servlet-2.22.1.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/containers/jersey-container-servlet-core/2.22.1/jersey-container-servlet-core-2.22.1.jar:/Users/wcpan2/.m2/repository/org/glassfish/hk2/external/javax.inject/2.4.0-b31/javax.inject-2.4.0-b31.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/core/jersey-common/2.22.1/jersey-common-2.22.1.jar:/Users/wcpan2/.m2/repository/javax/annotation/javax.annotation-api/1.2/javax.annotation-api-1.2.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/bundles/repackaged/jersey-guava/2.22.1/jersey-guava-2.22.1.jar:/Users/wcpan2/.m2/repository/org/glassfish/hk2/hk2-api/2.4.0-b31/hk2-api-2.4.0-b31.jar:/Users/wcpan2/.m2/repository/org/glassfish/hk2/hk2-utils/2.4.0-b31/hk2-utils-2.4.0-b31.jar:/Users/wcpan2/.m2/repository/org/glassfish/hk2/external/aopalliance-repackaged/2.4.0-b31/aopalliance-repackaged-2.4.0-b31.jar:/Users/wcpan2/.m2/repository/org/glassfish/hk2/hk2-locator/2.4.0-b31/hk2-locator-2.4.0-b31.jar:/Users/wcpan2/.m2/repository/org/glassfish/hk2/osgi-resource-locator/1.0.1/osgi-resource-locator-1.0.1.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/core/jersey-server/2.22.1/jersey-server-2.22.1.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/core/jersey-client/2.22.1/jersey-client-2.22.1.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/media/jersey-media-jaxb/2.22.1/jersey-media-jaxb-2.22.1.jar:/Users/wcpan2/.m2/repository/javax/validation/validation-api/1.1.0.Final/validation-api-1.1.0.Final.jar:/Users/wcpan2/.m2/repository/javax/ws/rs/javax.ws.rs-api/2.0.1/javax.ws.rs-api-2.0.1.jar:/Users/wcpan2/.m2/repository/javax/javaee-api/7.0/javaee-api-7.0.jar:/Users/wcpan2/.m2/repository/com/sun/mail/javax.mail/1.5.0/javax.mail-1.5.0.jar:/Users/wcpan2/.m2/repository/javax/activation/activation/1.1/activation-1.1.jar:/Users/wcpan2/.m2/repository/org/apache/curator/curator-framework/2.9.1/curator-framework-2.9.1.jar:/Users/wcpan2/.m2/repository/org/apache/curator/curator-client/2.9.1/curator-client-2.9.1.jar:/Users/wcpan2/.m2/repository/org/apache/curator/curator-test/2.9.1/curator-test-2.9.1.jar:/Users/wcpan2/.m2/repository/org/apache/zookeeper/zookeeper/3.4.6/zookeeper-3.4.6.jar:/Users/wcpan2/.m2/repository/jline/jline/0.9.94/jline-0.9.94.jar:/Users/wcpan2/.m2/repository/io/netty/netty/3.7.0.Final/netty-3.7.0.Final.jar:/Users/wcpan2/.m2/repository/org/javassist/javassist/3.18.1-GA/javassist-3.18.1-GA.jar:/Users/wcpan2/.m2/repository/org/apache/commons/commons-math/2.2/commons-math-2.2.jar:/Users/wcpan2/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.6.3/jackson-databind-2.6.3.jar:/Users/wcpan2/.m2/repository/com/fasterxml/jackson/core/jackson-annotations/2.6.0/jackson-annotations-2.6.0.jar:/Users/wcpan2/.m2/repository/com/fasterxml/jackson/core/jackson-core/2.6.3/jackson-core-2.6.3.jar:/Users/wcpan2/.m2/repository/org/apache/curator/curator-recipes/2.9.1/curator-recipes-2.9.1.jar:/Users/wcpan2/.m2/repository/com/purej/purej-vminspect/1.2.9/purej-vminspect-1.2.9.jar:/Users/wcpan2/.m2/repository/org/jrobin/jrobin/1.5.9/jrobin-1.5.9.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/media/jersey-media-json-jackson/2.22.1/jersey-media-json-jackson-2.22.1.jar:/Users/wcpan2/.m2/repository/org/glassfish/jersey/ext/jersey-entity-filtering/2.22.1/jersey-entity-filtering-2.22.1.jar:/Users/wcpan2/.m2/repository/com/fasterxml/jackson/jaxrs/jackson-jaxrs-base/2.5.4/jackson-jaxrs-base-2.5.4.jar:/Users/wcpan2/.m2/repository/com/fasterxml/jackson/jaxrs/jackson-jaxrs-json-provider/2.5.4/jackson-jaxrs-json-provider-2.5.4.jar:/Users/wcpan2/.m2/repository/com/fasterxml/jackson/module/jackson-module-jaxb-annotations/2.5.4/jackson-module-jaxb-annotations-2.5.4.jar:/Users/wcpan2/.m2/repository/commons-cli/commons-cli/1.3.1/commons-cli-1.3.1.jar:/Users/wcpan2/git/gondola/core/target/classes:/Users/wcpan2/.m2/repository/com/typesafe/config/1.3.0/config-1.3.0.jar:/Users/wcpan2/.m2/repository/mysql/mysql-connector-java/5.1.37/mysql-connector-java-5.1.37.jar:/Users/wcpan2/.m2/repository/com/h2database/h2/1.4.190/h2-1.4.190.jar:/Users/wcpan2/.m2/repository/com/zaxxer/HikariCP/2.4.2/HikariCP-2.4.2.jar:/Users/wcpan2/.m2/repository/org/slf4j/slf4j-api/1.7.13/slf4j-api-1.7.13.jar:/Users/wcpan2/.m2/repository/org/slf4j/slf4j-log4j12/1.7.13/slf4j-log4j12-1.7.13.jar:/Users/wcpan2/.m2/repository/log4j/log4j/1.2.17/log4j-1.2.17.jar:/Users/wcpan2/.m2/repository/org/testng/testng/6.9.9/testng-6.9.9.jar:/Users/wcpan2/.m2/repository/junit/junit/4.10/junit-4.10.jar:/Users/wcpan2/.m2/repository/org/hamcrest/hamcrest-core/1.1/hamcrest-core-1.1.jar:/Users/wcpan2/.m2/repository/com/beust/jcommander/1.48/jcommander-1.48.jar:/Users/wcpan2/.m2/repository/org/apache/ant/ant/1.7.0/ant-1.7.0.jar:/Users/wcpan2/.m2/repository/org/apache/ant/ant-launcher/1.7.0/ant-launcher-1.7.0.jar:/Users/wcpan2/.m2/repository/org/yaml/snakeyaml/1.15/snakeyaml-1.15.jar:/Users/wcpan2/.m2/repository/org/beanshell/bsh/2.0b4/bsh-2.0b4.jar:/Users/wcpan2/.m2/repository/org/mockito/mockito-all/1.10.19/mockito-all-1.10.19.jar:/Applications/IntelliJ IDEA 15.app/Contents/plugins/testng/lib/jcommander.jar" com.intellij.rt.execution.application.AppMain org.testng.RemoteTestNGStarter -port 56570 -usedefaultlisteners false -socket56571 @w@/private/var/folders/sc/wbydt3v52r75rxps4dbfc9940000gt/T/idea_working_dirs_testng0.tmp -temp /private/var/folders/sc/wbydt3v52r75rxps4dbfc9940000gt/T/idea_testng0.tmp
[TestNG] Running:
  /Users/wcpan2/Library/Caches/IntelliJIdea15/temp-testng-customsuite.xml
2015-12-14 12:18:25,969 INFO [host5-85] Initializing zookeeper node...
2015-12-14 12:18:26,124 INFO [host4-84] Initializing zookeeper node...
2015-12-14 12:18:26,160 INFO [host5] New leader 85 elected.
2015-12-14 12:18:26,160 WARN Trying to update routingTable with self appUri. -- skip
2015-12-14 12:18:26,163 INFO [host6] New leader 85 elected.
2015-12-14 12:18:26,163 INFO [host6] Update shard 'shard2' leader as http://localhost:8084
2015-12-14 12:18:26,165 INFO [host5-85] Become leader on "shard2", blocking all requests to the shard....
2015-12-14 12:18:26,165 INFO [host5] Block requests on shard : shard2
2015-12-14 12:18:26,165 INFO [host5-85] Wait until raft logs applied to storage...
2015-12-14 12:18:26,166 INFO [host4] New leader 85 elected.
2015-12-14 12:18:26,166 INFO [host4] Update shard 'shard2' leader as http://localhost:8084
2015-12-14 12:18:26,169 INFO [host6-86] Initializing zookeeper node...
2015-12-14 12:18:26,217 INFO [host1-81] Initializing zookeeper node...
2015-12-14 12:18:26,289 INFO [host3-83] Initializing zookeeper node...
2015-12-14 12:18:26,371 INFO [host2-82] Initializing zookeeper node...
2015-12-14 12:18:26,372 INFO [host3] New leader 83 elected.
2015-12-14 12:18:26,372 WARN Trying to update routingTable with self appUri. -- skip
2015-12-14 12:18:26,372 INFO [host2] New leader 83 elected.
2015-12-14 12:18:26,372 INFO [host1] New leader 83 elected.
2015-12-14 12:18:26,372 INFO [host2] Update shard 'shard1' leader as http://localhost:8082
2015-12-14 12:18:26,372 INFO [host1] Update shard 'shard1' leader as http://localhost:8082
2015-12-14 12:18:26,372 INFO [host3-83] Become leader on "shard1", blocking all requests to the shard....
2015-12-14 12:18:26,372 INFO [host3] Block requests on shard : shard1
2015-12-14 12:18:26,373 INFO [host3-83] Wait until raft logs applied to storage...
2015-12-14 12:18:26,667 INFO [host5-85] Raft logs are up-to-date, notify application is ready to serve...
2015-12-14 12:18:26,667 INFO [host5-85] Ready for serving, unblocking the requests...
2015-12-14 12:18:26,667 INFO [host5] Request unblocked on shardId=shard2
2015-12-14 12:18:26,667 INFO [host5-85] System is back to serving, unblocked 1 requests ...
2015-12-14 12:18:26,879 INFO [host3-83] Raft logs are up-to-date, notify application is ready to serve...
2015-12-14 12:18:26,879 INFO [host3-83] Ready for serving, unblocking the requests...
2015-12-14 12:18:26,879 INFO [host3] Request unblocked on shardId=shard1
2015-12-14 12:18:26,880 INFO [host3-83] System is back to serving, unblocked 1 requests ...
2015-12-14 12:18:27,455 INFO [admin] Executing assign buckets=[0‥10] from shard1 to shard2
2015-12-14 12:18:27,455 INFO [admin] Initializing slaves on shard2 ...
2015-12-14 12:18:27,457 INFO [admin] Write action START_SLAVE to memberId=86, params=[shard2, shard1, 9000]
2015-12-14 12:18:27,473 INFO [admin] Write action START_SLAVE to memberId=85, params=[shard2, shard1, 9000]
2015-12-14 12:18:27,474 INFO [admin] Write action START_SLAVE to memberId=84, params=[shard2, shard1, 9000]
2015-12-14 12:18:27,474 INFO [host6-86] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:27,474 INFO [host6-86] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:27,475 INFO [host5-85] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:27,475 INFO [host5-85] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:27,479 INFO [host4-84] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:27,479 INFO [host4-84] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:27,704 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:27,706 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:27,715 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:28,709 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:28,709 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:28,719 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:29,714 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:29,714 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:29,722 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:30,711 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:30,713 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:30,727 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:31,716 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:31,716 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:31,733 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:32,720 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:32,720 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:32,733 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:33,721 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:33,721 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:33,737 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:34,724 INFO [host5] Successfully connect to leader node=83
2015-12-14 12:18:34,724 INFO [host4] Successfully connect to leader node=83
2015-12-14 12:18:34,724 INFO Reset and interrupt change log processor
2015-12-14 12:18:34,724 INFO Reset and interrupt change log processor
2015-12-14 12:18:34,724 INFO [host5-85] Successfully to follow masterId=83
2015-12-14 12:18:34,724 INFO [host4-84] Successfully to follow masterId=83
2015-12-14 12:18:34,724 INFO [host5-85] ChangeLogProcessor reset appliedIndex to 0
2015-12-14 12:18:34,724 INFO [host4-84] ChangeLogProcessor reset appliedIndex to 0
2015-12-14 12:18:34,724 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:18:34,724 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:18:34,725 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:18:34,725 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:34,740 INFO [host6] Successfully connect to leader node=83
2015-12-14 12:18:34,740 INFO Reset and interrupt change log processor
2015-12-14 12:18:34,740 INFO [host6-86] Successfully to follow masterId=83
2015-12-14 12:18:34,740 INFO [host6-86] ChangeLogProcessor reset appliedIndex to 0
2015-12-14 12:18:34,740 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:18:34,740 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:18:34,742 INFO [admin] All nodes in shard2 are in slave mode, waiting for slave logs approaching to leader's log position.
2015-12-14 12:18:34,750 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:34,750 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:18:34,895 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:34,896 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:18:34,946 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:34,946 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:18:34,949 INFO [admin] All nodes in shard2 logs approached to leader's log position, assigning buckets=[0‥10] ...
2015-12-14 12:18:34,949 INFO [admin] Write action MIGRATE_1 to memberId=81, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:34,952 INFO [admin] Write action MIGRATE_1 to memberId=82, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:34,953 INFO [admin] Write action MIGRATE_1 to memberId=83, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:34,954 INFO [host1-81] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:34,954 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:18:34,955 INFO [host2-82] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:34,955 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:18:34,957 INFO [host3-83] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:34,957 INFO [host3] Block requests on buckets : [0‥10]
2015-12-14 12:18:34,957 INFO Waiting for no requests on buckets: [0‥10] with timeout=3000ms, current requestCount=0
2015-12-14 12:18:35,053 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,201 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,251 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,355 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,504 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,553 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,657 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,727 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:18:35,727 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:35,745 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:18:35,808 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,855 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:35,962 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,110 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,157 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,266 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,412 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,461 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,568 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,713 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,731 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:18:36,731 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:36,750 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:18:36,766 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:36,872 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,015 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,067 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,174 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,319 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,370 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,476 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,621 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,671 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,735 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:37,735 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:18:37,755 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:18:37,780 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,924 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:37,956 INFO [admin] Write action MIGRATE_2 to memberId=81, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,959 INFO [host3] Write action STOP_SLAVE to memberId=86, params=[shard2, shard1, 3000]
2015-12-14 12:18:37,964 INFO [admin] Write action MIGRATE_2 to memberId=82, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,964 INFO [host3] Write action STOP_SLAVE to memberId=85, params=[shard2, shard1, 3000]
2015-12-14 12:18:37,965 INFO [admin] Write action MIGRATE_2 to memberId=83, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,965 INFO [host3] Write action STOP_SLAVE to memberId=84, params=[shard2, shard1, 3000]
2015-12-14 12:18:37,966 INFO [admin] Write action MIGRATE_2 to memberId=84, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,966 INFO [host6-86] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:37,966 INFO [host6] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:37,966 INFO [host1-81] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,966 INFO [host1] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:37,967 INFO [host2-82] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,967 INFO [host2] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:37,968 INFO [host5-85] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:37,968 INFO [host5] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:37,968 INFO [admin] Write action MIGRATE_2 to memberId=85, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,969 INFO [admin] Write action MIGRATE_2 to memberId=86, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,969 INFO [host4-84] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:37,970 INFO [host4] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:37,980 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:37,981 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:37,981 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:38,037 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:38,038 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:38,038 INFO [host6-86] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:38,038 INFO [host6] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:38,039 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:38,039 INFO [host5-85] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:38,039 INFO [host5] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:38,039 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:38,043 INFO [host5] New leader 85 elected.
2015-12-14 12:18:38,044 WARN Trying to update routingTable with self appUri. -- skip
2015-12-14 12:18:38,044 INFO [host5-85] Become leader on "shard2", blocking all requests to the shard....
2015-12-14 12:18:38,044 INFO [host5] Block requests on shard : shard2
2015-12-14 12:18:38,044 INFO [host5-85] Wait until raft logs applied to storage...
2015-12-14 12:18:38,047 INFO [host6] New leader 85 elected.
2015-12-14 12:18:38,047 INFO [host6] Update shard 'shard2' leader as http://localhost:8084
2015-12-14 12:18:38,736 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:39,052 INFO [host5-85] Raft logs are up-to-date, notify application is ready to serve...
2015-12-14 12:18:39,052 INFO [host5-85] Ready for serving, unblocking the requests...
2015-12-14 12:18:39,052 INFO [host5] Request unblocked on shardId=shard2
2015-12-14 12:18:39,052 INFO [host5-85] System is back to serving, unblocked 1 requests ...
2015-12-14 12:18:39,736 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:40,738 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:40,971 INFO [host3] Update bucket range=[0‥10] from shard1 to shard2
2015-12-14 12:18:40,971 INFO [host3] Unblock requests on buckets : [0‥10]
2015-12-14 12:18:40,971 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:18:40,975 WARN Error occurred during assign buckets.. retrying 1 / 3, errorMsg=FAILED_SET_BUCKETS-timed out
2015-12-14 12:18:40,975 INFO [admin] Write action STOP_SLAVE to memberId=86, params=[shard2, shard1, 3000]
2015-12-14 12:18:40,980 INFO [host3-83] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:40,980 INFO [host3] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:40,980 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:40,980 INFO [admin] Write action STOP_SLAVE to memberId=85, params=[shard2, shard1, 3000]
2015-12-14 12:18:40,982 INFO [admin] Write action STOP_SLAVE to memberId=84, params=[shard2, shard1, 3000]
2015-12-14 12:18:40,982 INFO [host6-86] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:40,982 INFO [host6] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:40,982 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:40,984 INFO [host5-85] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:40,985 INFO [host5] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:40,985 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:40,986 INFO [host4-84] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:40,986 INFO [host4] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:41,066 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:41,068 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=81, params=[0, 10]
2015-12-14 12:18:41,069 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=82, params=[0, 10]
2015-12-14 12:18:41,070 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=83, params=[0, 10]
2015-12-14 12:18:41,070 INFO [host1-81] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:41,071 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:41,071 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=84, params=[0, 10]
2015-12-14 12:18:41,071 INFO [host2-82] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:41,071 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:41,073 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=85, params=[0, 10]
2015-12-14 12:18:41,074 INFO [host3-83] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:41,074 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:41,075 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=86, params=[0, 10]
2015-12-14 12:18:41,077 INFO [host4-84] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:41,078 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:41,079 INFO [host5-85] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:41,079 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:41,082 INFO [host4] New leader 85 elected.
2015-12-14 12:18:41,082 INFO [admin] Write action NOOP to memberId=81, params=[]
2015-12-14 12:18:41,082 INFO [host4] Update shard 'shard2' leader as http://localhost:8084
2015-12-14 12:18:41,082 INFO [host6-86] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:41,083 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:41,084 INFO [admin] Write action NOOP to memberId=82, params=[]
2015-12-14 12:18:41,085 INFO [admin] Write action NOOP to memberId=83, params=[]
2015-12-14 12:18:41,086 INFO [admin] Write action NOOP to memberId=84, params=[]
2015-12-14 12:18:41,087 INFO [admin] Write action NOOP to memberId=85, params=[]
2015-12-14 12:18:41,088 INFO [admin] Write action NOOP to memberId=86, params=[]
2015-12-14 12:18:41,090 INFO [admin] Initializing slaves on shard2 ...
2015-12-14 12:18:41,090 INFO [admin] Write action START_SLAVE to memberId=86, params=[shard2, shard1, 9000]
2015-12-14 12:18:41,091 INFO [admin] Write action START_SLAVE to memberId=85, params=[shard2, shard1, 9000]
2015-12-14 12:18:41,092 INFO [admin] Write action START_SLAVE to memberId=84, params=[shard2, shard1, 9000]
2015-12-14 12:18:41,092 INFO [host6-86] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:41,092 INFO [host6-86] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:41,094 INFO [host5-85] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:41,094 INFO [host5-85] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:41,095 INFO [host4-84] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:41,095 INFO [host4-84] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:41,344 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:41,352 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:41,368 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:41,739 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:42,348 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:42,356 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:42,369 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:42,743 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:43,349 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:43,361 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:43,373 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:43,743 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:44,353 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:44,360 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:44,378 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:44,748 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:45,359 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:45,362 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:45,382 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:45,752 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:46,361 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:46,366 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:46,383 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:46,756 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:47,360 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:47,367 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:47,392 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:47,761 INFO [host4-84] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (84) is in slave mode
2015-12-14 12:18:48,364 INFO [host5] Successfully connect to leader node=83
2015-12-14 12:18:48,364 INFO Reset and interrupt change log processor
2015-12-14 12:18:48,364 INFO [host5-85] Successfully to follow masterId=83
2015-12-14 12:18:48,364 INFO [host5-85] ChangeLogProcessor reset appliedIndex to 0
2015-12-14 12:18:48,364 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:18:48,364 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:18:48,370 INFO [host6] Successfully connect to leader node=83
2015-12-14 12:18:48,370 INFO Reset and interrupt change log processor
2015-12-14 12:18:48,370 INFO [host6-86] Successfully to follow masterId=83
2015-12-14 12:18:48,370 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:18:48,370 INFO [host6-86] ChangeLogProcessor reset appliedIndex to 0
2015-12-14 12:18:48,370 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:18:48,379 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:48,379 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:18:48,396 INFO [host4] Successfully connect to leader node=83
2015-12-14 12:18:48,396 INFO Reset and interrupt change log processor
2015-12-14 12:18:48,397 INFO [host4-84] Successfully to follow masterId=83
2015-12-14 12:18:48,397 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:18:48,397 WARN [host4-84] ChangeLogProcessor interrupted, exit..
2015-12-14 12:18:48,399 INFO [admin] All nodes in shard2 are in slave mode, waiting for slave logs approaching to leader's log position.
2015-12-14 12:18:48,529 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:48,529 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:18:48,567 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:48,567 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:18:48,569 INFO [admin] All nodes in shard2 logs approached to leader's log position, assigning buckets=[0‥10] ...
2015-12-14 12:18:48,569 INFO [admin] Write action MIGRATE_1 to memberId=81, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:48,570 INFO [admin] Write action MIGRATE_1 to memberId=82, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:48,571 INFO [admin] Write action MIGRATE_1 to memberId=83, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:48,571 INFO [host1-81] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:48,571 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:18:48,572 INFO [host2-82] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:48,572 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:18:48,573 INFO [host3-83] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:18:48,573 INFO [host3] Block requests on buckets : [0‥10]
2015-12-14 12:18:48,573 INFO Waiting for no requests on buckets: [0‥10] with timeout=3000ms, current requestCount=0
2015-12-14 12:18:48,683 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:48,834 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:48,872 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:48,985 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,139 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,176 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,290 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,368 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:18:49,374 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:18:49,443 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,479 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,590 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,745 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,780 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:49,891 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,048 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,084 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,193 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,349 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,372 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:18:50,378 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:18:50,385 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,494 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,652 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,688 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,796 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,953 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:50,994 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:51,098 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:51,256 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:51,295 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:51,377 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:18:51,382 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:18:51,403 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:51,556 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:18:51,574 INFO [admin] Write action MIGRATE_2 to memberId=81, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,575 INFO [host3] Write action STOP_SLAVE to memberId=86, params=[shard2, shard1, 3000]
2015-12-14 12:18:51,581 INFO [admin] Write action MIGRATE_2 to memberId=82, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,582 INFO [host3] Write action STOP_SLAVE to memberId=85, params=[shard2, shard1, 3000]
2015-12-14 12:18:51,582 INFO [admin] Write action MIGRATE_2 to memberId=83, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,583 INFO [host3] Write action STOP_SLAVE to memberId=84, params=[shard2, shard1, 3000]
2015-12-14 12:18:51,583 INFO [host1-81] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,583 INFO [host1] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:51,583 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:51,583 INFO [host6-86] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:51,584 INFO [host6] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:51,584 INFO [admin] Write action MIGRATE_2 to memberId=84, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,584 INFO [host2-82] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,584 INFO [host2] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:51,585 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:51,585 INFO [host5-85] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:51,585 INFO [host5] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:51,586 INFO [admin] Write action MIGRATE_2 to memberId=85, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,587 INFO [host4-84] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,587 INFO [host4] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:51,587 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:51,587 INFO [admin] Write action MIGRATE_2 to memberId=86, params=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,694 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:51,694 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:51,696 INFO [host6-86] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,696 INFO [host6] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:51,696 INFO [host5-85] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:51,696 INFO [host5] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:51,696 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:51,697 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:51,715 INFO [host5] New leader 85 elected.
2015-12-14 12:18:51,716 WARN Trying to update routingTable with self appUri. -- skip
2015-12-14 12:18:51,716 INFO [host6] New leader 85 elected.
2015-12-14 12:18:51,716 INFO [host6] Update shard 'shard2' leader as http://localhost:8084
2015-12-14 12:18:51,716 INFO [host5-85] Become leader on "shard2", blocking all requests to the shard....
2015-12-14 12:18:51,716 INFO [host5] Block requests on shard : shard2
2015-12-14 12:18:51,716 INFO [host5-85] Wait until raft logs applied to storage...
2015-12-14 12:18:52,718 INFO [host5-85] Raft logs are up-to-date, notify application is ready to serve...
2015-12-14 12:18:52,718 INFO [host5-85] Ready for serving, unblocking the requests...
2015-12-14 12:18:52,719 INFO [host5] Request unblocked on shardId=shard2
2015-12-14 12:18:52,719 INFO [host5-85] System is back to serving, unblocked 1 requests ...
2015-12-14 12:18:54,587 INFO [host3] Update bucket range=[0‥10] from shard1 to shard2
2015-12-14 12:18:54,588 INFO [host3] Unblock requests on buckets : [0‥10]
2015-12-14 12:18:54,588 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:18:54,593 WARN Error occurred during assign buckets.. retrying 2 / 3, errorMsg=FAILED_SET_BUCKETS-timed out
2015-12-14 12:18:54,593 INFO [admin] Write action STOP_SLAVE to memberId=86, params=[shard2, shard1, 3000]
2015-12-14 12:18:54,596 INFO [host3-83] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:18:54,596 INFO [host3] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:18:54,596 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:18:54,596 INFO [admin] Write action STOP_SLAVE to memberId=85, params=[shard2, shard1, 3000]
2015-12-14 12:18:54,597 INFO [admin] Write action STOP_SLAVE to memberId=84, params=[shard2, shard1, 3000]
2015-12-14 12:18:54,598 INFO [host6-86] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:54,598 INFO [host6] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:54,598 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,599 INFO [host5-85] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:54,600 INFO [host5] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:54,600 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,602 INFO [host4-84] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:18:54,602 INFO [host4] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:18:54,733 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,735 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=81, params=[0, 10]
2015-12-14 12:18:54,735 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=82, params=[0, 10]
2015-12-14 12:18:54,736 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=83, params=[0, 10]
2015-12-14 12:18:54,737 INFO [host1-81] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:54,737 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,737 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=84, params=[0, 10]
2015-12-14 12:18:54,737 INFO [host2-82] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:54,737 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,738 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=85, params=[0, 10]
2015-12-14 12:18:54,739 INFO [host3-83] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:54,739 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,739 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=86, params=[0, 10]
2015-12-14 12:18:54,740 INFO [host4-84] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:54,740 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,741 INFO [host5-85] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:54,741 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,741 INFO [admin] Write action NOOP to memberId=81, params=[]
2015-12-14 12:18:54,742 INFO [admin] Write action NOOP to memberId=82, params=[]
2015-12-14 12:18:54,743 INFO [host6-86] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:18:54,743 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:18:54,743 INFO [admin] Write action NOOP to memberId=83, params=[]
2015-12-14 12:18:54,745 INFO [admin] Write action NOOP to memberId=84, params=[]
2015-12-14 12:18:54,746 INFO [admin] Write action NOOP to memberId=85, params=[]
2015-12-14 12:18:54,748 INFO [admin] Write action NOOP to memberId=86, params=[]
2015-12-14 12:18:54,749 INFO [admin] Initializing slaves on shard2 ...
2015-12-14 12:18:54,749 INFO [admin] Write action START_SLAVE to memberId=86, params=[shard2, shard1, 9000]
2015-12-14 12:18:54,750 INFO [admin] Write action START_SLAVE to memberId=85, params=[shard2, shard1, 9000]
2015-12-14 12:18:54,750 INFO [host6-86] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:54,750 INFO [host6-86] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:54,751 INFO [admin] Write action START_SLAVE to memberId=84, params=[shard2, shard1, 9000]
2015-12-14 12:18:54,751 INFO [host4] New leader 85 elected.
2015-12-14 12:18:54,751 INFO [host4] Update shard 'shard2' leader as http://localhost:8084
2015-12-14 12:18:54,751 INFO [host5-85] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:54,751 INFO [host5-85] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:54,752 INFO [host4-84] Processing action=START_SLAVE args=[shard2, shard1, 9000]
2015-12-14 12:18:54,752 INFO [host4-84] Try to follow shardId=shard1 as slave...
2015-12-14 12:18:55,009 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:55,012 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:55,016 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:56,011 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:56,015 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:56,021 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:57,017 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:57,019 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:57,022 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=81, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:58,021 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:58,024 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:58,025 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:59,023 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:59,028 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:18:59,029 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:19:00,026 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:19:00,031 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:19:00,031 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=82, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:19:01,032 INFO [host5] Slave status=SlaveStatus{running=false, memberId=85, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:19:01,036 INFO [host4] Slave status=SlaveStatus{running=false, memberId=84, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:19:01,036 INFO [host6] Slave status=SlaveStatus{running=false, memberId=86, masterId=83, commitIndex=0, savedIndex=0, exception=null} role=CANDIDATE
2015-12-14 12:19:02,036 INFO [host5] Successfully connect to leader node=83
2015-12-14 12:19:02,036 INFO Reset and interrupt change log processor
2015-12-14 12:19:02,036 INFO [host5-85] Successfully to follow masterId=83
2015-12-14 12:19:02,036 INFO [host5-85] ChangeLogProcessor reset appliedIndex to 0
2015-12-14 12:19:02,036 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:19:02,036 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:19:02,043 INFO [host4] Successfully connect to leader node=83
2015-12-14 12:19:02,043 INFO [host6] Successfully connect to leader node=83
2015-12-14 12:19:02,043 INFO Reset and interrupt change log processor
2015-12-14 12:19:02,043 INFO [host6-86] Successfully to follow masterId=83
2015-12-14 12:19:02,043 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:19:02,043 INFO Reset and interrupt change log processor
2015-12-14 12:19:02,043 INFO [host4-84] Successfully to follow masterId=83
2015-12-14 12:19:02,043 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-12-14 12:19:02,043 INFO [host6-86] ChangeLogProcessor reset appliedIndex to 0
2015-12-14 12:19:02,043 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:19:02,046 INFO [admin] All nodes in shard2 are in slave mode, waiting for slave logs approaching to leader's log position.
2015-12-14 12:19:02,157 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:02,157 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:19:02,197 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:02,197 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:19:02,290 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:02,290 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-12-14 12:19:02,292 INFO [admin] All nodes in shard2 logs approached to leader's log position, assigning buckets=[0‥10] ...
2015-12-14 12:19:02,292 INFO [admin] Write action MIGRATE_1 to memberId=81, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:19:02,293 INFO [admin] Write action MIGRATE_1 to memberId=82, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:19:02,295 INFO [admin] Write action MIGRATE_1 to memberId=83, params=[0, 10, shard1, shard2, 3000]
2015-12-14 12:19:02,295 INFO [host1-81] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:19:02,295 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:19:02,296 INFO [host2-82] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:19:02,296 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:19:02,297 INFO [host3-83] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-12-14 12:19:02,297 INFO [host3] Block requests on buckets : [0‥10]
2015-12-14 12:19:02,297 INFO Waiting for no requests on buckets: [0‥10] with timeout=3000ms, current requestCount=0
2015-12-14 12:19:02,464 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:02,501 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:02,595 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:02,766 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:02,804 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:02,900 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,036 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:19:03,048 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:19:03,068 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,106 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,205 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,370 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,410 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,509 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,672 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,712 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,811 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:03,973 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,017 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,040 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:19:04,050 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:19:04,113 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,277 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,322 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,415 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,579 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,625 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,717 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,881 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:04,930 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:05,018 INFO [host5] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:05,044 INFO [host5-85] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (85) is in slave mode
2015-12-14 12:19:05,053 INFO [host6-86] Error while get gondola command, appliedIndex=0, error=This operation is not allowed while the member (86) is in slave mode
2015-12-14 12:19:05,185 INFO [host4] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:05,233 INFO [host6] shard2 Log status=RUNNING, ci=15, si=15, ai=0 targetDiff=0
2015-12-14 12:19:05,300 INFO [admin] Write action MIGRATE_2 to memberId=81, params=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,300 INFO [host3] Write action STOP_SLAVE to memberId=86, params=[shard2, shard1, 3000]
2015-12-14 12:19:05,307 INFO [admin] Write action MIGRATE_2 to memberId=82, params=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,307 INFO [host3] Write action STOP_SLAVE to memberId=85, params=[shard2, shard1, 3000]
2015-12-14 12:19:05,308 INFO [admin] Write action MIGRATE_2 to memberId=83, params=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,308 INFO [host3] Write action STOP_SLAVE to memberId=84, params=[shard2, shard1, 3000]
2015-12-14 12:19:05,309 INFO [host1-81] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,310 INFO [host1] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:19:05,310 INFO [host6-86] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:19:05,310 INFO [host6] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:19:05,310 INFO [admin] Write action MIGRATE_2 to memberId=84, params=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,310 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:19:05,310 INFO [host2-82] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,310 INFO [host2] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:19:05,310 INFO [host5-85] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:19:05,310 INFO [host5] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:19:05,311 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:19:05,311 INFO [admin] Write action MIGRATE_2 to memberId=85, params=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,312 INFO [host4-84] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,312 INFO [host4] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:19:05,312 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:19:05,313 INFO [admin] Write action MIGRATE_2 to memberId=86, params=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,349 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:05,351 INFO [host6-86] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,351 INFO [host6] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:19:05,353 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:05,354 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:19:05,357 INFO [host5-85] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:19:05,358 INFO [host5] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:19:05,358 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:19:05,360 INFO [host5] New leader 85 elected.
2015-12-14 12:19:05,360 WARN Trying to update routingTable with self appUri. -- skip
2015-12-14 12:19:05,361 INFO [host5-85] Become leader on "shard2", blocking all requests to the shard....
2015-12-14 12:19:05,361 INFO [host5] Block requests on shard : shard2
2015-12-14 12:19:05,361 INFO [host5-85] Wait until raft logs applied to storage...
2015-12-14 12:19:05,364 INFO [host6] New leader 85 elected.
2015-12-14 12:19:05,364 INFO [host6] Update shard 'shard2' leader as http://localhost:8084
2015-12-14 12:19:06,365 INFO [host5-85] Raft logs are up-to-date, notify application is ready to serve...
2015-12-14 12:19:06,365 INFO [host5-85] Ready for serving, unblocking the requests...
2015-12-14 12:19:06,365 INFO [host5] Request unblocked on shardId=shard2
2015-12-14 12:19:06,365 INFO [host5-85] System is back to serving, unblocked 1 requests ...
2015-12-14 12:19:08,314 INFO [host3] Update bucket range=[0‥10] from shard1 to shard2
2015-12-14 12:19:08,315 INFO [host3] Unblock requests on buckets : [0‥10]
2015-12-14 12:19:08,315 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-12-14 12:19:08,315 WARN Error occurred during assign buckets.. retrying 3 / 3, errorMsg=FAILED_SET_BUCKETS-timed out
2015-12-14 12:19:08,315 INFO [admin] Write action STOP_SLAVE to memberId=86, params=[shard2, shard1, 3000]
2015-12-14 12:19:08,322 INFO [host3-83] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-12-14 12:19:08,322 INFO [host3] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-12-14 12:19:08,322 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=MIGRATING_2, status=RUNNING, reason='null'}
2015-12-14 12:19:08,322 INFO [admin] Write action STOP_SLAVE to memberId=85, params=[shard2, shard1, 3000]
2015-12-14 12:19:08,324 INFO [admin] Write action STOP_SLAVE to memberId=84, params=[shard2, shard1, 3000]
2015-12-14 12:19:08,324 INFO [host6-86] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:19:08,324 INFO [host6] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:19:08,324 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,326 INFO [host5-85] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:19:08,326 INFO [host5] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:19:08,326 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,327 INFO [host4-84] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-12-14 12:19:08,327 INFO [host4] shardId=shard2 un-followed shardId=shard1
2015-12-14 12:19:08,384 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,386 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=81, params=[0, 10]
2015-12-14 12:19:08,387 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=82, params=[0, 10]
2015-12-14 12:19:08,388 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=83, params=[0, 10]
2015-12-14 12:19:08,388 INFO [host1-81] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:19:08,388 INFO [host1-81] Update stat stat=ZookeeperStat{memberId=81, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,389 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=84, params=[0, 10]
2015-12-14 12:19:08,390 INFO [host2-82] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:19:08,391 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,391 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=85, params=[0, 10]
2015-12-14 12:19:08,392 INFO [host3-83] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:19:08,392 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,392 INFO [admin] Write action MIGRATE_ROLLBACK to memberId=86, params=[0, 10]
2015-12-14 12:19:08,395 INFO [host4-84] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:19:08,395 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,395 INFO [admin] Write action NOOP to memberId=81, params=[]
2015-12-14 12:19:08,395 INFO [host4] New leader 85 elected.
2015-12-14 12:19:08,395 INFO [host4] Update shard 'shard2' leader as http://localhost:8084
2015-12-14 12:19:08,398 INFO [admin] Write action NOOP to memberId=82, params=[]
2015-12-14 12:19:08,398 INFO [host5-85] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:19:08,399 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,400 INFO [host6-86] Processing action=MIGRATE_ROLLBACK args=[0, 10]
2015-12-14 12:19:08,400 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-12-14 12:19:08,400 INFO [admin] Write action NOOP to memberId=83, params=[]
2015-12-14 12:19:08,403 INFO [admin] Write action NOOP to memberId=84, params=[]
2015-12-14 12:19:08,405 INFO [admin] Write action NOOP to memberId=85, params=[]
2015-12-14 12:19:08,406 INFO [admin] Write action NOOP to memberId=86, params=[]
2015-12-14 12:19:08,406 ERROR Assign bucket failed, lastError=FAILED_SET_BUCKETS-timed out
com.yahoo.gondola.container.AdminClient$AdminException: com.yahoo.gondola.container.ShardManagerProtocol$ShardManagerException: FAILED_SET_BUCKETS-timed out

	at com.yahoo.gondola.container.AdminClient.assignBuckets(AdminClient.java:163)
	at com.yahoo.gondola.container.AdminClientIT.testAssignBucketByType(AdminClientIT.java:192)
	at com.yahoo.gondola.container.AdminClientIT.testAssignBuckets_zookeeper(AdminClientIT.java:180)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
	at org.testng.internal.Invoker.invokeMethod(Invoker.java:639)
	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:816)
	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1124)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:108)
	at org.testng.TestRunner.privateRun(TestRunner.java:774)
	at org.testng.TestRunner.run(TestRunner.java:624)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:359)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:354)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:312)
	at org.testng.SuiteRunner.run(SuiteRunner.java:261)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1215)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
	at org.testng.TestNG.run(TestNG.java:1048)
	at org.testng.IDEARemoteTestNG.run(IDEARemoteTestNG.java:72)
	at org.testng.RemoteTestNGStarter.main(RemoteTestNGStarter.java:122)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:144)
Caused by: com.yahoo.gondola.container.ShardManagerProtocol$ShardManagerException: FAILED_SET_BUCKETS-timed out
	at com.yahoo.gondola.container.client.ZookeeperShardManagerClient.setBuckets(ZookeeperShardManagerClient.java:208)
	at com.yahoo.gondola.container.client.ZookeeperShardManagerClient.migrateBuckets(ZookeeperShardManagerClient.java:170)
	at com.yahoo.gondola.container.AdminClient.assignBuckets(AdminClient.java:147)
	... 30 more


===============================================
Default Suite
Total tests run: 1, Failures: 1, Skips: 0
===============================================


Process finished with exit code 0