You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pulsar.apache.org by "rdhabalia (via GitHub)" <gi...@apache.org> on 2023/05/24 23:48:46 UTC
[GitHub] [pulsar] rdhabalia opened a new pull request, #20394: [fix][broker] Fix stuck subscription due to cursor recovery timeout
rdhabalia opened a new pull request, #20394:
URL: https://github.com/apache/pulsar/pull/20394
### Motivation
It fixes: https://github.com/apache/pulsar/issues/20393
sometimes broker gets stuck while recovering managed cursor for a topic's subscription which causes subscription creation stuck on that broker and client application keeps timing out while creating consumers. It happens when broker tries to recover cursor and tries to persist cursors' state into ledger and broker never receives add-entry callback for that cursor ledger which will prevent broker to create subscription successfully.
**Broker-log**
```
05:50:28.411 [pulsar-io-4-32] INFO org.apache.pulsar.broker.service.ServerCnx - [/1.1.1.1:38126] Subscribing on topic persistent://pulsar/use1/myns/topic-1 / my-sub
05:50:28.411 [pulsar-io-4-32] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [pulsar/use1/myns/persistent/topic-1] Cursor my-sub recovered to position 52505149:179
05:50:28.412 [pulsar-io-4-32] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [pulsar/use1/myns/persistent/topic-1] Consumer my-sub cursor initialized with counters: consumed 0 mdPos 52505149:179 rdPos 52505149:180
05:50:28.412 [pulsar-io-4-32] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [pulsar/use1/myns/persistent/topic-1] Creating ledger, metadata: {component=[109, 97, 110, 97, 103, 101, 100, 45, 108, 101, 100, 103, 101, 114], pulsar/managed-ledger=[112, 117, 108, 115, 97, 114, 47, 112, 115, 116, 103, 45, 103, 113, 49, 47, 112, 115, 116, 103, 49, 45, 98, 114, 111, 107, 101, 114, 50, 46, 109, 101, 115, 115, 97, 103, 105, 110, 103, 46, 103, 113, 49, 46, 121, 97, 104, 111, 111, 46, 99, 111, 109, 58, 52, 48, 56, 48, 47, 112, 101, 114, 115, 105, 115, 116, 101, 110, 116, 47, 115, 97, 110, 105, 116, 121, 84, 101, 115, 116, 84, 111, 112, 105, 99, 45, 49], pulsar/cursor=[115, 97, 110, 105, 116, 121, 83, 117, 98], application=[112, 117, 108, 115, 97, 114]} - metadata ops timeout : 60 seconds
05:50:28.421 [main-EventThread] INFO org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [pulsar/use1/myns/persistent/topic-1] Created ledger 52506173 for cursor my-sub
05:50:29.860 [bookkeeper-ml-scheduler-OrderedScheduler-5-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [pulsar/use1/myns/persistent/topic-1] Ledger already created when timeout task is triggered
05:51:28.412 [bookkeeper-ml-scheduler-OrderedScheduler-2-0] INFO org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [pulsar/use1/myns/persistent/topic-1] Ledger already created when timeout task is triggered
05:51:40.443 [pulsar-io-4-2] INFO org.apache.pulsar.broker.service.ServerCnx - [/1.1.1.1:38174] Subscribing on topic persistent://pulsar/use1/myns/topic-1 / my-sub
05:53:47.732 [pulsar-io-4-5] INFO org.apache.pulsar.broker.service.ServerCnx - [/1.1.1.1:38206] Subscribing on topic persistent://pulsar/use1/myns/topic-1 / my-sub
05:55:55.171 [pulsar-io-4-8] INFO org.apache.pulsar.broker.service.ServerCnx - [/1.1.1.1:38238] Subscribing on topic persistent://pulsar/use1/myns/topic-1 / my-sub
05:58:02.655 [pulsar-io-4-11] INFO org.apache.pulsar.broker.service.ServerCnx - [/1.1.1.1:38316] Subscribing on topic persistent://pulsar/use1/myns/topic-1 / my-sub
06:00:10.991 [pulsar-io-4-13] INFO org.apache.pulsar.broker.service.ServerCnx - [/1.1.1.1:38348] Subscribing on topic persistent://pulsar/use1/myns/topic-1 / my-sub
```
**client-log**
```
2023-05-19 05:51:40 [pulsar-client-io-8-1] INFO o.a.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/use1/myns/topic-1][my-sub] Subscribing to topic on cnx
[id: 0xdcb4fbde, L:/1.1.1.1:38174 - R:broker2.use1.pulsar.com/1.1.1.1:6651], consumerId 0
2023-05-19 05:52:10 [pulsar-client-io-8-1] DEBUG o.a.p.common.protocol.PulsarDecoder - [broker2.use1.pulsar.com/1.1.1.1:6651] Received cmd PING
2023-05-19 05:52:10 [pulsar-client-io-8-1] DEBUG o.a.p.common.protocol.PulsarHandler - [[id: 0xdcb4fbde, L:/1.1.1.1:38174 - R:broker2.use1.pulsar.com/1.1.1.1:6651]] Replying back to ping mess
age
2023-05-19 05:52:10 [pulsar-client-io-8-1] DEBUG o.a.p.common.protocol.PulsarHandler - [[id: 0xdcb4fbde, L:/1.1.1.1:38174 - R:broker2.use1.pulsar.com/1.1.1.1:6651]] Sending ping message
2023-05-19 05:52:10 [pulsar-client-io-8-1] DEBUG o.a.p.common.protocol.PulsarDecoder - [broker2.use1.pulsar.com/1.1.1.1:6651] Received cmd PONG
2023-05-19 05:52:40 [pulsar-client-io-8-1] DEBUG o.a.p.common.protocol.PulsarDecoder - [broker2.use1.pulsar.com/1.1.1.1:6651] Received cmd PING
2023-05-19 05:52:40 [pulsar-client-io-8-1] DEBUG o.a.p.common.protocol.PulsarHandler - [[id: 0xdcb4fbde, L:/1.1.1.1:38174 - R:broker2.use1.pulsar.com/1.1.1.1:6651]] Replying back to ping mess
age
2023-05-19 05:52:40 [pulsar-client-io-8-1] DEBUG o.a.p.common.protocol.PulsarHandler - [[id: 0xdcb4fbde, L:/1.1.1.1:38174 - R:broker2.use1.pulsar.com/1.1.1.1:6651]] Sending ping message
2023-05-19 05:52:40 [pulsar-client-io-8-1] WARN o.a.pulsar.client.impl.ConsumerImpl - [persistent://pulsar/use1/myns/topic-1][my-sub] Failed to subscribe to topi
c on broker2.use1.pulsar.com/1.1.1.1:6651
2023-05-19 05:52:40 [pulsar-client-io-8-1] WARN o.a.pulsar.client.impl.ClientCnx - [id: 0xdcb4fbde, L:/1.1.1.1:38174 - R:broker2.use1.pulsar.com/1.1.1.1:6651] request timeout {'durationMs':
'30000', 'reqId':'3312998569082859124', 'remote':'broker2.use1.pulsar.com/1.1.1.1:6651', 'local':'/1.1.1.1:38174'}
```
### Modifications
Broker should be more resilient to handle such callback response and broker should have timeout if broker can't recover cursor and broker should retry to recover cursor and successfully to create subscription. This PR helps to handle such timeout and retries to successfully recover cursor and prevent stuck subscription.
### Verifying this change
- [ ] Make sure that the change passes the CI checks.
*(Please pick either of the following options)*
This change is a trivial rework / code cleanup without any test coverage.
*(or)*
This change is already covered by existing tests, such as *(please describe tests)*.
*(or)*
This change added tests and can be verified as follows:
*(example:)*
- *Added integration tests for end-to-end deployment with large payloads (10MB)*
- *Extended integration test for recovery after broker failure*
### Does this pull request potentially affect one of the following parts:
<!-- DO NOT REMOVE THIS SECTION. CHECK THE PROPER BOX ONLY. -->
*If the box was checked, please highlight the changes*
- [ ] Dependencies (add or upgrade a dependency)
- [ ] The public API
- [ ] The schema
- [ ] The default values of configurations
- [ ] The threading model
- [ ] The binary protocol
- [ ] The REST endpoints
- [ ] The admin CLI options
- [ ] The metrics
- [ ] Anything that affects deployment
### Documentation
<!-- DO NOT REMOVE THIS SECTION. CHECK THE PROPER BOX ONLY. -->
- [ ] `doc` <!-- Your PR contains doc changes. -->
- [ ] `doc-required` <!-- Your PR changes impact docs and you will update later -->
- [ ] `doc-not-needed` <!-- Your PR changes do not impact docs -->
- [ ] `doc-complete` <!-- Docs have been already added -->
### Matching PR in forked repository
PR in forked repository: <!-- ENTER URL HERE -->
<!--
After opening this PR, the build in apache/pulsar will fail and instructions will
be provided for opening a PR in the PR author's forked repository.
apache/pulsar pull requests should be first tested in your own fork since the
apache/pulsar CI based on GitHub Actions has constrained resources and quota.
GitHub Actions provides separate quota for pull requests that are executed in
a forked repository.
The tests will be run in the forked repository until all PR review comments have
been handled, the tests pass and the PR is approved by a reviewer.
-->
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] lifepuzzlefun commented on a diff in pull request #20394: [fix][broker] Fix stuck subscription due to cursor recovery timeout
Posted by "lifepuzzlefun (via GitHub)" <gi...@apache.org>.
lifepuzzlefun commented on code in PR #20394:
URL: https://github.com/apache/pulsar/pull/20394#discussion_r1208357469
##########
managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java:
##########
@@ -2820,13 +2827,23 @@ public void operationComplete() {
@Override
public void operationFailed(ManagedLedgerException exception) {
+ if (!isCbCompleted.compareAndSet(false, true)) {
+ log.info("[{}] Persist position {} already timed out for cursor {}", ledger.getName(),
+ mdEntry.newPosition, name);
+ return;
+ }
log.warn("[{}] Failed to persist position {} for cursor {}", ledger.getName(),
mdEntry.newPosition, name);
deleteLedgerAsync(newLedgerHandle);
callback.operationFailed(exception);
}
- });
+ };
+ // persist position completes the cursor recovery callback. it's important to retry if callabck doesn't
+ // complete else it can create unavailability for cursor read
+ persistPositionToLedgerWithRetry(newLedgerHandle, mdEntry, persistPositionCb, isCbCompleted,
+ AsyncOperationTimeoutSeconds);
+ persistPositionToLedger(newLedgerHandle, mdEntry, persistPositionCb);
Review Comment:
maybe this line for persistentPositionToLedger can be removed
##########
managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java:
##########
@@ -2835,6 +2852,21 @@ public void operationFailed(ManagedLedgerException exception) {
});
}
+ @VisibleForTesting
+ protected void persistPositionToLedgerWithRetry(LedgerHandle lh, MarkDeleteEntry mdEntry,
+ VoidCallback persistPositionCb, AtomicBoolean isCbCompleted, int timeoutSec) {
+ persistPositionToLedger(lh, mdEntry, persistPositionCb);
+ ledger.getScheduledExecutor().schedule(() -> {
+ if (isCbCompleted.get()) {
+ return;
+ }
+ log.info("[{}] couldn't persist position {} in timeout {} sec for cursor {}, retrying..", ledger.getName(),
+ mdEntry.newPosition, timeoutSec, name);
+ // keep retrying to recover cursor and enable reads
+ persistPositionToLedgerWithRetry(lh, mdEntry, persistPositionCb, isCbCompleted, timeoutSec);
Review Comment:
if this will retry again i wonder if the ManagedCursorImpl.this lock should be acquired.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] [fix][broker] Fix stuck subscription due to cursor recovery timeout [pulsar]
Posted by "merlimat (via GitHub)" <gi...@apache.org>.
merlimat commented on PR #20394:
URL: https://github.com/apache/pulsar/pull/20394#issuecomment-6355520613
Thanks @rdhabalia, and sorry this sat so long. Since #16389 (2.11), subscribing no longer creates or writes the cursor ledger: `initialize()` only stores the position in the metadata store, and the ledger is created lazily on the first mark-delete. The BK client also times out adds through `bookkeeperClientTimeoutInSeconds`. So the hang in #20393 can't happen on the subscribe path on current versions. Closing this one and #20393. If you still see a lost add callback on 3.x/4.x, please open a new issue with a stack trace. That would be a BK client bug we should fix at the source.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] [fix][broker] Fix stuck subscription due to cursor recovery timeout [pulsar]
Posted by "merlimat (via GitHub)" <gi...@apache.org>.
merlimat closed pull request #20394: [fix][broker] Fix stuck subscription due to cursor recovery timeout
URL: https://github.com/apache/pulsar/pull/20394
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] rdhabalia commented on pull request #20394: [fix][broker] Fix stuck subscription due to cursor recovery timeout
Posted by "rdhabalia (via GitHub)" <gi...@apache.org>.
rdhabalia commented on PR #20394:
URL: https://github.com/apache/pulsar/pull/20394#issuecomment-1581967063
@lifepuzzlefun yes root cause is due to callback was not triggered and I can't share the heapdump due to security purpose. we are having this timeout issues at multiple places with recent pulsar upgrade (2.10) and it's really painful to upgrade Pulsar. we have been seeing lot of publish/read and other bookie operation timeout with pulsar 2.10 upgrade. it's really impossible to use pulsar for a production system.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] lifepuzzlefun commented on pull request #20394: [fix][broker] Fix stuck subscription due to cursor recovery timeout
Posted by "lifepuzzlefun (via GitHub)" <gi...@apache.org>.
lifepuzzlefun commented on PR #20394:
URL: https://github.com/apache/pulsar/pull/20394#issuecomment-1565928609
by the way i wonder the root cause for callback not triggered. can you show the heap dump or stack trace for this ?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
[GitHub] [pulsar] github-actions[bot] commented on pull request #20394: [fix][broker] Fix stuck subscription due to cursor recovery timeout
Posted by "github-actions[bot] (via GitHub)" <gi...@apache.org>.
github-actions[bot] commented on PR #20394:
URL: https://github.com/apache/pulsar/pull/20394#issuecomment-1627574412
The pr had no activity for 30 days, mark with Stale label.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: commits-unsubscribe@pulsar.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org