Bug 509796

In the example above, if I use the journal of the new node (that failed to join) in recovery then on inspection the queue depth of the queue in question is 314568 bytes which seems well below capacity.

The journal footprint for these pertest messages is 256 bytes. (See Bug 509573, comment 1 for a detailed explanation on storage budgets and capacity variability.) This places the total enqueued message depth at 12.8MB - which is greater than the default journal capacity of 12.5MB. However, perftest enqueues and dequeues simultaneously on separate threads; as long as enqueue rate ~ dequeue rate, then the capacity is not an issue. If enqueues are faster than dequeues, then the dequeue rate "buys time" for the test to complete before capacity is reached.

Initial examination of the failed secondary node journal shows ~ 39k enqueues and no dequeues - which is the correct threshold for a default journal. What is unclear is which of these enqueues can be attributed to the initial sync with the primary node and which occurred subsequently (if any). This exposes two possible modes of failure:

a) The primary (somehow) is able to maintain its 39k + messages when the secondary is reaching its threshold (a size mismatch), and the failure occurs within the initial sync period;

b) The initial sync completes correctly, but subsequent updates are selective and only the enqueues are reaching the secondary as perftest continues its activity on the primary.

Investigating further, the message size of 8 in this test allows messages on the primary to exist in 1 dblk (with 3 bytes to spare), but on the secondary, because of the additional header info, 2 dblks are consumed per message. This means that the secondary consumes twice the journal space for the same number of messages than the primary.

Rerunning this test with a message size of 12 rather than 8 (which will force both the primary and the secondary to consume 2 dblks) causes an almost immediate enqueue capacity threshold error on the primary.

As this behaviour is now understood and expected, this bug is set to CLOSED/NOTABUG.

Reopening this bug as a question has arisen about whether different nodes should have differing header sizes.

This behaviour greatly increases the probability that cluster nodes will exit one at a time as they hit the enqueue threshold. The desired behaviour is a synchronized exception coming from all nodes at the same time, and this results in a reject of the enqueued message rather than the nodes exiting.

What is the question? I think we should recommend that cluster nodes have identical configuration in all respects. Is there something particular about the journal parameters?

I didn't ask any question... however the issue appears to be that a message takes up more space on new nodes than it does on nodes that were part of the cluster when it was published. I believe it was the exchange header that was different(?). See comment #3 above.

Understood, I'll investigate why this discrepancy arises.

Fixed in r889813

Reproduced on RHEL5/x86_64 with:

qpidd-0.5.752581-33.el5
rhm-0.5.3206-26.el5

# grep -i "Enqueue capacity threshold exceeded" /tmp/qpidd*.log
/tmp/qpidd1.log:2010-oct-04 08:46:56 warning Broker closed connection: 501, Enqueue capacity threshold exceeded on queue "perftest0". (JournalImpl.cpp:611)
/tmp/qpidd1.log:2010-oct-04 08:46:56 error Unbinding update queue perftest0: framing-error: Enqueue capacity threshold exceeded on queue "perftest0". (JournalImpl.cpp:611)
/tmp/qpidd1.log:2010-oct-04 08:46:56 error 10.16.64.153:26294(UPDATER) error sending update: Enqueue capacity threshold exceeded on queue "perftest0". (JournalImpl.cpp:611)
/tmp/qpidd2.log:2010-oct-04 08:46:56 warning Journal "perftest0": Enqueue capacity threshold exceeded on queue "perftest0".
/tmp/qpidd2.log:2010-oct-04 08:46:56 error Unexpected exception: Enqueue capacity threshold exceeded on queue "perftest0". (JournalImpl.cpp:611)
/tmp/qpidd2.log:2010-oct-04 08:46:56 error Connection 10.16.64.153:41592 closed by error: Enqueue capacity threshold exceeded on queue "perftest0". (JournalImpl.cpp:611)(501)

Regression found on RHEL5/x86_64 with current packages:

