-
Notifications
You must be signed in to change notification settings - Fork 3.5k
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.
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
cpp: fix race condition caused by consumer seek and close #7819
Merged
Conversation
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
sijie
approved these changes
Aug 19, 2020
wolfstudy
approved these changes
Aug 19, 2020
huangdx0726
pushed a commit
to huangdx0726/pulsar
that referenced
this pull request
Aug 24, 2020
## Motivation User try a loop of create-exclusive-consumer, seek, consume and close of a consumer with cpp client, and some times will meet “consumer busy” errors, which means the broker side consumer still alive while creating new a consumer. Here are suspicion logs. ``` INFO:Client(88)Subscribing on Topic :public/default/jeff-test-21-partition-0Tue Aug 11 11:38:38 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44648 -> 10.88.109.71:31051] Tue Aug 11 11:38:38 2020 INFO:HandlerBase(130)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Schedule reconnection in 0.1 sTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(1047)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Seek successfullyTue Aug 11 11:38:38 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44648 -> 10.88.109.71:31051] Tue Aug 11 11:38:40 2020 INFO:HandlerBase(130)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Schedule reconnection in 0.1 sTue Aug 11 11:38:41 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:41 2020 INFO:ConsumerImpl(848)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Closing consumer for topic persistent://public/default/jeff-test-21-partition-0Tue Aug 11 11:38:42 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44646 -> 10.88.109.71:31051] Tue Aug 11 11:38:42 2020 INFO:ConsumerImpl(104)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Destroyed consumer which was not properly closedTue Aug 11 11:38:42 2020 ``` - there is reconnection caused by seek command; - close operation happens at the same time of seek. - consumer destroyed with log `Destroyed consumer which was not properly closed`. The race condition happens like this: 1. seek command triggered consumer disconnect; ``` subscription.resetCursor \ disconnectFuture = dispatcher.disconnectActiveConsumers(true); \ disconnectAllConsumers(boolean isResetCursor) consumerList.forEach(consumer -> consumer.disconnect(isResetCursor)); ``` 2. client trigger disconnectConsumer, and triggered `connection_.reset();` ``` case BaseCommand::CLOSE_CONSUMER: { consumer->disconnectConsumer(); LOG_INFO("Broker notification of Closed consumer: " << consumerId_); \ void ConsumerImpl::disconnectConsumer() { LOG_INFO("Broker notification of Closed consumer: " << consumerId_); Lock lock(mutex_); connection_.reset(); < === lock.unlock(); } ``` 3. connection not ready, and close consumer happened, then it leaked send CloseConsumer command to broker. ``` void ConsumerImpl::closeAsync(ResultCallback callback) { ... LOG_INFO(getName() << "Closing consumer for topic " << topic_); state_ = Closing; ClientConnectionPtr cnx = getCnx().lock(); < === the seek operation caused cnx reset if (!cnx) { < === goes into this if, and set to Closed and returned directly without closeConsumer sent to broker state_ = Closed; lock.unlock(); // If connection is gone, also the consumer is closed on the broker side if (callback) { callback(ResultOk); } return; } ... Future<Result, ResponseData> future = cnx->sendRequestWithId(Commands::newCloseConsumer(consumerId_, requestId), requested); < ==== .... } ``` ### Modifications when consumer destroy, try to send another closeConsumer command if suitable. * fix race condition caused by consumer seek and close * fix format
lbenc135
pushed a commit
to lbenc135/pulsar
that referenced
this pull request
Sep 5, 2020
## Motivation User try a loop of create-exclusive-consumer, seek, consume and close of a consumer with cpp client, and some times will meet “consumer busy” errors, which means the broker side consumer still alive while creating new a consumer. Here are suspicion logs. ``` INFO:Client(88)Subscribing on Topic :public/default/jeff-test-21-partition-0Tue Aug 11 11:38:38 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44648 -> 10.88.109.71:31051] Tue Aug 11 11:38:38 2020 INFO:HandlerBase(130)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Schedule reconnection in 0.1 sTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(1047)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Seek successfullyTue Aug 11 11:38:38 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44648 -> 10.88.109.71:31051] Tue Aug 11 11:38:40 2020 INFO:HandlerBase(130)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Schedule reconnection in 0.1 sTue Aug 11 11:38:41 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:41 2020 INFO:ConsumerImpl(848)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Closing consumer for topic persistent://public/default/jeff-test-21-partition-0Tue Aug 11 11:38:42 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44646 -> 10.88.109.71:31051] Tue Aug 11 11:38:42 2020 INFO:ConsumerImpl(104)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Destroyed consumer which was not properly closedTue Aug 11 11:38:42 2020 ``` - there is reconnection caused by seek command; - close operation happens at the same time of seek. - consumer destroyed with log `Destroyed consumer which was not properly closed`. The race condition happens like this: 1. seek command triggered consumer disconnect; ``` subscription.resetCursor \ disconnectFuture = dispatcher.disconnectActiveConsumers(true); \ disconnectAllConsumers(boolean isResetCursor) consumerList.forEach(consumer -> consumer.disconnect(isResetCursor)); ``` 2. client trigger disconnectConsumer, and triggered `connection_.reset();` ``` case BaseCommand::CLOSE_CONSUMER: { consumer->disconnectConsumer(); LOG_INFO("Broker notification of Closed consumer: " << consumerId_); \ void ConsumerImpl::disconnectConsumer() { LOG_INFO("Broker notification of Closed consumer: " << consumerId_); Lock lock(mutex_); connection_.reset(); < === lock.unlock(); } ``` 3. connection not ready, and close consumer happened, then it leaked send CloseConsumer command to broker. ``` void ConsumerImpl::closeAsync(ResultCallback callback) { ... LOG_INFO(getName() << "Closing consumer for topic " << topic_); state_ = Closing; ClientConnectionPtr cnx = getCnx().lock(); < === the seek operation caused cnx reset if (!cnx) { < === goes into this if, and set to Closed and returned directly without closeConsumer sent to broker state_ = Closed; lock.unlock(); // If connection is gone, also the consumer is closed on the broker side if (callback) { callback(ResultOk); } return; } ... Future<Result, ResponseData> future = cnx->sendRequestWithId(Commands::newCloseConsumer(consumerId_, requestId), requested); < ==== .... } ``` ### Modifications when consumer destroy, try to send another closeConsumer command if suitable. * fix race condition caused by consumer seek and close * fix format
lbenc135
pushed a commit
to lbenc135/pulsar
that referenced
this pull request
Sep 5, 2020
## Motivation User try a loop of create-exclusive-consumer, seek, consume and close of a consumer with cpp client, and some times will meet “consumer busy” errors, which means the broker side consumer still alive while creating new a consumer. Here are suspicion logs. ``` INFO:Client(88)Subscribing on Topic :public/default/jeff-test-21-partition-0Tue Aug 11 11:38:38 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44648 -> 10.88.109.71:31051] Tue Aug 11 11:38:38 2020 INFO:HandlerBase(130)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Schedule reconnection in 0.1 sTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(1047)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Seek successfullyTue Aug 11 11:38:38 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44648 -> 10.88.109.71:31051] Tue Aug 11 11:38:40 2020 INFO:HandlerBase(130)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Schedule reconnection in 0.1 sTue Aug 11 11:38:41 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:41 2020 INFO:ConsumerImpl(848)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Closing consumer for topic persistent://public/default/jeff-test-21-partition-0Tue Aug 11 11:38:42 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44646 -> 10.88.109.71:31051] Tue Aug 11 11:38:42 2020 INFO:ConsumerImpl(104)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Destroyed consumer which was not properly closedTue Aug 11 11:38:42 2020 ``` - there is reconnection caused by seek command; - close operation happens at the same time of seek. - consumer destroyed with log `Destroyed consumer which was not properly closed`. The race condition happens like this: 1. seek command triggered consumer disconnect; ``` subscription.resetCursor \ disconnectFuture = dispatcher.disconnectActiveConsumers(true); \ disconnectAllConsumers(boolean isResetCursor) consumerList.forEach(consumer -> consumer.disconnect(isResetCursor)); ``` 2. client trigger disconnectConsumer, and triggered `connection_.reset();` ``` case BaseCommand::CLOSE_CONSUMER: { consumer->disconnectConsumer(); LOG_INFO("Broker notification of Closed consumer: " << consumerId_); \ void ConsumerImpl::disconnectConsumer() { LOG_INFO("Broker notification of Closed consumer: " << consumerId_); Lock lock(mutex_); connection_.reset(); < === lock.unlock(); } ``` 3. connection not ready, and close consumer happened, then it leaked send CloseConsumer command to broker. ``` void ConsumerImpl::closeAsync(ResultCallback callback) { ... LOG_INFO(getName() << "Closing consumer for topic " << topic_); state_ = Closing; ClientConnectionPtr cnx = getCnx().lock(); < === the seek operation caused cnx reset if (!cnx) { < === goes into this if, and set to Closed and returned directly without closeConsumer sent to broker state_ = Closed; lock.unlock(); // If connection is gone, also the consumer is closed on the broker side if (callback) { callback(ResultOk); } return; } ... Future<Result, ResponseData> future = cnx->sendRequestWithId(Commands::newCloseConsumer(consumerId_, requestId), requested); < ==== .... } ``` ### Modifications when consumer destroy, try to send another closeConsumer command if suitable. * fix race condition caused by consumer seek and close * fix format
lbenc135
pushed a commit
to lbenc135/pulsar
that referenced
this pull request
Sep 5, 2020
## Motivation User try a loop of create-exclusive-consumer, seek, consume and close of a consumer with cpp client, and some times will meet “consumer busy” errors, which means the broker side consumer still alive while creating new a consumer. Here are suspicion logs. ``` INFO:Client(88)Subscribing on Topic :public/default/jeff-test-21-partition-0Tue Aug 11 11:38:38 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44648 -> 10.88.109.71:31051] Tue Aug 11 11:38:38 2020 INFO:HandlerBase(130)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Schedule reconnection in 0.1 sTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(1047)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Seek successfullyTue Aug 11 11:38:38 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:38 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44648 -> 10.88.109.71:31051] Tue Aug 11 11:38:40 2020 INFO:HandlerBase(130)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Schedule reconnection in 0.1 sTue Aug 11 11:38:41 2020 INFO:HandlerBase(53)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Getting connection from poolTue Aug 11 11:38:41 2020 INFO:ConsumerImpl(848)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Closing consumer for topic persistent://public/default/jeff-test-21-partition-0Tue Aug 11 11:38:42 2020 INFO:ConsumerImpl(175)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Created consumer on broker [10.88.109.77:44646 -> 10.88.109.71:31051] Tue Aug 11 11:38:42 2020 INFO:ConsumerImpl(104)[persistent://public/default/jeff-test-21-partition-0, 0_itom_di_scheduler_bat_prod_jeff-test-21, 1612] Destroyed consumer which was not properly closedTue Aug 11 11:38:42 2020 ``` - there is reconnection caused by seek command; - close operation happens at the same time of seek. - consumer destroyed with log `Destroyed consumer which was not properly closed`. The race condition happens like this: 1. seek command triggered consumer disconnect; ``` subscription.resetCursor \ disconnectFuture = dispatcher.disconnectActiveConsumers(true); \ disconnectAllConsumers(boolean isResetCursor) consumerList.forEach(consumer -> consumer.disconnect(isResetCursor)); ``` 2. client trigger disconnectConsumer, and triggered `connection_.reset();` ``` case BaseCommand::CLOSE_CONSUMER: { consumer->disconnectConsumer(); LOG_INFO("Broker notification of Closed consumer: " << consumerId_); \ void ConsumerImpl::disconnectConsumer() { LOG_INFO("Broker notification of Closed consumer: " << consumerId_); Lock lock(mutex_); connection_.reset(); < === lock.unlock(); } ``` 3. connection not ready, and close consumer happened, then it leaked send CloseConsumer command to broker. ``` void ConsumerImpl::closeAsync(ResultCallback callback) { ... LOG_INFO(getName() << "Closing consumer for topic " << topic_); state_ = Closing; ClientConnectionPtr cnx = getCnx().lock(); < === the seek operation caused cnx reset if (!cnx) { < === goes into this if, and set to Closed and returned directly without closeConsumer sent to broker state_ = Closed; lock.unlock(); // If connection is gone, also the consumer is closed on the broker side if (callback) { callback(ResultOk); } return; } ... Future<Result, ResponseData> future = cnx->sendRequestWithId(Commands::newCloseConsumer(consumerId_, requestId), requested); < ==== .... } ``` ### Modifications when consumer destroy, try to send another closeConsumer command if suitable. * fix race condition caused by consumer seek and close * fix format
BewareMyPower
added a commit
to BewareMyPower/pulsar-client-cpp-demo
that referenced
this pull request
Jun 27, 2023
2 tasks
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Motivation
User try a loop of create-exclusive-consumer, seek, consume and close of a consumer with cpp client, and some times will meet “consumer busy” errors, which means the broker side consumer still alive while creating new a consumer.
Here are suspicion logs.
Destroyed consumer which was not properly closed
.The race condition happens like this:
connection_.reset();
Modifications
when consumer destroy, try to send another closeConsumer command if suitable.