camunda / camunda

Process Orchestration Framework
https://camunda.com/platform/
3.34k stars 612 forks source link

SnapshotReplicationTest.shouldReceiveLatestSnapshotOnRejoin flaky #4354

Closed pihme closed 4 years ago

pihme commented 4 years ago

Summary

Try to answer the following as best as possible

Failures

Outline known failure cases, e.g. a failed assertion and its stacktrace obtained from Jenkins

Example assertion failure
expected:<[tru]e> but was:<[fals]e>

org.junit.ComparisonFailure: expected:<[tru]e> but was:<[fals]e>
    at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
    at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
    at io.zeebe.test.util.TestUtil$Invocation.until(TestUtil.java:118)
    at io.zeebe.test.util.TestUtil$Invocation.until(TestUtil.java:73)
    at io.zeebe.test.util.TestUtil.waitUntil(TestUtil.java:45)
    at io.zeebe.broker.it.clustering.ClusteringRule.waitForNewSnapshotAtBroker(ClusteringRule.java:635)
    at io.zeebe.broker.it.clustering.ClusteringRule.waitForSnapshotAtBroker(ClusteringRule.java:615)
    at io.zeebe.broker.it.clustering.SnapshotReplicationTest.shouldReceiveLatestSnapshotOnRejoin(SnapshotReplicationTest.java:93)
    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.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
    at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
    at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
    at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
    at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
    at org.junit.rules.RunRules.evaluate(RunRules.java:20)
    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
    at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
    at org.junit.runners.Suite.runChild(Suite.java:128)
    at org.junit.runners.Suite.runChild(Suite.java:27)
    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
    at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
    at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
    at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeLazy(JUnitCoreWrapper.java:119)
    at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:87)
    at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
    at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:158)
    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:377)
    at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:138)
    at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:465)
    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:451)

Hypotheses

List any hypotheses if you have one; can be ommitted

Logs

If possible, provide more context here, e.g. standard output logs, link to build, etc.