qpid-cpp-client-ssl-0.7.946106-17.el5
qpid-java-common-0.7.946106-10.el5
qpid-cpp-server-devel-0.7.946106-17.el5
qpid-cpp-client-0.7.946106-17.el5
qpid-cpp-server-ssl-0.7.946106-17.el5
qpid-tools-0.7.946106-11.el5
qpid-cpp-client-devel-0.7.946106-17.el5
python-qpid-0.7.946106-14.el5
qpid-cpp-client-devel-docs-0.7.946106-17.el5
qpid-java-client-0.7.946106-10.el5
qpidc-debuginfo-0.5.752581-33.el5
qpid-cpp-server-store-0.7.946106-17.el5
qpid-cpp-server-0.7.946106-17.el5
qpid-dotnet-0.4.738274-2.el5
qpid-cpp-server-cluster-0.7.946106-17.el5
qpid-cpp-server-xml-0.7.946106-17.el5

Broker log:
2010-10-04 10:08:18 notice cluster(10.16.64.153:28518 READY) last broker standing, update queue policies
2010-10-04 10:08:19 warning Timer callback overran by 3ms [taking 8000ns]
2010-10-04 10:08:19 warning Timer callback overran by 3ms [taking 2000ns]
2010-10-04 10:08:19 warning Journal "qpid-perftest0": Enqueue capacity threshold exceeded on queue "qpid-perftest0".
2010-10-04 10:08:19 error Unexpected exception: Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)
2010-10-04 10:08:19 error Connection 127.0.0.1:42476 closed by error: Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)(501)

Perftest:
23825.8	14544.4	24645.4	0.188029
23148.9	18034.8	37104.3	0.283083
2010-10-04 10:08:19 warning Broker closed connection: 501, Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)
PublishThread exception: framing-error: Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)

Regression confirmed also for RHEL5/x86 packages.

From the log in comment 12 it appears that the capacity exception occurred on the established broker, not on the broker that was joining the cluster. The "last broker standing" message is only logged on an established broker. That would not be a bug, it is simply the perftest filling up the queue faster than it is consumed and exceeding the store limit.

Thanks Alan, then it's not regression. Now, we must to wait for 639994, which blocks us - qpidd crash during shutdown.

    Technical note added. If any revisions are required, please edit the "Technical Notes" field
    accordingly. All revisions will be proofread by the Engineering Content Services team.
    
    New Contents:
Adding a new node to a cluster no longer fails with a journal capacity exception.

This is still marked needinfo from me - what info is needed?

Retested with interesting result:

The above exception is there thrown on RHEL5 x86_64 with auth=yes only, all other cases are w/o exception.


At the moment broker does not leave the cluster.
  python-qpid-0.7.946106-15.el5
  qpid-cpp-client-0.7.946106-27.el5
  qpid-cpp-client-devel-0.7.946106-27.el5
  qpid-cpp-client-devel-docs-0.7.946106-27.el5
  qpid-cpp-client-rdma-0.7.946106-27.el5
  qpid-cpp-client-ssl-0.7.946106-27.el5
  qpid-cpp-mrg-debuginfo-0.7.946106-27.el5
  qpid-cpp-server-0.7.946106-27.el5
  qpid-cpp-server-cluster-0.7.946106-27.el5
  qpid-cpp-server-devel-0.7.946106-27.el5
  qpid-cpp-server-rdma-0.7.946106-27.el5
  qpid-cpp-server-ssl-0.7.946106-27.el5
  qpid-cpp-server-store-0.7.946106-27.el5
  qpid-cpp-server-xml-0.7.946106-27.el5
  qpid-dotnet-0.4.738274-2.el5
  qpid-java-client-0.7.946106-14.el5
  qpid-java-common-0.7.946106-14.el5
  qpid-java-example-0.7.946106-14.el5
  qpid-tools-0.7.946106-12.el5
  rh-qpid-cpp-tests-0.7.946106-27.el5

OK, the issue is retested now with interesting observation:

  # broker as cluster node
  [root@mrg-qe-10 bz509796_639994]# qpid-cluster
    Cluster Name: fcluster
  Cluster Status: ACTIVE
    Cluster Size: 1
        Members: ID=10.34.45.10:11062
URL=amqp:tcp:10.34.33.63:5672,tcp:10.34.44.10:5672,tcp:10.34.45.10:5672
  [root@mrg-qe-10 bz509796_639994]# qpid-config queues | grep perft
  [root@mrg-qe-10 bz509796_639994]# qpid-perftest --durable true --count 50000
--size 8 --summary --username guest --password guest
  2011-01-25 16:40:27 warning Broker closed connection: 501, Enqueue capacity
threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)
  PublishThread exception: framing-error: Enqueue capacity threshold exceeded
on queue "qpid-perftest0". (JournalImpl.cpp:616)


  # broker as standalone

  [root@mrg-qe-10 bz509796_639994]# vi /etc/qpidd.conf
  [root@mrg-qe-10 bz509796_639994]# service qpidd restart
  Stopping Qpid AMQP daemon: qpidd
  Starting Qpid AMQP daemon:  qpidd
  [root@mrg-qe-10 bz509796_639994]# qpid-stat -b
  Brokers
    broker          cluster       uptime  conn  sess  exch  queue
    ===============================================================
    localhost:5672  <standalone>  8s         2     2     8     6
  [root@mrg-qe-10 bz509796_639994]# qpid-perftest --durable true --count 50000
--size 8 --summary --username guest --password guest
  41096.7 41028.9 80447.2 0.613763

  # broker as cluster node

  [root@mrg-qe-10 bz509796_639994]# vi /etc/qpidd.conf
  [root@mrg-qe-10 bz509796_639994]# service qpidd restart
  Stopping Qpid AMQP daemon: qpidd
  Starting Qpid AMQP daemon:  qpidd
  [root@mrg-qe-10 bz509796_639994]# qpid-stat -b
  Brokers
    broker            cluster           uptime  conn  sess  exch  queue
    =====================================================================
    10.34.33.63:5672  fcluster(ACTIVE)  4s         2     2     8     6
  [root@mrg-qe-10 bz509796_639994]# qpid-perftest --durable true --count 50000
--size 8 --summary --username guest --password guest
  2011-01-25 16:42:20 warning Broker closed connection: 501, Enqueue capacity
threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)
  PublishThread exception: framing-error: Enqueue capacity threshold exceeded
on queue "qpid-perftest0". (JournalImpl.cpp:616)



  [root@mrg-qe-10 ~]# uname -a
  Linux mrg-qe-10.lab.eng.brq.redhat.com 2.6.18-238.1.1.el5 #1 SMP Tue Jan 4
13:32:19 EST 2011 x86_64 x86_64 x86_64 GNU/Linux
  [root@mrg-qe-10 ~]# rpm -qa | grep qpid | sort
  python-qpid-0.7.946106-15.el5
  qpid-cpp-client-0.7.946106-27.el5
  qpid-cpp-client-devel-0.7.946106-27.el5
  qpid-cpp-client-devel-docs-0.7.946106-27.el5
  qpid-cpp-client-rdma-0.7.946106-27.el5
  qpid-cpp-client-ssl-0.7.946106-27.el5
  qpid-cpp-mrg-debuginfo-0.7.946106-27.el5
  qpid-cpp-server-0.7.946106-27.el5
  qpid-cpp-server-cluster-0.7.946106-27.el5
  qpid-cpp-server-devel-0.7.946106-27.el5
  qpid-cpp-server-rdma-0.7.946106-27.el5
  qpid-cpp-server-ssl-0.7.946106-27.el5
  qpid-cpp-server-store-0.7.946106-27.el5
  qpid-cpp-server-xml-0.7.946106-27.el5
  qpid-dotnet-0.4.738274-2.el5
  qpid-java-client-0.7.946106-14.el5
  qpid-java-common-0.7.946106-14.el5
  qpid-java-example-0.7.946106-14.el5
  qpid-tools-0.7.946106-12.el5
  rh-qpid-cpp-tests-0.7.946106-27.el5


Above lines clearly shows that running qpid-perftest:
qpid-perftest --durable true --count 50000 --size 8 --summary --username guest
--password guest

with authentication enabled on broker and in cluster additionally the machine
has to be 64 bit machine, fails with journal exception, but should not!

No such behavior on 64 bit machine with auth=no.
No such behavior on 32 bit machine.

Another interesting fact is that I was unable to reproduce on RHEL 5.6 x86_64
VM which indicates that it might be HW related (machines are AMD Opterons).

Retested according the described test scenario and issue is visible after couple of hours of looping.

I believe the cause of this issue is connected with comment 19.

