Bug 595787

Summary: qpid python client crashes when testing whether message transfer is possible after session_detach
Product: Red Hat Enterprise MRG Reporter: Frantisek Reznicek <freznice>
Component: qpid-cppAssignee: Gordon Sim <gsim>
Status: CLOSED ERRATA QA Contact: Frantisek Reznicek <freznice>
Severity: medium Docs Contact:
Priority: medium    
Version: DevelopmentCC: esammons, gsim
Target Milestone: 1.3   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard: RHTSdone=MRG/Messaging/qpid_test_msg_trasfer_after_session_detach_bz461816 TCMSdone=44351
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2010-10-20 11:30:46 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 569698    
Bug Blocks:    

Description Frantisek Reznicek 2010-05-25 15:36:53 UTC 
Description of problem:

There is problem either in python client and/or in broker.

Some time ago bug 461816 got python reproducer which tests whether python client is not able to transfer messages after session_detach.

The test was PASSing and now suddenly fails for RHEL5 only (i386/x86_64).

There are observed multiple symptoms depending on broker log level!

a] client ran against broker --log-enable info+
  In most of the cases python test client/program exits with this exception:

  --- python ./bz461816.py log ---
  1 of 100
  2 of 100
  3 of 100
  4 of 100
  5 of 100
  6 of 100
  7 of 100
  8 of 100
  Traceback (most recent call last):
    File "./bz461816.py", line 97, in ?
      receiver.process(10)
    File "./bz461816.py", line 65, in process
      incoming.start()
    File "/usr/lib/python2.4/site-packages/qpid/session.py", line 278, in start
      self.session.message_flow(self.destination, unit, 0xFFFFFFFFL)
    File "/usr/lib/python2.4/site-packages/qpid/generator.py", line 25, in <lambda>
      method = lambda self, *args, **kwargs: self.invoke(op, args, kwargs)
    File "/usr/lib/python2.4/site-packages/qpid/session.py", line 138, in invoke
      return self.do_invoke(op, args, kwargs)
    File "/usr/lib/python2.4/site-packages/qpid/session.py", line 183, in do_invoke
      self.sync(self.timeout)
    File "/usr/lib/python2.4/site-packages/qpid/session.py", line 103, in sync
      raise SessionException(self.error())
  qpid.session.SessionException: (None, 'connection aborted')


  --- qpidd log ---
  2010-05-25 16:56:38 info Loaded Module: /usr/lib64/qpid/daemon/replicating_listener.so
  2010-05-25 16:56:38 info Loaded Module: /usr/lib64/qpid/daemon/acl.so
  2010-05-25 16:56:38 info Loaded Module: /usr/lib64/qpid/daemon/msgstore.so
  2010-05-25 16:56:38 info Loaded Module: /usr/lib64/qpid/daemon/replication_exchange.so
  2010-05-25 16:56:38 info Loaded Module: /usr/lib64/qpid/daemon/watchdog.so
  2010-05-25 16:56:38 info Loaded Module: /usr/lib64/qpid/daemon/ssl.so
  2010-05-25 16:56:38 info Loaded Module: /usr/lib64/qpid/daemon/xml.so
  2010-05-25 16:56:38 info Loaded Module: /usr/lib64/qpid/daemon/cluster.so
  2010-05-25 16:56:38 info No message store configured, persistence is disabled.
  2010-05-25 16:56:38 info Management enabled
  2010-05-25 16:56:38 info ManagementAgent generated broker ID: a84f1332-4592-457c-a3fb-a8b17896c3cb
  2010-05-25 16:56:39 notice Journal "TplStore": Created
  2010-05-25 16:56:39 notice Store module initialized; store-dir=/root/MRG/Messaging/qpid_test_msg_trasfer_after_session_detach_bz46181
  6/rhts_qpidd/20100525_165632/broker.1384
  2010-05-25 16:56:39 info > Default files per journal: 8
  2010-05-25 16:56:39 info > Default journal file size: 24 (wpgs)
  2010-05-25 16:56:39 info > Default write cache page size: 32 (Kib)
  2010-05-25 16:56:39 info > Default number of write cache pages: 32
  2010-05-25 16:56:39 info > TPL files per journal: 8
  2010-05-25 16:56:39 info > TPL journal file size: 24 (wpgs)
  2010-05-25 16:56:39 info > TPL write cache page size: 4 (Kib)
  2010-05-25 16:56:39 info > TPL number of write cache pages: 64
  2010-05-25 16:56:39 info Registered replication exchange
  2010-05-25 16:56:39 info Registered xml exchange
  2010-05-25 16:56:39 info Most recent persistence id found: 0x0
  2010-05-25 16:56:40 notice SASL disabled: No Authentication Performed
  2010-05-25 16:56:40 notice Listening on TCP port 5672
  2010-05-25 16:56:40 info Policy file not specified. ACL Disabled, no ACL checking being done!
  2010-05-25 16:56:40 info SSL plugin not enabled, you must set --ssl-cert-db to enable it.
  2010-05-25 16:56:40 notice Broker running
  2010-05-25 16:56:41 info Queue "bz461816": Policy created: type=reject; maxCount=0; maxSize=104857600
  2010-05-25 16:56:41 error Execution exception: not-found: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)
  2010-05-25 16:56:42 error Execution exception: not-found: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)
  2010-05-25 16:56:42 error Execution exception: not-found: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)
  2010-05-25 16:56:42 error Execution exception: not-found: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)
  2010-05-25 16:56:42 error Execution exception: not-found: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)
  2010-05-25 16:56:43 error Execution exception: not-found: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)
  2010-05-25 16:56:44 notice Shut down


  Above can be read as broker shutdown itself after couple of exceptions:
    error Execution exception: not-found: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)


