You are viewing a plain text version of this content. The canonical link for it is here.
Posted to jira@kafka.apache.org by "Matthias J. Sax (Jira)" <ji...@apache.org> on 2021/12/10 09:15:00 UTC
[jira] [Comment Edited] (KAFKA-8115) Flaky Test CoordinatorTest#testTaskRequestWithOldStartMsGetsUpdated
[ https://issues.apache.org/jira/browse/KAFKA-8115?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17456993#comment-17456993 ]
Matthias J. Sax edited comment on KAFKA-8115 at 12/10/21, 9:14 AM:
-------------------------------------------------------------------
One more on 3.0.
was (Author: mjsax):
One more on 3.1.
> Flaky Test CoordinatorTest#testTaskRequestWithOldStartMsGetsUpdated
> -------------------------------------------------------------------
>
> Key: KAFKA-8115
> URL: https://issues.apache.org/jira/browse/KAFKA-8115
> Project: Kafka
> Issue Type: Bug
> Components: core, unit tests
> Affects Versions: 2.3.0
> Reporter: Matthias J. Sax
> Priority: Critical
> Labels: flaky-test
>
> [https://builds.apache.org/job/kafka-pr-jdk11-scala2.12/3254/testReport/junit/org.apache.kafka.trogdor.coordinator/CoordinatorTest/testTaskRequestWithOldStartMsGetsUpdated/]
> {quote}org.junit.runners.model.TestTimedOutException: test timed out after 120000 milliseconds at java.base@11.0.1/jdk.internal.misc.Unsafe.park(Native Method) at java.base@11.0.1/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:234) at java.base@11.0.1/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2123) at java.base@11.0.1/java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1454) at java.base@11.0.1/java.util.concurrent.Executors$DelegatedExecutorService.awaitTermination(Executors.java:709) at app//org.apache.kafka.trogdor.rest.JsonRestServer.waitForShutdown(JsonRestServer.java:157) at app//org.apache.kafka.trogdor.agent.Agent.waitForShutdown(Agent.java:123) at app//org.apache.kafka.trogdor.common.MiniTrogdorCluster.close(MiniTrogdorCluster.java:285) at app//org.apache.kafka.trogdor.coordinator.CoordinatorTest.testTaskRequestWithOldStartMsGetsUpdated(CoordinatorTest.java:596) at java.base@11.0.1/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base@11.0.1/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base@11.0.1/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base@11.0.1/java.lang.reflect.Method.invoke(Method.java:566) at app//org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) at app//org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at app//org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) at app//org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at app//org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:288) at app//org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:282) at java.base@11.0.1/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base@11.0.1/java.lang.Thread.run(Thread.java:834){quote}
> STDOUT
> {quote}[2019-03-15 09:23:41,364] INFO Creating MiniTrogdorCluster with agents: node02 and coordinator: node01 (org.apache.kafka.trogdor.common.MiniTrogdorCluster:135) [2019-03-15 09:23:41,595] INFO Logging initialized @13340ms to org.eclipse.jetty.util.log.Slf4jLog (org.eclipse.jetty.util.log:193) [2019-03-15 09:23:41,752] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:23:41,912] INFO Registered resource org.apache.kafka.trogdor.agent.AgentRestResource@3fa38ceb (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:23:42,178] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:23:42,360] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:23:42,362] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:23:42,370] INFO node0 Scavenging every 660000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:23:44,412] INFO Started o.e.j.s.ServletContextHandler@335a5293\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:23:44,473] INFO Started ServerConnector@79a93bf1\{HTTP/1.1,[http/1.1]}{0.0.0.0:33477} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:23:44,474] INFO Started @16219ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:23:44,475] INFO REST server listening at [http://127.0.1.1:33477/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:23:44,484] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:23:44,485] INFO Registered resource org.apache.kafka.trogdor.coordinator.CoordinatorRestResource@2e06ee92 (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:23:44,486] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:23:44,536] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:23:44,537] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:23:44,537] INFO node0 Scavenging every 600000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:23:44,901] INFO Started o.e.j.s.ServletContextHandler@742ebd90\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:23:44,912] INFO Started ServerConnector@1fcfcaee\{HTTP/1.1,[http/1.1]}{0.0.0.0:33468} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:23:44,913] INFO Started @16658ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:23:44,914] INFO REST server listening at [http://127.0.1.1:33468/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:23:44,952] INFO Created TaskManager for agent(s) on: node01, node02 (org.apache.kafka.trogdor.coordinator.TaskManager:144) [2019-03-15 09:23:44,959] DEBUG Sending POST with input \{"id":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}} to [http://localhost:33468/coordinator/task/create] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:45,471] TRACE Scheduling org.apache.kafka.trogdor.coordinator.TaskManager$RunTask@5b39f9b3 for 1 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:23:45,472] INFO Created a new task foo with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}, scheduled to start 1 ms from now. (org.apache.kafka.trogdor.coordinator.TaskManager:366) [2019-03-15 09:23:45,584] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks/foo] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:45,624] INFO 127.0.0.1 - - [15/Mar/2019:09:23:45 +0000] "POST /coordinator/task/create HTTP/1.1" 200 2 356 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:45,672] TRACE Invoking org.apache.kafka.trogdor.coordinator.TaskManager$RunTask@5b39f9b3 at 2 (org.apache.kafka.common.utils.MockScheduler:105) [2019-03-15 09:23:45,673] INFO Running task foo on node(s): node02 (org.apache.kafka.trogdor.coordinator.TaskManager:400) [2019-03-15 09:23:45,675] INFO node02: scheduling worker foo_0 to start. (org.apache.kafka.trogdor.coordinator.NodeManager:297) [2019-03-15 09:23:45,676] DEBUG Sending GET with input null to [http://127.0.0.1:33477/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:45,693] INFO 127.0.0.1 - - [15/Mar/2019:09:23:45 +0000] "GET /coordinator/tasks/foo HTTP/1.1" 200 123 57 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:45,699] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:45,761] INFO 127.0.0.1 - - [15/Mar/2019:09:23:45 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 41 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:45,795] INFO 127.0.0.1 - - [15/Mar/2019:09:23:45 +0000] "GET /agent/status HTTP/1.1" 200 19 55 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:45,795] TRACE node02: got heartbeat status \{"serverStartMs":0} (org.apache.kafka.trogdor.coordinator.NodeManager:205) [2019-03-15 09:23:45,801] DEBUG Sending POST with input \{"workerId":0,"taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}} to [http://127.0.0.1:33477/agent/worker/create] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:45,799] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:45,806] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:45,806] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:45,829] INFO node02: Created worker foo_0 with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10} (org.apache.kafka.trogdor.agent.WorkerManager:402) [2019-03-15 09:23:45,836] INFO foo: Activating NoOpTask. (org.apache.kafka.trogdor.task.NoOpTaskWorker:40) [2019-03-15 09:23:45,839] INFO node02: Worker foo_0 is now RUNNING. Scheduled to stop in 10 ms. (org.apache.kafka.trogdor.agent.WorkerManager:431) [2019-03-15 09:23:45,839] INFO 127.0.0.1 - - [15/Mar/2019:09:23:45 +0000] "POST /agent/worker/create HTTP/1.1" 200 2 37 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:45,851] TRACE Scheduling org.apache.kafka.trogdor.agent.WorkerManager$StopWorker@7ae7edae for 9 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:23:45,907] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:45,916] INFO 127.0.0.1 - - [15/Mar/2019:09:23:45 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 7 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:45,924] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:45,925] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:45,925] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:45,941] DEBUG Sending GET with input null to [http://127.0.0.1:8888/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:45,943] INFO GET [http://127.0.0.1:8888/agent/status:] error: Connection refused (Connection refused) (org.apache.kafka.trogdor.rest.JsonRestServer:281) [2019-03-15 09:23:45,943] ERROR node01: failed to get agent status: ConnectException Connection refused (Connection refused) (org.apache.kafka.trogdor.coordinator.NodeManager:196) [2019-03-15 09:23:46,026] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,031] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,033] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:46,034] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:46,034] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:46,135] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,140] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,141] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:46,142] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:46,142] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:46,243] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,247] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,249] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:46,250] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:46,250] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:46,352] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,356] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,357] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:46,358] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:46,358] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:46,459] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,464] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,468] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:46,469] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:46,469] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:46,570] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,574] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,575] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:46,576] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:46,577] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:46,676] DEBUG Sending GET with input null to [http://127.0.0.1:33477/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:46,680] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /agent/status HTTP/1.1" 200 192 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,681] TRACE node02: got heartbeat status \{"serverStartMs":0,"workers":{"0":{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.coordinator.NodeManager:205) [2019-03-15 09:23:46,682] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,688] INFO node02: worker state changed from \{"state":"RECEIVING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}} to \{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"} (org.apache.kafka.trogdor.coordinator.NodeManager:252) [2019-03-15 09:23:46,691] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 162 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,692] DEBUG Task foo: Updating worker state for 0 on node02 from \{"state":"RECEIVING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}} to \{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}. (org.apache.kafka.trogdor.coordinator.TaskManager:563) [2019-03-15 09:23:46,693] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:46,694] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:46,694] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:46,795] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,801] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 159 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,803] DEBUG Sending GET with input null to [http://localhost:33477/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:46,809] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /agent/status HTTP/1.1" 200 192 4 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,810] DEBUG Sending GET with input null to [http://localhost:33468/coordinator/tasks/non-existent-foo] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:46,824] DEBUG Uncaught exception in REST call: (org.apache.kafka.trogdor.rest.RestExceptionMapper:36) javax.ws.rs.NotFoundException: No task with ID "non-existent-foo" exists. at org.apache.kafka.trogdor.coordinator.CoordinatorRestResource.tasks(CoordinatorRestResource.java:135) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory.lambda$static$0(ResourceMethodInvocationHandlerFactory.java:76) at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:148) at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:191) at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$TypeOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:243) at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:103) at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:493) at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:415) at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:104) at org.glassfish.jersey.server.ServerRuntime$1.run(ServerRuntime.java:277) at org.glassfish.jersey.internal.Errors$1.call(Errors.java:272) at org.glassfish.jersey.internal.Errors$1.call(Errors.java:268) at org.glassfish.jersey.internal.Errors.process(Errors.java:316) at org.glassfish.jersey.internal.Errors.process(Errors.java:298) at org.glassfish.jersey.internal.Errors.process(Errors.java:268) at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:289) at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:256) at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:703) at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:416) at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:370) at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:389) at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:342) at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:229) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:867) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:542) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1588) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1557) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126) at org.eclipse.jetty.server.handler.StatisticsHandler.handle(StatisticsHandler.java:174) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:502) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:364) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) at java.base/java.lang.Thread.run(Thread.java:834) [2019-03-15 09:23:46,854] INFO Closing MiniTrogdorCluster. (org.apache.kafka.trogdor.common.MiniTrogdorCluster:277) [2019-03-15 09:23:46,856] INFO 127.0.0.1 - - [15/Mar/2019:09:23:46 +0000] "GET /coordinator/tasks/non-existent-foo HTTP/1.1" 404 69 45 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:46,857] INFO Shutting down TaskManager. (org.apache.kafka.trogdor.coordinator.TaskManager:695) [2019-03-15 09:23:46,886] INFO Stopping REST server (org.apache.kafka.trogdor.rest.JsonRestServer:137) [2019-03-15 09:23:46,892] INFO node02: Shutting down WorkerManager. (org.apache.kafka.trogdor.agent.WorkerManager:648) [2019-03-15 09:23:46,892] INFO Stopping REST server (org.apache.kafka.trogdor.rest.JsonRestServer:137) [2019-03-15 09:23:46,903] INFO node02: Destroying all workers. (org.apache.kafka.trogdor.agent.WorkerManager:675) [2019-03-15 09:23:46,903] INFO node02: Stopping running worker foo_0. (org.apache.kafka.trogdor.agent.WorkerManager:569) [2019-03-15 09:23:46,909] INFO Stopped ServerConnector@1fcfcaee\{HTTP/1.1,[http/1.1]}{0.0.0.0:0} (org.eclipse.jetty.server.AbstractConnector:341) [2019-03-15 09:23:46,912] INFO foo: Deactivating NoOpTask. (org.apache.kafka.trogdor.task.NoOpTaskWorker:47) [2019-03-15 09:23:46,920] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:167) [2019-03-15 09:23:46,932] INFO node02: destroying worker foo_0 with error (org.apache.kafka.trogdor.agent.WorkerManager:516) [2019-03-15 09:23:46,938] INFO node02: Waiting for shutdownManager quiescence... (org.apache.kafka.trogdor.agent.WorkerManager:651) [2019-03-15 09:23:46,939] INFO node02: Waiting for workerCleanupExecutor to terminate... (org.apache.kafka.trogdor.agent.WorkerManager:655) [2019-03-15 09:23:46,939] INFO node02: Waiting for stateChangeExecutor to terminate... (org.apache.kafka.trogdor.agent.WorkerManager:657) [2019-03-15 09:23:46,939] INFO node02: Shutting down shutdownExecutor. (org.apache.kafka.trogdor.agent.WorkerManager:659) [2019-03-15 09:23:46,939] INFO Stopped ServerConnector@79a93bf1\{HTTP/1.1,[http/1.1]}{0.0.0.0:0} (org.eclipse.jetty.server.AbstractConnector:341) [2019-03-15 09:23:46,954] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:167) [2019-03-15 09:23:46,998] INFO Stopped o.e.j.s.ServletContextHandler@335a5293\{/,null,UNAVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1045) [2019-03-15 09:23:47,004] INFO Stopped o.e.j.s.ServletContextHandler@742ebd90\{/,null,UNAVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1045) [2019-03-15 09:23:47,012] INFO REST server stopped (org.apache.kafka.trogdor.rest.JsonRestServer:140) [2019-03-15 09:23:47,019] INFO REST server stopped (org.apache.kafka.trogdor.rest.JsonRestServer:140) [2019-03-15 09:23:47,027] INFO Creating MiniTrogdorCluster with agents: node01, node02 and coordinator: node01 (org.apache.kafka.trogdor.common.MiniTrogdorCluster:135) [2019-03-15 09:23:47,028] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:23:47,029] INFO Registered resource org.apache.kafka.trogdor.agent.AgentRestResource@351085f7 (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:23:47,030] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:23:47,084] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:23:47,084] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:23:47,085] INFO node0 Scavenging every 660000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:23:47,292] INFO Started o.e.j.s.ServletContextHandler@43466c8e\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:23:47,296] INFO Started ServerConnector@658cfca9\{HTTP/1.1,[http/1.1]}{0.0.0.0:41062} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:23:47,297] INFO Started @19041ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:23:47,297] INFO REST server listening at [http://127.0.1.1:41062/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:23:47,297] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:23:47,298] INFO Registered resource org.apache.kafka.trogdor.agent.AgentRestResource@72bf6cef (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:23:47,298] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:23:47,304] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:23:47,305] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:23:47,305] INFO node0 Scavenging every 600000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:23:47,472] INFO Started o.e.j.s.ServletContextHandler@58aa975e\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:23:47,474] INFO Started ServerConnector@6c1978a5\{HTTP/1.1,[http/1.1]}{0.0.0.0:35161} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:23:47,475] INFO Started @19219ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:23:47,475] INFO REST server listening at [http://127.0.1.1:35161/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:23:47,475] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:23:47,476] INFO Registered resource org.apache.kafka.trogdor.coordinator.CoordinatorRestResource@fa46412 (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:23:47,477] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:23:47,512] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:23:47,512] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:23:47,513] INFO node0 Scavenging every 600000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:23:47,719] INFO Started o.e.j.s.ServletContextHandler@65cc8f98\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:23:47,725] INFO Started ServerConnector@1bb30d40\{HTTP/1.1,[http/1.1]}{0.0.0.0:46695} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:23:47,725] INFO Started @19470ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:23:47,725] INFO REST server listening at [http://127.0.1.1:46695/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:23:47,743] INFO Created TaskManager for agent(s) on: node01, node02 (org.apache.kafka.trogdor.coordinator.TaskManager:144) [2019-03-15 09:23:47,744] DEBUG Sending GET with input null to [http://localhost:46695/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:47,847] INFO 127.0.0.1 - - [15/Mar/2019:09:23:47 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 2 94 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:47,848] DEBUG Sending GET with input null to [http://localhost:41062/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:47,929] INFO 127.0.0.1 - - [15/Mar/2019:09:23:47 +0000] "GET /agent/status HTTP/1.1" 200 19 72 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:47,930] DEBUG Sending GET with input null to [http://localhost:35161/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:48,012] INFO 127.0.0.1 - - [15/Mar/2019:09:23:47 +0000] "GET /agent/status HTTP/1.1" 200 19 79 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,014] DEBUG Sending DELETE with input null to [http://localhost:46695/coordinator/tasks?taskId=foo] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,020] INFO Can't destroy task foo: no such task found. (org.apache.kafka.trogdor.coordinator.TaskManager:512) [2019-03-15 09:23:48,022] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "DELETE /coordinator/tasks?taskId=foo HTTP/1.1" 200 2 7 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,022] DEBUG Sending POST with input \{"id":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12}} to [http://localhost:46695/coordinator/task/create] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,025] TRACE Scheduling org.apache.kafka.trogdor.coordinator.TaskManager$RunTask@19cd20f9 for 2 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:23:48,025] INFO Created a new task foo with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12}, scheduled to start 2 ms from now. (org.apache.kafka.trogdor.coordinator.TaskManager:366) [2019-03-15 09:23:48,026] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "POST /coordinator/task/create HTTP/1.1" 200 2 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,028] DEBUG Sending POST with input \{"id":"bar","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":20,"durationMs":20}} to [http://localhost:46695/coordinator/task/create] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,035] TRACE Scheduling org.apache.kafka.trogdor.coordinator.TaskManager$RunTask@170addb0 for 20 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:23:48,036] INFO Created a new task bar with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":20,"durationMs":20}, scheduled to start 20 ms from now. (org.apache.kafka.trogdor.coordinator.TaskManager:366) [2019-03-15 09:23:48,037] DEBUG Sending DELETE with input null to [http://localhost:46695/coordinator/tasks?taskId=bar] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,037] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "POST /coordinator/task/create HTTP/1.1" 200 2 5 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,039] INFO Destroying task bar. (org.apache.kafka.trogdor.coordinator.TaskManager:515) [2019-03-15 09:23:48,056] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "DELETE /coordinator/tasks?taskId=bar HTTP/1.1" 200 2 15 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,058] DEBUG Sending GET with input null to [http://localhost:46695/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,063] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 141 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,063] DEBUG Sending GET with input null to [http://localhost:41062/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:48,089] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /agent/status HTTP/1.1" 200 19 25 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,089] DEBUG Sending GET with input null to [http://localhost:35161/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:48,109] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /agent/status HTTP/1.1" 200 19 19 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,112] TRACE Invoking org.apache.kafka.trogdor.coordinator.TaskManager$RunTask@19cd20f9 at 10 (org.apache.kafka.common.utils.MockScheduler:105) [2019-03-15 09:23:48,113] INFO Running task foo on node(s): node01, node02 (org.apache.kafka.trogdor.coordinator.TaskManager:400) [2019-03-15 09:23:48,113] INFO node02: scheduling worker foo_1 to start. (org.apache.kafka.trogdor.coordinator.NodeManager:297) [2019-03-15 09:23:48,113] DEBUG Sending GET with input null to [http://127.0.0.1:35161/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:48,116] INFO node01: scheduling worker foo_0 to start. (org.apache.kafka.trogdor.coordinator.NodeManager:297) [2019-03-15 09:23:48,118] DEBUG Sending GET with input null to [http://127.0.0.1:41062/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:48,119] DEBUG Sending GET with input null to [http://localhost:46695/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,133] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /agent/status HTTP/1.1" 200 19 11 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,134] TRACE node02: got heartbeat status \{"serverStartMs":0} (org.apache.kafka.trogdor.coordinator.NodeManager:205) [2019-03-15 09:23:48,133] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 195 14 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,148] DEBUG Sending POST with input \{"workerId":1,"taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12}} to [http://127.0.0.1:35161/agent/worker/create] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:48,133] TRACE node01: got heartbeat status \{"serverStartMs":0} (org.apache.kafka.trogdor.coordinator.NodeManager:205) [2019-03-15 09:23:48,148] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /agent/status HTTP/1.1" 200 19 28 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,134] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"active","node02":"active"}}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:48,156] INFO node02: Created worker foo_1 with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12} (org.apache.kafka.trogdor.agent.WorkerManager:402) [2019-03-15 09:23:48,156] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"receiving","node02":"receiving"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:48,156] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"active","node02":"active"}}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"receiving","node02":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:48,149] DEBUG Sending POST with input \{"workerId":0,"taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12}} to [http://127.0.0.1:41062/agent/worker/create] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:23:48,156] INFO foo: Activating NoOpTask. (org.apache.kafka.trogdor.task.NoOpTaskWorker:40) [2019-03-15 09:23:48,223] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "POST /agent/worker/create HTTP/1.1" 200 2 73 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,224] INFO node02: Worker foo_1 is now RUNNING. Scheduled to stop in 12 ms. (org.apache.kafka.trogdor.agent.WorkerManager:431) [2019-03-15 09:23:48,224] TRACE Scheduling org.apache.kafka.trogdor.agent.WorkerManager$StopWorker@2476f9ef for 4 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:23:48,246] INFO node01: Created worker foo_0 with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12} (org.apache.kafka.trogdor.agent.WorkerManager:402) [2019-03-15 09:23:48,254] INFO foo: Activating NoOpTask. (org.apache.kafka.trogdor.task.NoOpTaskWorker:40) [2019-03-15 09:23:48,254] INFO node01: Worker foo_0 is now RUNNING. Scheduled to stop in 12 ms. (org.apache.kafka.trogdor.agent.WorkerManager:431) [2019-03-15 09:23:48,255] TRACE Scheduling org.apache.kafka.trogdor.agent.WorkerManager$StopWorker@621eb217 for 4 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:23:48,261] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "POST /agent/worker/create HTTP/1.1" 200 2 39 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,321] DEBUG Sending GET with input null to [http://localhost:46695/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,329] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 195 7 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,330] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"active","node02":"active"}}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:48,331] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"receiving","node02":"receiving"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:48,331] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"active","node02":"active"}}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"receiving","node02":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:48,431] DEBUG Sending GET with input null to [http://localhost:46695/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,439] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 195 7 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,440] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"active","node02":"active"}}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:48,441] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"receiving","node02":"receiving"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:48,441] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"active","node02":"active"}}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"receiving","node02":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:48,541] DEBUG Sending GET with input null to [http://localhost:46695/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,549] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 195 7 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,550] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"active","node02":"active"}}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:23:48,550] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"receiving","node02":"receiving"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:23:48,550] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"active","node02":"active"}}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":\{"node01":"receiving","node02":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:23:48,651] DEBUG Sending GET with input null to [http://localhost:46695/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:23:48,662] INFO 127.0.0.1 - - [15/Mar/2019:09:23:48 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 195 6 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:23:48,663] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":2,"durationMs":12},"startedMs":10,"status":{"node01":"active","node02": ...[truncated 346606 chars]... Sending GET with input null to [http://localhost:39105/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:05,901] INFO 127.0.0.1 - - [15/Mar/2019:09:26:05 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 158 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:05,901] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:05,902] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:05,902] INFO Invalid state for task foo: expected \{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:06,002] DEBUG Sending GET with input null to [http://localhost:39105/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,005] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 158 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,005] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:06,005] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:06,006] INFO Invalid state for task foo: expected \{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:06,106] DEBUG Sending GET with input null to [http://localhost:39105/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,109] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 158 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,111] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:06,111] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:06,111] INFO Invalid state for task foo: expected \{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:06,192] DEBUG Sending GET with input null to [http://127.0.0.1:8888/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:06,193] INFO GET [http://127.0.0.1:8888/agent/status:] error: Connection refused (Connection refused) (org.apache.kafka.trogdor.rest.JsonRestServer:281) [2019-03-15 09:26:06,193] ERROR node01: failed to get agent status: ConnectException Connection refused (Connection refused) (org.apache.kafka.trogdor.coordinator.NodeManager:196) [2019-03-15 09:26:06,212] DEBUG Sending GET with input null to [http://localhost:39105/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,214] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 158 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,215] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:06,215] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:06,215] INFO Invalid state for task foo: expected \{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:06,315] DEBUG Sending GET with input null to [http://localhost:39105/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,318] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 158 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,319] INFO EXPECTED TASKS: \{"foo":{"id":"foo","taskState":{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:06,319] INFO ACTUAL TASKS : \{"foo":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:06,319] INFO Invalid state for task foo: expected \{"state":"DONE","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"cancelled":false,"status":"done"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:06,320] DEBUG Sending GET with input null to [http://127.0.0.1:33887/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:06,329] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /agent/status HTTP/1.1" 200 197 7 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,329] TRACE node02: got heartbeat status \{"serverStartMs":0,"workers":{"0":{"state":"DONE","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"status":"done"}}} (org.apache.kafka.trogdor.coordinator.NodeManager:205) [2019-03-15 09:26:06,329] INFO node02: worker state changed from \{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"} to \{"state":"DONE","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"status":"done"} (org.apache.kafka.trogdor.coordinator.NodeManager:252) [2019-03-15 09:26:06,329] DEBUG Task foo: Updating worker state for 0 on node02 from \{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"status":"active"} to \{"state":"DONE","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":2},"startedMs":2,"doneMs":5,"status":"done"}. (org.apache.kafka.trogdor.coordinator.TaskManager:563) [2019-03-15 09:26:06,329] INFO node02: Worker foo finished with status '"done"' (org.apache.kafka.trogdor.coordinator.TaskManager:587) [2019-03-15 09:26:06,329] INFO node02: Task foo is now complete on node02 with error: (none) (org.apache.kafka.trogdor.coordinator.TaskManager:598) [2019-03-15 09:26:06,419] DEBUG Sending GET with input null to [http://localhost:39105/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,422] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 182 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,423] INFO Closing MiniTrogdorCluster. (org.apache.kafka.trogdor.common.MiniTrogdorCluster:277) [2019-03-15 09:26:06,423] INFO Shutting down TaskManager. (org.apache.kafka.trogdor.coordinator.TaskManager:695) [2019-03-15 09:26:06,423] INFO Stopping REST server (org.apache.kafka.trogdor.rest.JsonRestServer:137) [2019-03-15 09:26:06,424] INFO Stopping REST server (org.apache.kafka.trogdor.rest.JsonRestServer:137) [2019-03-15 09:26:06,425] INFO Stopped ServerConnector@4e96ef63\{HTTP/1.1,[http/1.1]}{0.0.0.0:0} (org.eclipse.jetty.server.AbstractConnector:341) [2019-03-15 09:26:06,440] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:167) [2019-03-15 09:26:06,441] INFO Stopped o.e.j.s.ServletContextHandler@750b28b2\{/,null,UNAVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1045) [2019-03-15 09:26:06,442] INFO REST server stopped (org.apache.kafka.trogdor.rest.JsonRestServer:140) [2019-03-15 09:26:06,443] INFO node02: Shutting down WorkerManager. (org.apache.kafka.trogdor.agent.WorkerManager:648) [2019-03-15 09:26:06,443] INFO node02: Destroying all workers. (org.apache.kafka.trogdor.agent.WorkerManager:675) [2019-03-15 09:26:06,444] INFO node02: destroying worker foo_0 with error (org.apache.kafka.trogdor.agent.WorkerManager:578) [2019-03-15 09:26:06,444] INFO node02: Waiting for shutdownManager quiescence... (org.apache.kafka.trogdor.agent.WorkerManager:651) [2019-03-15 09:26:06,444] INFO node02: Waiting for workerCleanupExecutor to terminate... (org.apache.kafka.trogdor.agent.WorkerManager:655) [2019-03-15 09:26:06,444] INFO Stopped ServerConnector@538e4944\{HTTP/1.1,[http/1.1]}{0.0.0.0:0} (org.eclipse.jetty.server.AbstractConnector:341) [2019-03-15 09:26:06,452] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:167) [2019-03-15 09:26:06,454] INFO Stopped o.e.j.s.ServletContextHandler@2b100b0\{/,null,UNAVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1045) [2019-03-15 09:26:06,455] INFO REST server stopped (org.apache.kafka.trogdor.rest.JsonRestServer:140) [2019-03-15 09:26:06,456] INFO node02: Waiting for stateChangeExecutor to terminate... (org.apache.kafka.trogdor.agent.WorkerManager:657) [2019-03-15 09:26:06,456] INFO node02: Shutting down shutdownExecutor. (org.apache.kafka.trogdor.agent.WorkerManager:659) [2019-03-15 09:26:06,460] INFO Creating MiniTrogdorCluster with agents: node02 and coordinator: node01 (org.apache.kafka.trogdor.common.MiniTrogdorCluster:135) [2019-03-15 09:26:06,460] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:26:06,460] INFO Registered resource org.apache.kafka.trogdor.agent.AgentRestResource@71c34250 (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:26:06,461] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:26:06,508] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:26:06,508] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:26:06,509] INFO node0 Scavenging every 660000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:26:06,600] INFO Started o.e.j.s.ServletContextHandler@6c85d064\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:26:06,617] INFO Started ServerConnector@6a7d40d2\{HTTP/1.1,[http/1.1]}{0.0.0.0:37168} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:26:06,617] INFO Started @158362ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:26:06,618] INFO REST server listening at [http://127.0.1.1:37168/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:26:06,618] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:26:06,619] INFO Registered resource org.apache.kafka.trogdor.coordinator.CoordinatorRestResource@149c2a46 (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:26:06,619] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:26:06,668] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:26:06,668] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:26:06,668] INFO node0 Scavenging every 660000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:26:06,771] INFO Started o.e.j.s.ServletContextHandler@25bf1e09\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:26:06,780] INFO Started ServerConnector@ac53d60\{HTTP/1.1,[http/1.1]}{0.0.0.0:45996} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:26:06,780] INFO Started @158525ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:26:06,780] INFO REST server listening at [http://127.0.1.1:45996/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:26:06,795] INFO Created TaskManager for agent(s) on: node01, node02 (org.apache.kafka.trogdor.coordinator.TaskManager:144) [2019-03-15 09:26:06,796] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,845] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 2 29 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,845] DEBUG Sending POST with input \{"id":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}} to [http://localhost:45996/coordinator/task/create] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,848] TRACE Scheduling org.apache.kafka.trogdor.coordinator.TaskManager$RunTask@46b03bf6 for 1 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:26:06,849] INFO Created a new task foo with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}, scheduled to start 1 ms from now. (org.apache.kafka.trogdor.coordinator.TaskManager:366) [2019-03-15 09:26:06,850] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "POST /coordinator/task/create HTTP/1.1" 200 2 4 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,852] DEBUG Sending POST with input \{"id":"bar","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1}} to [http://localhost:45996/coordinator/task/create] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,858] TRACE Scheduling org.apache.kafka.trogdor.coordinator.TaskManager$RunTask@4877cd50 for 3 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:26:06,858] INFO Created a new task bar with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1}, scheduled to start 3 ms from now. (org.apache.kafka.trogdor.coordinator.TaskManager:366) [2019-03-15 09:26:06,859] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "POST /coordinator/task/create HTTP/1.1" 200 2 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,860] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,866] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 270 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,868] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=10&lastStartMs=0&firstEndMs=10&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,872] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=10&lastStartMs=0&firstEndMs=10&lastEndMs=0 HTTP/1.1" 200 2 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,876] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?taskId=foo&taskId=baz&firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,878] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?taskId=foo&taskId=baz&firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 141 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,887] TRACE Invoking org.apache.kafka.trogdor.coordinator.TaskManager$RunTask@46b03bf6 at 2 (org.apache.kafka.common.utils.MockScheduler:105) [2019-03-15 09:26:06,888] INFO Running task foo on node(s): node02 (org.apache.kafka.trogdor.coordinator.TaskManager:400) [2019-03-15 09:26:06,888] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:06,888] INFO node02: scheduling worker foo_0 to start. (org.apache.kafka.trogdor.coordinator.NodeManager:297) [2019-03-15 09:26:06,888] DEBUG Sending GET with input null to [http://127.0.0.1:37168/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:06,898] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 8 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,900] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "GET /agent/status HTTP/1.1" 200 19 9 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:06,900] TRACE node02: got heartbeat status \{"serverStartMs":0} (org.apache.kafka.trogdor.coordinator.NodeManager:205) [2019-03-15 09:26:06,901] DEBUG Sending POST with input \{"workerId":0,"taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}} to [http://127.0.0.1:37168/agent/worker/create] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:06,900] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:06,902] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:06,902] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:06,908] INFO node02: Created worker foo_0 with spec \{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10} (org.apache.kafka.trogdor.agent.WorkerManager:402) [2019-03-15 09:26:06,917] INFO foo: Activating NoOpTask. (org.apache.kafka.trogdor.task.NoOpTaskWorker:40) [2019-03-15 09:26:06,917] INFO node02: Worker foo_0 is now RUNNING. Scheduled to stop in 10 ms. (org.apache.kafka.trogdor.agent.WorkerManager:431) [2019-03-15 09:26:06,917] TRACE Scheduling org.apache.kafka.trogdor.agent.WorkerManager$StopWorker@7e4a1640 for 9 ms from now. (org.apache.kafka.common.utils.MockScheduler:117) [2019-03-15 09:26:06,920] INFO 127.0.0.1 - - [15/Mar/2019:09:26:06 +0000] "POST /agent/worker/create HTTP/1.1" 200 2 19 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,002] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,008] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 5 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,009] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,009] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,009] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,109] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,112] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,113] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,113] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,113] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,213] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,216] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,216] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,216] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,217] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,317] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,320] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,320] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,320] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,320] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,421] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,424] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 1 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,424] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,424] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,424] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,524] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,527] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,527] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,527] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,528] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,628] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,633] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 4 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,633] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,633] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,634] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,734] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,737] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,737] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,737] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,737] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,784] DEBUG Sending GET with input null to [http://127.0.0.1:8888/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:07,785] INFO GET [http://127.0.0.1:8888/agent/status:] error: Connection refused (Connection refused) (org.apache.kafka.trogdor.rest.JsonRestServer:281) [2019-03-15 09:26:07,785] ERROR node01: failed to get agent status: ConnectException Connection refused (Connection refused) (org.apache.kafka.trogdor.coordinator.NodeManager:196) [2019-03-15 09:26:07,838] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,841] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 291 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,841] INFO EXPECTED TASKS: \{"bar":{"id":"bar","taskState":{"state":"PENDING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null}},"foo":\{"id":"foo","taskState":{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"},"workerState":\{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.common.ExpectedTasks:163) [2019-03-15 09:26:07,841] INFO ACTUAL TASKS : \{"bar":{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":3,"durationMs":1},"status":null},"foo":\{"spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"}} (org.apache.kafka.trogdor.common.ExpectedTasks:164) [2019-03-15 09:26:07,841] INFO Invalid state for task foo: expected \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}, got \{"state":"RUNNING","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"receiving"} (org.apache.kafka.trogdor.common.ExpectedTasks:165) [2019-03-15 09:26:07,889] DEBUG Sending GET with input null to [http://127.0.0.1:37168/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:07,892] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /agent/status HTTP/1.1" 200 192 3 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,892] TRACE node02: got heartbeat status \{"serverStartMs":0,"workers":{"0":{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}}} (org.apache.kafka.trogdor.coordinator.NodeManager:205) [2019-03-15 09:26:07,892] INFO node02: worker state changed from \{"state":"RECEIVING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}} to \{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"} (org.apache.kafka.trogdor.coordinator.NodeManager:252) [2019-03-15 09:26:07,893] DEBUG Task foo: Updating worker state for 0 on node02 from \{"state":"RECEIVING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10}} to \{"state":"RUNNING","taskId":"foo","spec":{"class":"org.apache.kafka.trogdor.task.NoOpTaskSpec","startMs":1,"durationMs":10},"startedMs":2,"status":"active"}. (org.apache.kafka.trogdor.coordinator.TaskManager:563) [2019-03-15 09:26:07,942] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,945] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=0&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 288 1 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,945] DEBUG Sending GET with input null to [http://localhost:37168/agent/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:07,947] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /agent/status HTTP/1.1" 200 192 1 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,947] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=1&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,950] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=1&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 159 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,950] DEBUG Sending GET with input null to [http://localhost:45996/coordinator/tasks?firstStartMs=3&lastStartMs=0&firstEndMs=0&lastEndMs=0] (org.apache.kafka.trogdor.coordinator.CoordinatorClient:193) [2019-03-15 09:26:07,952] INFO Closing MiniTrogdorCluster. (org.apache.kafka.trogdor.common.MiniTrogdorCluster:277) [2019-03-15 09:26:07,952] INFO Shutting down TaskManager. (org.apache.kafka.trogdor.coordinator.TaskManager:695) [2019-03-15 09:26:07,952] INFO Stopping REST server (org.apache.kafka.trogdor.rest.JsonRestServer:137) [2019-03-15 09:26:07,952] INFO 127.0.0.1 - - [15/Mar/2019:09:26:07 +0000] "GET /coordinator/tasks?firstStartMs=3&lastStartMs=0&firstEndMs=0&lastEndMs=0 HTTP/1.1" 200 2 2 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:07,953] INFO Stopping REST server (org.apache.kafka.trogdor.rest.JsonRestServer:137) [2019-03-15 09:26:07,954] INFO node02: Shutting down WorkerManager. (org.apache.kafka.trogdor.agent.WorkerManager:648) [2019-03-15 09:26:07,954] INFO node02: Destroying all workers. (org.apache.kafka.trogdor.agent.WorkerManager:675) [2019-03-15 09:26:07,954] INFO node02: Stopping running worker foo_0. (org.apache.kafka.trogdor.agent.WorkerManager:569) [2019-03-15 09:26:07,955] INFO Stopped ServerConnector@6a7d40d2\{HTTP/1.1,[http/1.1]}{0.0.0.0:0} (org.eclipse.jetty.server.AbstractConnector:341) [2019-03-15 09:26:07,955] INFO node02: Waiting for shutdownManager quiescence... (org.apache.kafka.trogdor.agent.WorkerManager:651) [2019-03-15 09:26:07,956] INFO Stopped ServerConnector@ac53d60\{HTTP/1.1,[http/1.1]}{0.0.0.0:0} (org.eclipse.jetty.server.AbstractConnector:341) [2019-03-15 09:26:07,956] INFO foo: Deactivating NoOpTask. (org.apache.kafka.trogdor.task.NoOpTaskWorker:47) [2019-03-15 09:26:07,963] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:167) [2019-03-15 09:26:07,964] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:167) [2019-03-15 09:26:07,968] INFO node02: destroying worker foo_0 with error (org.apache.kafka.trogdor.agent.WorkerManager:516) [2019-03-15 09:26:07,983] INFO Stopped o.e.j.s.ServletContextHandler@25bf1e09\{/,null,UNAVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1045) [2019-03-15 09:26:07,988] INFO node02: Waiting for workerCleanupExecutor to terminate... (org.apache.kafka.trogdor.agent.WorkerManager:655) [2019-03-15 09:26:07,988] INFO node02: Waiting for stateChangeExecutor to terminate... (org.apache.kafka.trogdor.agent.WorkerManager:657) [2019-03-15 09:26:07,997] INFO Stopped o.e.j.s.ServletContextHandler@6c85d064\{/,null,UNAVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1045) [2019-03-15 09:26:07,998] INFO REST server stopped (org.apache.kafka.trogdor.rest.JsonRestServer:140) [2019-03-15 09:26:07,998] INFO node02: Shutting down shutdownExecutor. (org.apache.kafka.trogdor.agent.WorkerManager:659) [2019-03-15 09:26:08,003] INFO REST server stopped (org.apache.kafka.trogdor.rest.JsonRestServer:140) [2019-03-15 09:26:08,009] INFO Creating MiniTrogdorCluster with agents: and coordinator: node01 (org.apache.kafka.trogdor.common.MiniTrogdorCluster:135) [2019-03-15 09:26:08,010] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:26:08,010] INFO Registered resource org.apache.kafka.trogdor.coordinator.CoordinatorRestResource@69042100 (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:26:08,011] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:26:08,022] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:26:08,023] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:26:08,023] INFO node0 Scavenging every 600000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:26:08,153] INFO Started o.e.j.s.ServletContextHandler@7dd0793a\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:26:08,162] INFO Started ServerConnector@6f2a69c3\{HTTP/1.1,[http/1.1]}{0.0.0.0:46030} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:26:08,163] INFO Started @159908ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:26:08,163] INFO REST server listening at [http://127.0.1.1:46030/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:26:08,179] INFO Created TaskManager for agent(s) on: node01 (org.apache.kafka.trogdor.coordinator.TaskManager:144) [2019-03-15 09:26:08,180] DEBUG Sending GET with input null to [http://localhost:46030/coordinator/status] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:08,186] INFO 127.0.0.1 - - [15/Mar/2019:09:26:08 +0000] "GET /coordinator/status HTTP/1.1" 200 31 4 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:08,195] INFO Closing MiniTrogdorCluster. (org.apache.kafka.trogdor.common.MiniTrogdorCluster:277) [2019-03-15 09:26:08,209] INFO Stopping REST server (org.apache.kafka.trogdor.rest.JsonRestServer:137) [2019-03-15 09:26:08,211] INFO Stopped ServerConnector@6f2a69c3\{HTTP/1.1,[http/1.1]}{0.0.0.0:0} (org.eclipse.jetty.server.AbstractConnector:341) [2019-03-15 09:26:08,212] INFO Shutting down TaskManager. (org.apache.kafka.trogdor.coordinator.TaskManager:695) [2019-03-15 09:26:08,213] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:167) [2019-03-15 09:26:08,215] INFO Stopped o.e.j.s.ServletContextHandler@7dd0793a\{/,null,UNAVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1045) [2019-03-15 09:26:08,216] INFO REST server stopped (org.apache.kafka.trogdor.rest.JsonRestServer:140) [2019-03-15 09:26:08,225] INFO Creating MiniTrogdorCluster with agents: and coordinator: node01 (org.apache.kafka.trogdor.common.MiniTrogdorCluster:135) [2019-03-15 09:26:08,226] INFO Starting REST server (org.apache.kafka.trogdor.rest.JsonRestServer:89) [2019-03-15 09:26:08,228] INFO Registered resource org.apache.kafka.trogdor.coordinator.CoordinatorRestResource@5baa2d2d (org.apache.kafka.trogdor.rest.JsonRestServer:94) [2019-03-15 09:26:08,230] INFO jetty-9.4.14.v20181114; built: 2018-11-14T21:20:31.478Z; git: c4550056e785fb5665914545889f21dc136ad9e6; jvm 11.0.1+13-LTS (org.eclipse.jetty.server.Server:370) [2019-03-15 09:26:08,234] INFO DefaultSessionIdManager workerName=node0 (org.eclipse.jetty.server.session:365) [2019-03-15 09:26:08,234] INFO No SessionScavenger set, using defaults (org.eclipse.jetty.server.session:370) [2019-03-15 09:26:08,235] INFO node0 Scavenging every 600000ms (org.eclipse.jetty.server.session:149) [2019-03-15 09:26:08,310] INFO Started o.e.j.s.ServletContextHandler@3c3abc1f\{/,null,AVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:855) [2019-03-15 09:26:08,336] INFO Started ServerConnector@6a7dcfa7\{HTTP/1.1,[http/1.1]}{0.0.0.0:42585} (org.eclipse.jetty.server.AbstractConnector:292) [2019-03-15 09:26:08,336] INFO Started @160081ms (org.eclipse.jetty.server.Server:407) [2019-03-15 09:26:08,336] INFO REST server listening at [http://127.0.1.1:42585/] (org.apache.kafka.trogdor.rest.JsonRestServer:123) [2019-03-15 09:26:08,337] INFO Created TaskManager for agent(s) on: node01 (org.apache.kafka.trogdor.coordinator.TaskManager:144) [2019-03-15 09:26:08,338] DEBUG Sending GET with input null to [http://localhost:42585/coordinator/uptime] (org.apache.kafka.trogdor.rest.JsonRestServer:193) [2019-03-15 09:26:08,380] INFO 127.0.0.1 - - [15/Mar/2019:09:26:08 +0000] "GET /coordinator/uptime HTTP/1.1" 200 33 36 (org.apache.kafka.trogdor.rest.JsonRestServer:60) [2019-03-15 09:26:08,381] INFO Closing MiniTrogdorCluster. (org.apache.kafka.trogdor.common.MiniTrogdorCluster:277) [2019-03-15 09:26:08,383] INFO Stopping REST server (org.apache.kafka.trogdor.rest.JsonRestServer:137) [2019-03-15 09:26:08,384] INFO Stopped ServerConnector@6a7dcfa7\{HTTP/1.1,[http/1.1]}{0.0.0.0:0} (org.eclipse.jetty.server.AbstractConnector:341) [2019-03-15 09:26:08,388] INFO Shutting down TaskManager. (org.apache.kafka.trogdor.coordinator.TaskManager:695) [2019-03-15 09:26:08,391] INFO node0 Stopped scavenging (org.eclipse.jetty.server.session:167) [2019-03-15 09:26:08,402] INFO Stopped o.e.j.s.ServletContextHandler@3c3abc1f\{/,null,UNAVAILABLE} (org.eclipse.jetty.server.handler.ContextHandler:1045) [2019-03-15 09:26:08,406] INFO REST server stopped (org.apache.kafka.trogdor.rest.JsonRestServer:140){quote}
> STDERR
> {quote}Mar 15, 2019 9:23:43 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:23:44 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:23:47 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:23:47 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:23:47 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:23:49 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:23:49 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:23:49 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:23:53 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:23:53 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:23:57 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:23:57 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:23:57 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:24:00 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:24:00 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:26:00 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:26:00 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:26:00 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:26:00 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:26:01 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:26:01 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:26:01 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:26:02 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:26:02 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:26:03 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:26:04 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:26:06 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.agent.AgentRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.agent.AgentRestResource will be ignored. Mar 15, 2019 9:26:06 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:26:08 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored. Mar 15, 2019 9:26:08 AM org.glassfish.jersey.internal.inject.Providers checkProviderRuntime WARNING: A provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.apache.kafka.trogdor.coordinator.CoordinatorRestResource will be ignored.{quote}
--
This message was sent by Atlassian Jira
(v8.20.1#820001)