Lost server status update in IdleCommand response about aioimaplib HOT 17 CLOSED

hello @dirkmb thanks for the bug report, the analysis and the push. Sorry being late, I was on holiday until yesterday.

The CI says that yes it break things.
I look after what's going on.

from aioimaplib.

Ok, I understand what you are asking, but I don't understand why.

the server responses should not being lost because they are appended to the buffer in line

So you should have a response with the whole list in it like the unit test shows here :

And here :

I don't understand when you say :

When there is server status update after the 'DONE' is sent it is appended to the response to the 'IDLE'

It shouldn't because when DONE is sent, you are exiting the IDLE command so the server should not send status update.

Could you show how you are doing your idle loop ?

from aioimaplib.

To give some context :
we did this to avoid the exit of the idle loop when a server sends multiple lines in one data frame. This allows the idle loop to be easier to write (without adding conditionals branches).

Cf the b521786 commit that provides the ability to write loop like this:

while True:
      idle = yield from imap_client.idle_start(timeout=60)
      do_things_with_server_status((yield from imap_client.wait_server_push()))

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

from aioimaplib.

i use following loop (based on the first example of the readme)

idle = await self.imap_client.idle_start(timeout=10)
while self.imap_client.has_pending_idle():
        msg = await self.imap_client.wait_server_push()
        self.logger.debug('--> received from server: %s (%s)', msg, type(msg))
        if isinstance(msg, str) and msg.upper() == 'STOP_WAIT_SERVER_PUSH':
                self.imap_client.idle_done()
                break;
        # do sth. with the msg status update(s)
        await asyncio.wait_for(idle, 10)
        t = idle.result()

the problem here is when a server status change occures after one of the two last lines. before the next idle command is send to the server. then the server appends the server status update to the answer

[aioimaplib.py:350 send] Sending : b'KBFH4 IDLE\r\n' [aioimaplib.py:287 data_received] Received : b'+ idling\r\n* 413 FETCH (FLAGS ())\r\n* 420 FETCH (FLAGS ())\r\n' [aioimaplib.py:601 _continuation] continuation line appended to pending sync command KBFH4 IDLE : + idling
these FETCH flags are stored in the buffer. the whole answer is added to the queue, but when I call wait_server_push this first output of the server is never retrieved.
I have not found where this first item of the queue is consumed. but when I print the qsize before the wait_server_push it shows 0 in this case.

I think the reason why my change breaks things is that wait_server_push now always returns strings and not a list. Btw. why is 'STOP_WAIT_SERVER_PUSH' not a list in the queue? (thats the reason why i assumed that the type does not matter and could be string for other messages as well)

from aioimaplib.

I don't understand when you say :

When there is server status update after the 'DONE' is sent it is appended to the response to the 'IDLE'

It shouldn't because when DONE is sent, you are exiting the IDLE command so the server should not send status update.

The server does not send status updates to the client directly, but it'll attach these status updates to the next answer he sends out.
The stackoverflow answer which started my debugging:
https://stackoverflow.com/questions/2513194/imap-idle-timeout?answertab=votes#tab-top

And the rfc3501 for that:
https://tools.ietf.org/html/rfc3501#section-5.2

In the particular case I'm talking about, the next message after the 'DONE' ist the restart of the IDLE loop and the 'IDLE' message. So all status updates are added to the response of this IDLE message. But this message is consumed somewhere in the aioimaplib (or I did not found the function/return value where this data can be retrieved) the idle.result() does not include those messages. This response is e.g.
'GMDM59 OK Idle completed (10.012 + 10.012 + 10.011 secs).' Not the answer to the starting 'IDLE' command send to the server.

from aioimaplib.

I think I understand. The use case may be the continuation line sent in the same data frame as the server status lines.

from aioimaplib.

if continuation line means the next start of the idle command, yes.

from aioimaplib.

continuation line means a line starting with '+' like : https://tools.ietf.org/html/rfc3501#page-79

from aioimaplib.

yes than you're right. the status update is send in the same frame as the continuation.

from aioimaplib.

No I don't get it, I wrote this test :

class TestBlah(unittest.TestCase):
    def setUp(self):
        self.imap_protocol = IMAP4ClientProtocol(None)

    def test_when_idle_continuation_line_in_same_dataframe_as_status_update(self):
        queue = asyncio.Queue()
        cmd = IdleCommand('TAG', queue)
        self.imap_protocol.pending_sync_command = cmd
        self.imap_protocol.data_received(b'+ idling\r\n* 1 EXISTS\r\n* 1 RECENT\r\n')

        self.assertEqual(['+ idling', '1 EXISTS', '1 RECENT'], queue.get_nowait())

And it passes.

from aioimaplib.

Ok I think I understand. Your loop is not the same as the readme. When you call break then your loop is not ending, you are never reading the result of the idle command. You should not call break (and it is generally a bad smell when you have to break a loop : the loop condition should be enough).

Maybe you are mentioning the old readme loop, it has changed since then.

from aioimaplib.

Try this loop :

while True:
      idle = yield from imap_client.idle_start(timeout=60)
      server_status_lines = yield from imap_client.wait_server_push()
      imap_client.idle_done()
      yield from asyncio.wait_for(idle, 30)
      do_something_with(server_status_lines)

from aioimaplib.

I used your code. after the select of the mailbox and before the while True I modified the server state. This is the log output:

[aioimaplib.py:350 send] Sending : b'NDMO3 IDLE\r\n'
[aioimaplib.py:287 data_received] Received : b'+ idling\r\n* 410 FETCH (FLAGS ())\r\n'
[aioimaplib.py:602 _continuation] continuation line appended to pending sync command NDMO3 IDLE : + idling

after that the function wait_server_push does NOT return. because the queue is empty.
I never geht the + idling answer when i do wait_server_push.
I just found the reason for that. In idle_start in line 701 the library does
yield from self.wait_server_push(self.timeout) # idling continuation and does consume the item I need to handle. And the return value of this is just discarded.

from aioimaplib.

I see.
Maybe the solution is to flush when there is an IDLE command continuation.
I'm going to look after this.
Thank you.

from aioimaplib.

flush after the continuation is a good idea. then there would me more than one item in the queue (similar the my supposed fix) and it would be retrieved using the wait_server_push command.

from aioimaplib.

tell me if 37fa64e fixes your issue

from aioimaplib.

yeah your commit fixes this issue.
Thanks a lot for the quick fix!

from aioimaplib.