Skip to content

Each batch processed twice. #517

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
GeminPatel opened this issue Jan 3, 2018 · 14 comments
Closed

Each batch processed twice. #517

GeminPatel opened this issue Jan 3, 2018 · 14 comments

Comments

@GeminPatel
Copy link

GeminPatel commented Jan 3, 2018 •
edited by dasch
Loading

If this is a bug report, please fill out the following:

  • Version of Ruby: 2.3.1
  • Version of Kafka: 0.11.0.1
  • Version of ruby-kafka: 0.4
  • Version of racecar: 0.3.5

I am running a single batch consumer on a single broker kafka. There are 40k records in the topic so on the first batch fetch it is fetching around 11k records. Time taken in processing these records is 15-17 mins. And then when offset is tried to be commited, it reconnects as the connection is idle by definition. It reconnects and again starts from offset 0. Then it commits the correct offset. Then once the first 11k records are reprocessed, it moves to the next batch. Same is repeated for the next batch.

I am not uploading any code as I am using racecar and the the process batch function can be as simple as sleep for 100 milliseconds.

LOGS:

D, [2018-01-03T15:47:08.476771 #67956] DEBUG -- : Sending offset_fetch API request 4 to localhost:9092
D, [2018-01-03T15:47:08.476858 #67956] DEBUG -- : Waiting for response 4 from localhost:9092
D, [2018-01-03T15:47:08.477231 #67956] DEBUG -- : Received response 4 from localhost:9092
D, [2018-01-03T15:47:08.477358 #67956] DEBUG -- : Sending list_offset API request 5 to localhost:9092
D, [2018-01-03T15:47:08.477444 #67956] DEBUG -- : Waiting for response 5 from localhost:9092
D, [2018-01-03T15:47:08.477890 #67956] DEBUG -- : Received response 5 from localhost:9092
D, [2018-01-03T15:47:08.477947 #67956] DEBUG -- : Fetching batch from users/0 starting at offset 0
D, [2018-01-03T15:47:08.478052 #67956] DEBUG -- : Sending fetch API request 6 to localhost:9092
D, [2018-01-03T15:47:08.478159 #67956] DEBUG -- : Waiting for response 6 from localhost:9092
D, [2018-01-03T15:47:08.844198 #67956] DEBUG -- : Received response 6 from localhost:9092
D, [2018-01-03T16:03:42.122501 #67956] DEBUG -- : Marking users/0:11247 as processed
I, [2018-01-03T16:03:42.123127 #67956]  INFO -- : Committing offsets with recommit: users/0:11248
W, [2018-01-03T16:03:42.124098 #67956]  WARN -- : Connection has been unused for too long, re-connecting...
D, [2018-01-03T16:03:42.124254 #67956] DEBUG -- : Closing socket to localhost:9092
D, [2018-01-03T16:03:42.124595 #67956] DEBUG -- : Opening connection to localhost:9092 with client id platform...
D, [2018-01-03T16:03:42.127465 #67956] DEBUG -- : Sending offset_commit API request 1 to localhost:9092
D, [2018-01-03T16:03:42.127698 #67956] DEBUG -- : Waiting for response 1 from localhost:9092
D, [2018-01-03T16:03:42.159462 #67956] DEBUG -- : Received response 1 from localhost:9092
E, [2018-01-03T16:03:42.159988 #67956] ERROR -- : Error committing offsets: Kafka::IllegalGeneration
I, [2018-01-03T16:03:42.160283 #67956]  INFO -- : Joining group `platform.user-consumer`
D, [2018-01-03T16:03:42.160451 #67956] DEBUG -- : Sending join_group API request 2 to localhost:9092
D, [2018-01-03T16:03:42.160702 #67956] DEBUG -- : Waiting for response 2 from localhost:9092
D, [2018-01-03T16:03:42.162919 #67956] DEBUG -- : Received response 2 from localhost:9092
E, [2018-01-03T16:03:42.163269 #67956] ERROR -- : Failed to join group; resetting member id and retrying in 1s...
I, [2018-01-03T16:03:43.167116 #67956]  INFO -- : Joining group `platform.user-consumer`
D, [2018-01-03T16:03:43.167421 #67956] DEBUG -- : Sending join_group API request 3 to localhost:9092
D, [2018-01-03T16:03:43.167845 #67956] DEBUG -- : Waiting for response 3 from localhost:9092
D, [2018-01-03T16:03:43.174238 #67956] DEBUG -- : Received response 3 from localhost:9092
I, [2018-01-03T16:03:43.174300 #67956]  INFO -- : Joined group `platform.user-consumer` with member id `platform-02546eed-8471-47ce-b3fa-e9141bfd1d19`
I, [2018-01-03T16:03:43.174353 #67956]  INFO -- : Chosen as leader of group `platform.user-consumer`
D, [2018-01-03T16:03:43.174541 #67956] DEBUG -- : Sending sync_group API request 4 to localhost:9092
D, [2018-01-03T16:03:43.174696 #67956] DEBUG -- : Waiting for response 4 from localhost:9092
D, [2018-01-03T16:03:43.177252 #67956] DEBUG -- : Received response 4 from localhost:9092
I, [2018-01-03T16:03:43.177394 #67956]  INFO -- : Partitions assigned for `users`: 0
I, [2018-01-03T16:03:43.177505 #67956]  INFO -- : Sending heartbeat...
D, [2018-01-03T16:03:43.177632 #67956] DEBUG -- : Sending heartbeat API request 5 to localhost:9092
D, [2018-01-03T16:03:43.177852 #67956] DEBUG -- : Waiting for response 5 from localhost:9092
D, [2018-01-03T16:03:43.178427 #67956] DEBUG -- : Received response 5 from localhost:9092
D, [2018-01-03T16:03:43.178675 #67956] DEBUG -- : Sending offset_fetch API request 6 to localhost:9092
D, [2018-01-03T16:03:43.178978 #67956] DEBUG -- : Waiting for response 6 from localhost:9092
D, [2018-01-03T16:03:43.180070 #67956] DEBUG -- : Received response 6 from localhost:9092
D, [2018-01-03T16:03:43.180275 #67956] DEBUG -- : Sending list_offset API request 7 to localhost:9092
D, [2018-01-03T16:03:43.180445 #67956] DEBUG -- : Waiting for response 7 from localhost:9092
D, [2018-01-03T16:03:43.182186 #67956] DEBUG -- : Received response 7 from localhost:9092
D, [2018-01-03T16:03:43.182321 #67956] DEBUG -- : Fetching batch from users/0 starting at offset 0
D, [2018-01-03T16:03:43.182652 #67956] DEBUG -- : Sending fetch API request 8 to localhost:9092
D, [2018-01-03T16:03:43.182986 #67956] DEBUG -- : Waiting for response 8 from localhost:9092
D, [2018-01-03T16:03:43.619081 #67956] DEBUG -- : Received response 8 from localhost:9092
D, [2018-01-03T16:04:10.777506 #67956] DEBUG -- : Marking users/0:11247 as processed
I, [2018-01-03T16:04:10.777565 #67956]  INFO -- : Committing offsets with recommit: users/0:11248
D, [2018-01-03T16:04:10.777618 #67956] DEBUG -- : Sending offset_commit API request 9 to localhost:9092
D, [2018-01-03T16:04:10.777800 #67956] DEBUG -- : Waiting for response 9 from localhost:9092
D, [2018-01-03T16:04:10.779273 #67956] DEBUG -- : Received response 9 from localhost:9092
I, [2018-01-03T16:04:10.779345 #67956]  INFO -- : Sending heartbeat...
D, [2018-01-03T16:04:10.779398 #67956] DEBUG -- : Sending heartbeat API request 10 to localhost:9092
D, [2018-01-03T16:04:10.779487 #67956] DEBUG -- : Waiting for response 10 from localhost:9092
D, [2018-01-03T16:04:10.779807 #67956] DEBUG -- : Received response 10 from localhost:9092
D, [2018-01-03T16:04:10.779920 #67956] DEBUG -- : Fetching batch from users/0 starting at offset 11248
D, [2018-01-03T16:04:10.780066 #67956] DEBUG -- : Sending fetch API request 11 to localhost:9092
D, [2018-01-03T16:04:10.780252 #67956] DEBUG -- : Waiting for response 11 from localhost:9092
D, [2018-01-03T16:04:11.132678 #67956] DEBUG -- : Received response 11 from localhost:9092
D, [2018-01-03T16:16:50.123631 #67956] DEBUG -- : Marking users/0:20840 as processed
I, [2018-01-03T16:16:50.123852 #67956]  INFO -- : Committing offsets: users/0:20841
W, [2018-01-03T16:16:50.124548 #67956]  WARN -- : Connection has been unused for too long, re-connecting...
D, [2018-01-03T16:16:50.124614 #67956] DEBUG -- : Closing socket to localhost:9092
D, [2018-01-03T16:16:50.124810 #67956] DEBUG -- : Opening connection to localhost:9092 with client id platform...
D, [2018-01-03T16:16:50.126938 #67956] DEBUG -- : Sending offset_commit API request 1 to localhost:9092
D, [2018-01-03T16:16:50.127149 #67956] DEBUG -- : Waiting for response 1 from localhost:9092
D, [2018-01-03T16:16:50.130036 #67956] DEBUG -- : Received response 1 from localhost:9092
E, [2018-01-03T16:16:50.130564 #67956] ERROR -- : Error committing offsets: Kafka::UnknownMemberId
I, [2018-01-03T16:16:50.130829 #67956]  INFO -- : Joining group `platform.user-consumer`
D, [2018-01-03T16:16:50.130959 #67956] DEBUG -- : Sending join_group API request 2 to localhost:9092
D, [2018-01-03T16:16:50.131165 #67956] DEBUG -- : Waiting for response 2 from localhost:9092
D, [2018-01-03T16:16:50.132501 #67956] DEBUG -- : Received response 2 from localhost:9092
E, [2018-01-03T16:16:50.132820 #67956] ERROR -- : Failed to join group; resetting member id and retrying in 1s...
I, [2018-01-03T16:16:51.136459 #67956]  INFO -- : Joining group `platform.user-consumer`
D, [2018-01-03T16:16:51.136690 #67956] DEBUG -- : Sending join_group API request 3 to localhost:9092
D, [2018-01-03T16:16:51.137015 #67956] DEBUG -- : Waiting for response 3 from localhost:9092
D, [2018-01-03T16:16:51.143663 #67956] DEBUG -- : Received response 3 from localhost:9092
I, [2018-01-03T16:16:51.143740 #67956]  INFO -- : Joined group `platform.user-consumer` with member id `platform-933f9bf3-fbb8-4e23-a789-5832cb0ab8e1`
I, [2018-01-03T16:16:51.143803 #67956]  INFO -- : Chosen as leader of group `platform.user-consumer`
D, [2018-01-03T16:16:51.143993 #67956] DEBUG -- : Sending sync_group API request 4 to localhost:9092
D, [2018-01-03T16:16:51.144263 #67956] DEBUG -- : Waiting for response 4 from localhost:9092
D, [2018-01-03T16:16:51.157700 #67956] DEBUG -- : Received response 4 from localhost:9092
I, [2018-01-03T16:16:51.157831 #67956]  INFO -- : Partitions assigned for `users`: 0
I, [2018-01-03T16:16:51.157912 #67956]  INFO -- : Sending heartbeat...
D, [2018-01-03T16:16:51.158012 #67956] DEBUG -- : Sending heartbeat API request 5 to localhost:9092
D, [2018-01-03T16:16:51.158211 #67956] DEBUG -- : Waiting for response 5 from localhost:9092
D, [2018-01-03T16:16:51.161562 #67956] DEBUG -- : Received response 5 from localhost:9092
D, [2018-01-03T16:16:51.161911 #67956] DEBUG -- : Sending offset_fetch API request 6 to localhost:9092
D, [2018-01-03T16:16:51.162345 #67956] DEBUG -- : Waiting for response 6 from localhost:9092
D, [2018-01-03T16:16:51.164139 #67956] DEBUG -- : Received response 6 from localhost:9092
D, [2018-01-03T16:16:51.164271 #67956] DEBUG -- : Fetching batch from users/0 starting at offset 11248
@dasch
Copy link
Contributor

dasch commented Jan 3, 2018

It's very unlikely that your consumer is still in the group after 15-17 minutes of processing time – I don't think Kafka allows more than 30 seconds of "away time".

I would either switch to single-message processing or ensure that batches are small enough that they can be processed in under 30 seconds.

@dasch
Copy link
Contributor

dasch commented Jan 3, 2018

Also, you should upgrade to the most recent release of ruby-kafka.

@GeminPatel
Copy link
Author

GeminPatel commented Jan 3, 2018 •
edited
Loading

@dasch '~> 0.4' is in racecar's gemspec.
For Doing small batch I am unable to find a way to configure this. Max I could find was, I would stop using racecar and use ruby-kafka directly and specify the max_bytes to something lesser. What do you suggest?

@dasch
Copy link
Contributor

dasch commented Jan 3, 2018

@GeminPatel you should still be able to upgrade ruby-kafka to 0.5.1 even with that constraint.

It's not documented in the README, but the code docs describe how you can limit the size of the returned batches on a per-partition level: https://github.com/zendesk/racecar/blob/437cb7e38349837f97bf46a65ae6e72b9648788c/lib/racecar/consumer.rb#L17-L18

@dasch
Copy link
Contributor

dasch commented Jan 3, 2018

Note that if you use #process instead of #process_batch, your consumer will checkpoint more frequently and you won't run into this problem. Do you really need batch processing?

@GeminPatel
Copy link
Author

This also happens on single message processing by the way. But the circumstances are a bit different. I was able to observer it on an older version of racecar where pause config was not present. Even in current version, if u specify pause as 0 you can reproduce this.

Scenario: message processing should break due to raise. What is expected is that this message is retried only once. But this message will actually be processed twice. If you want I can give you example code and logs. [But because I am using pause, I do not much care about this issue].

@dasch
Copy link
Contributor

dasch commented Jan 3, 2018

The expectation is not that a message is retried once – it is retried indefinitely.

@GeminPatel
Copy link
Author

I had seen this, but missed it. Thanks for pointing out.
https://github.com/zendesk/racecar/blob/437cb7e38349837f97bf46a65ae6e72b9648788c/lib/racecar/consumer.rb#L17-L18

"The expectation is not that a message is retried once – it is retried indefinitely."
Let me rephrase. 1st time failure -> expect to retry. It is tried and it is success. Still it is processed for third time.

Yeah I wanted to batch process as I am trying to do one time migration of 40 million messages and need to do this in constrained time.

@dasch
Copy link
Contributor

dasch commented Jan 3, 2018

Are you using batch operations, or processing each message individually? The single-message processing mode still uses batching under the hood, it just makes sure to handle checkpointing in between message processing as per the offset commit policy (e.g. commit every n seconds or after n messages). It's typically what you want.

@GeminPatel
Copy link
Author

Ok. This makes things much clear. I will try and follow on what I have understood.

PS: I will put a code and log in sometime which will reproduce the bug I mentioned for single-message processing(#process) with pause 0.

@GeminPatel
Copy link
Author

Config:

development:
  <<: *common
  brokers:
    - localhost:9092
  pause_timeout: 0

Consumer Code:

class IssueConsumer < Racecar::Consumer
  @@flag = true
  subscribes_to 'test', start_from_beginning: true

  def process(message)
    Rails.logger.debug("############################ PROCESSING #########################")
    if @@flag
      @@flag = false
      raise 'error'
    end
  end
end

Run the code using:
bundle exec racecar IssueConsumer --log issue_consumer.log

STDOUT:

=> Starting Racecar consumer IssueConsumer...
=> Detected Rails, booting application...
=> Logging to issue_consumer.log
=> Wrooooom!
=> Ctrl-C to shutdown consumer
############################ PROCESSING #########################
############################ PROCESSING #########################
############################ PROCESSING #########################

issue_consumer.log


I, [2018-01-03T18:46:42.145708 #85681]  INFO -- : Partitions assigned for `test`: 0
D, [2018-01-03T18:46:42.145806 #85681] DEBUG -- : Sending offset_fetch API request 4 to localhost:9092
D, [2018-01-03T18:46:42.145973 #85681] DEBUG -- : Waiting for response 4 from localhost:9092
D, [2018-01-03T18:46:42.157573 #85681] DEBUG -- : Received response 4 from localhost:9092
D, [2018-01-03T18:46:42.157790 #85681] DEBUG -- : Sending list_offset API request 5 to localhost:9092
D, [2018-01-03T18:46:42.157970 #85681] DEBUG -- : Waiting for response 5 from localhost:9092
D, [2018-01-03T18:46:42.186618 #85681] DEBUG -- : Received response 5 from localhost:9092
D, [2018-01-03T18:46:42.186710 #85681] DEBUG -- : Fetching batch from test/0 starting at offset 0
D, [2018-01-03T18:46:42.186840 #85681] DEBUG -- : Sending fetch API request 6 to localhost:9092
D, [2018-01-03T18:46:42.187248 #85681] DEBUG -- : Waiting for response 6 from localhost:9092
D, [2018-01-03T18:46:47.272617 #85681] DEBUG -- : Received response 6 from localhost:9092
D, [2018-01-03T18:46:47.272858 #85681] DEBUG -- : Fetching batch from test/0 starting at offset 0
D, [2018-01-03T18:46:47.273057 #85681] DEBUG -- : Sending fetch API request 7 to localhost:9092
D, [2018-01-03T18:46:47.273238 #85681] DEBUG -- : Waiting for response 7 from localhost:9092
D, [2018-01-03T18:46:52.410208 #85681] DEBUG -- : Received response 7 from localhost:9092
I, [2018-01-03T18:46:52.410439 #85681]  INFO -- : Sending heartbeat...
D, [2018-01-03T18:46:52.410581 #85681] DEBUG -- : Sending heartbeat API request 8 to localhost:9092
D, [2018-01-03T18:46:52.410816 #85681] DEBUG -- : Waiting for response 8 from localhost:9092
D, [2018-01-03T18:46:52.415096 #85681] DEBUG -- : Received response 8 from localhost:9092
D, [2018-01-03T18:46:52.415228 #85681] DEBUG -- : Fetching batch from test/0 starting at offset 0
D, [2018-01-03T18:46:52.415409 #85681] DEBUG -- : Sending fetch API request 9 to localhost:9092
D, [2018-01-03T18:46:52.415682 #85681] DEBUG -- : Waiting for response 9 from localhost:9092
D, [2018-01-03T18:46:54.641443 #85681] DEBUG -- : Received response 9 from localhost:9092
E, [2018-01-03T18:46:54.641985 #85681] ERROR -- : Exception raised when processing test/0 at offset 0 -- RuntimeError: error
/Users/gemin.patel/Documents/workspace/test/app/consumers/issue_consumer.rb:9:in `process'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/racecar-0.3.5/lib/racecar/runner.rb:70:in `block (2 levels) in run'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/notifications.rb:166:in `instrument'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/racecar-0.3.5/lib/racecar/runner.rb:69:in `block in run'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/consumer.rb:218:in `block (4 levels) in each_message'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/activesupport-5.0.0.1/lib/active_support/notifications.rb:166:in `instrument'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/instrumenter.rb:19:in `instrument'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/instrumenter.rb:33:in `instrument'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/consumer.rb:206:in `block (3 levels) in each_message'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/consumer.rb:205:in `each'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/consumer.rb:205:in `block (2 levels) in each_message'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/consumer.rb:204:in `each'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/consumer.rb:204:in `block in each_message'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/consumer.rb:356:in `consumer_loop'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/ruby-kafka-0.5.1/lib/kafka/consumer.rb:196:in `each_message'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/racecar-0.3.5/lib/racecar/runner.rb:57:in `run'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/racecar-0.3.5/lib/racecar.rb:48:in `run'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/racecar-0.3.5/lib/racecar/cli.rb:63:in `run'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/racecar-0.3.5/lib/racecar/cli.rb:10:in `main'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/gems/racecar-0.3.5/exe/racecar:9:in `<top (required)>'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/bin/racecar:23:in `load'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/bin/racecar:23:in `<main>'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/bin/ruby_executable_hooks:15:in `eval'
/Users/gemin.patel/.rvm/gems/ruby-2.3.1/bin/ruby_executable_hooks:15:in `<main>'
I, [2018-01-03T18:46:54.642241 #85681]  INFO -- : Leaving group `platform.issue-consumer`
D, [2018-01-03T18:46:54.642379 #85681] DEBUG -- : Sending leave_group API request 10 to localhost:9092
D, [2018-01-03T18:46:54.642618 #85681] DEBUG -- : Waiting for response 10 from localhost:9092
D, [2018-01-03T18:46:54.649007 #85681] DEBUG -- : Received response 10 from localhost:9092
E, [2018-01-03T18:46:54.649116 #85681] ERROR -- : Error processing partition test/0 at offset 0
D, [2018-01-03T18:46:54.839896 #85681] DEBUG -- : Fetching batch from test/0 starting at offset 0
D, [2018-01-03T18:46:54.840223 #85681] DEBUG -- : Sending fetch API request 11 to localhost:9092
D, [2018-01-03T18:46:54.841196 #85681] DEBUG -- : Waiting for response 11 from localhost:9092
D, [2018-01-03T18:46:54.848151 #85681] DEBUG -- : Received response 11 from localhost:9092
D, [2018-01-03T18:46:54.848581 #85681] DEBUG -- : Marking test/0:0 as processed
I, [2018-01-03T18:46:54.848713 #85681]  INFO -- : Committing offsets with recommit: test/0:1
D, [2018-01-03T18:46:54.849860 #85681] DEBUG -- : Sending offset_commit API request 12 to localhost:9092
D, [2018-01-03T18:46:54.850220 #85681] DEBUG -- : Waiting for response 12 from localhost:9092
D, [2018-01-03T18:46:54.858968 #85681] DEBUG -- : Received response 12 from localhost:9092
E, [2018-01-03T18:46:54.859638 #85681] ERROR -- : Error committing offsets: Kafka::UnknownMemberId
I, [2018-01-03T18:46:54.860521 #85681]  INFO -- : Joining group `platform.issue-consumer`
D, [2018-01-03T18:46:54.860848 #85681] DEBUG -- : Sending join_group API request 13 to localhost:9092
D, [2018-01-03T18:46:54.861739 #85681] DEBUG -- : Waiting for response 13 from localhost:9092
D, [2018-01-03T18:46:54.873330 #85681] DEBUG -- : Received response 13 from localhost:9092
E, [2018-01-03T18:46:54.873712 #85681] ERROR -- : Failed to join group; resetting member id and retrying in 1s...
I, [2018-01-03T18:46:55.875079 #85681]  INFO -- : Joining group `platform.issue-consumer`
D, [2018-01-03T18:46:55.875247 #85681] DEBUG -- : Sending join_group API request 14 to localhost:9092
D, [2018-01-03T18:46:55.875424 #85681] DEBUG -- : Waiting for response 14 from localhost:9092
D, [2018-01-03T18:46:55.880357 #85681] DEBUG -- : Received response 14 from localhost:9092
I, [2018-01-03T18:46:55.880498 #85681]  INFO -- : Joined group `platform.issue-consumer` with member id `platform-3f3d3f19-f3d9-425a-887b-668b8b0a8725`
I, [2018-01-03T18:46:55.880585 #85681]  INFO -- : Chosen as leader of group `platform.issue-consumer`
D, [2018-01-03T18:46:55.880900 #85681] DEBUG -- : Sending sync_group API request 15 to localhost:9092
D, [2018-01-03T18:46:55.881692 #85681] DEBUG -- : Waiting for response 15 from localhost:9092
D, [2018-01-03T18:46:55.883798 #85681] DEBUG -- : Received response 15 from localhost:9092
I, [2018-01-03T18:46:55.884050 #85681]  INFO -- : Partitions assigned for `test`: 0
D, [2018-01-03T18:46:55.884322 #85681] DEBUG -- : Sending offset_fetch API request 16 to localhost:9092
D, [2018-01-03T18:46:55.884648 #85681] DEBUG -- : Waiting for response 16 from localhost:9092
D, [2018-01-03T18:46:55.886002 #85681] DEBUG -- : Received response 16 from localhost:9092
D, [2018-01-03T18:46:55.888155 #85681] DEBUG -- : Sending list_offset API request 17 to localhost:9092
D, [2018-01-03T18:46:55.888450 #85681] DEBUG -- : Waiting for response 17 from localhost:9092
D, [2018-01-03T18:46:55.889504 #85681] DEBUG -- : Received response 17 from localhost:9092
D, [2018-01-03T18:46:55.889629 #85681] DEBUG -- : Fetching batch from test/0 starting at offset 0
D, [2018-01-03T18:46:55.889857 #85681] DEBUG -- : Sending fetch API request 18 to localhost:9092
D, [2018-01-03T18:46:55.890226 #85681] DEBUG -- : Waiting for response 18 from localhost:9092
D, [2018-01-03T18:46:55.896523 #85681] DEBUG -- : Received response 18 from localhost:9092
D, [2018-01-03T18:46:55.897125 #85681] DEBUG -- : Marking test/0:0 as processed
I, [2018-01-03T18:46:55.897295 #85681]  INFO -- : Committing offsets with recommit: test/0:1
D, [2018-01-03T18:46:55.897527 #85681] DEBUG -- : Sending offset_commit API request 19 to localhost:9092
D, [2018-01-03T18:46:55.898224 #85681] DEBUG -- : Waiting for response 19 from localhost:9092
D, [2018-01-03T18:46:55.919122 #85681] DEBUG -- : Received response 19 from localhost:9092
D, [2018-01-03T18:46:55.919284 #85681] DEBUG -- : Fetching batch from test/0 starting at offset 1

@dasch
Copy link
Contributor

dasch commented Jan 3, 2018

I think #518 will fix that problem. Can you try pinning your version of ruby-kafka to that commit and then test again?

gem 'ruby-kafka', :git => 'https://github.com/zendesk/ruby-kafka.git', :ref => '4710d7d'

@GeminPatel
Copy link
Author

Yes this fixes it.

@dasch
Copy link
Contributor

dasch commented Jan 4, 2018

Fixed by #518.

@dasch dasch closed this as completed Jan 4, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@dasch @GeminPatel