Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 5.1.0, 5.2.0
    • Fix Version/s: 5.3.0
    • Component/s: Broker
    • Labels:
      None
    • Environment:

      JBOSS 4.2.2, AMQ 5.2.0 RA, JDK 1.5, Windows

      Description

      Messages are processed FIFO when messages with different groups are sent to a queue and then the consumers are started.
      If the messages are sent after the consumers are started, then message grouping works as expected.
      Two JUnit tests are attached.
      1. MessageGroupTest.java starts up 3 consumers and then sends 30 messages evenly distributed across 3 groups A, B, and C.
      Each consumer then gets assigned a group and the ordering is as expected based on the different sleep intervals defined as seen in the log below

      2008-11-26 15:06:09,841 INFO [main] [com.test.MessageGroupTest] 30 messages sent to group A/B/C
      2008-11-26 15:06:09,841 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 9
      2008-11-26 15:06:09,841 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 9
      2008-11-26 15:06:09,841 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 9
      2008-11-26 15:06:09,934 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 8
      2008-11-26 15:06:10,044 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 7
      2008-11-26 15:06:10,137 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 6
      2008-11-26 15:06:10,247 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 5
      2008-11-26 15:06:10,340 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 4
      2008-11-26 15:06:10,450 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 3
      2008-11-26 15:06:10,544 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 2
      2008-11-26 15:06:10,653 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 1
      2008-11-26 15:06:10,747 INFO [Thread-4] [com.test.MessageGroupTest] worker3 received msg C remaining 0
      2008-11-26 15:06:10,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 8
      2008-11-26 15:06:11,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 7
      2008-11-26 15:06:12,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 6
      2008-11-26 15:06:13,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 5
      2008-11-26 15:06:14,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 8
      2008-11-26 15:06:14,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 4
      2008-11-26 15:06:15,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 3
      2008-11-26 15:06:16,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 2
      2008-11-26 15:06:17,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 1
      2008-11-26 15:06:18,840 INFO [Thread-2] [com.test.MessageGroupTest] worker1 received msg B remaining 0
      2008-11-26 15:06:19,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 7
      2008-11-26 15:06:24,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 6
      2008-11-26 15:06:29,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 5
      2008-11-26 15:06:34,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 4
      2008-11-26 15:06:39,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 3
      2008-11-26 15:06:44,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 2
      2008-11-26 15:06:49,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 1
      2008-11-26 15:06:54,840 INFO [Thread-3] [com.test.MessageGroupTest] worker2 received msg A remaining 0

      2. MessageGroupDelayedTest.java sends 30 messages evenly distributed across 3 groups A, B, and C and then starts up 3 consumers.
      All 30 messages are delivered in FIFO order to a single consumer as seen in the log below

      2008-11-26 15:25:50,021 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 9
      2008-11-26 15:25:55,021 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 9
      2008-11-26 15:25:56,021 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 9
      2008-11-26 15:25:56,130 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 8
      2008-11-26 15:26:01,130 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 8
      2008-11-26 15:26:02,130 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 8
      2008-11-26 15:26:02,224 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 7
      2008-11-26 15:26:07,224 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 7
      2008-11-26 15:26:08,224 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 7
      2008-11-26 15:26:08,333 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 6
      2008-11-26 15:26:13,333 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 6
      2008-11-26 15:26:14,333 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 6
      2008-11-26 15:26:14,427 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 5
      2008-11-26 15:26:19,427 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 5
      2008-11-26 15:26:20,427 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 5
      2008-11-26 15:26:20,536 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 4
      2008-11-26 15:26:25,536 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 4
      2008-11-26 15:26:26,536 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 4
      2008-11-26 15:26:26,630 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 3
      2008-11-26 15:26:31,630 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 3
      2008-11-26 15:26:32,630 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 3
      2008-11-26 15:26:32,739 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 2
      2008-11-26 15:26:37,739 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 2
      2008-11-26 15:26:38,739 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 2
      2008-11-26 15:26:38,833 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 1
      2008-11-26 15:26:43,832 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 1
      2008-11-26 15:26:44,832 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 1
      2008-11-26 15:26:44,926 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg A remaining 0
      2008-11-26 15:26:49,926 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg B remaining 0
      2008-11-26 15:26:50,926 INFO [Thread-4] [com.test.MessageGroupDelayedTest] worker3 received msg C remaining 0

      1. MessageGroupDelayedTest.java
        5 kB
        Hari Iyer
      2. MessageGroupTest.java
        5 kB
        Hari Iyer

        Activity

        Hide
        Gordon Hopper added a comment -

        bug summary: Message grouping fails when consumers are added.
        keywords: JMSXGroupID JMSXGroupSeq

        Uploading a new unit test. An excerpt of the test results is below, which shows that the message groups GrA and GrB are being handled by both consumers simultaneously.

        15:11:58,498 INFO GroupNewConsumerTest - Con2 got message GrA-5
        15:11:58,560 INFO GroupNewConsumerTest - Con2 got message GrB-5
        15:11:58,560 INFO GroupNewConsumerTest - Con1 got message GrB-3
        15:11:58,623 INFO GroupNewConsumerTest - Con1 got message GrA-4
        15:11:58,623 INFO GroupNewConsumerTest - Con2 got message GrA-6
        15:11:58,685 INFO GroupNewConsumerTest - Con1 got message GrB-4
        15:11:58,685 INFO GroupNewConsumerTest - Con2 got message GrB-6
        15:11:58,748 INFO GroupNewConsumerTest - Con1 got message GrB-7
        15:11:58,748 INFO GroupNewConsumerTest - Con2 got message GrA-7
        15:11:58,810 INFO GroupNewConsumerTest - Con1 got message GrB-8
        15:11:58,810 INFO GroupNewConsumerTest - Con2 got message GrA-8
        15:11:58,873 INFO GroupNewConsumerTest - Con2 got message GrA-9
        15:11:58,935 INFO GroupNewConsumerTest - Con2 got message GrB-9

        This is probably the same issue described in:
        http://www.nabble.com/Message-groups-not-working-when-consuming-existing-messages-td18445237.html#a18445237

        Note that setting the prefetch to 1 made reproducing the issue much easier. (See the unit test)

        Show
        Gordon Hopper added a comment - bug summary: Message grouping fails when consumers are added. keywords: JMSXGroupID JMSXGroupSeq Uploading a new unit test. An excerpt of the test results is below, which shows that the message groups GrA and GrB are being handled by both consumers simultaneously. 15:11:58,498 INFO GroupNewConsumerTest - Con2 got message GrA-5 15:11:58,560 INFO GroupNewConsumerTest - Con2 got message GrB-5 15:11:58,560 INFO GroupNewConsumerTest - Con1 got message GrB-3 15:11:58,623 INFO GroupNewConsumerTest - Con1 got message GrA-4 15:11:58,623 INFO GroupNewConsumerTest - Con2 got message GrA-6 15:11:58,685 INFO GroupNewConsumerTest - Con1 got message GrB-4 15:11:58,685 INFO GroupNewConsumerTest - Con2 got message GrB-6 15:11:58,748 INFO GroupNewConsumerTest - Con1 got message GrB-7 15:11:58,748 INFO GroupNewConsumerTest - Con2 got message GrA-7 15:11:58,810 INFO GroupNewConsumerTest - Con1 got message GrB-8 15:11:58,810 INFO GroupNewConsumerTest - Con2 got message GrA-8 15:11:58,873 INFO GroupNewConsumerTest - Con2 got message GrA-9 15:11:58,935 INFO GroupNewConsumerTest - Con2 got message GrB-9 This is probably the same issue described in: http://www.nabble.com/Message-groups-not-working-when-consuming-existing-messages-td18445237.html#a18445237 Note that setting the prefetch to 1 made reproducing the issue much easier. (See the unit test)
        Hide
        Gary Tully added a comment -

        prefetch=1 should help here. Part of the problem is that the dispatch logic can only deal with the consumers that it has and on the first dispatch iteration it finds only one consumer and figures that that consumer has to deal with all of the groups. With prefetch of one, after the first dispatch iteration there may be another consumer (at least it allow the internal dispatch lock to be released so that another consumer can be added between dispatch attempts)

        Currently there is an issue that evaluates message group selection before determining if a consumer is full, but if this is resolved, prefetch=1 should make group selection evenly distributed among subscriptions that arrive at the same time and before the group assignment has been determined.

        Show
        Gary Tully added a comment - prefetch=1 should help here. Part of the problem is that the dispatch logic can only deal with the consumers that it has and on the first dispatch iteration it finds only one consumer and figures that that consumer has to deal with all of the groups. With prefetch of one, after the first dispatch iteration there may be another consumer (at least it allow the internal dispatch lock to be released so that another consumer can be added between dispatch attempts) Currently there is an issue that evaluates message group selection before determining if a consumer is full, but if this is resolved, prefetch=1 should make group selection evenly distributed among subscriptions that arrive at the same time and before the group assignment has been determined.
        Hide
        Gordon Hopper added a comment -

        After reviewing Hari's original files and the response from Gary, I think my issue is different than the original issue. Hari is concerned with balancing between multiple consumers, while I am concerned with the exclusive property. Sorry for the confusion.

        Moved my test case to the ticket AMQ-2082.

        Show
        Gordon Hopper added a comment - After reviewing Hari's original files and the response from Gary, I think my issue is different than the original issue. Hari is concerned with balancing between multiple consumers, while I am concerned with the exclusive property. Sorry for the confusion. Moved my test case to the ticket AMQ-2082 .
        Hide
        Dejan Bosanac added a comment -

        Recovery dispatch refactoring, which was the root of the problem, has been committed in SVN revision 736720. All that is left to be done is to add a configurable logic that would make broker to wait for a certain number of consumers (and/or a bit of time) before it starts dispatching. This will allow an even distribution of groups among consumers. Coming soon.

        Show
        Dejan Bosanac added a comment - Recovery dispatch refactoring, which was the root of the problem, has been committed in SVN revision 736720. All that is left to be done is to add a configurable logic that would make broker to wait for a certain number of consumers (and/or a bit of time) before it starts dispatching. This will allow an even distribution of groups among consumers. Coming soon.
        Hide
        Dejan Bosanac added a comment -

        The configurable queue policies has been added, which allows us to wait for specified number of consumers (and/or time) before we start dispatching messages. This ensures an even distribution of groups among consumers.

        More documentation can be found at:
        http://cwiki.apache.org/confluence/display/ACTIVEMQ/Message+Groups#MessageGroups-Gettingnotifiedofownershipchangesofmessagegroups
        Modified test case (tests for different policies condemnations and fails if there is no even distribution of messages and groups) can be found here
        http://svn.apache.org/viewvc/activemq/trunk/activemq-core/src/test/java/org/apache/activemq/usecases/MessageGroupDelayedTest.java?view=markup

        Show
        Dejan Bosanac added a comment - The configurable queue policies has been added, which allows us to wait for specified number of consumers (and/or time) before we start dispatching messages. This ensures an even distribution of groups among consumers. More documentation can be found at: http://cwiki.apache.org/confluence/display/ACTIVEMQ/Message+Groups#MessageGroups-Gettingnotifiedofownershipchangesofmessagegroups Modified test case (tests for different policies condemnations and fails if there is no even distribution of messages and groups) can be found here http://svn.apache.org/viewvc/activemq/trunk/activemq-core/src/test/java/org/apache/activemq/usecases/MessageGroupDelayedTest.java?view=markup
        Hide
        Rich Christy added a comment -

        Any luck getting a fix for version 5.2?

        Show
        Rich Christy added a comment - Any luck getting a fix for version 5.2?
        Hide
        Dejan Bosanac added a comment -

        Hi Rich,

        we don't maintain 5.2 branch anymore. Any specific reason you don't want to upgrade to 5.3 (it should be much more stable than 5.2)?

        Show
        Dejan Bosanac added a comment - Hi Rich, we don't maintain 5.2 branch anymore. Any specific reason you don't want to upgrade to 5.3 (it should be much more stable than 5.2)?

          People

          • Assignee:
            Dejan Bosanac
            Reporter:
            Hari Iyer
          • Votes:
            3 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development