b] client ran against broker --log-enable debug+
Mostly fail with another observations, there are runs which pass.
The failure observation:

  --- python ./bz461816.py log ---
  1 of 100
  2 of 100
  3 of 100
  4 of 100
  5 of 100
  6 of 100
  7 of 100
  8 of 100
  9 of 100
  10 of 100
  11 of 100
  12 of 100
  13 of 100
  14 of 100
  15 of 100
  16 of 100
  17 of 100
  18 of 100
  19 of 100
  20 of 100
  21 of 100
  22 of 100
  23 of 100
  24 of 100
  25 of 100
  26 of 100
  27 of 100
  28 of 100
  29 of 100
  30 of 100
  31 of 100
  32 of 100
  33 of 100
  34 of 100
  35 of 100
  36 of 100
  37 of 100
  38 of 100
  Traceback (most recent call last):
    File "./bz461816.py", line 97, in ?
      receiver.process(10)
    File "./bz461816.py", line 71, in process
      self.session = self.connection.session(str(uuid4()))
    File "/usr/lib/python2.4/site-packages/qpid/connection.py", line 124, in session
      ssn.channel.session_attach(name)
    File "/usr/lib/python2.4/site-packages/qpid/generator.py", line 25, in <lambda>
      method = lambda self, *args, **kwargs: self.invoke(op, args, kwargs)
    File "/usr/lib/python2.4/site-packages/qpid/connection.py", line 228, in invoke
      self.connection.write_op(ctl)
    File "/usr/lib/python2.4/site-packages/qpid/connection.py", line 199, in write_op
      self.flush()
    File "/usr/lib/python2.4/site-packages/qpid/framer.py", line 57, in flush
      self._write(cipher_buf)
    File "/usr/lib/python2.4/site-packages/qpid/framer.py", line 68, in _write
      n = self.sock.send(buf)
    File "/usr/lib64/python2.4/socket.py", line 144, in _dummy
      raise error(EBADF, 'Bad file descriptor')
  socket.error: (9, 'Bad file descriptor')
  --- qpidd log ---
  2010-05-25 17:12:41 info Loaded Module: /usr/lib64/qpid/daemon/replicating_listener.so
  2010-05-25 17:12:41 info Loaded Module: /usr/lib64/qpid/daemon/acl.so
  2010-05-25 17:12:41 info Loaded Module: /usr/lib64/qpid/daemon/msgstore.so
  2010-05-25 17:12:41 info Loaded Module: /usr/lib64/qpid/daemon/replication_exchange.so
  2010-05-25 17:12:41 info Loaded Module: /usr/lib64/qpid/daemon/watchdog.so
  2010-05-25 17:12:41 info Loaded Module: /usr/lib64/qpid/daemon/ssl.so
  2010-05-25 17:12:41 info Loaded Module: /usr/lib64/qpid/daemon/xml.so
  2010-05-25 17:12:41 info Loaded Module: /usr/lib64/qpid/daemon/cluster.so
  2010-05-25 17:12:41 info No message store configured, persistence is disabled.
  2010-05-25 17:12:41 info Management enabled
  2010-05-25 17:12:41 info ManagementAgent generated broker ID: 0ef8a863-05a1-4ae4-9514-8e5b890dadf4
  2010-05-25 17:12:41 debug ManagementAgent boot sequence: 1
  2010-05-25 17:12:41 debug ManagementAgent added package org.apache.qpid.broker
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:system
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:broker
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:agent
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:vhost
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:queue
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:exchange
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:binding
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:subscription
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:connection
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:link
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:bridge
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:session
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:managementsetupstate
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:clientConnect
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:clientConnectFail
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:clientDisconnect
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:brokerLinkUp
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:brokerLinkDown
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:queueDeclare
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:queueDelete
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:exchangeDeclare
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:exchangeDelete
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:bind
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:unbind
  2010-05-25 17:12:41 debug ManagementAgent added class org.apache.qpid.broker:subscribe
  ...
  
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug Sufficient credit for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, have bytes: 4294967295 msgs: 4294967295, need 21 bytes
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug Sufficient credit for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, have bytes: 4294967295 msgs: 4294967295, need 21 bytes
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug Sufficient credit for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, have bytes: 4294967295 msgs: 4294967295, need 21 bytes
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug Sufficient credit for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, have bytes: 4294967295 msgs: 4294967295, need 21 bytes
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug Sufficient credit for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, have bytes: 4294967295 msgs: 4294967295, need 21 bytes
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug Sufficient credit for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, have bytes: 4294967295 msgs: 4294967295, need 21 bytes
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug Sufficient credit for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, have bytes: 4294967295 msgs: 4294967295, need 21 bytes
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug Sufficient credit for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, have bytes: 4294967295 msgs: 4294967295, need 22 bytes
  2010-05-25 17:12:56 debug Credit allocated for received on anonymous.216b81f1-77e4-6842-93a4-1c96883212cb, was  bytes: 4294967295 msgs: 4294967295 now bytes: 4294967295 msgs: 4294967295
  2010-05-25 17:12:56 debug No messages to dispatch on queue 'bz461816'
  2010-05-25 17:12:56 debug Exception constructed: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)
  2010-05-25 17:12:56 error Execution exception: not-found: Queue not found: i-don't-exist (qpid/broker/SessionAdapter.cpp:754)
  2010-05-25 17:12:56 debug DISCONNECTED [127.0.0.1:49176]
  2010-05-25 17:12:56 debug anonymous.216b81f1-77e4-6842-93a4-1c96883212cb: detached on broker.
  2010-05-25 17:12:56 debug DISCONNECTED [127.0.0.1:49175]
  2010-05-25 17:12:56 debug anonymous.495c0884-caaf-d847-9a07-370f6b58539a: detached on broker.
  2010-05-25 17:12:59 notice Shut down
  2010-05-25 17:12:59 debug Journal "TplStore": Destroyed
  
