Bug 1285751 - [AMQP1.0] client wrongly logging "info delivery 0 was not accepted by peer" when using transactions
[AMQP1.0] client wrongly logging "info delivery 0 was not accepted by peer" w...
Status: NEW
Product: Red Hat Enterprise MRG
Classification: Red Hat
Component: qpid-cpp (Show other bugs)
3.2
All Linux
low Severity low
: ---
: ---
Assigned To: messaging-bugs
Messaging QE
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-11-26 06:44 EST by Pavel Moravec
Modified: 2015-11-26 06:57 EST (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Pavel Moravec 2015-11-26 06:44:02 EST
Description of problem:
When using transactions over AMQP1.0, the client library logs:

2015-11-26 09:48:50 [Messaging] info delivery 0 was not accepted by peer

several times. Despite every delivery was accepted.

Per my understanding, this log should not appear and is caused by a bug in qpid broker and missing constant in proton - see additional info.


Version-Release number of selected component (if applicable):
qpid-cpp-client-0.34-5.el6.x86_64
qpid-proton-c-0.10-2.el6.x86_64


How reproducible:
100%


Steps to Reproduce:
1. Have program sending one transaction over AMQP1.0:

int main(int argc, char** argv) {
    const char* url = "amqp:localhost:5672";
    std::string connectionOptions = "{ protocol: 'amqp1.0', tcp_nodelay: 'true' }";
    Address broadcast("testqueue; { node: { type: queue }, create: always }");

    Connection connection(url, connectionOptions);
    Session session;
    Sender sender;

     try {
        connection.open();
        session = connection.createTransactionalSession();

        std::cout << "Connection opened, session created" << std::endl;

        sender = session.createSender(broadcast);
        std::cout << "Sender created " << sender.getName() << std::endl;
        sender.setCapacity(1000);

        Message msg = Message("test message");
        msg.setDurable(true);
        sender.send(msg, false);

        session.commit();
        session.sync(true);

        sender.close();
        session.close();
        connection.close();
        return 0;
    } catch(const std::exception& error) {
    	std::cout << "Exception: " << error.what() << std::endl;
    	std::cout << "Closing the connection." << std::endl;
    	sender.close();
    	session.close();
    	connection.close();
        std::cout << "Connection closed" << std::endl;
    }
    return 1;
}

2. compile and run it with info logs enabled on client:

g++ -Wall BroadcastProducerTX-1.cpp -o BroadcastProducerTX-1 -lqpidclient -lqpidcommon -lqpidmessaging -lqpidtypes
export QPID_LOG_ENABLE="info+"
./BroadcastProducerTX-1 2>&1 | grep "was not accepted by peer"


Actual results:
2015-11-26 12:20:20 [Messaging] info delivery 0 was not accepted by peer
2015-11-26 12:20:20 [Messaging] info delivery 0 was not accepted by peer
2015-11-26 12:20:20 [Messaging] info delivery 2 was not accepted by peer


Expected results:
Emtpy output


Additional info:
gdb showed me:

2015-11-26 09:48:46 [Protocol] trace [1aa0d300-aeb5-4343-b5ac-3b3c55c4cbf6]: 0 <- @disposition(21) [role=true, first=0, last=0, settled=true, state=@declared(51) [txn-id=b"0x7f2e580048b0"]]
2015-11-26 09:48:46 [Network] debug tcp:10.34.84.251:5672 decoded 99 bytes from 99

Breakpoint 1, qpid::messaging::amqp::SenderContext::Delivery::delivered (this=0x639f80) at /usr/src/debug/qpid-cpp-0.34/src/qpid/messaging/amqp/SenderContext.cpp:546
546     {
(gdb) p *token
$3 = {local = {condition = {name = 0x63b6d0, description = 0x63b720, info = 0x63b770}, type = 0, data = 0x6263b0, annotations = 0x6265e0, section_offset = 0, section_number = 0,
    failed = false, undeliverable = false, settled = false}, remote = {condition = {name = 0x63bda0, description = 0x63bdf0, info = 0x63be40}, type = 51, data = 0x63b980,
    annotations = 0x63bb90, section_offset = 0, section_number = 0, failed = false, undeliverable = false, settled = true}, link = 0x637560, tag = 0x6268d0, unsettled_next = 0x0,
  unsettled_prev = 0x0, work_next = 0x0, work_prev = 0x0, tpwork_next = 0x0, tpwork_prev = 0x0, state = {id = 0, sent = true, init = true}, bytes = 0x626370, context = 0x63c050,
  updated = true, settled = false, work = true, tpwork = false, done = true, referenced = false}
(gdb) continue
Continuing.
2015-11-26 09:48:50 [Messaging] info delivery 0 was not accepted by peer

See token->remote.type = 51 (0x33), while it is compared to PN_ACCEPTED aka 0x24=36.

0x33 is mentioned in proton:
./proton-c/src/transactions.xml:      <descriptor name="amqp:declared:list" code="0x00000000:0x00000033"/>

and the disposition performative that broker "comments" really has "declared" list in disposition arguments. While for usual disposition, there is:

./proton-c/src/messaging.xml:      <descriptor name="amqp:accepted:list" code="0x00000000:0x00000024"/>


I.e. SenderContext::Delivery::delivered should update

        } else if (!accepted()) {

to e.g.:

        } else if (!accepted())&&(!transactDeclared())) {

(where transactDeclared returns:

pn_delivery_remote_state(token) == 0x33

(I am in favour of updating proton as well, to introduce there a constant like PN_TRANS_DECLARED (0x0000000000000033) )
Comment 1 Pavel Moravec 2015-11-26 06:56:49 EST
Btw. both warning and info logs in SenderContext::Delivery::delivered method should be enhanced to include e.g. sender information or connection information. The log entry "delivery 2 was not accepted by peer" without a context is useless.

Note You need to log in before you can comment on or make changes to this bug.