Running spec/lib/phobos/listener_spec.rb:54 with ruby kafka 0.4.4

gistfile1.txt

## With ruby kafka 0.4.4
#
~  src  phobos  debug-0.5.x-issues  ✎  docker-compose run -e DEFAULT_TIMEOUT=30 --rm test rspec spec/lib/phobos/listener_spec.rb:54
Starting phobos_zookeeper_1 ... done
Starting phobos_kafka_1 ... done
Run options: include {:locations=>{"./spec/lib/phobos/listener_spec.rb"=>[54]}}

Randomized with seed 16222

Phobos::Listener
  consuming in batches
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Phobos configured", :env=>"development"}
[<timestamp>] INFO  -- RubyKafka : New topics added to target list: test-topic-1
[<timestamp>] INFO  -- RubyKafka : Fetching cluster metadata from kafka://localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Opening connection to localhost:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from localhost:9092
[<timestamp>] INFO  -- RubyKafka : Discovered cluster metadata; nodes: 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Closing socket to localhost:9092
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Listener started", :listener_id=>"listener-id-1", :group_id=>"testgroup_id-group-1", :topic=>"test-topic-1"}
[<timestamp>] INFO  -- RubyKafka : Joining group `testgroup_id-group-1`
[<timestamp>] DEBUG -- RubyKafka : Getting group coordinator for `testgroup_id-group-1`
[<timestamp>] DEBUG -- RubyKafka : Opening connection to 10.3.220.156:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : New topics added to target list: test-topic-1
[<timestamp>] INFO  -- RubyKafka : Fetching cluster metadata from kafka://localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Opening connection to localhost:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Coordinator for group `testgroup_id-group-1` is 0. Connecting...
[<timestamp>] DEBUG -- RubyKafka : Connected to coordinator: 10.3.220.156:9092 (node_id=0) for group `testgroup_id-group-1`
[<timestamp>] DEBUG -- RubyKafka : Sending request 2 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 2 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 2 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Joined group `testgroup_id-group-1` with member id `phobos-ddc12876-3664-44be-b70d-2c256db787dc`
[<timestamp>] INFO  -- RubyKafka : Chosen as leader of group `testgroup_id-group-1`
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from localhost:9092
[<timestamp>] INFO  -- RubyKafka : Discovered cluster metadata; nodes: 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Closing socket to localhost:9092
[<timestamp>] ERROR -- RubyKafka : Failed to assign partitions to 1 messages in test-topic-1
[<timestamp>] WARN  -- RubyKafka : Failed to send all messages; attempting retry 1 of 2 after 1s
[<timestamp>] INFO  -- RubyKafka : Fetching cluster metadata from kafka://localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Opening connection to localhost:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from localhost:9092
[<timestamp>] INFO  -- RubyKafka : Discovered cluster metadata; nodes: 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Closing socket to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Sending request 3 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 3 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 3 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Partitions assigned for `test-topic-1`: 0
[<timestamp>] DEBUG -- RubyKafka : Sending request 4 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 4 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 4 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Sending request 5 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 5 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 5 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Fetching batch from test-topic-1/0 starting at offset 0
[<timestamp>] DEBUG -- RubyKafka : Sending request 6 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 6 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Fetching cluster metadata from kafka://localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Opening connection to localhost:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from localhost:9092
[<timestamp>] INFO  -- RubyKafka : Discovered cluster metadata; nodes: 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Closing socket to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Current leader for test-topic-1/0 is node 10.3.220.156:9092 (node_id=0)
[<timestamp>] INFO  -- RubyKafka : Sending 1 messages to 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Opening connection to 10.3.220.156:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 6 from 10.3.220.156:9092
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Committed offset", :listener_id=>"listener-id-1", :group_id=>"testgroup_id-group-1", :topic=>"test-topic-1", :batch_size=>1, :partition=>0, :offset_lag=>0, :time_elapsed=>0.1}
[<timestamp>] DEBUG -- RubyKafka : Marking test-topic-1/0:0 as processed
[<timestamp>] INFO  -- RubyKafka : Committing offsets with recommit: test-topic-1/0:1
[<timestamp>] DEBUG -- RubyKafka : Sending request 7 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 7 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Successfully appended 1 messages to test-topic-1/0 on 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Received response 7 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Fetching batch from test-topic-1/0 starting at offset 1
[<timestamp>] DEBUG -- RubyKafka : Sending request 8 to 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Disconnecting broker 0
[<timestamp>] DEBUG -- RubyKafka : Closing socket to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 8 from 10.3.220.156:9092
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Listener stopping", :listener_id=>"listener-id-1", :group_id=>"testgroup_id-group-1", :topic=>"test-topic-1"}
[<timestamp>] DEBUG -- RubyKafka : Received response 8 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Committing offsets: test-topic-1/0:1
[<timestamp>] DEBUG -- RubyKafka : Sending request 9 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 9 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 9 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Leaving group `testgroup_id-group-1`
[<timestamp>] DEBUG -- RubyKafka : Sending request 10 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 10 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 10 from 10.3.220.156:9092
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Listener stopped", :listener_id=>"listener-id-1", :group_id=>"testgroup_id-group-1", :topic=>"test-topic-1"}
   calls handler with message payload, group_id and topic
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Phobos configured", :env=>"development"}
[<timestamp>] INFO  -- RubyKafka : New topics added to target list: test-topic-2
[<timestamp>] INFO  -- RubyKafka : Fetching cluster metadata from kafka://localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Opening connection to localhost:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from localhost:9092
[<timestamp>] INFO  -- RubyKafka : Discovered cluster metadata; nodes: 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Closing socket to localhost:9092
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Listener started", :listener_id=>"listener-id-2", :group_id=>"testgroup_id-group-2", :topic=>"test-topic-2"}
[<timestamp>] INFO  -- RubyKafka : Joining group `testgroup_id-group-2`
[<timestamp>] DEBUG -- RubyKafka : Getting group coordinator for `testgroup_id-group-2`
[<timestamp>] DEBUG -- RubyKafka : Opening connection to 10.3.220.156:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Starting async producer in the background...
[<timestamp>] INFO  -- RubyKafka : New topics added to target list: test-topic-2
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Coordinator for group `testgroup_id-group-2` is 0. Connecting...
[<timestamp>] DEBUG -- RubyKafka : Connected to coordinator: 10.3.220.156:9092 (node_id=0) for group `testgroup_id-group-2`
[<timestamp>] DEBUG -- RubyKafka : Sending request 2 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 2 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Fetching cluster metadata from kafka://localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Opening connection to localhost:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 2 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Joined group `testgroup_id-group-2` with member id `phobos-4d623735-7387-4ff1-ab33-1719d1305b52`
[<timestamp>] INFO  -- RubyKafka : Chosen as leader of group `testgroup_id-group-2`
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from localhost:9092
[<timestamp>] INFO  -- RubyKafka : Discovered cluster metadata; nodes: 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Closing socket to localhost:9092
[<timestamp>] ERROR -- RubyKafka : Failed to assign partitions to 1 messages in test-topic-2
[<timestamp>] WARN  -- RubyKafka : Failed to send all messages; attempting retry 1 of 2 after 1s
[<timestamp>] INFO  -- RubyKafka : Fetching cluster metadata from kafka://localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Opening connection to localhost:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from localhost:9092
[<timestamp>] INFO  -- RubyKafka : Discovered cluster metadata; nodes: 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Closing socket to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Sending request 3 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 3 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 3 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Partitions assigned for `test-topic-2`: 0
[<timestamp>] DEBUG -- RubyKafka : Sending request 4 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 4 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 4 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Sending request 5 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 5 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 5 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Fetching batch from test-topic-2/0 starting at offset 0
[<timestamp>] DEBUG -- RubyKafka : Sending request 6 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 6 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Fetching cluster metadata from kafka://localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Opening connection to localhost:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from localhost:9092
[<timestamp>] INFO  -- RubyKafka : Discovered cluster metadata; nodes: 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Closing socket to localhost:9092
[<timestamp>] DEBUG -- RubyKafka : Current leader for test-topic-2/0 is node 10.3.220.156:9092 (node_id=0)
[<timestamp>] INFO  -- RubyKafka : Sending 1 messages to 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Opening connection to 10.3.220.156:9092 with client id phobos...
[<timestamp>] DEBUG -- RubyKafka : Sending request 1 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 1 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 1 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Successfully appended 1 messages to test-topic-2/0 on 10.3.220.156:9092 (node_id=0)
[<timestamp>] DEBUG -- RubyKafka : Received response 6 from 10.3.220.156:9092
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"message-1", :listener_id=>"listener-id-2", :group_id=>"testgroup_id-group-2", :topic=>"test-topic-2", :key=>nil, :partition=>0, :offset=>0, :retry_count=>0}
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Committed offset", :listener_id=>"listener-id-2", :group_id=>"testgroup_id-group-2", :topic=>"test-topic-2", :batch_size=>1, :partition=>0, :offset_lag=>0, :time_elapsed=>0.0}
[<timestamp>] DEBUG -- RubyKafka : Marking test-topic-2/0:0 as processed
[<timestamp>] INFO  -- RubyKafka : Committing offsets with recommit: test-topic-2/0:1
[<timestamp>] DEBUG -- RubyKafka : Sending request 7 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 7 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 7 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Fetching batch from test-topic-2/0 starting at offset 1
[<timestamp>] DEBUG -- RubyKafka : Sending request 8 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 8 from 10.3.220.156:9092
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Listener stopping", :listener_id=>"listener-id-2", :group_id=>"testgroup_id-group-2", :topic=>"test-topic-2"}
[<timestamp>] DEBUG -- RubyKafka : Received response 8 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Committing offsets: test-topic-2/0:1
[<timestamp>] DEBUG -- RubyKafka : Sending request 9 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 9 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 9 from 10.3.220.156:9092
[<timestamp>] INFO  -- RubyKafka : Leaving group `testgroup_id-group-2`
[<timestamp>] DEBUG -- RubyKafka : Sending request 10 to 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Waiting for response 10 from 10.3.220.156:9092
[<timestamp>] DEBUG -- RubyKafka : Received response 10 from 10.3.220.156:9092
[<timestamp>] INFO  -- Phobos : <Hash> {:message=>"Listener stopped", :listener_id=>"listener-id-2", :group_id=>"testgroup_id-group-2", :topic=>"test-topic-2"}
[<timestamp>] INFO  -- RubyKafka : Disconnecting broker 0
[<timestamp>] DEBUG -- RubyKafka : Closing socket to 10.3.220.156:9092
   calls Phobos::Actions::ProcessBatch with the fetched Kafka batch

Finished in 2.53 seconds (files took 0.69387 seconds to load)
2 examples, 0 failures

Randomized with seed 16222

Coverage report generated for RSpec to /opt/phobos/coverage. 300 / 365 LOC (82.19%) covered.