[#MB-1117] KahaDB journal files retained after delay in "unsubscribing" durable subscriber from topic.

FUSE Message Broker

KahaDB journal files retained after delay in "unsubscribing" durable subscriber from topic.

Created: 09/Mar/12 02:18 PM Updated: 21/Aug/12 07:20 PM

Component/s:

broker

Affects Version/s:

5.5.1-fuse-02-05

Fix Version/s:

5.6.0-fuse-00-00, 5.5.1-fuse-07-11

File Attachments:

DurableSubDelayedUnsubscribeTest.java (26 kB)
2.

DurableSubProcessWithRestartTest.java (29 kB)
3.

DurableSubProcessWithRestartTest.java (29 kB)
4.

DurableSubProcessWithRestartTest_WITHLONGERCLIENTTIMES.java (29 kB)
5.

DurableSubProcessWithRestartTest_WITHLONGERCLIENTTIMES_V2.java (29 kB)
6.

DurableSubProcessWithRestartTest_WITHLONGERCLIENTTIMES_V3.java (30 kB)
7.

DurableSubSelectorDelayTest.java (10 kB)
8.

DurableSubSelectorDelayTest.java (10 kB)
9.

DurableSubSelectorDelayTest.java (10 kB)
10.

DurableSubSelectorDelayWithRestartTest.java (11 kB)

Environment:

replicated on 5.5.1-fuse-03-04

Issue Links:

Linked

This issue is linked to:

~~MB-1114~~ regression to "MB-834 using durable subs messages stay in KahaDB indefinitely if broker is restarted"

This issue is linked from:

~~MB-1133~~ DurableSubProcessWithRestartTest , acknowledged messages appear to intermittently be redelivered to the subscriber

External Issue URL:

https://issues.apache.org/jira/browse/AMQ-3775

Description

« Hide

Scenario:

Msg Producer sending messages to topic.

Durable subscriber registered with a selector on topic
After 20 seconds; stop calling consumer.receive() .
Another Durable subscriber registers on the topic
After 20 seconds; stop calling consumer.receive() .
Continue this pattern till 10 durable subscribers are registered with topic

Then unsubscribe all 10 Durable subscribers.

Other Notes:
When durable subs unsubscribed DIRECTLY after use, no KahaDB journal files are retained
When selector "matches" all messages, no KahaDB journal files are retained
No subscribers appear to be subscribed to topic in JMX tree at end of test (using jconsole to visually inspect)

For 5.5.1.Fuse-03-04 KahaDB debug log contains:

..  Checkpoint started.
2012-03-09 15:07:35,018 [eckpoint Worker] - TRACE MessageDatabase                - Last update: 36:354945, full gc candidates set: [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36]
2012-03-09 15:07:35,018 [eckpoint Worker] - TRACE MessageDatabase                - gc candidates after first tx:36:354945, [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:07:35,019 [eckpoint Worker] - TRACE MessageDatabase                - gc candidates after dest:1:TopicT, [3, 4, 5, 6, 7]
2012-03-09 15:07:35,019 [eckpoint Worker] - TRACE MessageDatabase                - gc candidates: [3, 4, 5, 6, 7]
2012-03-09 15:07:35,019 [eckpoint Worker] - DEBUG MessageDatabase                - Cleanup removing the data files: [3, 4, 5, 6, 7]
2012-03-09 15:07:35,019 [eckpoint Worker] - DEBUG MessageDatabase                - Checkpoint done.

Same test in 5.4.2.Fuse-02-00 gives KahaDB debug log

... - Checkpoint started.
2012-03-09 15:14:21,703 [eckpoint Worker] TRACE MessageDatabase                - Last update: 36:225386, full gc candidates set: [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36]
2012-03-09 15:14:21,703 [eckpoint Worker] TRACE MessageDatabase                - gc candidates after first tx:36:225386, [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:14:21,703 [eckpoint Worker] TRACE MessageDatabase                - gc candidates after dest:1:TopicT, [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:14:21,703 [eckpoint Worker] TRACE MessageDatabase                - gc candidates: [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:14:21,703 [eckpoint Worker] DEBUG MessageDatabase                - Cleanup removing the data files: [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:14:21,707 [eckpoint Worker] DEBUG MessageDatabase                - Checkpoint done.

Description

KahaDB journal files retained after delay in "unsubscribing" durable subscriber from topic.This issue only appears to occur when Durable Subscriber is registered with a "selector" that does not match all messages on topic. Scenario: Msg Producer sending messages to topic. Durable subscriber registered with a selector on topic After 20 seconds; stop calling consumer.receive() . Another Durable subscriber registers on the topic After 20 seconds; stop calling consumer.receive() . Continue this pattern till 10 durable subscribers are registered with topic Then unsubscribe all 10 Durable subscribers. Other Notes: When durable subs unsubscribed DIRECTLY after use, no KahaDB journal files are retained When selector "matches" all messages, no KahaDB journal files are retained No subscribers appear to be subscribed to topic in JMX tree at end of test (using jconsole to visually inspect) For 5.5.1.Fuse-03-04 KahaDB debug log contains:

..  Checkpoint started.
2012-03-09 15:07:35,018 [eckpoint Worker] - TRACE MessageDatabase                - Last update: 36:354945, full gc candidates set: [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36]
2012-03-09 15:07:35,018 [eckpoint Worker] - TRACE MessageDatabase                - gc candidates after first tx:36:354945, [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:07:35,019 [eckpoint Worker] - TRACE MessageDatabase                - gc candidates after dest:1:TopicT, [3, 4, 5, 6, 7]
2012-03-09 15:07:35,019 [eckpoint Worker] - TRACE MessageDatabase                - gc candidates: [3, 4, 5, 6, 7]
2012-03-09 15:07:35,019 [eckpoint Worker] - DEBUG MessageDatabase                - Cleanup removing the data files: [3, 4, 5, 6, 7]
2012-03-09 15:07:35,019 [eckpoint Worker] - DEBUG MessageDatabase                - Checkpoint done.

Same test in 5.4.2.Fuse-02-00 gives KahaDB debug log

... - Checkpoint started.
2012-03-09 15:14:21,703 [eckpoint Worker] TRACE MessageDatabase                - Last update: 36:225386, full gc candidates set: [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36]
2012-03-09 15:14:21,703 [eckpoint Worker] TRACE MessageDatabase                - gc candidates after first tx:36:225386, [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:14:21,703 [eckpoint Worker] TRACE MessageDatabase                - gc candidates after dest:1:TopicT, [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:14:21,703 [eckpoint Worker] TRACE MessageDatabase                - gc candidates: [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:14:21,703 [eckpoint Worker] DEBUG MessageDatabase                - Cleanup removing the data files: [3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35]
2012-03-09 15:14:21,707 [eckpoint Worker] DEBUG MessageDatabase                - Checkpoint done.

Show »

All

Comments

Change History

Sort Order:

[ Permlink | « Hide ]

Pat Fox added a comment - 09/Mar/12 02:23 PM

This issue was originally detected in DurableSubProcessWithRestartTest.java. I believe DurableSubSelectorDelayTest reproduces the same issue but in a simpler approach.

[ Permlink | « Hide ]

Timothy Bish added a comment - 21/Mar/12 01:40 PM

Fixed merged to 5.5.1-fuse branch.

[ Permlink | « Hide ]

Gary Tully added a comment - 12/Apr/12 02:02 PM

snapshot with the fix: http://repo.fusesource.com/nexus/content/repositories/snapshots/org/apache/activemq/apache-activemq/5.5.1.fuse-SNAPSHOT/apache-activemq-5.5.1.fuse-20120412.134309-11-bin.tar.gz