This behavior can confirm case a] with the difference that it triggers issue in the python client library.

c] client ran against broker --log-enable trace+
  I was not able to trigger the problem, so it seems that disk I/O logging operations prevent the issue.

This issue is observed on RHEL5 only, not observed on RHEL4.


Version-Release number of selected component (if applicable):
python-qpid-0.7.946106-1.el5
qpid-tests-0.7.946106-1.el5
qpid-tools-0.7.946106-4.el5
qpid-cpp-*0.7.946106-1.el5


How reproducible:
very rapidly (>80%)

Steps to Reproduce:
1. start broker
2. run against the broker linked python testing client
http://cvs.devel.redhat.com/cgi-bin/cvsweb.cgi/tests/distribution/MRG/Messaging/qpid_test_msg_trasfer_after_session_detach_bz461816/bz461816.py?rev=1.2
3. loop until you get broker stopped and python client exited
  
Actual results:
Client crashes, broker shutdowns after couple of iterations.

Expected results:
Client and broker should both exit cleanly (ecode == 0).

Additional info:
Comment 1 Gordon Sim 2010-05-28 15:44:29 UTC 
This is the result of problems in saslwrapper (see bug 569698) and is fixed by saslwrapper-0.1.934605-2.el5.
Comment 2 Frantisek Reznicek 2010-06-02 13:25:06 UTC 
The issue has been fixed, tested on RHEL 4.8 / 5.5 i386 / x86_64 on packages:

 qmf-0.7.946106-2.el5
 qmf-devel-0.7.946106-2.el5
 qpid-cpp-client-0.7.946106-2.el5
 qpid-cpp-client-devel-0.7.946106-2.el5
 qpid-cpp-client-devel-docs-0.7.946106-2.el5
 qpid-cpp-client-rdma-0.7.946106-2.el5
 qpid-cpp-client-ssl-0.7.946106-2.el5
 qpid-cpp-mrg-debuginfo-0.7.946106-2.el5
 qpid-cpp-server-0.7.946106-2.el5
 qpid-cpp-server-cluster-0.7.946106-2.el5
 qpid-cpp-server-devel-0.7.946106-2.el5
 qpid-cpp-server-rdma-0.7.946106-2.el5
 qpid-cpp-server-ssl-0.7.946106-2.el5
 qpid-cpp-server-store-0.7.946106-2.el5
 qpid-cpp-server-xml-0.7.946106-2.el5
 qpid-java-client-0.7.946106-3.el5
 qpid-java-common-0.7.946106-3.el5
 qpid-tests-0.7.946106-1.el5
 qpid-tools-0.7.946106-4.el5
 saslwrapper-0.1.934605-2.el5
 saslwrapper-devel-0.1.934605-2.el5

-> VERIFIED