The test result is following (after about 5 hours' run):
test tail transcript:
  run11063: 22061.2       19026.1 38660.9 0.294959 -------------------------------------------------------
  run11064: 31266.8       30040.2 61601.2 0.46998 -------------------------------------------------------
  run11065: 30808.2       28911   59241.2 0.451975 -------------------------------------------------------
  run11066: 31865.7       30435.4 62445.9 0.476425 -------------------------------------------------------
  2011-01-25 22:45:02 warning Broker closed connection: 501, Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)
  2011-01-25 22:45:02 warning Connection [34469 localhost:5672] closed
  2011-01-25 22:45:02 warning Connection [34470 localhost:5672] closed
  run11067: PublishThread exception: framing-error: Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)
  Controller exception: Connection [34470 localhost:5672] closed
  SubscribeThread exception: Connection [34469 localhost:5672] closed -------------------------------------------------------
  2011-01-25 22:45:02 warning Connection [34476 localhost:5672] closed
  run11068:
  Connection [34476 localhost:5672] closed -------------------------------------------------------
  broker exited!
  
broker log tail:
  2011-01-25 22:45:00 notice cluster(10.34.45.9:24684 UPDATER) sending update to 10.34.45.11:1401 at amqp:tcp:10.34.33.64:5672,tcp:10.34.44.11:5672,tcp:10.34.45.11:5672
  2011-01-25 22:45:00 info Connection  connected to tcp:10.34.33.64:5672
  2011-01-25 22:45:01 info Connection  connected to tcp:10.34.33.64:5672
  2011-01-25 22:45:01 info Connection  connected to tcp:10.34.33.64:5672
  2011-01-25 22:45:01 info Connection  connected to tcp:10.34.33.64:5672
  2011-01-25 22:45:01 info Connection  connected to tcp:10.34.33.64:5672
  2011-01-25 22:45:01 warning Broker closed connection: 200, OK
  2011-01-25 22:45:01 notice cluster(10.34.45.9:24684 UPDATER) update sent
  2011-01-25 22:45:01 info cluster(10.34.45.9:24684 READY) member update: 10.34.45.9:24684(member) 10.34.45.11:1401(member) frameSeq=1727220900
  2011-01-25 22:45:01 notice Running in a cluster, marking store dirty.
  2011-01-25 22:45:01 notice cluster(10.34.45.9:24684 READY) last broker standing joined by 1 replicas, updating queue policies.
  2011-01-25 22:45:02 warning Journal "qpid-perftest0": Enqueue capacity threshold exceeded on queue "qpid-perftest0".
  2011-01-25 22:45:02 error Unexpected exception: Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)
  2011-01-25 22:45:02 error Connection 127.0.0.1:34468 closed by error: Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)(501)
  2011-01-25 22:45:02 critical cluster(10.34.45.9:24684 READY/error) local error 1727363037 did not occur on member 10.34.45.11:1401: Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616)
  2011-01-25 22:45:02 critical Error delivering frames: local error did not occur on all cluster members : Enqueue capacity threshold exceeded on queue "qpid-perftest0". (JournalImpl.cpp:616) (qpid/cluster/ErrorCheck.cpp:89)
  2011-01-25 22:45:02 notice cluster(10.34.45.9:24684 LEFT/error) leaving cluster fclusterA
  2011-01-25 22:45:02 notice Shut down



Reproducers:
  - ./node1.sh on machine where one broker runs continuously and perftest loops
  - ./node2.sh on machine which restarts broker

[root@mrg-qe-09 bz509796_639994]# cat ./node1.sh
#!/bin/bash
service qpidd stop

