Bug 798731

Summary: clustered brokers rewrite timestamps in messages
Product: Red Hat Enterprise MRG Reporter: Leonid Zhaldybin <lzhaldyb>
Component: qpid-cppAssignee: Ken Giusti <kgiusti>
Status: NEW --- QA Contact: Messaging QE <messaging-qe-bugs>
Severity: medium Docs Contact:
Priority: low    
Version: DevelopmentCC: jross, kgiusti
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Leonid Zhaldybin 2012-02-29 17:04:47 UTC
Description of problem:
The new feature was introduced in qpid 0.14 - "Support for timestamping messages on arrival at the broker." A broker can be configured to add a timestamp to the message it receives from a client.
The problem is that when a broker which is part of a cluster, receives a message from another broker, and this message has a timestamp in it already, this timestamp gets rewritten. This leads to an inconsistency in cluster.

For example, I have a cluster consisting of just two brokers. They are both running:
[root@lzhaldyb-rhel62i ~]# qpid-cluster
  Cluster Name: lzhaldyb-cluster
Cluster Status: ACTIVE
  Cluster Size: 2
       Members: ID=192.168.62.1:1984 URL=amqp:tcp:10.34.33.227:5672,tcp:192.168.62.1:5672
              : ID=192.168.62.2:3691 URL=amqp:tcp:10.34.33.226:5672,tcp:192.168.62.2:5672

Step 1: send two messages to one of the brokers.
[root@lzhaldyb-rhel62i ~]# ./spout -c 1 -i message_$(date +%s) test_cluster_timestamps && sleep 8 && ./spout -c 1 -i message_$(date +%s) test_cluster_timestamps
Both brokers have both messages with identical timestamps after this step:
[root@lzhaldyb-rhel62i ~]# ./drain -c 0 'test_cluster_timestamps; {mode: browse}'
Message(properties={spout-id:message_1330528317:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528317}, content='')
Message(properties={spout-id:message_1330528325:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528325}, content='')
[root@lzhaldyb-rhel62x ~]# ./drain -c 0 'test_cluster_timestamps; {mode: browse}'
Message(properties={spout-id:message_1330528317:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528317}, content='')
Message(properties={spout-id:message_1330528325:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528325}, content='')

Step 2: turn off one of the brokers and send two more messages to the active one.
[root@lzhaldyb-rhel62x ~]# service qpidd stop
Stopping Qpid AMQP daemon:                                 [  OK  ]
[root@lzhaldyb-rhel62i ~]# qpid-cluster
  Cluster Name: lzhaldyb-cluster
Cluster Status: ACTIVE
  Cluster Size: 1
       Members: ID=192.168.62.1:2296 URL=amqp:tcp:10.34.33.227:5672,tcp:192.168.62.1:5672
[root@lzhaldyb-rhel62i ~]# ./drain -c 0 'test_cluster_timestamps; {mode: browse}'
Message(properties={spout-id:message_1330528317:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528317}, content='')
Message(properties={spout-id:message_1330528325:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528325}, content='')
Message(properties={spout-id:message_1330528499:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528499}, content='')
Message(properties={spout-id:message_1330528507:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528507}, content='')

Step 3: turn the second broker back on.
On this step, the first broker sends the messages to the second one, which sets the timestamps to the current value:
[root@lzhaldyb-rhel62x ~]# service qpidd start
Starting Qpid AMQP daemon:                                 [  OK  ]
[root@lzhaldyb-rhel62x ~]# ./drain -c 0 'test_cluster_timestamps; {mode: browse}'
Message(properties={spout-id:message_1330528317:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330532153}, content='')
Message(properties={spout-id:message_1330528325:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330532153}, content='')
Message(properties={spout-id:message_1330528499:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330532153}, content='')
Message(properties={spout-id:message_1330528507:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330532153}, content='')
whereas the timestamps on the first broker remain the same:
[root@lzhaldyb-rhel62i ~]# ./drain -c 0 'test_cluster_timestamps; {mode: browse}'
Message(properties={spout-id:message_1330528317:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528317}, content='')
Message(properties={spout-id:message_1330528325:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528325}, content='')
Message(properties={spout-id:message_1330528499:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528499}, content='')
Message(properties={spout-id:message_1330528507:0, x-amqp-0-10.routing-key:test_cluster_timestamps, x-amqp-0-10.timestamp:1330528507}, content='')

As a result we have a cluster with two brokers, each of which has the exact same messages, but timestamps of these messages differ among brokers.

Version-Release number of selected component (if applicable):
qpid-cpp-client-0.14-7.el6.i686
qpid-cpp-client-devel-0.14-7.el6.i686
qpid-cpp-client-ssl-0.14-7.el6.i686
qpid-cpp-server-0.14-7.el6.i686
qpid-cpp-server-cluster-0.14-7.el6.i686
qpid-cpp-server-devel-0.14-7.el6.i686
qpid-cpp-server-ssl-0.14-7.el6.i686
qpid-cpp-server-store-0.14-7.el6.i686
qpid-cpp-server-xml-0.14-7.el6.i686


How reproducible:
always

Steps to Reproduce:
1. Configure cluster, turn one of the clustered brokers off.
2. Send a few messages to the currently active broker.
3. Turn the broker from Step 1 back on.
4. Compare timestamps of the messages on the newly started broker and the one they were initially sent to by the client.
  
Actual results:
The timestamps of the same message differ on different brokers.

Expected results:
Timestamps are consistent throughout the broker.

Additional info: