AdminClientIT.java

2015-11-30 17:07:49,559 INFO [host5] Update shard 'shard2' leader as http://localhost:8084
2015-11-30 17:07:49,566 INFO [host5-85] Become leader on "shard2", blocking all requests to the shard....
2015-11-30 17:07:49,566 INFO [host5] Block requests on shard : shard2
2015-11-30 17:07:49,566 INFO [host5-85] Wait until raft logs applied to storage...
2015-11-30 17:07:49,877 INFO [host1] Update shard 'shard1' leader as http://localhost:8080
2015-11-30 17:07:49,877 INFO [host1-81] Become leader on "shard1", blocking all requests to the shard....
2015-11-30 17:07:49,878 INFO [host1] Block requests on shard : shard1
2015-11-30 17:07:49,878 INFO [host1-81] Wait until raft logs applied to storage...
2015-11-30 17:07:49,967 INFO [host9] Update shard 'shard3' leader as http://localhost:8088
2015-11-30 17:07:49,976 INFO [host9-89] Become leader on "shard3", blocking all requests to the shard....
2015-11-30 17:07:49,976 INFO [host9] Block requests on shard : shard3
2015-11-30 17:07:49,976 INFO [host9-89] Wait until raft logs applied to storage...
2015-11-30 17:07:49,985 INFO [admin] Executing assign buckets=[0‥10] from shard1 to shard2
2015-11-30 17:07:49,985 INFO [admin] Initializing slaves on shard2 ...
2015-11-30 17:07:49,986 INFO [admin] Write action START_SLAVE to memberId=86
2015-11-30 17:07:50,001 INFO [admin] Write action START_SLAVE to memberId=85
2015-11-30 17:07:50,002 INFO [admin] Write action START_SLAVE to memberId=84
2015-11-30 17:07:50,002 INFO [host6-86] Processing action=START_SLAVE args=[shard2, shard1, 3000]
2015-11-30 17:07:50,002 INFO [host6] shardId=shard2 follows shardId=shard1 as slave
2015-11-30 17:07:50,003 INFO [host5-85] Processing action=START_SLAVE args=[shard2, shard1, 3000]
2015-11-30 17:07:50,003 INFO [host5] shardId=shard2 follows shardId=shard1 as slave
2015-11-30 17:07:50,005 INFO [host4-84] Processing action=START_SLAVE args=[shard2, shard1, 3000]
2015-11-30 17:07:50,005 INFO [host4] shardId=shard2 follows shardId=shard1 as slave
2015-11-30 17:07:50,067 INFO [host5-85] Raft logs are up-to-date, notify application is ready to serve...
2015-11-30 17:07:50,067 INFO [host5-85] Ready for serving, unblocking the requests...
2015-11-30 17:07:50,067 INFO [host5] Request unblocked on shardId=shard2
2015-11-30 17:07:50,067 INFO [host5-85] System is back to serving, unblocked 1 requests ...
2015-11-30 17:07:50,225 INFO [host8] Update shard 'shard3' leader as http://localhost:8088
2015-11-30 17:07:50,225 INFO [host6] Successfully connect to leader node=81
2015-11-30 17:07:50,225 INFO [host6] Successfully to follow masterId=81
2015-11-30 17:07:50,225 INFO [host4] Successfully connect to leader node=81
2015-11-30 17:07:50,225 INFO [host4] Successfully to follow masterId=81
2015-11-30 17:07:50,225 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-11-30 17:07:50,225 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-11-30 17:07:50,232 INFO [host5] Successfully connect to leader node=81
2015-11-30 17:07:50,233 INFO [host5] Successfully to follow masterId=81
2015-11-30 17:07:50,233 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=RUNNING, reason='null'}
2015-11-30 17:07:50,246 INFO [host4] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:50,246 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-11-30 17:07:50,380 INFO [host1-81] Raft logs are up-to-date, notify application is ready to serve...
2015-11-30 17:07:50,380 INFO [host1-81] Ready for serving, unblocking the requests...
2015-11-30 17:07:50,380 INFO [host1] Request unblocked on shardId=shard1
2015-11-30 17:07:50,380 INFO [host1-81] System is back to serving, unblocked 1 requests ...
2015-11-30 17:07:50,403 INFO [host6] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:50,403 INFO [host5] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:50,403 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-11-30 17:07:50,403 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=APPROACHED, reason='null'}
2015-11-30 17:07:50,481 INFO [host9-89] Raft logs are up-to-date, notify application is ready to serve...
2015-11-30 17:07:50,481 INFO [host9-89] Ready for serving, unblocking the requests...
2015-11-30 17:07:50,481 INFO [host9] Request unblocked on shardId=shard3
2015-11-30 17:07:50,481 INFO [host9-89] System is back to serving, unblocked 1 requests ...
2015-11-30 17:07:50,547 INFO [host4] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:50,706 INFO [host5] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:50,706 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=SLAVE, status=SYNCED, reason='null'}
2015-11-30 17:07:50,850 INFO [host4] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:51,010 INFO [host5] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:51,017 INFO [admin] All nodes in shard2 are in slave mode, waiting for slave logs approaching to leader's log position.
2015-11-30 17:07:51,018 INFO [admin] All nodes in shard2 logs approached to leader's log position, assigning buckets=[0‥10] ...
2015-11-30 17:07:51,019 INFO [admin] Write action MIGRATE_1 to memberId=81
2015-11-30 17:07:51,022 INFO [admin] Write action MIGRATE_1 to memberId=82
2015-11-30 17:07:51,023 INFO [admin] Write action MIGRATE_1 to memberId=83
2015-11-30 17:07:51,023 INFO [host1-81] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-11-30 17:07:51,023 INFO [host1] Block requests on buckets : [0‥10]
2015-11-30 17:07:51,023 INFO Waiting for no requests on buckets: [0‥10] with timeout=3000ms, current requestCount=0
2015-11-30 17:07:51,034 INFO [host2-82] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-11-30 17:07:51,034 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-11-30 17:07:51,034 INFO [host3-83] Processing action=MIGRATE_1 args=[0, 10, shard1, shard2, 3000]
2015-11-30 17:07:51,034 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=MIGRATING_1, status=RUNNING, reason='null'}
2015-11-30 17:07:51,155 INFO [host4] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:51,310 INFO [host5] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:51,458 INFO [host4] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:51,612 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=SLAVE, status=SYNCED, reason='null'}
2015-11-30 17:07:51,762 INFO [host4] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:52,066 INFO [host4] shard2 Log status=RUNNING, currentDiff=N/A, targetDiff=0
2015-11-30 17:07:52,369 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=SLAVE, status=FAILED, reason='java.util.concurrent.ExecutionException: com.yahoo.gondola.container.ShardManagerProtocol$ShardManagerException: MASTER_IS_GONE'}
2015-11-30 17:07:54,031 INFO [host1] Write action STOP_SLAVE to memberId=86
2015-11-30 17:07:54,031 INFO [admin] Write action MIGRATE_3 to memberId=81
2015-11-30 17:07:54,039 INFO [admin] Write action MIGRATE_3 to memberId=82
2015-11-30 17:07:54,039 INFO [host1] Write action STOP_SLAVE to memberId=85
2015-11-30 17:07:54,041 INFO [admin] Write action MIGRATE_3 to memberId=83
2015-11-30 17:07:54,041 INFO [host1] Write action STOP_SLAVE to memberId=84
2015-11-30 17:07:54,042 INFO [admin] Write action MIGRATE_3 to memberId=84
2015-11-30 17:07:54,043 INFO [host6-86] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-11-30 17:07:54,043 INFO [host6] shardId=shard2 un-followed shardId=shard1
2015-11-30 17:07:54,043 INFO [host2-82] Processing action=MIGRATE_3 args=[0, 10, shard1, shard2, true]
2015-11-30 17:07:54,043 INFO [host5-85] Processing action=STOP_SLAVE args=[shard2, shard1, 3000]
2015-11-30 17:07:54,043 INFO [host2] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=COMPLETE
2015-11-30 17:07:54,044 INFO [host5] shardId=shard2 un-followed shardId=shard1
2015-11-30 17:07:54,047 INFO [admin] Write action MIGRATE_3 to memberId=85
2015-11-30 17:07:54,047 INFO [host3-83] Processing action=MIGRATE_3 args=[0, 10, shard1, shard2, true]
2015-11-30 17:07:54,047 INFO [host3] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=COMPLETE
2015-11-30 17:07:54,048 INFO [host4-84] Processing action=MIGRATE_3 args=[0, 10, shard1, shard2, true]
2015-11-30 17:07:54,048 INFO [host4] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=COMPLETE
2015-11-30 17:07:54,050 INFO [admin] Write action MIGRATE_3 to memberId=86
2015-11-30 17:07:54,056 INFO [admin] Write action MIGRATE_3 to memberId=87
2015-11-30 17:07:54,058 INFO [admin] Write action MIGRATE_3 to memberId=88
2015-11-30 17:07:54,060 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,060 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,061 INFO [admin] Write action MIGRATE_3 to memberId=89
2015-11-30 17:07:54,062 INFO [host7-87] Processing action=MIGRATE_3 args=[0, 10, shard1, shard2, true]
2015-11-30 17:07:54,062 INFO [host7] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=COMPLETE
2015-11-30 17:07:54,068 INFO [host8-88] Processing action=MIGRATE_3 args=[0, 10, shard1, shard2, true]
2015-11-30 17:07:54,068 INFO [host5-85] Processing action=MIGRATE_3 args=[0, 10, shard1, shard2, true]
2015-11-30 17:07:54,068 INFO [host8] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=COMPLETE
2015-11-30 17:07:54,068 INFO [host5] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=COMPLETE
2015-11-30 17:07:54,069 INFO [host6-86] Processing action=MIGRATE_3 args=[0, 10, shard1, shard2, true]
2015-11-30 17:07:54,069 INFO [host6] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=COMPLETE
2015-11-30 17:07:54,072 INFO [host9-89] Processing action=MIGRATE_3 args=[0, 10, shard1, shard2, true]
2015-11-30 17:07:54,072 INFO [host9] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=COMPLETE
2015-11-30 17:07:54,074 INFO [host6-86] Update stat stat=ZookeeperStat{memberId=86, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,074 INFO [host9-89] Update stat stat=ZookeeperStat{memberId=89, shardId='shard3', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,074 INFO [host8-88] Update stat stat=ZookeeperStat{memberId=88, shardId='shard3', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,074 INFO [host2-82] Update stat stat=ZookeeperStat{memberId=82, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,074 INFO [host5-85] Update stat stat=ZookeeperStat{memberId=85, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,074 INFO [host3-83] Update stat stat=ZookeeperStat{memberId=83, shardId='shard1', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,074 INFO [host4-84] Update stat stat=ZookeeperStat{memberId=84, shardId='shard2', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:54,074 INFO [host7-87] Update stat stat=ZookeeperStat{memberId=87, shardId='shard3', mode=NORMAL, status=RUNNING, reason='null'}
2015-11-30 17:07:55,048 INFO Update global bucket table for buckets= from [0‥10] to shard1
2015-11-30 17:07:55,049 INFO [host1] Write action MIGRATE_2 to memberId=81
2015-11-30 17:07:55,057 INFO [host1] Write action MIGRATE_2 to memberId=82
2015-11-30 17:07:55,060 INFO [host1] Write action MIGRATE_2 to memberId=83
2015-11-30 17:07:55,061 INFO [host1] Write action MIGRATE_2 to memberId=84
2015-11-30 17:07:55,061 INFO [host2-82] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-11-30 17:07:55,062 INFO [host2] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-11-30 17:07:55,062 INFO [host1] Write action MIGRATE_2 to memberId=85
2015-11-30 17:07:55,062 INFO [host3-83] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-11-30 17:07:55,062 INFO [host3] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-11-30 17:07:55,062 WARN [host2] Process action error - Bucket range=[0‥10] should be owned by shard=shard1, but got shard=shard2
2015-11-30 17:07:55,062 WARN [host3] Process action error - Bucket range=[0‥10] should be owned by shard=shard1, but got shard=shard2
2015-11-30 17:07:55,062 INFO [host1] Write action MIGRATE_2 to memberId=86
2015-11-30 17:07:55,063 INFO [host4-84] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-11-30 17:07:55,063 INFO [host4] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-11-30 17:07:55,063 WARN [host4] Process action error - Bucket range=[0‥10] should be owned by shard=shard1, but got shard=shard2
2015-11-30 17:07:55,063 INFO [host1] Write action MIGRATE_2 to memberId=87
2015-11-30 17:07:55,063 INFO [host5-85] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-11-30 17:07:55,063 INFO [host5] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-11-30 17:07:55,064 WARN [host5] Process action error - Bucket range=[0‥10] should be owned by shard=shard1, but got shard=shard2
2015-11-30 17:07:55,064 INFO [host1] Write action MIGRATE_2 to memberId=88
2015-11-30 17:07:55,064 INFO [host6-86] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-11-30 17:07:55,064 INFO [host6] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-11-30 17:07:55,065 WARN [host6] Process action error - Bucket range=[0‥10] should be owned by shard=shard1, but got shard=shard2
2015-11-30 17:07:55,065 INFO [host1] Write action MIGRATE_2 to memberId=89
2015-11-30 17:07:55,065 INFO [host7-87] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-11-30 17:07:55,065 INFO [host7] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-11-30 17:07:55,065 WARN [host7] Process action error - Bucket range=[0‥10] should be owned by shard=shard1, but got shard=shard2
2015-11-30 17:07:55,066 INFO [host8-88] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-11-30 17:07:55,066 INFO [host8] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-11-30 17:07:55,066 WARN [host8] Process action error - Bucket range=[0‥10] should be owned by shard=shard1, but got shard=shard2
2015-11-30 17:07:55,066 INFO [host9-89] Processing action=MIGRATE_2 args=[0, 10, shard1, shard2, false]
2015-11-30 17:07:55,067 INFO [host9] Update local bucket table: buckets=[0‥10] shard1 => shard2. status=MIGRATING
2015-11-30 17:07:55,067 WARN [host9] Process action error - Bucket range=[0‥10] should be owned by shard=shard1, but got shard=shard2
2015-11-30 17:07:55,068 INFO [admin] Done!
java.lang.AssertionError: expected [shard2] but found [shard1]
Expected :shard2
Actual   :shard1
 <Click to see difference>


	at org.testng.Assert.fail(Assert.java:94)
	at org.testng.Assert.failNotEquals(Assert.java:496)
	at org.testng.Assert.assertEquals(Assert.java:125)
	at org.testng.Assert.assertEquals(Assert.java:178)
	at org.testng.Assert.assertEquals(Assert.java:188)
	at com.yahoo.gondola.container.AdminClientIT.testAssignBuckets(AdminClientIT.java:181)
	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)