Uploaded image for project: 'Qpid Proton'
  1. Qpid Proton
  2. PROTON-2378

[Python] AMQP client with only sender gets stuck on select timing out

Agile BoardAttach filesAttach ScreenshotVotersWatch issueWatchersCreate sub-taskLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Invalid
    • proton-c-0.33.0
    • None
    • proton-c, python-binding
    • None

    Description

      Python version: 3.6.8

      Unfortunately not yet tested on proton-c-0.34.0 as the pypi release is still at 0.33.0.

       

      Situation:

      There is an AMQP receiver and an AMQP sender with only 1 link being used from the sender to the receiver. There is data sent every 1 second by the sender.

      In my testing of the proton library for Python I noticed that sending messages is sometimes delayed up to 3.14 seconds. It appears the code gets 'stuck' on the line

      readable, writable, expired = self._selector.select(r.timeout)

      at _handlers.py.IOHandler.on_reactor_quiesced (line 1210: https://github.com/apache/qpid-proton/blob/0.33.0/python/proton/_handlers.py#L1210 )

      The value of `r.timeout` always appears to be 3.14 which is set at line 718 _reactor.py.Reactor.run.

      self.timeout = 3.14159265359

       

      All-in-all this shows behavior where no new TCP data or AMQP frames are expected by the sender so the select waits and times out. However, there is new data to be sent by the Sender but this does not cause the select to terminate early. Therefore, the messages send by the sender are 'batched' in 3's before being send to the receiver.

       

      Attached is an AMQP receiver and sender meant as an minimal example to showcase the issue.

      The Sender logs the sent & accepted timestamps. We would expect a message to be send every 1 second and it should be accepted in milliseconds. Instead it can take up to 3.14 seconds to be accepted. An example log:

       

      
       Delivery 1 which was sent at 1619095634.3362126 was accepted at 1619095634.3540177 so it took 0.017805099487304688 seconds.
       Delivery 2 which was sent at 1619095635.3695796 was accepted at 1619095637.5099232 so it took 2.14034366607666 seconds.
       Delivery 3 which was sent at 1619095636.3740473 was accepted at 1619095637.5107296 so it took 1.1366822719573975 seconds.
       Delivery 4 which was sent at 1619095637.381199 was accepted at 1619095637.5114946 so it took 0.1302957534790039 seconds.
       Delivery 5 which was sent at 1619095638.383219 was accepted at 1619095640.671438 so it took 2.2882189750671387 seconds.
       Delivery 6 which was sent at 1619095639.384885 was accepted at 1619095640.6722338 so it took 1.287348747253418 seconds.
       Delivery 7 which was sent at 1619095640.3868084 was accepted at 1619095640.6729164 so it took 0.28610801696777344 seconds.
       Delivery 8 which was sent at 1619095641.3904433 was accepted at 1619095643.8257194 so it took 2.4352760314941406 seconds.
       Delivery 9 which was sent at 1619095642.3931684 was accepted at 1619095643.8264139 so it took 1.4332454204559326 seconds.
       Delivery 10 which was sent at 1619095643.3968666 was accepted at 1619095643.8271492 so it took 0.4302825927734375 seconds.
       Delivery 11 which was sent at 1619095644.4198678 was accepted at 1619095646.986702 so it took 2.5668342113494873 seconds.
       Delivery 12 which was sent at 1619095645.420819 was accepted at 1619095646.9876444 so it took 1.5668253898620605 seconds.
       Delivery 13 which was sent at 1619095646.421948 was accepted at 1619095646.988455 so it took 0.56650710105896 seconds.
       Delivery 14 which was sent at 1619095647.4390144 was accepted at 1619095650.140986 so it took 2.7019715309143066 seconds.
       Delivery 15 which was sent at 1619095648.4405417 was accepted at 1619095650.1420805 so it took 1.7015388011932373 seconds.
       Delivery 16 which was sent at 1619095649.4577622 was accepted at 1619095650.1430688 so it took 0.6853065490722656 seconds.
       Delivery 17 which was sent at 1619095650.5015457 was accepted at 1619095653.3227403 so it took 2.821194648742676 seconds.
       Delivery 18 which was sent at 1619095651.5050397 was accepted at 1619095653.3230667 so it took 1.8180270195007324 seconds.
       Delivery 19 which was sent at 1619095652.5123448 was accepted at 1619095653.3235378 so it took 0.8111929893493652 seconds.
       Delivery 20 which was sent at 1619095653.5286038 was accepted at 1619095656.4846065 so it took 2.956002712249756 seconds.
       Delivery 21 which was sent at 1619095654.5309548 was accepted at 1619095656.4857142 so it took 1.9547593593597412 seconds.

      Attachments

        Activity

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            Unassigned Unassigned
            Sebastiaan NS-SlaFleur
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Slack

                Issue deployment