Lost server status update in IdleCommand response

[dirkmb]

Hi, I use the idle command to get notified for new messages. I restart the idle command every x minutes. When there is server status update after the 'DONE' is send, it is appended to the response to the 'IDLE' command.

[aioimaplib.py:289 data_received] Received : b'+ idling\r\n 418 FETCH (FLAGS ())\r\n 420 FETCH (FLAGS (\Seen))\r\n 421 FETCH (FLAGS (\Seen))\r\n 451 FETCH (FLAGS ())\r\n'

All these lines are added to the IdleCommand buffer and the answer is consumed from die aioimaplib somewhere. The changed Flags are beeing lost.

Here is a Solution: We should change line 220 from self.queue.put_nowait(copy(self.buffer)) to for item in self.buffer: self.queue.put_nowait(copy(item))

so each item from the buffer (e.g. each line of the response) is added individually to queue.

Because I'm not so familiar with the code I'm not sure if this change breaks something. Can someone please comment on this?

Thanks!

[bamthomas]

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.

[bamthomas]

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 https://github.com/bamthomas/aioimaplib/blob/fae66fd4a476d30da32386e9126af104d909e47f/aioimaplib/aioimaplib.py#L217

So you should have a response with the whole list in it like the unit test shows here : https://github.com/bamthomas/aioimaplib/blob/fae66fd4a476d30da32386e9126af104d909e47f/aioimaplib/tests/test_aioimaplib.py#L471

And here : https://github.com/bamthomas/aioimaplib/blob/fae66fd4a476d30da32386e9126af104d909e47f/aioimaplib/tests/test_aioimaplib.py#L494

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 ?

[bamthomas]

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)

[dirkmb]

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)

[dirkmb]

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.

[bamthomas]

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

[dirkmb]

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

[bamthomas]

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

[dirkmb]

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

[bamthomas]

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.

[bamthomas]

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.

[bamthomas]

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)

[dirkmb]

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.

[bamthomas]

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

[dirkmb]

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.

[bamthomas]

tell me if 37fa64e fixes your issue

[dirkmb]

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