['+ idling from'] from imap_client.wait_server_push() #30

vert-rouge · 2018-01-18T14:38:23Z

Hi

In a coroutine, I have

imap_client = aioimaplib.IMAP4_SSL(host=host, timeout=30)
yield from imap_client.wait_hello_from_server()

   yield from imap_client.login(user, password)
   yield from imap_client.select()

   while True:
      #print((yield from imap_client.uid('fetch', '1:*', 'FLAGS')))

      idle = yield from imap_client.idle_start(timeout=6)
      print((yield from imap_client.wait_server_push()))

      imap_client.idle_done()
      yield from asyncio.wait_for(idle, 30)

sometimes I got the following debug:

[…]
2018-01-18 14:23:15,478 DEBUG [aioimaplib:360] Sending : b'DONE\r\n'
2018-01-18 14:23:15,514 DEBUG [aioimaplib:295] Received : b'GJDH3 OK Idle completed.\r\n'
2018-01-18 14:23:15,514 DEBUG [aioimaplib:581] tagged status GJDH3 OK Idle completed.
2018-01-18 14:23:15,514 DEBUG [aioimaplib:360] Sending : b'GJDH4 IDLE\r\n'
2018-01-18 14:23:15,550 DEBUG [aioimaplib:295] Received : b'+ idling\r\n'
2018-01-18 14:23:15,550 DEBUG [aioimaplib:610] continuation line appended to pending sync command GJDH4 IDLE : + idling
stop_wait_server_push
2018-01-18 14:23:21,515 DEBUG [aioimaplib:360] Sending : b'DONE\r\n'
2018-01-18 14:23:21,641 DEBUG [aioimaplib:295] Received : b'* 493 EXISTS\r\n* 1 RECENT\r\n'
2018-01-18 14:23:21,674 DEBUG [aioimaplib:295] Received : b'GJDH4 OK Idle completed.\r\n'
2018-01-18 14:23:21,675 DEBUG [aioimaplib:581] tagged status GJDH4 OK Idle completed.
2018-01-18 14:23:21,675 DEBUG [aioimaplib:360] Sending : b'GJDH5 IDLE\r\n'
2018-01-18 14:23:21,710 DEBUG [aioimaplib:295] Received : b'+ idling\r\n'
2018-01-18 14:23:21,711 DEBUG [aioimaplib:610] continuation line appended to pending sync command GJDH5 IDLE : + idling
['+ idling']
2018-01-18 14:23:21,711 DEBUG [aioimaplib:360] Sending : b'DONE\r\n'
2018-01-18 14:23:21,746 DEBUG [aioimaplib:295] Received : b'GJDH5 OK Idle completed.\r\n'
2018-01-18 14:23:21,747 DEBUG [aioimaplib:581] tagged status GJDH5 OK Idle completed.
2018-01-18 14:23:21,747 DEBUG [aioimaplib:360] Sending : b'GJDH6 IDLE\r\n'
2018-01-18 14:23:21,783 DEBUG [aioimaplib:295] Received : b'+ idling\r\n'
2018-01-18 14:23:21,783 DEBUG [aioimaplib:610] continuation line appended to pending sync command GJDH6 IDLE : + idling
stop_wait_server_push
[…]

I don’t understand why I have this line ['+ idling']

I’m using dovecot as the imap server.

The text was updated successfully, but these errors were encountered:

bamthomas · 2018-01-19T10:12:48Z

this is the continuation (starting with +) sent by the server after the IDLE command. That just means that the client will wait events from the server.

vert-rouge · 2018-01-19T10:34:30Z

I understand that.
My concern is that I was expecting imap_client.wait_server_push() to answer [b'493 EXISTS', b'1 RECENT'] or something like that.
And I don’t get this message.

I don’t really understand why should I receive ['+ idling'] stop_wait_server_push seems good.

bamthomas · 2018-01-19T12:20:49Z

It seems that stop_wait_server_push has been done just before receiving 493 EXISTS\r\n* 1 RECENT thus probably closing the Queue. So maybe the problem is that the Queue should be kept until DONE ack is received. I must look at the code, I can't right now.

It is not easy to throw away +idling as it is different from different IMAP servers. It would adds an if with lots of different responses.

vert-rouge · 2018-01-19T12:30:47Z

Thank you.

In the log, when there is stop_wait_server_push, It comes from the print and there is a received message : b"+ idling"
I see a similar below but the result is different.

Let me know if I can help.

bamthomas · 2018-02-22T08:22:46Z

Hey @vert-rouge (hope you are fine BTW I did not recognized your avatar on my phone). I suspect a race condition between the new message received at 14:23:21,641 and the IDLE DONE. Just looked the code, it seems that it comes from the self.pending_sync_command.flush() here : https://github.com/bamthomas/aioimaplib/blob/master/aioimaplib/aioimaplib.py#L629

But I don't know why at 14:23:15,550 or in other cases it does not happen. I'll take a closer look. Sorry for the delay..

Use an event to wait/signal that the IDLE command has been acknowledged by receipt of a continuation line from the server, avoiding the idle_queue. When starting idle mode (idle_start), it isn't safe to assume that the results of reading from the idle queue is a continuation line, as the queue may have other content, such as: - an unsolicited server keepalive that just happens to arrive while the IDLE command is starting - an EXISTS from a previous IDLE loop (see bamthomas#30) - a 'stop_wait_server_push' from a previous IDLE loop, if the idle timeout coincided with receipt of a message from the server. Calling code should probably be draining the queue before initiating a new loop, but that wouldn't prevent an unsolicited server keepalive from racing. Fixes bamthomas#30

Use an event to wait/signal that the IDLE command has been acknowledged by receipt of a continuation line from the server, avoiding the idle_queue. When starting idle mode (idle_start), it isn't safe to assume that the results of reading from the idle queue is a continuation line, as the queue may have other content, such as: - an unsolicited server message that just happens to arrive while the IDLE command is starting - an EXISTS from a previous IDLE loop (see bamthomas#30) - a 'stop_wait_server_push' from a previous IDLE loop, if the idle timeout coincided with receipt of a message from the server. Calling code should probably be draining the queue before initiating a new loop, but that wouldn't prevent an unsolicited server messages from racing. Fixes bamthomas#30

Use an event to wait/signal that the IDLE command has been acknowledged by receipt of a continuation line from the server, avoiding the idle_queue. When starting idle mode (idle_start), it isn't safe to assume that the results of reading from the idle queue is a continuation line, as the queue may have other content, such as: - an unsolicited server message that just happens to arrive while the IDLE command is starting - an EXISTS from a previous IDLE loop (see bamthomas#30) - a 'stop_wait_server_push' from a previous IDLE loop, if the idle timeout coincided with receipt of a message from the server. Calling code should probably be draining the queue before initiating a new loop, but that wouldn't prevent an unsolicited server message from racing. Fixes bamthomas#30

surajiyer · 2021-02-13T21:59:29Z

@darkrain42 any update on the fix for the race condition? I am facing the same issue when I checked out the DEBUG logs and it seems to be an important functional issue within the library.

surajiyer · 2021-02-13T22:47:47Z

One workaround I used:

while not self.should_exit:
    # start IDLE waiting
    # idle queue must be empty, otherwise we get race
    # conditions between idle command status update
    # and unsolicited server messages
    if (
        (not self.imap_client.has_pending_idle())
        and self.imap_client.protocol.idle_queue.empty()
    ):
        logging.debug("Start IDLE waiting")
        idle = await self.imap_client.idle_start()
    
    try:
        # wait for status update
        msg = await self.imap_client.wait_server_push()
        logging.debug(f"Received IDLE message: {msg}")
    
        # send IDLE done to server; this has to happen
        # before search or fetch or any other command
        # for some reason.
        # https://tools.ietf.org/html/rfc2177
        if self.imap_client.has_pending_idle():
            logging.debug("Send IDLE done")
            self.imap_client.idle_done()
            await asyncio.wait_for(idle, 10)
    except concurrent.futures.TimeoutError:
        ...

    # do something with the msg
    ...

So check if the idle_queue is empty before restarting the idle waiting, else handle the messages in the queue until empty.

darkrain42 · 2021-02-16T00:28:23Z

@darkrain42 any update on the fix for the race condition?

I'm pretty happy with the fix I coded. I can't test it currently, because aioimaplib fails more fundamentally for me (Debian sid has python 3.9), and I was waiting for #52 to be merged, to then rebase on top of that.

I think your workaround is valid.

bamthomas · 2021-04-09T17:48:56Z

hello @darkrain42 thanks for your feedback, I've looked at the code you made and the test is great.
As explained I won't merge PR #52 as it is now (lot of broken tests plus untested/duplication).

I'd rather merge your code first, could do a PR with what you did ?
Thanks

bamthomas mentioned this issue Feb 27, 2018

Test failure on aarch64 #32

Closed

darkrain42 mentioned this issue Apr 10, 2021

avoid race when entering/leaving idle mode #60

Merged

bamthomas closed this as completed in #60 Apr 10, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

['+ idling from'] from imap_client.wait_server_push() #30

['+ idling from'] from imap_client.wait_server_push() #30

vert-rouge commented Jan 18, 2018 •

edited

Loading

bamthomas commented Jan 19, 2018 •

edited

Loading

vert-rouge commented Jan 19, 2018

bamthomas commented Jan 19, 2018

vert-rouge commented Jan 19, 2018

bamthomas commented Feb 22, 2018

surajiyer commented Feb 13, 2021

surajiyer commented Feb 13, 2021

darkrain42 commented Feb 16, 2021

bamthomas commented Apr 9, 2021

['+ idling from'] from imap_client.wait_server_push() #30

['+ idling from'] from imap_client.wait_server_push() #30

Comments

vert-rouge commented Jan 18, 2018 • edited Loading

bamthomas commented Jan 19, 2018 • edited Loading

vert-rouge commented Jan 19, 2018

bamthomas commented Jan 19, 2018

vert-rouge commented Jan 19, 2018

bamthomas commented Feb 22, 2018

surajiyer commented Feb 13, 2021

surajiyer commented Feb 13, 2021

darkrain42 commented Feb 16, 2021

bamthomas commented Apr 9, 2021

vert-rouge commented Jan 18, 2018 •

edited

Loading

bamthomas commented Jan 19, 2018 •

edited

Loading