Created
November 15, 2017 16:14
-
-
Save klippx/a119fcb8225bd9df46f4941562572040 to your computer and use it in GitHub Desktop.
Running spec/lib/phobos/listener_spec.rb:54 with ruby kafka 0.4.4
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
## 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. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment