Hi Alex, thanks for the logs and the debug info.
> Log for the altered script follows below.
Looks like the queues are getting set up correctly, so we can rule that out.
This part can be explained and is expected:
> > .QueueFlowLimitTests.test_flow_size ............... start
> > QUEUE DECL ARGS={'qpid.flow_stop_size': 351133,
> > 'qpid.flow_resume_size': 251143}
> > QUEUE ACTUAL ARGS={u'qpid.flow_stop_count': 373,
> > u'qpid.flow_resume_count': 229}
>
> DECL ARGS have keys like *size
> ACTUAL ARGS have keys like *count, same as in previous test.
It's reporting the configuration for the last successful create of test-q, so
this is just fallout from the previous failures.
The log you sent, however, is -very- interesting. Things seem to be happening
very, very, very slowly...
The log appears to be a run of the
"queue_flow_limit_tests.QueueFlowLimitTests.test_flow_count" test. First, it
appears that the queue is setup as expected - from the log:
2011-09-07 13:02:42 trace RECV [127.0.0.1:57764-127.0.0.1:59912]: Frame[BEbe;
channel=1; {QueueDeclareBody: queue=test-q;
arguments={qpid.flow_resume_count:F8:int64(229),qpid.flow_stop_count:F8:int64(373)};
}]
2011-09-07 13:02:42 trace [email protected]: recv cmd 0:
{QueueDeclareBody: queue=test-q;
arguments={qpid.flow_resume_count:F8:int64(229),qpid.flow_stop_count:F8:int64(373)};
}
<snip>
2011-09-07 13:02:42 info Queue "test-q": Flow limit created: flowStopCount=373,
flowResumeCount=229, flowStopSize=0, flowResumeSize=0
That's all good. Then I see traffic arriving on the queue, but REALLY SLOWLY.
Here's a grep of the message flow from the logs:
2011-09-07 13:02:45 debug Message 0x2aaaac0233a0 enqueued on test-q
2011-09-07 13:02:46 debug Message 0x2aaab00473b0 enqueued on test-q
2011-09-07 13:02:46 debug Message 0xd43e240 enqueued on test-q
2011-09-07 13:02:46 debug Message 0x2aaaac024020 enqueued on test-q
2011-09-07 13:02:46 debug Message 0x2aaaac023cc0 enqueued on test-q
2011-09-07 13:02:46 debug Message 0xd43e4c0 enqueued on test-q
2011-09-07 13:02:46 debug Message 0x2aaaac024fb0 enqueued on test-q
2011-09-07 13:02:46 debug Message 0x2aaaac0255f0 enqueued on test-q
2011-09-07 13:02:46 debug Message 0xd43fa30 enqueued on test-q
2011-09-07 13:02:46 debug Message 0x2aaaac025f70 enqueued on test-q
2011-09-07 13:02:46 debug Message 0x2aaaac0249f0 enqueued on test-q
2011-09-07 13:02:46 debug Message 0xd43fcb0 enqueued on test-q
2011-09-07 13:02:47 debug Message 0x2aaaac0266f0 enqueued on test-q
2011-09-07 13:02:47 debug Message 0x2aaaac0261f0 enqueued on test-q
2011-09-07 13:02:47 debug Message 0xd4420b0 enqueued on test-q
2011-09-07 13:02:47 debug Message 0x2aaaac027390 enqueued on test-q
2011-09-07 13:02:47 debug Message 0x2aaaac0269a0 enqueued on test-q
2011-09-07 13:02:47 debug Message 0xd442b20 enqueued on test-q
2011-09-07 13:02:47 debug Message 0x2aaaac028040 enqueued on test-q
2011-09-07 13:02:47 debug Message 0x2aaaac027be0 enqueued on test-q
2011-09-07 13:02:47 debug Message 0xd444020 enqueued on test-q
2011-09-07 13:02:47 debug Message 0x2aaaac15c480 enqueued on test-q
2011-09-07 13:02:47 debug Message 0x2aaaac028480 enqueued on test-q
2011-09-07 13:02:48 debug Message 0xd445700 enqueued on test-q
See the timestamp - it's something like 11 messages a second - the tests end up
timing out before the flow control state is being hit.
Further down in the log, I can see where the queue actually enters flow control
as expected:
2011-09-07 13:03:15 debug Message 0xd369b40 enqueued on test-q
2011-09-07 13:03:15 info Queue "test-q": has reached 373 enqueued messages.
Producer flow control activated.
2011-09-07 13:03:15 trace Queue "test-q": setting flow control for msg pos=374
2011-09-07 13:03:15 debug Message 0x2aaab00c8420 enqueued on test-q
2011-09-07 13:03:15 trace Queue "test-q": setting flow control for msg pos=375
2011-09-07 13:03:15 debug Message 0xd36a6a0 enqueued on test-q
But it's too late at this point, the test has timed out.
That's my best guess as to what is happening. But I'm at a loss as to why
those tests are running so slowly.
-K
----- Original Message -----
> On Sep 7, 2011, at 9:53 AM, Ken Giusti wrote:
>
> > Alex - if you'd like to try to debug this, can you alter the
> > cpp/src/
> > tests/queue_flow_limit_test.py file to dump the queue configuration
> > arguments before and after the queue is created (in the
> > _create_queue() method)?
>
>
> Log for the altered script follows below.
> Note, we use custom rebuilt python 2.6 to enable few modules if that
> matter. The same python binary used during build and check phase.
> I'll send you broker log directly.
> Alex.
>
> > Running Queue flow limit tests using broker on port 57764
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_blocked_queue_delete .... start
> > QUEUE DECL ARGS={'qpid.flow_stop_size': 10,
> > 'qpid.flow_resume_size': 2}
> > QUEUE ACTUAL ARGS={u'qpid.flow_stop_size': 10,
> > u'qpid.flow_resume_size': 2}
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_blocked_queue_delete .... fail
> > Error during test:
> > Traceback (most recent call last):
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/commands/qpid-
> > python-test", line 311, in run
> > phase()
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 373, in test_blocked_queue_delete
> > self.failIf(sender.isAlive())
> > File "/opt/enstore/Python/lib/python2.6/unittest.py", line 321,
> > in failIf
> > if expr: raise self.failureException, msg
> > AssertionError
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_default_flow_count ...... start
> > QUEUE DECL ARGS={'qpid.max_count': 1000}
> > QUEUE ACTUAL ARGS={u'qpid.max_count': 1000}
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_default_flow_count ...... fail
> > Error during test:
> > Traceback (most recent call last):
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/commands/qpid-
> > python-test", line 311, in run
> > phase()
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 306, in test_default_flow_count
> > self.verify_limit(TestQ(oid))
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 268, in verify_limit
> > self.failUnless(testq.verifyStopped())
> > File "/opt/enstore/Python/lib/python2.6/unittest.py", line 325,
> > in failUnless
> > if not expr: raise self.failureException, msg
> > AssertionError
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_default_flow_size ....... start
> > QUEUE DECL ARGS={'qpid.max_size': 10000}
> > QUEUE ACTUAL ARGS={u'qpid.max_size': 10000}
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_default_flow_size ....... fail
> > Error during test:
> > Traceback (most recent call last):
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/commands/qpid-
> > python-test", line 311, in run
> > phase()
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 332, in test_default_flow_size
> > self.verify_limit(TestQ(oid))
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 268, in verify_limit
> > self.failUnless(testq.verifyStopped())
> > File "/opt/enstore/Python/lib/python2.6/unittest.py", line 325,
> > in failUnless
> > if not expr: raise self.failureException, msg
> > AssertionError
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_flow_count .............. start
> > QUEUE DECL ARGS={'qpid.flow_stop_count': 373,
> > 'qpid.flow_resume_count': 229}
> > QUEUE ACTUAL ARGS={u'qpid.flow_stop_count': 373,
> > u'qpid.flow_resume_count': 229}
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_flow_count .............. fail
> > Error during test:
> > Traceback (most recent call last):
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/commands/qpid-
> > python-test", line 311, in run
> > phase()
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 169, in test_flow_count
> > self.failUnless(self.qmf.getObjects(_objectId=oid)
> > [0].flowStopped)
> > File "/opt/enstore/Python/lib/python2.6/unittest.py", line 325,
> > in failUnless
> > if not expr: raise self.failureException, msg
> > AssertionError
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_flow_size ............... start
> > QUEUE DECL ARGS={'qpid.flow_stop_size': 351133,
> > 'qpid.flow_resume_size': 251143}
> > QUEUE ACTUAL ARGS={u'qpid.flow_stop_count': 373,
> > u'qpid.flow_resume_count': 229}
>
> DECL ARGS have keys like *size
> ACTUAL ARGS have keys like *count, same as in previous test.
>
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_flow_size ............... fail
> > Error during test:
> > Traceback (most recent call last):
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/commands/qpid-
> > python-test", line 311, in run
> > phase()
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 210, in test_flow_size
> > oid = self._create_queue("test-q", stop_size=351133,
> > resume_size=251143)
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 78, in _create_queue
> > self.assertEqual(i.arguments.get("qpid.flow_stop_size"),
> > stop_size)
> > File "/opt/enstore/Python/lib/python2.6/unittest.py", line 350,
> > in failUnlessEqual
> > (msg or '%r != %r' % (first, second))
> > AssertionError: None != 351133
> > queue_flow_limit_tests
> > .QueueFlowLimitTests.test_qpid_config_cmd ......... fail
> > Error during test:
> > Traceback (most recent call last):
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/commands/qpid-
> > python-test", line 311, in run
> > phase()
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 136, in test_qpid_config_cmd
> > self.startQmf();
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/qpid/
> > testlib.py", line 193, in startQmf
> > self.qmf_broker = self.qmf.addBroker(str(self.broker))
> > File "/opt/install/qpid-0.12/extras/qmf/src/py/qmf/console.py",
> > line 643, in addBroker
> > ssl = url.scheme == URL.AMQPS, connTimeout=timeout)
> > File "/opt/install/qpid-0.12/extras/qmf/src/py/qmf/console.py",
> > line 2283, in __init__
> > self._waitForStable()
> > File "/opt/install/qpid-0.12/extras/qmf/src/py/qmf/console.py",
> > line 2723, in _waitForStable
> > raise RuntimeError("Timed out waiting for broker to
> > synchronize")
> > RuntimeError: Timed out waiting for broker to synchronize
> > Error during teardown:
> > Traceback (most recent call last):
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/commands/qpid-
> > python-test", line 311, in run
> > phase()
> > File "/opt/install/qpid-0.12/cpp/src/tests/python/qpid/
> > testlib.py", line 219, in tearDown
> > self.qmf.delBroker(self.qmf_broker)
> > File "/opt/install/qpid-0.12/cpp/src/tests/
> > queue_flow_limit_tests.py", line 36, in __getattr__
> > raise AttributeError
> > AttributeError
> > Totals: 6 tests, 0 passed, 0 skipped, 0 ignored, 6 failed
> > 2011-09-07 13:05:12 warning Connection [127.0.0.1:59908-localhost:
> > 57764] closed
> > qpid-send: Failed to connect (reconnect disabled)
> > 2011-09-07 13:05:12 warning Connection [127.0.0.1:59911-localhost:
> > 57764] closed
> > qpid-send: Failed to connect (reconnect disabled)
> > 2011-09-07 13:05:12 warning Connection [127.0.0.1:59915-localhost:
> > 57764] closed
> > qpid-send: Failed to connect (reconnect disabled)
> > 2011-09-07 13:05:12 warning Connection [127.0.0.1:59916-localhost:
> > 57764] closed
> > qpid-send: Failed to connect (reconnect disabled)
> > 2011-09-07 13:05:12 warning Connection [127.0.0.1:59914-localhost:
> > 57764] closed
> > qpid-send: Failed to connect (reconnect disabled)
> > FAIL queue flow limit tests
> > FAIL: run_queue_flow_limit_tests
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:[email protected]
