Pulsar: When ttlDurationDefaultInSeconds is set the messages are expired one by one every 5 minutes even before ttlDurationDefaultInSeconds is reached

[AmitANetskope]

Messages are being expired even before ttlDurationDefaultInSeconds is reached when ttlDurationDefaultInSeconds is set.

To Reproduce

1. in broker conf auto topic creation is enabled
2. in broker set ttlDurationDefaultInSeconds to 604800 (in all brokers and restart them)
3. now create subscription to topic - persistent/public/default/amit_test
4. close the subscription
5. create producer to above topic - providing a name and setting timeout to 0 (also dedup has been enabled in broker conf)
6. Now send 2 messages to the topic using the producer one after another
7. Now close the producer and client
8. Now using admin stats monitor the topic - pulsar-broker:8080/admin/v2/persistent/public/default/amit_test/stats
9. under the subscription can see that 2 messages are present in msgBacklog and lastExpireTimestamp is 0 (and no active producers or consumers)
10. After couple of minutes can observe msgBacklog reduced to 1 and lastExpireTimestamp is set to recent timestamp
11. After 5 more min can observe msgBacklog reduced to 0 and lastExpireTimestamp is updated to recent timestamp

Expected behavior
Messages should not be expired until ttl is reached.

Desktop (please complete the following information):

• OS: Ubuntu
• Pulsar version - 2.5.0

[codelipenghui]

@AmitANetskope The lastExpireTimestamp updates when the task of message expiration triggers, so the recent timestamp is an expected value. I have tried on my laptop and I add a test #6638 to ensure messages do not expire early, but can't reproduce your problem. Is the problem appears frequently or not? And if you can reproduce it, could you please add your server log here? This will help find the problem.

[AmitANetskope]

Broker log file -
pulsar-broker-pulsar-broker-1.log

Expiry kicking in -
15:24:11.453 [bookkeeper-ml-workers-OrderedExecutor-5-0] INFO org.apache.pulsar.broker.service.persistent.PersistentMessageExpiryMonitor - [persistent://public/amit_test/amit_test][amit_test] Expiring all messages until position 406:0

Topic Stats -
{"msgRateIn":0.0,"msgThroughputIn":0.0,"msgRateOut":0.0,"msgThroughputOut":0.0,"averageMsgSize":0.0,"storageSize":108,"backlogSize":108,"publishers":[],"subscriptions":{"amit_test":{"msgRateOut":0.0,"msgThroughputOut":0.0,"msgRateRedeliver":0.0,"msgBacklog":0,"blockedSubscriptionOnUnackedMsgs":false,"msgDelayed":0,"unackedMessages":0,"type":"Shared","msgRateExpired":0.0033340130445517232,"lastExpireTimestamp":1585582151394,"consumers":[],"isReplicated":false}},"replication":{},"deduplicationStatus":"Enabled","bytesInCounter":108,"msgInCounter":2}

Internal Stats -
{"entriesAddedCounter":0,"numberOfEntries":2,"totalSize":108,"currentLedgerEntries":0,"currentLedgerSize":0,"lastLedgerCreatedTimestamp":"2020-03-30T15:49:01.83Z","waitingCursorsCount":0,"pendingAddEntriesCount":0,"lastConfirmedEntry":"406:1","state":"LedgerOpened","ledgers":[{"ledgerId":406,"entries":2,"size":108,"offloaded":false},{"ledgerId":409,"entries":0,"size":0,"offloaded":false}],"cursors":{"amit_test":{"markDeletePosition":"406:1","readPosition":"406:2","waitingReadOp":false,"pendingReadOps":0,"messagesConsumedCounter":0,"cursorLedger":-1,"cursorLedgerLastEntry":-1,"individuallyDeletedMessages":"[]","lastLedgerSwitchTimestamp":"2020-03-30T15:49:01.863Z","state":"NoLedger","numberOfEntriesSinceFirstNotAckedMessage":1,"totalNonContiguousDeletedMessagesRange":0,"properties":{}},"pulsar.dedup":{"markDeletePosition":"406:-1","readPosition":"406:2","waitingReadOp":false,"pendingReadOps":0,"messagesConsumedCounter":-2,"cursorLedger":-1,"cursorLedgerLastEntry":-1,"individuallyDeletedMessages":"[]","lastLedgerSwitchTimestamp":"2020-03-30T15:49:01.858Z","state":"NoLedger","numberOfEntriesSinceFirstNotAckedMessage":3,"totalNonContiguousDeletedMessagesRange":0,"properties":{}}}}

@codelipenghui I am easily able to reproduce this issue, attached the broker logs containing all logs from adding consumer, producing messages to messages being expired.

[sijie]

@AmitANetskope I think the issue has been fixed by #6211. I also verified it. It will be included in the upcoming 2.5.1 release.

For testing purpose, you can try out our weekly build: https://github.com/streamnative/pulsar/releases/tag/v2.6.0-347d3851b

It includes that fix.

[sijie]

Closed the issue since it is already fixed by #6211