rm -rf /var/lib/qpidd/*

service qpidd start
netstat -nlp | grep qpidd
qpid-cluster


i=0
while true; do

  out=$(qpid-perftest --durable true --count $((50000+${RANDOM}%1000)) --size 8 --summary)
  ecode=$?
  echo "run${i}: ${out} -------------------------------------------------------"

  [ "${ecode}" != "0" ] && break

  let "i++"

  usleep $(( ${RANDOM} + ${RANDOM} ))

done

echo "broker exited!"


# eof

[root@mrg-qe-09 bz509796_639994]# cat ./node2.sh
#!/bin/bash
#2 node thread


service qpidd stop

rm -rf /var/lib/qpidd/*


i=0
while true; do

  echo "run${i} ---------------------------------------------------------------"
  service qpidd start

  # wait 1 + 2typ (0...4)
  usleep $(( 1000000 + ((${RANDOM} % 2000) * 2000) ))
  qpid-cluster

  service qpidd stop

  # wait 0.5 + 1typ (0...2)
  usleep $(( 500000 + ((${RANDOM} % 2000) * 1000) ))

  let "i++"

done

# eof

The broker config was:
cluster-mechanism=ANONYMOUS
#auth=yes
auth=no
log-to-file=/tmp/qpidd.log
log-enable=info+
#log-enable=debug+:cluster
cluster-name=fclusterA
mgmt-pub-interval=2


Moving the defect to ASSIGNED as I'm able to see cluster width reduction due to journal's exception which should not be thrown as
qpid-perftest --durable true --count $((50000+${RANDOM}%1000)) \
              --size 8 --summary

should not trigger the journal exception.

The above test data show that the journal exception was thrown after couple of hours during 11067th run of the perftest.


-> ASSIGNED

comment 18 and comment 19 are a different issue: they are the expected behaviour of a client that overruns queue limits. auth=yes adds an additional header to the messages and I'm guessing that journal entries take more space on 64 bit (kpvdr?), so the two must be combining to push the total size over the journal limit.

comment 20 looks similar to the original issue and needs investigation. Can I just confirm that both brokers in the test had identical config with auth=no? Is there any chance that one broker had auth=yes and the other auth=no?

Thanks for an update.

ad reaction on comment 18 and comment 19:

If it is confirmed that authentication info take more info on 64 bit, then this is fine.


ad reaction on comment 20:
I can confirm that the case from comment 20 was run with auth=no (both machines, RHEL 5.6 one i[36]86, the second one x86_64.

Using the reproducer in comment 20 I reproduced the issue on two x86_64 hosts, so the difference in architecture is probably not an issue.

In this case it was node1 (the stable node) that crashed, not node2 (the one joining & leaving)

I don't think this is a regression. I think it's an example of why we originally introduced the inconsistent error mechanism: brokers with different histories do not have identical capacity to enqueue messages (e.g. in this case probably the new broker's journal was more compact because it didn't have as many dequeue records.) So I think this is a case of the design working as expected (although obviously no as desired) - the broker that is unable to store messages that are successfully stored on other brokers leaves the cluster.

A better solution to the persistent cluster problem is probably something for the new cluster work, and may also requires more transparency from the store.

I'm going to retest to confirm Alan's comment 23.
ETC 2011-02-11.
(Raising NEEDINFO for myself to keep it in as the top 10 TODO task.)

The issue from comment 19 is addressed as separate bug 676627.

I'm reliably able to trigger the original issue on packages:

python-qpid-0.7.946106-15.el5
qpid-cpp-client-0.7.946106-28.el5
qpid-cpp-client-devel-0.7.946106-28.el5
qpid-cpp-client-devel-docs-0.7.946106-28.el5
qpid-cpp-client-rdma-0.7.946106-28.el5
qpid-cpp-client-ssl-0.7.946106-28.el5
qpid-cpp-mrg-debuginfo-0.7.946106-28.el5
qpid-cpp-server-0.7.946106-28.el5
qpid-cpp-server-cluster-0.7.946106-28.el5
qpid-cpp-server-devel-0.7.946106-28.el5
qpid-cpp-server-rdma-0.7.946106-28.el5
qpid-cpp-server-ssl-0.7.946106-28.el5
qpid-cpp-server-store-0.7.946106-28.el5
qpid-cpp-server-xml-0.7.946106-28.el5
qpid-dotnet-0.4.738274-2.el5
qpid-java-client-0.7.946106-15.el5
qpid-java-common-0.7.946106-15.el5
qpid-java-example-0.7.946106-15.el5
qpid-tools-0.7.946106-12.el5
rh-qpid-cpp-tests-0.7.946106-28.el5


with the modified reproducer from comment 20.

The repro patch is:
-  out=$(qpid-perftest --durable true --count $((50000+${RANDOM}%1000)) --size 8 --summary)
+  out=$(qpid-perftest --durable true --count $((50000+${RANDOM}%1000)) --size 8 --summary --username guest --password guest)

and of course auth=yes in qpidd.conf

keeping ASSIGNED

i can confirm issue is seen on 1.3.3 packages

# rpm -qa | grep qpid | sort -u
python-qpid-0.7.946106-15.el5
qpid-cpp-client-0.7.946106-34.el5
qpid-cpp-client-devel-0.7.946106-34.el5
qpid-cpp-client-devel-docs-0.7.946106-34.el5
qpid-cpp-client-ssl-0.7.946106-34.el5
qpid-cpp-server-0.7.946106-34.el5
qpid-cpp-server-cluster-0.7.946106-34.el5
qpid-cpp-server-devel-0.7.946106-34.el5
qpid-cpp-server-ssl-0.7.946106-34.el5
qpid-cpp-server-store-0.7.946106-34.el5
qpid-cpp-server-xml-0.7.946106-34.el5
qpid-java-client-0.10-6.el5
qpid-java-common-0.10-6.el5
qpid-java-example-0.10-6.el5
qpid-tools-0.7.946106-12.el5


2011-08-02 13:16:07 debug cluster(10.34.44.23:9252 READY) replicated connection 10.34.33.84:5672-10.34.33.84:47004(10.34.44.22:25262-6304 shadow)
2011-08-02 13:16:07 debug cluster(10.34.44.23:9252 READY) closed connection 127.0.0.1:5672-127.0.0.1:34159(10.34.44.23:9252-4052 local)
2011-08-02 13:16:08 debug cluster(10.34.44.23:9252 READY/error) connection error 56218379 on 10.34.33.84:5672-10.34.33.84:47002(10.34.44.22:25262-6302 shadow) must be resolved with: 10.34.44.21:16272 10.34.44.22:25262 10.34.44.23:9252 10.34.44.24:2664 : Enqueue capacity threshold exceeded on queue "mrg-qe-17.lab.eng.brq.redhat.com_5406630000". (JournalImpl.cpp:616)
2011-08-02 13:16:08 debug cluster(10.34.44.23:9252 READY/error) error 56218379 resolved with 10.34.44.23:9252
2011-08-02 13:16:08 debug cluster(10.34.44.23:9252 READY/error) error 56218379 must be resolved with 10.34.44.21:16272 10.34.44.22:25262 10.34.44.24:2664 
2011-08-02 13:16:08 critical cluster(10.34.44.23:9252 READY/error) local error 56218379 did not occur on member 10.34.44.21:16272: Enqueue capacity threshold exceeded on queue "mrg-qe-17.lab.eng.brq.redhat.com_5406630000". (JournalImpl.cpp:616)
2011-08-02 13:16:08 critical Error delivering frames: local error did not occur on all cluster members : Enqueue capacity threshold exceeded on queue "mrg-qe-17.lab.eng.brq.redhat.com_5406630000". (JournalImpl.cpp:616) (qpid/cluster/ErrorCheck.cpp:89)
2011-08-02 13:16:08 notice cluster(10.34.44.23:9252 LEFT/error) leaving cluster mrg-qe-1.3.3-clusterA

(In reply to comment #0)
on 1.3.3 happened on 4 node settled cluster, then we started  without joining new node, test scenario described in Bug # 726379 section "Steps to Reproduce".
cluster worked for 3hours 5minutes, then 2 of 4 nodes left cluster with result from comment #28

> Description of problem:
> 
> Adding a new node to a cluster failed with a journal capacity exception.
> However the new node was using the default journal size options as was the
> existing cluster node so its not clear why this error should occur.
> 
> Version-Release number of selected component (if applicable):
> 
> qpidd-0.5.752581-22.el5
> rhm-0.5.3206-5.el5
> 
> How reproducible:
> 
> Fairly easily
> 
> Steps to Reproduce:
> 1. start one cluster node
> 2. run  while perftest --durable true --count 50000 --size 8 --summary; do
> true; done
> 3. while this is running add a new node to the cluster, then stop it, then
> re-add it and repeat this for several times until eventually you see an error
> 
> Actual results:
> 
> 2009-jul-06 05:07:10 notice Journal "perftest0": Created
> 2009-jul-06 05:07:11 warning Journal "perftest0": Enqueue capacity threshold
> exceeded on queue "perftest0".
> 2009-jul-06 05:07:11 error Unexpected exception: Enqueue capacity threshold
> exceeded on queue "perftest0". (JournalImpl.cpp:576)
> 2009-jul-06 05:07:11 error Connection 10.16.44.221:46092 closed by error:
> Enqueue capacity threshold exceeded on queue "perftest0".
> (JournalImpl.cpp:576)(501)
> 2009-jul-06 05:07:11 error Channel exception: not-attached: Channel 1 is not
> attached (qpid/amqp_0_10/SessionHandler.cpp:40)
> 2009-jul-06 05:07:11 critical 10.16.44.221:19499(UPDATEE) catch-up connection
> closed prematurely 10.16.44.221:19499-1(local,catchup)
> 2009-jul-06 05:07:11 notice 10.16.44.221:19499(LEFT) leaving cluster
> grs-mrg14-test-cluster
> 2009-jul-06 05:07:11 notice Shut down
> 
> 
> Expected results:
> 
> Should always be able to add the new node since the queue on the original node
> in the cluster has the same capacity.
> 
> Additional info:

From comment #2 'the total enqueued message depth at 12.8MB - which is
greater than the default journal capacity of 12.5MB', i.e. if testing with 50,000 messages.

It is important to distinguish two cases: (i) general capacity issues for nodes already in the cluster (comment #29 sounds like it is in this category, where two nodes leave a cluster), (ii) a capacity error on updating a new member (which was the original issue and seems also to me the case for comment #20).

The first case cannot be ruled out, though it is unlikely. The exact history may differ between nodes, and this history may affect the actual capacity. Thus the actual capacity may vary by node and may in theory on occasion be insufficient for the defined perftest run. 

I can't however explain why the second is ever legitimate if the nodes all have the same configuration and are on the same architecture. The new member should, if anything, have *greater* capacity than the member from which it is receiving the update. A new member by definition has no history and therefore has the maximum actual capacity when receiving the update. Since the existing member giving the update has not hit the capacity, I don't understand why the new member ever would.

For the purposes of any automated testing around this bug, I would suggest that we reduce the count or increase the journal to the point where we can be certain no journal capacity problems can ever occur even if all the messages are enqueued at once. That will rule out any false negatives.

From comment 30: Another approach to avoid this in tests would be to set a discard policy on the queues that is lower than the journal capacity. Queue policy calculations are consistent in a cluster so this won't cause brokers to crash.

That would still result in occasional hangs (or errors if reject was used instead) in perftest. You really want the test to run smoothly unless there is a genuine bug uncovered.

Assuming that the size of headers is always the same, let me shed some light on how enqueue threshold exception decisions are made in the store.

* The store uses fixed files of fixed size in a circular buffer.

* Each file contains a header that is overwritten each time that file is written.

* Any file that contains an unconsumed record (or part of one) cannot be overwritten at all, even if that record is at the end of the file, as once the header is overwritten, it becomes more problematic to recover.

* The method for determining whether to enqueue a record is as follows: Starting with the current write position in the currently written file, add the size of the record to be written and then jump ahead another 20% of the total journal size. In whichever file this places you, check to see if there is any unconsumed record present. If not, the enqueue proceeds, if there is a record anywhere in this file, the enqueue is rejected with the Enqueue Threshold error.

This method has inherent uncertainty in the point of rejection of one journal file, depending on where the current write point is relative to the next unconsumed record. The most optimistic scenario will cause the error to occur at 80% capacity; however, the most pessimistic scenario will occur at 80% less one file size.

Clearly the number of files used in a journal will influence this uncertainty. If the minimum number of files is used in a journal (4) then one file represents 25% of the capacity, so the error would occur anywhere between 55% and 80%. Eight files (the default) yields 67.5% to 80%, and using the maximum number (64 files at present) yields 78.4% to 80%.

In a cluster where nodes join at different times are subject to this uncertainty. The simplest strategy to mitigate this risk from testing is to ensure the store is big enough to accommodate all messages. However, using a large number of small files will provide better uncertainty than a similarly sized store composed of a smaller number of larger files. Of course, using more files consumes file handles, so care needs to be taken that there are sufficient handles available for the test in question.

I think the summary is: if you're store isn't large enough to handle your peak load, then it's possible for clustered brokers to exit with this error. 
We should re-run the tests with a large enough store and see if there are still any issues.

Yes, agreed (though I still maintain that there should *never* be a capacity error on an update).