Logs
13:59:18.047 [] [main] INFO  io.zeebe.test - Test finished: shouldReceiveNewSnapshotsOnRejoin(io.zeebe.broker.it.clustering.SnapshotReplicationTest)
13:59:18.047 [] [main] INFO  io.zeebe.test - Test started: shouldReceiveLatestSnapshotOnRejoin(io.zeebe.broker.it.clustering.SnapshotReplicationTest)
13:59:18.049 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30890 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=91}
13:59:18.049 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30891 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=92}
13:59:18.050 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30892 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=93}
13:59:18.050 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30893 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=94}
13:59:18.050 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30894 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=95}
13:59:18.050 [] [main] DEBUG io.zeebe.broker.system - Initializing system with base path /tmp/junit6607366519595549948/0
13:59:18.051 [] [Thread-2249] INFO  io.zeebe.broker.system - Version: 0.24.0-SNAPSHOT
13:59:18.051 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30895 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=96}
13:59:18.052 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30896 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=97}
13:59:18.052 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30897 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=98}
13:59:18.052 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30898 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=99}
13:59:18.052 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30899 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=100}
13:59:18.052 [] [main] DEBUG io.zeebe.broker.system - Initializing system with base path /tmp/junit6607366519595549948/1
13:59:18.052 [] [Thread-2249] INFO  io.zeebe.broker.system - Starting broker 0 with configuration {
  "network" : {
    "host" : "0.0.0.0",
    "portOffset" : 0,
    "maxMessageSize" : "4MB",
    "advertisedHost" : "0.0.0.0",
    "commandApi" : {
      "host" : "0.0.0.0",
      "port" : 30892,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30892,
      "address" : "0.0.0.0:30892",
      "advertisedAddress" : "0.0.0.0:30892"
    },
    "internalApi" : {
      "host" : "0.0.0.0",
      "port" : 30893,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30893,
      "address" : "0.0.0.0:30893",
      "advertisedAddress" : "0.0.0.0:30893"
    },
    "monitoringApi" : {
      "host" : "0.0.0.0",
      "port" : 30894,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30894,
      "address" : "0.0.0.0:30894",
      "advertisedAddress" : "0.0.0.0:30894"
    },
    "maxMessageSizeInBytes" : 4194304
  },
  "cluster" : {
    "initialContactPoints" : [ ],
    "partitionIds" : [ 1 ],
    "nodeId" : 0,
    "partitionsCount" : 1,
    "replicationFactor" : 3,
    "clusterSize" : 3,
    "clusterName" : "zeebe-cluster-5",
    "gossipFailureTimeout" : 2000,
    "gossipInterval" : 150,
    "gossipProbeInterval" : 250
  },
  "threads" : {
    "cpuThreadCount" : 2,
    "ioThreadCount" : 2
  },
  "data" : {
    "directories" : [ "/tmp/junit6607366519595549948/0/data" ],
    "logSegmentSize" : "512MB",
    "snapshotPeriod" : "PT5M",
    "logIndexDensity" : 100,
    "logSegmentSizeInBytes" : 536870912
  },
  "exporters" : {
    "test-recorder" : {
      "jarPath" : null,
      "className" : "io.zeebe.test.util.record.RecordingExporter",
      "args" : null,
      "external" : false
    }
  },
  "gateway" : {
    "network" : {
      "host" : "0.0.0.0",
      "port" : 30890,
      "minKeepAliveInterval" : "PT30S"
    },
    "cluster" : {
      "contactPoint" : "0.0.0.0:30893",
      "requestTimeout" : "PT15S",
      "clusterName" : "zeebe-cluster",
      "memberId" : "gateway",
      "host" : "0.0.0.0",
      "port" : 30891
    },
    "threads" : {
      "managementThreads" : 1
    },
    "monitoring" : {
      "enabled" : false,
      "host" : "0.0.0.0",
      "port" : 9600
    },
    "security" : {
      "enabled" : false,
      "certificateChainPath" : null,
      "privateKeyPath" : null
    },
    "enable" : false
  },
  "backpressure" : {
    "enabled" : true,
    "algorithm" : "VEGAS"
  },
  "stepTimeout" : "PT5M",
  "executionMetricsExporterEnabled" : false
}
13:59:18.053 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [1/10]: actor scheduler
13:59:18.053 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [1/10]: actor scheduler started in 0 ms
13:59:18.053 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [2/10]: membership and replication protocol
13:59:18.053 [] [Thread-2254] INFO  io.zeebe.broker.system - Version: 0.24.0-SNAPSHOT
13:59:18.054 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30800 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=101}
13:59:18.054 [] [Thread-2254] INFO  io.zeebe.broker.system - Starting broker 1 with configuration {
  "network" : {
    "host" : "0.0.0.0",
    "portOffset" : 0,
    "maxMessageSize" : "4MB",
    "advertisedHost" : "0.0.0.0",
    "commandApi" : {
      "host" : "0.0.0.0",
      "port" : 30897,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30897,
      "address" : "0.0.0.0:30897",
      "advertisedAddress" : "0.0.0.0:30897"
    },
    "internalApi" : {
      "host" : "0.0.0.0",
      "port" : 30898,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30898,
      "address" : "0.0.0.0:30898",
      "advertisedAddress" : "0.0.0.0:30898"
    },
    "monitoringApi" : {
      "host" : "0.0.0.0",
      "port" : 30899,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30899,
      "address" : "0.0.0.0:30899",
      "advertisedAddress" : "0.0.0.0:30899"
    },
    "maxMessageSizeInBytes" : 4194304
  },
  "cluster" : {
    "initialContactPoints" : [ "0.0.0.0:30893" ],
    "partitionIds" : [ 1 ],
    "nodeId" : 1,
    "partitionsCount" : 1,
    "replicationFactor" : 3,
    "clusterSize" : 3,
    "clusterName" : "zeebe-cluster-5",
    "gossipFailureTimeout" : 2000,
    "gossipInterval" : 150,
    "gossipProbeInterval" : 250
  },
  "threads" : {
    "cpuThreadCount" : 2,
    "ioThreadCount" : 2
  },
  "data" : {
    "directories" : [ "/tmp/junit6607366519595549948/1/data" ],
    "logSegmentSize" : "512MB",
    "snapshotPeriod" : "PT5M",
    "logIndexDensity" : 100,
    "logSegmentSizeInBytes" : 536870912
  },
  "exporters" : {
    "test-recorder" : {
      "jarPath" : null,
      "className" : "io.zeebe.test.util.record.RecordingExporter",
      "args" : null,
      "external" : false
    }
  },
  "gateway" : {
    "network" : {
      "host" : "0.0.0.0",
      "port" : 30895,
      "minKeepAliveInterval" : "PT30S"
    },
    "cluster" : {
      "contactPoint" : "0.0.0.0:30898",
      "requestTimeout" : "PT15S",
      "clusterName" : "zeebe-cluster",
      "memberId" : "gateway",
      "host" : "0.0.0.0",
      "port" : 30896
    },
    "threads" : {
      "managementThreads" : 1
    },
    "monitoring" : {
      "enabled" : false,
      "host" : "0.0.0.0",
      "port" : 9600
    },
    "security" : {
      "enabled" : false,
      "certificateChainPath" : null,
      "privateKeyPath" : null
    },
    "enable" : false
  },
  "backpressure" : {
    "enabled" : true,
    "algorithm" : "VEGAS"
  },
  "stepTimeout" : "PT5M",
  "executionMetricsExporterEnabled" : false
}
13:59:18.054 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30801 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=102}
13:59:18.054 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30802 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=103}
13:59:18.054 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [1/10]: actor scheduler
13:59:18.055 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30803 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=104}
13:59:18.055 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30804 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=105}
13:59:18.055 [] [main] DEBUG io.zeebe.broker.system - Initializing system with base path /tmp/junit6607366519595549948/2
13:59:18.055 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [1/10]: actor scheduler started in 1 ms
13:59:18.055 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [2/10]: membership and replication protocol
13:59:18.055 [] [Thread-2254] DEBUG io.zeebe.broker.clustering - Member 1 will contact node: 0.0.0.0:30893
13:59:18.056 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30805 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=106}
13:59:18.056 [] [main] INFO  io.zeebe.test.util.SocketUtil - Choosing next port 30806 for test fork 5 with range PortRange{host='localhost', basePort=30800, maxOffset=100, currentOffset=107}
13:59:18.056 [] [Thread-2260] INFO  io.zeebe.broker.system - Version: 0.24.0-SNAPSHOT
13:59:18.057 [] [Thread-2260] INFO  io.zeebe.broker.system - Starting broker 2 with configuration {
  "network" : {
    "host" : "0.0.0.0",
    "portOffset" : 0,
    "maxMessageSize" : "4MB",
    "advertisedHost" : "0.0.0.0",
    "commandApi" : {
      "host" : "0.0.0.0",
      "port" : 30802,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30802,
      "address" : "0.0.0.0:30802",
      "advertisedAddress" : "0.0.0.0:30802"
    },
    "internalApi" : {
      "host" : "0.0.0.0",
      "port" : 30803,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30803,
      "address" : "0.0.0.0:30803",
      "advertisedAddress" : "0.0.0.0:30803"
    },
    "monitoringApi" : {
      "host" : "0.0.0.0",
      "port" : 30804,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30804,
      "address" : "0.0.0.0:30804",
      "advertisedAddress" : "0.0.0.0:30804"
    },
    "maxMessageSizeInBytes" : 4194304
  },
  "cluster" : {
    "initialContactPoints" : [ "0.0.0.0:30893" ],
    "partitionIds" : [ 1 ],
    "nodeId" : 2,
    "partitionsCount" : 1,
    "replicationFactor" : 3,
    "clusterSize" : 3,
    "clusterName" : "zeebe-cluster-5",
    "gossipFailureTimeout" : 2000,
    "gossipInterval" : 150,
    "gossipProbeInterval" : 250
  },
  "threads" : {
    "cpuThreadCount" : 2,
    "ioThreadCount" : 2
  },
  "data" : {
    "directories" : [ "/tmp/junit6607366519595549948/2/data" ],
    "logSegmentSize" : "512MB",
    "snapshotPeriod" : "PT5M",
    "logIndexDensity" : 100,
    "logSegmentSizeInBytes" : 536870912
  },
  "exporters" : {
    "test-recorder" : {
      "jarPath" : null,
      "className" : "io.zeebe.test.util.record.RecordingExporter",
      "args" : null,
      "external" : false
    }
  },
  "gateway" : {
    "network" : {
      "host" : "0.0.0.0",
      "port" : 30800,
      "minKeepAliveInterval" : "PT30S"
    },
    "cluster" : {
      "contactPoint" : "0.0.0.0:30803",
      "requestTimeout" : "PT15S",
      "clusterName" : "zeebe-cluster",
      "memberId" : "gateway",
      "host" : "0.0.0.0",
      "port" : 30801
    },
    "threads" : {
      "managementThreads" : 1
    },
    "monitoring" : {
      "enabled" : false,
      "host" : "0.0.0.0",
      "port" : 9600
    },
    "security" : {
      "enabled" : false,
      "certificateChainPath" : null,
      "privateKeyPath" : null
    },
    "enable" : false
  },
  "backpressure" : {
    "enabled" : true,
    "algorithm" : "VEGAS"
  },
  "stepTimeout" : "PT5M",
  "executionMetricsExporterEnabled" : false
}
13:59:18.057 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [1/10]: actor scheduler
13:59:18.058 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [1/10]: actor scheduler started in 1 ms
13:59:18.058 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [2/10]: membership and replication protocol
13:59:18.058 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [2/10]: membership and replication protocol started in 5 ms
13:59:18.058 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [3/10]: command api transport
13:59:18.058 [] [Thread-2260] DEBUG io.zeebe.broker.clustering - Member 2 will contact node: 0.0.0.0:30893
13:59:18.064 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bound command API to 0.0.0.0:30892 
13:59:18.065 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [3/10]: command api transport started in 7 ms
13:59:18.065 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [4/10]: command api handler
13:59:18.065 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [4/10]: command api handler started in 0 ms
13:59:18.065 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [5/10]: subscription api
13:59:18.065 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [5/10]: subscription api started in 0 ms
13:59:18.065 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [6/10]: cluster services
13:59:18.073 [] [atomix-0] INFO  io.atomix.raft.partition.impl.RaftPartitionServer - Starting server for partition PartitionId{id=1, group=raft-partition}
13:59:18.136 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [2/10]: membership and replication protocol started in 81 ms
13:59:18.136 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [2/10]: membership and replication protocol started in 78 ms
13:59:18.136 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [3/10]: command api transport
13:59:18.137 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [3/10]: command api transport
13:59:18.140 [] [atomix-0] WARN  io.atomix.primitive.partition.impl.DefaultPartitionGroupMembershipService - Failed to locate partition group(s) via bootstrap nodes. Please ensure partition groups are configured either locally or remotely and the node is able to reach partition group members.
13:59:18.141 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bound command API to 0.0.0.0:30897 
13:59:18.141 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [3/10]: command api transport started in 4 ms
13:59:18.141 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [4/10]: command api handler
13:59:18.141 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [4/10]: command api handler started in 0 ms
13:59:18.141 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [5/10]: subscription api
13:59:18.142 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bound command API to 0.0.0.0:30802 
13:59:18.142 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [5/10]: subscription api started in 1 ms
13:59:18.142 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [6/10]: cluster services
13:59:18.142 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [3/10]: command api transport started in 5 ms
13:59:18.142 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [4/10]: command api handler
13:59:18.142 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [4/10]: command api handler started in 0 ms
13:59:18.142 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [5/10]: subscription api
13:59:18.143 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [5/10]: subscription api started in 1 ms
13:59:18.143 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [6/10]: cluster services
13:59:18.155 [] [atomix-0] INFO  io.atomix.raft.partition.impl.RaftPartitionServer - Starting server for partition PartitionId{id=1, group=raft-partition}
13:59:18.157 [] [atomix-0] INFO  io.atomix.raft.partition.impl.RaftPartitionServer - Starting server for partition PartitionId{id=1, group=raft-partition}
13:59:18.253 [] [raft-server-0-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to FOLLOWER
13:59:18.270 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to FOLLOWER
13:59:18.348 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to FOLLOWER
13:59:19.143 [] [raft-partition-group-raft-partition-0] INFO  io.atomix.raft.partition.RaftPartitionGroup - Started
13:59:19.145 [] [main] INFO  io.zeebe.gateway - Version: 0.24.0-SNAPSHOT
13:59:19.145 [] [main] INFO  io.zeebe.gateway - Starting gateway with configuration {
  "network" : {
    "host" : "0.0.0.0",
    "port" : 30805,
    "minKeepAliveInterval" : "PT30S"
  },
  "cluster" : {
    "contactPoint" : "0.0.0.0:30893",
    "requestTimeout" : "PT45S",
    "clusterName" : "zeebe-cluster-5",
    "memberId" : "gateway",
    "host" : "0.0.0.0",
    "port" : 30806
  },
  "threads" : {
    "managementThreads" : 1
  },
  "monitoring" : {
    "enabled" : false,
    "host" : "0.0.0.0",
    "port" : 9600
  },
  "security" : {
    "enabled" : false,
    "certificateChainPath" : null,
    "privateKeyPath" : null
  }
}
13:59:22.234 [] [raft-server-0-raft-partition-partition-1] INFO  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - No heartbeat from null in the last PT3.959S (calculated from last 3980 ms), sending poll requests
13:59:22.236 [] [raft-server-0-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to CANDIDATE
13:59:22.237 [] [raft-server-0-raft-partition-partition-1] INFO  io.atomix.raft.roles.CandidateRole - RaftServer{raft-partition-partition-1}{role=CANDIDATE} - Starting election
13:59:22.251 [] [raft-server-0-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to LEADER
13:59:22.252 [] [raft-server-0-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Found leader 0
13:59:22.278 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Found leader 0
13:59:22.278 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Found leader 0
13:59:22.359 [] [raft-partition-group-raft-partition-0] INFO  io.atomix.raft.partition.RaftPartitionGroup - Started
13:59:22.360 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [6/10]: cluster services started in 4295 ms
13:59:22.360 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [7/10]: topology manager
13:59:22.361 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [7/10]: topology manager started in 1 ms
13:59:22.361 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [8/10]: metric's server
13:59:22.373 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [8/10]: metric's server started in 12 ms
13:59:22.373 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [9/10]: leader management request handler
13:59:22.374 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [9/10]: leader management request handler started in 1 ms
13:59:22.374 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 [10/10]: zeebe partitions
13:59:22.374 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 partitions [1/1]: partition 1
13:59:22.374 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Removing follower partition service for partition PartitionId{id=1, group=raft-partition}
13:59:22.374 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Partition role transitioning from null to LEADER
13:59:22.374 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Installing leader partition service for partition PartitionId{id=1, group=raft-partition}
13:59:22.456 [GatewayTopologyManager] [gateway-scheduler-zb-actors-0] DEBUG io.zeebe.gateway - Received metadata change from Broker 0, partitions {} and terms {}.
13:59:22.464 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.logstreams.snapshot - Available snapshots: []
13:59:22.551 [] [raft-partition-group-raft-partition-0] INFO  io.atomix.raft.partition.RaftPartitionGroup - Started
13:59:22.551 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [6/10]: cluster services started in 4408 ms
13:59:22.551 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [7/10]: topology manager
13:59:22.552 [] [raft-partition-group-raft-partition-0] INFO  io.atomix.raft.partition.RaftPartitionGroup - Started
13:59:22.552 [Broker-2-TopologyManager] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 0, partitions {} terms {}
13:59:22.552 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [6/10]: cluster services started in 4410 ms
13:59:22.552 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [7/10]: topology manager
13:59:22.552 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [7/10]: topology manager started in 1 ms
13:59:22.552 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [8/10]: metric's server
13:59:22.552 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [7/10]: topology manager started in 0 ms
13:59:22.553 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [8/10]: metric's server
13:59:22.553 [Broker-1-TopologyManager] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 0, partitions {} terms {}
13:59:22.557 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [8/10]: metric's server started in 4 ms
13:59:22.557 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [9/10]: leader management request handler
13:59:22.557 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [8/10]: metric's server started in 5 ms
13:59:22.557 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [9/10]: leader management request handler
13:59:22.558 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [9/10]: leader management request handler started in 0 ms
13:59:22.558 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [10/10]: zeebe partitions
13:59:22.558 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [9/10]: leader management request handler started in 1 ms
13:59:22.558 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 [10/10]: zeebe partitions
13:59:22.558 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 partitions [1/1]: partition 1
13:59:22.558 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 partitions [1/1]: partition 1
13:59:22.558 [Broker-2-ZeebePartition-1] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.system - Removing leader partition services for partition PartitionId{id=1, group=raft-partition}
13:59:22.558 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.system - Removing leader partition services for partition PartitionId{id=1, group=raft-partition}
13:59:22.558 [Broker-2-ZeebePartition-1] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.system - Partition role transitioning from null to FOLLOWER
13:59:22.558 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.system - Partition role transitioning from null to FOLLOWER
13:59:22.559 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.system - Installing follower partition service for partition PartitionId{id=1, group=raft-partition}
13:59:22.559 [Broker-2-ZeebePartition-1] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.system - Installing follower partition service for partition PartitionId{id=1, group=raft-partition}
13:59:22.580 [Broker-2-HealthCheckService] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.system - All partitions are installed. Broker is ready!
13:59:22.580 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 partitions [1/1]: partition 1 started in 22 ms
13:59:22.580 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 partitions succeeded. Started 1 steps in 22 ms.
13:59:22.580 [] [Thread-2260] DEBUG io.zeebe.broker.system - Bootstrap Broker-2 [10/10]: zeebe partitions started in 22 ms
13:59:22.580 [] [Thread-2260] INFO  io.zeebe.broker.system - Bootstrap Broker-2 succeeded. Started 10 steps in 4523 ms.
13:59:22.585 [Broker-1-HealthCheckService] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.system - All partitions are installed. Broker is ready!
13:59:22.585 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 partitions [1/1]: partition 1 started in 27 ms
13:59:22.585 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 partitions succeeded. Started 1 steps in 27 ms.
13:59:22.585 [] [Thread-2254] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [10/10]: zeebe partitions started in 27 ms
13:59:22.585 [] [Thread-2254] INFO  io.zeebe.broker.system - Bootstrap Broker-1 succeeded. Started 10 steps in 4531 ms.
13:59:22.649 [Broker-2-TopologyManager] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 1, partitions {1=FOLLOWER} terms {}
13:59:22.649 [Broker-0-TopologyManager] [Broker-0-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 1, partitions {1=FOLLOWER} terms {}
13:59:22.656 [Broker-1-TopologyManager] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 2, partitions {1=FOLLOWER} terms {}
13:59:22.656 [GatewayTopologyManager] [gateway-scheduler-zb-actors-0] DEBUG io.zeebe.gateway - Received metadata change from Broker 1, partitions {1=FOLLOWER} and terms {}.
13:59:22.657 [GatewayTopologyManager] [gateway-scheduler-zb-actors-0] DEBUG io.zeebe.gateway - Received metadata change from Broker 2, partitions {1=FOLLOWER} and terms {}.
13:59:22.889 [Broker-0-TopologyManager] [Broker-0-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 2, partitions {1=FOLLOWER} terms {}
13:59:23.289 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.logstreams.snapshot - Opened database from '/tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/runtime'.
13:59:23.388 [Broker-0-LogStream-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.logstreams - Configured log appender back pressure at partition 1 as AppenderVegasCfg{initialLimit=1024, maxConcurrency=32768, alphaLimit=0.7, betaLimit=0.95}. Window limiting is disabled
13:59:23.394 [Broker-0-StreamProcessor-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.logstreams - Recovering state of partition 1 from snapshot
13:59:23.394 [Broker-0-StreamProcessor-1] [Broker-0-zb-actors-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.zeebe.el.impl.feel.MessagePackValueMapper@248f0a1f)), function-provider: io.zeebe.el.impl.feel.FeelFunctionProvider@17dc7391, configuration: Configuration(false)]
13:59:23.403 [Broker-0-StreamProcessor-1] [Broker-0-zb-actors-1] INFO  io.zeebe.logstreams - Recovered state of partition 1 from snapshot at position -1
13:59:23.403 [Broker-0-StreamProcessor-1] [Broker-0-zb-actors-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.zeebe.el.impl.feel.MessagePackValueMapper@4d565df1)), function-provider: io.zeebe.el.impl.feel.FeelFunctionProvider@11d579b6, configuration: Configuration(false)]
13:59:23.404 [Broker-0-StreamProcessor-1] [Broker-0-zb-actors-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.zeebe.el.impl.feel.MessagePackValueMapper@6561c0e6)), function-provider: io.zeebe.el.impl.feel.FeelFunctionProvider@52aac29f, configuration: Configuration(false)]
13:59:23.434 [Broker-0-Exporter-1] [Broker-0-zb-fs-workers-1] DEBUG io.zeebe.broker.exporter - Recovering exporter from snapshot
13:59:23.439 [Broker-0-HealthCheckService] [Broker-0-zb-actors-0] DEBUG io.zeebe.broker.system - All partitions are installed. Broker is ready!
13:59:23.439 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 partitions [1/1]: partition 1 started in 1065 ms
13:59:23.439 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 partitions succeeded. Started 1 steps in 1065 ms.
13:59:23.439 [] [Thread-2249] DEBUG io.zeebe.broker.system - Bootstrap Broker-0 [10/10]: zeebe partitions started in 1065 ms
13:59:23.439 [] [Thread-2249] INFO  io.zeebe.broker.system - Bootstrap Broker-0 succeeded. Started 10 steps in 5386 ms.
13:59:23.458 [Broker-0-Exporter-1] [Broker-0-zb-fs-workers-1] DEBUG io.zeebe.broker.exporter - Recovered exporter 'Broker-0-Exporter-1' from snapshot at lastExportedPosition -1
13:59:23.458 [Broker-0-Exporter-1] [Broker-0-zb-fs-workers-1] DEBUG io.zeebe.broker.exporter - Configure exporter with id 'test-recorder'
13:59:23.458 [Broker-0-Exporter-1] [Broker-0-zb-fs-workers-1] DEBUG io.zeebe.broker.exporter - Set event filter for exporters: ExporterEventFilter{acceptRecordTypes={COMMAND_REJECTION=true, SBE_UNKNOWN=true, NULL_VAL=true, EVENT=true, COMMAND=true}, acceptValueTypes={JOB=true, WORKFLOW_INSTANCE_CREATION=true, INCIDENT=true, MESSAGE_START_EVENT_SUBSCRIPTION=true, SBE_UNKNOWN=true, MESSAGE=true, MESSAGE_SUBSCRIPTION=true, WORKFLOW_INSTANCE_RESULT=true, WORKFLOW_INSTANCE=true, DEPLOYMENT=true, TIMER=true, VARIABLE_DOCUMENT=true, JOB_BATCH=true, VARIABLE=true, WORKFLOW_INSTANCE_SUBSCRIPTION=true, ERROR=true, NULL_VAL=true}}
13:59:23.459 [Broker-0-Exporter-1] [Broker-0-zb-fs-workers-1] DEBUG io.zeebe.broker.exporter - Open exporter with id 'test-recorder'
13:59:23.472 [Broker-2-TopologyManager] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 0, partitions {1=LEADER} terms {1=1}
13:59:23.472 [Broker-1-TopologyManager] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.clustering - Received metadata change for 0, partitions {1=LEADER} terms {1=1}
13:59:23.574 [GatewayTopologyManager] [gateway-scheduler-zb-actors-0] DEBUG io.zeebe.gateway - Received metadata change from Broker 0, partitions {1=LEADER} and terms {1=1}.
13:59:23.579 [] [main] INFO  io.zeebe.broker.system - Full replication factor
13:59:23.585 [] [main] INFO  io.zeebe.broker.system - All brokers in topology TopologyImpl{brokers=[BrokerInfoImpl{nodeId=0, host='0.0.0.0', port=30892, version=0.24.0-SNAPSHOT, partitions=[PartitionInfoImpl{partitionId=1, role=LEADER}]}, BrokerInfoImpl{nodeId=1, host='0.0.0.0', port=30897, version=0.24.0-SNAPSHOT, partitions=[PartitionInfoImpl{partitionId=1, role=FOLLOWER}]}, BrokerInfoImpl{nodeId=2, host='0.0.0.0', port=30802, version=0.24.0-SNAPSHOT, partitions=[PartitionInfoImpl{partitionId=1, role=FOLLOWER}]}], clusterSize=3, partitionsCount=1, replicationFactor=3, gatewayVersion=0.24.0-SNAPSHOT}
13:59:23.586 [] [main] INFO  io.zeebe.broker.test - 
====
Client startup time: 1
====

13:59:23.595 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [1/10]: zeebe partitions
13:59:23.595 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 partitions [1/1]: partition 1
13:59:23.595 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.system - Closing Broker-1-DeletionService-1
13:59:23.595 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.system - Closed Broker-1-DeletionService-1 successfully
13:59:23.595 [Broker-1-LogStream-1] [Broker-1-zb-actors-1] INFO  io.zeebe.logstreams - On closing logstream raft-partition-partition-1 close 1 readers
13:59:23.595 [Broker-1-LogStream-1] [Broker-1-zb-actors-1] INFO  io.zeebe.logstreams - Close log storage with name raft-partition-partition-1
13:59:23.595 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 partitions [1/1]: partition 1 closed in 0 ms
13:59:23.595 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 partitions succeeded. Closed 1 steps in 0 ms.
13:59:23.595 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [1/10]: zeebe partitions closed in 0 ms
13:59:23.595 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [2/10]: leader management request handler
13:59:23.596 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [2/10]: leader management request handler closed in 0 ms
13:59:23.596 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [3/10]: metric's server
13:59:23.599 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [3/10]: metric's server closed in 3 ms
13:59:23.599 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [4/10]: topology manager
13:59:23.599 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [4/10]: topology manager closed in 0 ms
13:59:23.599 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [5/10]: cluster services
13:59:23.599 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [5/10]: cluster services closed in 0 ms
13:59:23.599 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [6/10]: subscription api
13:59:23.599 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [6/10]: subscription api closed in 0 ms
13:59:23.599 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [7/10]: command api handler
13:59:23.599 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [7/10]: command api handler closed in 0 ms
13:59:23.599 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [8/10]: command api transport
13:59:25.839 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [8/10]: command api transport closed in 2240 ms
13:59:25.839 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [9/10]: membership and replication protocol
13:59:25.841 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to INACTIVE
13:59:25.841 [] [ForkJoinPool.commonPool-worker-5] INFO  io.atomix.raft.partition.RaftPartitionGroup - Stopped
13:59:26.039 [] [raft-server-0-raft-partition-partition-1] WARN  io.atomix.raft.roles.LeaderAppender - RaftServer{raft-partition-partition-1} - AppendRequest{term=1, leader=0, prevLogIndex=1, prevLogTerm=1, entries=0, commitIndex=1} to 1 failed: java.util.concurrent.CompletionException: io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /0.0.0.0:30898
13:59:26.074 [Broker-0-TopologyManager] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.clustering - Received REACHABILITY_CHANGED from member 1, was not handled.
13:59:26.140 [GatewayTopologyManager] [gateway-scheduler-zb-actors-0] DEBUG io.zeebe.gateway - Received REACHABILITY_CHANGED for broker 1, do nothing.
13:59:26.289 [] [raft-server-0-raft-partition-partition-1] WARN  io.atomix.raft.roles.LeaderAppender - RaftServer{raft-partition-partition-1} - AppendRequest{term=1, leader=0, prevLogIndex=1, prevLogTerm=1, entries=0, commitIndex=1} to 1 failed: java.util.concurrent.CompletionException: io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /0.0.0.0:30898
13:59:26.539 [] [raft-server-0-raft-partition-partition-1] WARN  io.atomix.raft.roles.LeaderAppender - RaftServer{raft-partition-partition-1} - AppendRequest{term=1, leader=0, prevLogIndex=1, prevLogTerm=1, entries=0, commitIndex=1} to 1 failed: java.util.concurrent.CompletionException: io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /0.0.0.0:30898
13:59:26.658 [Broker-2-TopologyManager] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.clustering - Received REACHABILITY_CHANGED from member 1, was not handled.
13:59:28.052 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [9/10]: membership and replication protocol closed in 2213 ms
13:59:28.052 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [10/10]: actor scheduler
13:59:28.053 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [10/10]: actor scheduler closed in 1 ms
13:59:28.053 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 succeeded. Closed 10 steps in 4458 ms.
13:59:28.054 [] [main] INFO  io.zeebe.broker.system - Broker shut down.
13:59:28.122 [Broker-0-TopologyManager] [Broker-0-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received member removed BrokerInfo{nodeId=1, partitionsCount=1, clusterSize=3, replicationFactor=3, partitionRoles={1=FOLLOWER}, partitionLeaderTerms={}, version=0.24.0-SNAPSHOT} 
13:59:28.122 [Broker-2-TopologyManager] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received member removed BrokerInfo{nodeId=1, partitionsCount=1, clusterSize=3, replicationFactor=3, partitionRoles={1=FOLLOWER}, partitionLeaderTerms={}, version=0.24.0-SNAPSHOT} 
13:59:28.122 [GatewayTopologyManager] [gateway-scheduler-zb-actors-0] DEBUG io.zeebe.gateway - Received broker was removed BrokerInfo{nodeId=1, partitionsCount=1, clusterSize=3, replicationFactor=3, partitionRoles={1=FOLLOWER}, partitionLeaderTerms={}, version=0.24.0-SNAPSHOT}.
13:59:28.221 [] [main] DEBUG io.zeebe.broker.system - Initializing system with base path /tmp/junit6607366519595549948/1
13:59:28.221 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-0] DEBUG io.zeebe.broker.system - Detected unhealthy components. The current health status of components: {Raft-1=HEALTHY, Broker-0-StreamProcessor-1=UNHEALTHY, logStream=HEALTHY}
13:59:28.221 [Broker-0-HealthCheckService] [Broker-0-zb-actors-0] ERROR io.zeebe.broker.system - Partition-1 failed, marking it as unhealthy
13:59:28.222 [] [main] INFO  io.zeebe.broker.system - Version: 0.24.0-SNAPSHOT
13:59:28.224 [] [main] INFO  io.zeebe.broker.system - Starting broker 1 with configuration {
  "network" : {
    "host" : "0.0.0.0",
    "portOffset" : 0,
    "maxMessageSize" : "4MB",
    "advertisedHost" : "0.0.0.0",
    "commandApi" : {
      "host" : "0.0.0.0",
      "port" : 30897,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30897,
      "address" : "0.0.0.0:30897",
      "advertisedAddress" : "0.0.0.0:30897"
    },
    "internalApi" : {
      "host" : "0.0.0.0",
      "port" : 30898,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30898,
      "address" : "0.0.0.0:30898",
      "advertisedAddress" : "0.0.0.0:30898"
    },
    "monitoringApi" : {
      "host" : "0.0.0.0",
      "port" : 30899,
      "advertisedHost" : "0.0.0.0",
      "advertisedPort" : 30899,
      "address" : "0.0.0.0:30899",
      "advertisedAddress" : "0.0.0.0:30899"
    },
    "maxMessageSizeInBytes" : 4194304
  },
  "cluster" : {
    "initialContactPoints" : [ "0.0.0.0:30893" ],
    "partitionIds" : [ 1 ],
    "nodeId" : 1,
    "partitionsCount" : 1,
    "replicationFactor" : 3,
    "clusterSize" : 3,
    "clusterName" : "zeebe-cluster-5",
    "gossipFailureTimeout" : 2000,
    "gossipInterval" : 150,
    "gossipProbeInterval" : 250
  },
  "threads" : {
    "cpuThreadCount" : 2,
    "ioThreadCount" : 2
  },
  "data" : {
    "directories" : [ "/tmp/junit6607366519595549948/1/data" ],
    "logSegmentSize" : "512MB",
    "snapshotPeriod" : "PT5M",
    "logIndexDensity" : 100,
    "logSegmentSizeInBytes" : 536870912
  },
  "exporters" : {
    "test-recorder" : {
      "jarPath" : null,
      "className" : "io.zeebe.test.util.record.RecordingExporter",
      "args" : null,
      "external" : false
    }
  },
  "gateway" : {
    "network" : {
      "host" : "0.0.0.0",
      "port" : 30895,
      "minKeepAliveInterval" : "PT30S"
    },
    "cluster" : {
      "contactPoint" : "0.0.0.0:30898",
      "requestTimeout" : "PT15S",
      "clusterName" : "zeebe-cluster",
      "memberId" : "gateway",
      "host" : "0.0.0.0",
      "port" : 30896
    },
    "threads" : {
      "managementThreads" : 1
    },
    "monitoring" : {
      "enabled" : false,
      "host" : "0.0.0.0",
      "port" : 9600
    },
    "security" : {
      "enabled" : false,
      "certificateChainPath" : null,
      "privateKeyPath" : null
    },
    "enable" : false
  },
  "backpressure" : {
    "enabled" : true,
    "algorithm" : "VEGAS"
  },
  "stepTimeout" : "PT5M",
  "executionMetricsExporterEnabled" : false
}
13:59:28.224 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [1/10]: actor scheduler
13:59:28.225 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [1/10]: actor scheduler started in 1 ms
13:59:28.225 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [2/10]: membership and replication protocol
13:59:28.225 [] [main] DEBUG io.zeebe.broker.clustering - Member 1 will contact node: 0.0.0.0:30893
13:59:28.229 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [2/10]: membership and replication protocol started in 4 ms
13:59:28.229 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [3/10]: command api transport
13:59:28.230 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Taking temporary snapshot into /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/pushed-pending/2-1-1587477568230.
13:59:28.231 [] [main] DEBUG io.zeebe.broker.system - Bound command API to 0.0.0.0:30897 
13:59:28.231 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [3/10]: command api transport started in 2 ms
13:59:28.231 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [4/10]: command api handler
13:59:28.231 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [4/10]: command api handler started in 0 ms
13:59:28.231 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [5/10]: subscription api
13:59:28.232 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [5/10]: subscription api started in 0 ms
13:59:28.232 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [6/10]: cluster services
13:59:28.237 [] [atomix-0] INFO  io.atomix.raft.partition.impl.RaftPartitionServer - Starting server for partition PartitionId{id=1, group=raft-partition}
13:59:28.276 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to FOLLOWER
13:59:28.295 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Found leader 0
13:59:28.300 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Created snapshot for Broker-0-StreamProcessor-1
13:59:28.300 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] INFO  io.zeebe.logstreams.snapshot - Finished taking snapshot, need to wait until last written event position 0 is committed, current commit position is 4294967296. After that snapshot can be marked as valid.
13:59:28.300 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] INFO  io.zeebe.logstreams.snapshot - Current commit position 4294971584 is greater then 0, snapshot is valid.
13:59:28.334 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.broker.clustering.atomix.storage.snapshot.AtomixSnapshotStorage - Purging snapshots older than DbSnapshot{directory=/tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230, metadata=DbSnapshotMetadata{index=2, term=1, timestamp=2020-04-21 01:59:28,230}}
13:59:28.334 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.broker.clustering.atomix.storage.snapshot.AtomixSnapshotStorage - Search for orphaned snapshots below oldest valid snapshot with index 2 in /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/pushed-pending
13:59:28.334 [Broker-0-DeletionService-1] [Broker-0-zb-actors-0] DEBUG io.zeebe.broker.logstreams.delete - Compacting Atomix log up to index 2
13:59:28.334 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.broker.clustering.atomix.storage.snapshot.DbSnapshotStore - Committed new snapshot DbSnapshot{directory=/tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230, metadata=DbSnapshotMetadata{index=2, term=1, timestamp=2020-04-21 01:59:28,230}}
13:59:28.335 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Start replicating latest snapshot /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230
13:59:28.335 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000091.log
13:59:28.336 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000092.sst
13:59:28.336 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000093.sst
13:59:28.336 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000094.sst
13:59:28.336 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000095.sst
13:59:28.337 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000096.log
13:59:28.337 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000097.sst
13:59:28.337 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000098.sst
13:59:28.337 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000099.sst
13:59:28.337 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/000100.sst
13:59:28.337 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/CURRENT
13:59:28.338 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/MANIFEST-000004
13:59:28.338 [Broker-0-SnapshotDirector-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.logstreams.snapshot - Replicate snapshot chunk /tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/snapshots/2-1-1587477568230/OPTIONS-000090
13:59:28.338 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000091.log of snapshot 2-1-1587477568230
13:59:28.338 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 1/13
13:59:28.338 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000092.sst of snapshot 2-1-1587477568230
13:59:28.338 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 2/13
13:59:28.338 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000093.sst of snapshot 2-1-1587477568230
13:59:28.339 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 3/13
13:59:28.339 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000094.sst of snapshot 2-1-1587477568230
13:59:28.339 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 4/13
13:59:28.339 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000095.sst of snapshot 2-1-1587477568230
13:59:28.339 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 5/13
13:59:28.339 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000096.log of snapshot 2-1-1587477568230
13:59:28.340 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 6/13
13:59:28.340 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000097.sst of snapshot 2-1-1587477568230
13:59:28.341 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 7/13
13:59:28.341 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000098.sst of snapshot 2-1-1587477568230
13:59:28.341 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 8/13
13:59:28.341 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000099.sst of snapshot 2-1-1587477568230
13:59:28.341 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 9/13
13:59:28.341 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk 000100.sst of snapshot 2-1-1587477568230
13:59:28.341 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 10/13
13:59:28.341 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk CURRENT of snapshot 2-1-1587477568230
13:59:28.342 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 11/13
13:59:28.342 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk MANIFEST-000004 of snapshot 2-1-1587477568230
13:59:28.342 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Waiting for more snapshot chunks, currently have 12/13
13:59:28.343 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Consume snapshot chunk OPTIONS-000090 of snapshot 2-1-1587477568230
13:59:28.343 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.logstreams.snapshot - Received all snapshot chunks (13/13), snapshot is valid
13:59:28.344 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.broker.clustering.atomix.storage.snapshot.AtomixSnapshotStorage - Purging snapshots older than DbSnapshot{directory=/tmp/junit6607366519595549948/2/data/raft-partition/partitions/1/snapshots/2-1-1587477568230, metadata=DbSnapshotMetadata{index=2, term=1, timestamp=2020-04-21 01:59:28,230}}
13:59:28.344 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.broker.clustering.atomix.storage.snapshot.AtomixSnapshotStorage - Search for orphaned snapshots below oldest valid snapshot with index 2 in /tmp/junit6607366519595549948/2/data/raft-partition/partitions/1/pushed-pending
13:59:28.344 [Broker-2-DeletionService-1] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.logstreams.delete - Compacting Atomix log up to index 2
13:59:28.344 [] [Broker-2-StateReplication-1] DEBUG io.zeebe.broker.clustering.atomix.storage.snapshot.DbSnapshotStore - Committed new snapshot DbSnapshot{directory=/tmp/junit6607366519595549948/2/data/raft-partition/partitions/1/snapshots/2-1-1587477568230, metadata=DbSnapshotMetadata{index=2, term=1, timestamp=2020-04-21 01:59:28,230}}
13:59:28.349 [] [raft-partition-group-raft-partition-0] INFO  io.atomix.raft.partition.RaftPartitionGroup - Started
13:59:28.350 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [6/10]: cluster services started in 118 ms
13:59:28.350 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [7/10]: topology manager
13:59:28.350 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [7/10]: topology manager started in 0 ms
13:59:28.350 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [8/10]: metric's server
13:59:28.350 [Broker-1-TopologyManager] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 0, partitions {1=LEADER} terms {1=1}
13:59:28.350 [Broker-1-TopologyManager] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 2, partitions {1=FOLLOWER} terms {}
13:59:28.351 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [8/10]: metric's server started in 1 ms
13:59:28.351 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [9/10]: leader management request handler
13:59:28.352 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [9/10]: leader management request handler started in 1 ms
13:59:28.352 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 [10/10]: zeebe partitions
13:59:28.352 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 partitions [1/1]: partition 1
13:59:28.352 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.system - Removing leader partition services for partition PartitionId{id=1, group=raft-partition}
13:59:28.352 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.system - Partition role transitioning from null to FOLLOWER
13:59:28.352 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.system - Installing follower partition service for partition PartitionId{id=1, group=raft-partition}
13:59:28.369 [Broker-1-HealthCheckService] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.system - All partitions are installed. Broker is ready!
13:59:28.369 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 partitions [1/1]: partition 1 started in 17 ms
13:59:28.369 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 partitions succeeded. Started 1 steps in 17 ms.
13:59:28.369 [] [main] DEBUG io.zeebe.broker.system - Bootstrap Broker-1 [10/10]: zeebe partitions started in 17 ms
13:59:28.369 [] [main] INFO  io.zeebe.broker.system - Bootstrap Broker-1 succeeded. Started 10 steps in 145 ms.
13:59:28.386 [Broker-2-TopologyManager] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received metadata change for 1, partitions {1=FOLLOWER} terms {}
13:59:28.386 [GatewayTopologyManager] [gateway-scheduler-zb-actors-0] DEBUG io.zeebe.gateway - Received metadata change from Broker 1, partitions {1=FOLLOWER} and terms {}.
13:59:28.388 [Broker-0-TopologyManager] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.clustering - Received metadata change for 1, partitions {1=FOLLOWER} terms {}
14:00:28.238 [Broker-0-HealthCheckService] [Broker-0-zb-actors-0] DEBUG io.zeebe.broker.system - Partition-1 recovered, marking it as healthy
14:01:08.652 [] [main] INFO  io.zeebe.broker.test - Client Rule assumption: Test execution time: 105065
14:01:08.653 [] [main] INFO  io.zeebe.broker.test - Client closing time: 1
14:01:08.654 [] [main] INFO  io.zeebe.test.records - Test failed, following records where exported:
14:01:08.666 [] [main] INFO  io.zeebe.test.records - {"valueType":"DEPLOYMENT","key":-1,"position":4294967296,"timestamp":1587477568174,"recordType":"COMMAND","intent":"CREATE","partitionId":1,"rejectionType":"NULL_VAL","rejectionReason":"","value":{"resources":[{"resource":"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9Im5vIj8+CjxkZWZpbml0aW9ucyB4bWxuczpicG1uZGk9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0JQTU4vMjAxMDA1MjQvREkiIHhtbG5zOmRjPSJodHRwOi8vd3d3Lm9tZy5vcmcvc3BlYy9ERC8yMDEwMDUyNC9EQyIgeG1sbnM6ZGk9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0RELzIwMTAwNTI0L0RJIiBpZD0iZGVmaW5pdGlvbnNfODgzZmJlMDctM2NiMi00ZDdiLWIxMWQtN2ExYzgxMmMyMmFhIiB0YXJnZXROYW1lc3BhY2U9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0JQTU4vMjAxMDA1MjQvTU9ERUwiIHhtbG5zPSJodHRwOi8vd3d3Lm9tZy5vcmcvc3BlYy9CUE1OLzIwMTAwNTI0L01PREVMIj4KICA8cHJvY2VzcyBpZD0icHJvY2VzcyIgaXNFeGVjdXRhYmxlPSJ0cnVlIj4KICAgIDxzdGFydEV2ZW50IGlkPSJzdGFydEV2ZW50X2MyYTVjZWY1LTg4M2QtNGMxYi04OGYzLWI1YTc0NWY0MGUxZSI+CiAgICAgIDxvdXRnb2luZz5zZXF1ZW5jZUZsb3dfNmVhZTA3NTEtZmE4MS00OWM4LTk1ZGUtY2MzN2ViZTkyZjk4PC9vdXRnb2luZz4KICAgIDwvc3RhcnRFdmVud...
14:01:08.667 [] [main] INFO  io.zeebe.test.records - {"valueType":"DEPLOYMENT","key":2251799813685250,"position":4294969392,"timestamp":1587477568218,"recordType":"EVENT","intent":"CREATED","partitionId":1,"rejectionType":"NULL_VAL","rejectionReason":"","value":{"resources":[{"resource":"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9Im5vIj8+CjxkZWZpbml0aW9ucyB4bWxuczpicG1uZGk9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0JQTU4vMjAxMDA1MjQvREkiIHhtbG5zOmRjPSJodHRwOi8vd3d3Lm9tZy5vcmcvc3BlYy9ERC8yMDEwMDUyNC9EQyIgeG1sbnM6ZGk9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0RELzIwMTAwNTI0L0RJIiBpZD0iZGVmaW5pdGlvbnNfODgzZmJlMDctM2NiMi00ZDdiLWIxMWQtN2ExYzgxMmMyMmFhIiB0YXJnZXROYW1lc3BhY2U9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0JQTU4vMjAxMDA1MjQvTU9ERUwiIHhtbG5zPSJodHRwOi8vd3d3Lm9tZy5vcmcvc3BlYy9CUE1OLzIwMTAwNTI0L01PREVMIj4KICA8cHJvY2VzcyBpZD0icHJvY2VzcyIgaXNFeGVjdXRhYmxlPSJ0cnVlIj4KICAgIDxzdGFydEV2ZW50IGlkPSJzdGFydEV2ZW50X2MyYTVjZWY1LTg4M2QtNGMxYi04OGYzLWI1YTc0NWY0MGUxZSI+CiAgICAgIDxvdXRnb2luZz5zZXF1ZW5jZUZsb3dfNmVhZTA3NTEtZmE4MS00OWM4LTk1ZGUtY2MzN2ViZTkyZjk4PC9vdXRnb2luZz4KICAgIDwv...
14:01:08.668 [] [main] INFO  io.zeebe.test.records - {"valueType":"DEPLOYMENT","key":2251799813685250,"position":4294971584,"timestamp":1587477868256,"recordType":"COMMAND","intent":"DISTRIBUTE","partitionId":1,"rejectionType":"NULL_VAL","rejectionReason":"","value":{"resources":[{"resource":"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9Im5vIj8+CjxkZWZpbml0aW9ucyB4bWxuczpicG1uZGk9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0JQTU4vMjAxMDA1MjQvREkiIHhtbG5zOmRjPSJodHRwOi8vd3d3Lm9tZy5vcmcvc3BlYy9ERC8yMDEwMDUyNC9EQyIgeG1sbnM6ZGk9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0RELzIwMTAwNTI0L0RJIiBpZD0iZGVmaW5pdGlvbnNfODgzZmJlMDctM2NiMi00ZDdiLWIxMWQtN2ExYzgxMmMyMmFhIiB0YXJnZXROYW1lc3BhY2U9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0JQTU4vMjAxMDA1MjQvTU9ERUwiIHhtbG5zPSJodHRwOi8vd3d3Lm9tZy5vcmcvc3BlYy9CUE1OLzIwMTAwNTI0L01PREVMIj4KICA8cHJvY2VzcyBpZD0icHJvY2VzcyIgaXNFeGVjdXRhYmxlPSJ0cnVlIj4KICAgIDxzdGFydEV2ZW50IGlkPSJzdGFydEV2ZW50X2MyYTVjZWY1LTg4M2QtNGMxYi04OGYzLWI1YTc0NWY0MGUxZSI+CiAgICAgIDxvdXRnb2luZz5zZXF1ZW5jZUZsb3dfNmVhZTA3NTEtZmE4MS00OWM4LTk1ZGUtY2MzN2ViZTkyZjk4PC9vdXRnb2luZz4KICA...
14:01:08.668 [] [main] INFO  io.zeebe.test.records - {"valueType":"DEPLOYMENT","key":2251799813685250,"position":4294973776,"timestamp":1587477868282,"recordType":"EVENT","intent":"DISTRIBUTED","partitionId":1,"rejectionType":"NULL_VAL","rejectionReason":"","value":{"resources":[{"resource":"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiIHN0YW5kYWxvbmU9Im5vIj8+CjxkZWZpbml0aW9ucyB4bWxuczpicG1uZGk9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0JQTU4vMjAxMDA1MjQvREkiIHhtbG5zOmRjPSJodHRwOi8vd3d3Lm9tZy5vcmcvc3BlYy9ERC8yMDEwMDUyNC9EQyIgeG1sbnM6ZGk9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0RELzIwMTAwNTI0L0RJIiBpZD0iZGVmaW5pdGlvbnNfODgzZmJlMDctM2NiMi00ZDdiLWIxMWQtN2ExYzgxMmMyMmFhIiB0YXJnZXROYW1lc3BhY2U9Imh0dHA6Ly93d3cub21nLm9yZy9zcGVjL0JQTU4vMjAxMDA1MjQvTU9ERUwiIHhtbG5zPSJodHRwOi8vd3d3Lm9tZy5vcmcvc3BlYy9CUE1OLzIwMTAwNTI0L01PREVMIj4KICA8cHJvY2VzcyBpZD0icHJvY2VzcyIgaXNFeGVjdXRhYmxlPSJ0cnVlIj4KICAgIDxzdGFydEV2ZW50IGlkPSJzdGFydEV2ZW50X2MyYTVjZWY1LTg4M2QtNGMxYi04OGYzLWI1YTc0NWY0MGUxZSI+CiAgICAgIDxvdXRnb2luZz5zZXF1ZW5jZUZsb3dfNmVhZTA3NTEtZmE4MS00OWM4LTk1ZGUtY2MzN2ViZTkyZjk4PC9vdXRnb2luZz4KICAg...
14:01:08.670 [] [ForkJoinPool.commonPool-worker-15] INFO  io.atomix.raft.partition.RaftPartitionGroup - Stopped
14:01:08.670 [] [main] DEBUG io.zeebe.gateway - Closing gateway broker client ...
14:01:08.670 [] [main] DEBUG io.zeebe.gateway - topology manager closed
14:01:08.671 [] [main] DEBUG io.zeebe.gateway - Gateway broker client closed.
14:01:08.671 [] [main] DEBUG io.zeebe.broker.system - Closing ClusteringRule...
14:01:08.671 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [1/10]: zeebe partitions
14:01:08.671 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 partitions [1/1]: partition 1
14:01:08.671 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Closing Broker-0-Exporter-1
14:01:08.671 [Broker-0-Exporter-1] [Broker-0-zb-fs-workers-0] DEBUG io.zeebe.broker.exporter - Closed exporter director 'Broker-0-Exporter-1'.
14:01:08.671 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Closed Broker-0-Exporter-1 successfully
14:01:08.671 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Closing Broker-0-SnapshotDirector-1
14:01:08.671 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Closed Broker-0-SnapshotDirector-1 successfully
14:01:08.671 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Closing Broker-0-StreamProcessor-1
14:01:08.672 [Broker-0-StreamProcessor-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.logstreams - Closed stream processor controller Broker-0-StreamProcessor-1.
14:01:08.672 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Closed Broker-0-StreamProcessor-1 successfully
14:01:08.672 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Closing Broker-0-DeletionService-1
14:01:08.672 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.broker.system - Closed Broker-0-DeletionService-1 successfully
14:01:08.712 [Broker-0-ZeebePartition-1] [Broker-0-zb-actors-1] DEBUG io.zeebe.logstreams.snapshot - Closed database from '/tmp/junit6607366519595549948/0/data/raft-partition/partitions/1/runtime'.
14:01:08.712 [Broker-0-LogStream-1] [Broker-0-zb-actors-1] INFO  io.zeebe.logstreams - Close appender for log stream raft-partition-partition-1
14:01:08.712 [raft-partition-partition-1-write-buffer] [Broker-0-zb-actors-1] DEBUG io.zeebe.dispatcher - Dispatcher closed
14:01:08.712 [Broker-0-LogStream-1] [Broker-0-zb-actors-1] INFO  io.zeebe.logstreams - On closing logstream raft-partition-partition-1 close 3 readers
14:01:08.712 [Broker-0-LogStream-1] [Broker-0-zb-actors-1] INFO  io.zeebe.logstreams - Close log storage with name raft-partition-partition-1
14:01:08.713 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 partitions [1/1]: partition 1 closed in 42 ms
14:01:08.713 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 partitions succeeded. Closed 1 steps in 42 ms.
14:01:08.713 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [1/10]: zeebe partitions closed in 42 ms
14:01:08.713 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [2/10]: leader management request handler
14:01:08.713 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [2/10]: leader management request handler closed in 0 ms
14:01:08.713 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [3/10]: metric's server
14:01:08.716 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [3/10]: metric's server closed in 3 ms
14:01:08.716 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [4/10]: topology manager
14:01:08.717 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [4/10]: topology manager closed in 1 ms
14:01:08.717 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [5/10]: cluster services
14:01:08.717 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [5/10]: cluster services closed in 0 ms
14:01:08.717 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [6/10]: subscription api
14:01:08.717 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [6/10]: subscription api closed in 0 ms
14:01:08.717 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [7/10]: command api handler
14:01:08.717 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [7/10]: command api handler closed in 0 ms
14:01:08.717 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [8/10]: command api transport
14:01:10.922 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [8/10]: command api transport closed in 2205 ms
14:01:10.922 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [9/10]: membership and replication protocol
14:01:10.924 [] [raft-server-0-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to INACTIVE
14:01:10.927 [] [ForkJoinPool.commonPool-worker-13] INFO  io.atomix.raft.partition.RaftPartitionGroup - Stopped
14:01:10.988 [Broker-1-TopologyManager] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received REACHABILITY_CHANGED from member 0, was not handled.
14:01:11.136 [Broker-2-TopologyManager] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received REACHABILITY_CHANGED from member 0, was not handled.
14:01:13.086 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Known leader 0 was removed from cluster, sending poll requests
14:01:13.086 [Broker-1-TopologyManager] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received member removed BrokerInfo{nodeId=0, partitionsCount=1, clusterSize=3, replicationFactor=3, partitionRoles={1=LEADER}, partitionLeaderTerms={1=1}, version=0.24.0-SNAPSHOT} 
14:01:13.086 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Known leader 0 was removed from cluster, sending poll requests
14:01:13.086 [Broker-2-TopologyManager] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received member removed BrokerInfo{nodeId=0, partitionsCount=1, clusterSize=3, replicationFactor=3, partitionRoles={1=LEADER}, partitionLeaderTerms={1=1}, version=0.24.0-SNAPSHOT} 
14:01:13.088 [] [raft-server-1-raft-partition-partition-1] WARN  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - java.net.ConnectException
14:01:13.088 [] [raft-server-2-raft-partition-partition-1] WARN  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - java.net.ConnectException
14:01:13.089 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Accepted PollRequest{term=1, candidate=1, lastLogIndex=5, lastLogTerm=1}: candidate's log is up-to-date
14:01:13.089 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Accepted PollRequest{term=1, candidate=2, lastLogIndex=5, lastLogTerm=1}: candidate's log is up-to-date
14:01:13.089 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to CANDIDATE
14:01:13.089 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to CANDIDATE
14:01:13.089 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.roles.CandidateRole - RaftServer{raft-partition-partition-1}{role=CANDIDATE} - Starting election
14:01:13.089 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.roles.CandidateRole - RaftServer{raft-partition-partition-1}{role=CANDIDATE} - Starting election
14:01:13.095 [] [raft-server-1-raft-partition-partition-1] WARN  io.atomix.raft.roles.CandidateRole - RaftServer{raft-partition-partition-1}{role=CANDIDATE} - java.net.ConnectException
14:01:13.096 [Broker-2-ZeebePartition-1] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.system - Partition role transitioning from FOLLOWER to CANDIDATE
14:01:13.095 [] [raft-server-2-raft-partition-partition-1] WARN  io.atomix.raft.roles.CandidateRole - RaftServer{raft-partition-partition-1}{role=CANDIDATE} - java.net.ConnectException
14:01:13.095 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.system - Partition role transitioning from FOLLOWER to CANDIDATE
14:01:13.096 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to FOLLOWER
14:01:13.096 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-1] DEBUG io.zeebe.broker.system - Partition role transitioning from CANDIDATE to FOLLOWER
14:01:13.096 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to FOLLOWER
14:01:13.097 [Broker-2-ZeebePartition-1] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.system - Partition role transitioning from CANDIDATE to FOLLOWER
14:01:13.133 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [9/10]: membership and replication protocol closed in 2211 ms
14:01:13.133 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 [10/10]: actor scheduler
14:01:13.134 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-0 [10/10]: actor scheduler closed in 0 ms
14:01:13.134 [] [main] INFO  io.zeebe.broker.system - Closing Broker-0 succeeded. Closed 10 steps in 4463 ms.
14:01:13.134 [] [main] INFO  io.zeebe.broker.system - Broker shut down.
14:01:13.134 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [1/10]: zeebe partitions
14:01:13.134 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 partitions [1/1]: partition 1
14:01:13.135 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.system - Closing Broker-1-DeletionService-1
14:01:13.135 [Broker-1-ZeebePartition-1] [Broker-1-zb-actors-0] DEBUG io.zeebe.broker.system - Closed Broker-1-DeletionService-1 successfully
14:01:13.135 [Broker-1-LogStream-1] [Broker-1-zb-actors-0] INFO  io.zeebe.logstreams - On closing logstream raft-partition-partition-1 close 1 readers
14:01:13.135 [Broker-1-LogStream-1] [Broker-1-zb-actors-0] INFO  io.zeebe.logstreams - Close log storage with name raft-partition-partition-1
14:01:13.135 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 partitions [1/1]: partition 1 closed in 1 ms
14:01:13.135 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 partitions succeeded. Closed 1 steps in 1 ms.
14:01:13.135 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [1/10]: zeebe partitions closed in 1 ms
14:01:13.135 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [2/10]: leader management request handler
14:01:13.135 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [2/10]: leader management request handler closed in 0 ms
14:01:13.135 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [3/10]: metric's server
14:01:13.138 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [3/10]: metric's server closed in 3 ms
14:01:13.138 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [4/10]: topology manager
14:01:13.138 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [4/10]: topology manager closed in 0 ms
14:01:13.138 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [5/10]: cluster services
14:01:13.138 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [5/10]: cluster services closed in 0 ms
14:01:13.138 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [6/10]: subscription api
14:01:13.138 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [6/10]: subscription api closed in 0 ms
14:01:13.138 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [7/10]: command api handler
14:01:13.138 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [7/10]: command api handler closed in 0 ms
14:01:13.138 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [8/10]: command api transport
14:01:15.343 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [8/10]: command api transport closed in 2205 ms
14:01:15.343 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [9/10]: membership and replication protocol
14:01:15.344 [] [raft-server-1-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to INACTIVE
14:01:15.345 [] [ForkJoinPool.commonPool-worker-13] INFO  io.atomix.raft.partition.RaftPartitionGroup - Stopped
14:01:15.656 [Broker-2-TopologyManager] [Broker-2-zb-actors-0] DEBUG io.zeebe.broker.clustering - Received REACHABILITY_CHANGED from member 1, was not handled.
14:01:16.637 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - No heartbeat from null in the last PT3.54S (calculated from last 3540 ms), sending poll requests
14:01:16.638 [] [raft-server-2-raft-partition-partition-1] WARN  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - java.net.ConnectException
14:01:16.638 [] [raft-server-2-raft-partition-partition-1] WARN  io.atomix.raft.roles.FollowerRole - RaftServer{raft-partition-partition-1}{role=FOLLOWER} - io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /0.0.0.0:30898
14:01:17.561 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [9/10]: membership and replication protocol closed in 2218 ms
14:01:17.561 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 [10/10]: actor scheduler
14:01:17.562 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-1 [10/10]: actor scheduler closed in 1 ms
14:01:17.562 [] [main] INFO  io.zeebe.broker.system - Closing Broker-1 succeeded. Closed 10 steps in 4428 ms.
14:01:17.562 [] [main] INFO  io.zeebe.broker.system - Broker shut down.
14:01:17.562 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [1/10]: zeebe partitions
14:01:17.562 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 partitions [1/1]: partition 1
14:01:17.562 [Broker-2-ZeebePartition-1] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.system - Closing Broker-2-DeletionService-1
14:01:17.562 [Broker-2-ZeebePartition-1] [Broker-2-zb-actors-1] DEBUG io.zeebe.broker.system - Closed Broker-2-DeletionService-1 successfully
14:01:17.563 [Broker-2-LogStream-1] [Broker-2-zb-actors-1] INFO  io.zeebe.logstreams - On closing logstream raft-partition-partition-1 close 1 readers
14:01:17.563 [Broker-2-LogStream-1] [Broker-2-zb-actors-1] INFO  io.zeebe.logstreams - Close log storage with name raft-partition-partition-1
14:01:17.563 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 partitions [1/1]: partition 1 closed in 1 ms
14:01:17.563 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 partitions succeeded. Closed 1 steps in 1 ms.
14:01:17.563 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [1/10]: zeebe partitions closed in 1 ms
14:01:17.563 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [2/10]: leader management request handler
14:01:17.563 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [2/10]: leader management request handler closed in 0 ms
14:01:17.563 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [3/10]: metric's server
14:01:17.566 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [3/10]: metric's server closed in 3 ms
14:01:17.566 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [4/10]: topology manager
14:01:17.566 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [4/10]: topology manager closed in 0 ms
14:01:17.566 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [5/10]: cluster services
14:01:17.566 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [5/10]: cluster services closed in 0 ms
14:01:17.566 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [6/10]: subscription api
14:01:17.566 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [6/10]: subscription api closed in 0 ms
14:01:17.566 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [7/10]: command api handler
14:01:17.566 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [7/10]: command api handler closed in 0 ms
14:01:17.566 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [8/10]: command api transport
14:01:19.771 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [8/10]: command api transport closed in 2205 ms
14:01:19.771 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [9/10]: membership and replication protocol
14:01:19.773 [] [raft-server-2-raft-partition-partition-1] INFO  io.atomix.raft.impl.RaftContext - RaftServer{raft-partition-partition-1} - Transitioning to INACTIVE
14:01:19.773 [] [ForkJoinPool.commonPool-worker-13] INFO  io.atomix.raft.partition.RaftPartitionGroup - Stopped
14:01:21.979 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [9/10]: membership and replication protocol closed in 2208 ms
14:01:21.979 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 [10/10]: actor scheduler
14:01:21.980 [] [main] DEBUG io.zeebe.broker.system - Closing Broker-2 [10/10]: actor scheduler closed in 1 ms
14:01:21.980 [] [main] INFO  io.zeebe.broker.system - Closing Broker-2 succeeded. Closed 10 steps in 4418 ms.
14:01:21.980 [] [main] INFO  io.zeebe.broker.system - Broker shut down.
deepthidevaki commented 4 years ago

Looks like we are testing a behavior that does not exist :smile: Our snapshot replication is not reliable - that is - if a node is not reachable during the snapshot replication it won't receive it. There are no retries. But this test is testing that the node will receive it when it comes back. Test sometimes passes because restart is fast and the broker is up before the other node replicates snapshot.

We can remove this test. There is already a test for testing restarted node receives snapshot when there is a new snapshot.

npepinpe commented 4 years ago

I think the goal here was to test the Raft replication. Can we restart the follower with data loss so we do send it the latest snapshot? Or do we have tests for this?

deepthidevaki commented 4 years ago

I think the goal here was to test the Raft replication. Can we restart the follower with data loss so we do send it the latest snapshot? Or do we have tests for this?

Aren't we testing in RestoreTest?

npepinpe commented 4 years ago

You're right, thanks! :)