Bug 756795

Created attachment 535958 [details]
python test reproduce

Created attachment 535962 [details]
cpp test reproducer (does the same as the python one)

Created attachment 535965 [details]
broker log file (snip)

I'm a bit confused also with another test case:

If also third cmdline argument is given to the test reproducer, a new sender on another session is used to fill the "q2" with messages and timeout of receiver fetch() method is set to non-zero value.

In my opinion it shall be the same case as without this new sender, sender on one session shall not affect the unsettled messages on another session. So I would expected the number of unsettled messages to be 1 in each loop, because the receiver fetch() method was called. 

If session.acknowledge is used after the receiver fetch() method or fetch method uses timeout of 0, the result is as I would expect. (probably I do not correctly understand to the difference between session.acknowledge and session.completed methods)

moreover C++ client is giving different result than python client (I assume because it's faster? the output is always the same in my configuration).

Python:

# qpid_reboot; ./session.py 5 1 1
Stopping Qpid AMQP daemon:                                 [  OK  ]
Starting Qpid AMQP daemon:                                 [  OK  ]
sender capacity: 5
sending: Message 1
unsettled sender messages count: 1
sending: Message 2
unsettled sender messages count: 2
sending: Message 3
unsettled sender messages count: 3
sending: Message 4
unsettled sender messages count: 1
sending: Message 5
unsettled sender messages count: 2
sending: Message 6
unsettled sender messages count: 3
sending: Message 7
unsettled sender messages count: 1
sending: Message 8
unsettled sender messages count: 2
sending: Message 9
unsettled sender messages count: 3
sending: Message 10
unsettled sender messages count: 1

C++:

# qpid_reboot; ./session.out 5 1 1
Stopping Qpid AMQP daemon:                                 [  OK  ]
Starting Qpid AMQP daemon:                                 [  OK  ]
sender capacity: 5
sending: Message 1
unsettled sender messages count: 1
sending: Message 2
unsettled sender messages count: 1
sending: Message 3
unsettled sender messages count: 2
sending: Message 4
unsettled sender messages count: 3
sending: Message 5
unsettled sender messages count: 2
sending: Message 6
unsettled sender messages count: 3
sending: Message 7
unsettled sender messages count: 2
sending: Message 8
unsettled sender messages count: 3
sending: Message 9
unsettled sender messages count: 2
sending: Message 10
unsettled sender messages count: 3

Ken, is there any unexpected behavior here?

(In reply to comment #4)
> I'm a bit confused also with another test case:
> 
> If also third cmdline argument is given to the test reproducer, a new sender on
> another session is used to fill the "q2" with messages and timeout of receiver
> fetch() method is set to non-zero value.
> 
> In my opinion it shall be the same case as without this new sender, sender on
> one session shall not affect the unsettled messages on another session. So I
> would expected the number of unsettled messages to be 1 in each loop, because
> the receiver fetch() method was called. 
> 

The difference you are seeing is due to the fetch actually returning a message in this case.  This causes the broker to perform an additional message.transfer command, before replenishing the session's credit.  So, depending on the timing of the calls, you're more likely to see the credit value change in this case.

This seems well within my understanding of the design, since credit is being replenished correctly, just at a different pace.

> If session.acknowledge is used after the receiver fetch() method or fetch
> method uses timeout of 0, the result is as I would expect. (probably I do not
> correctly understand to the difference between session.acknowledge and
> session.completed methods)
> 
> moreover C++ client is giving different result than python client (I assume
> because it's faster? the output is always the same in my configuration).
> 
> Python:
> 
> # qpid_reboot; ./session.py 5 1 1
> Stopping Qpid AMQP daemon:                                 [  OK  ]
> Starting Qpid AMQP daemon:                                 [  OK  ]
> sender capacity: 5
> sending: Message 1
> unsettled sender messages count: 1
> sending: Message 2
> unsettled sender messages count: 2
> sending: Message 3
> unsettled sender messages count: 3
> sending: Message 4
> unsettled sender messages count: 1
> sending: Message 5
> unsettled sender messages count: 2
> sending: Message 6
> unsettled sender messages count: 3
> sending: Message 7
> unsettled sender messages count: 1
> sending: Message 8
> unsettled sender messages count: 2
> sending: Message 9
> unsettled sender messages count: 3
> sending: Message 10
> unsettled sender messages count: 1
> 
> C++:
> 
> # qpid_reboot; ./session.out 5 1 1
> Stopping Qpid AMQP daemon:                                 [  OK  ]
> Starting Qpid AMQP daemon:                                 [  OK  ]
> sender capacity: 5
> sending: Message 1
> unsettled sender messages count: 1
> sending: Message 2
> unsettled sender messages count: 1
> sending: Message 3
> unsettled sender messages count: 2
> sending: Message 4
> unsettled sender messages count: 3
> sending: Message 5
> unsettled sender messages count: 2
> sending: Message 6
> unsettled sender messages count: 3
> sending: Message 7
> unsettled sender messages count: 2
> sending: Message 8
> unsettled sender messages count: 3
> sending: Message 9
> unsettled sender messages count: 2
> sending: Message 10
> unsettled sender messages count: 3

First of all, I precede that I'm not saying that the behaviour is wrong, I just don't understand it well and I am trying to catch the point. 

In my opinion this issue is not affected by the session's credit, the log shows sufficient credit in each loop, I have also tried to set the limit on the sender and the consumer to some big value (say 1000) and the results are not affected by this. The numbers in the output of the test reproducer are not related to credit but to messages not acked by the broker (the usage of sender capacity - unsettled messages).

In my opinion it is also not related to the message.transfer command because if you put the sender and the consumer on different sessions same behaviour as reported in Comment 4 can be seen regardless if the message.transfer command was issued or not (regardless the queue from which the consumer is consuming messages is empty or not).  This is similar to the  original issue reported - different behaviour of client sharing one session vs. behaviour of clients on different session. When consuming from empty queue using one session for both sender and receiver the sent messages are acked by the broker in each loop, when the clients are on different sessions the sent messages are not acked by the broker in each loop. So the session.completed command is not invoked after every fetch() method, as you've mentioned in our previous conversation. 

The question here is how the acks shall be sent by the broker (when the session.complete command shall be triggered)? Can they arrive at any time? or they shall be acked after the full sender capacity was reached?

What I see here, the behaviour on different sessions is that the sent messages are acked by the broker at next message after the border of 50% capacity was reached. It can be seen by changing the value of first argument of the test reproducer.

In any case, the behaviour is that all the messages are correctly delivered, the sent messages are acked in the range of sender capacity which is correct as well, so maybe only the difference in acking between clients sharing one session and clients on different session shall be pointed out in our programming guide so users are aware of it. The behaviour is independent on the sender/consumer address. (acts the same  regardless the clients are using the same address or not).

I am also wondering about the session acknowledge() behaviour, if performed after the send method call in loop, the messages are not acked in acknowlegde method (with session sync() they naturally do). The messages are always acked during send method call after the capacity is reached. It can be demonstrated using the following code:

  for i in range(msg_cnt):
    sender.send(Message("Message %s" % (i+1)), sync=False)
    print "unsettled sender messages count: %s" % (sender.unsettled())
    session.acknowledge()
    print "unsettled sender messages count: %s" % (sender.unsettled())


Question summary:
1] When it is expected broker should send back the message acks? (assuming the sender is using asynchronous send operations and broker just confirms by ack that received from client the message)
2] Does the receiver.fetch() always trigger the session_complete() which triggers delivery of all pending send operation acks?
3] What happens when a client uses sender.send() interleaved with session.acknowledge() ?

Thanks in advance for clarification.

Created attachment 539206 [details]
test_reproducer shared/independent session

I am attaching a new test reproducer that shows the different behaviour on the shared/independent session more clearly.
example use: 
clients on shared session, sender capacity=5:
# ./session.py 5 1
clients on independent session, sender capacity=5:
# ./session.py 5 0