idling but not moving messages

[deatharse]

So I'm attempting move from polling to idling and have some weird behavior that if I call enter_idle() at the end of my function and there are messages that match the rule those are moved when starting imapfilter but if a new one that matches comes in it is not moved when IDLE terminates only moving when the process is restarted. This happens on multiple IMAP servers and versions of imapfilter.

my config file:

MAILBOX = IMAP {
    server = '[REDACTED]',
    username = 'dummy@mydomain.com',
    password = mypass,
    port = 993,
    ssl = 'tls1.2'
}

function doIdle ()
    msg = MAILBOX['INBOX']:is_unseen()

    test = msg:contain_subject('test')
    test:move_messages(MAILBOX['INBOX/Test'])

    status = MAILBOX.INBOX:enter_idle()
end

while true do
    if not pcall(recover, 'doIdle') then
        doIdle()
    end 
end

Here is the output from the command:

~$ imapfilter -v -c .imapfilter/test/online.lua -d .imapfilter/test/2.6.12-debug-received-whilst-idle.log
S (4): * OK [REDACTED]
C (4): 1000 NOOP
S (4): 1000 OK Success
C (4): 1001 CAPABILITY
S (4): 1001 OK CAPABILITY completed
C (4): 1002 LOGIN "dummy@mydomain.com" *
S (4): 1002 OK Success
C (4): 1003 CAPABILITY
S (4): 1003 OK CAPABILITY completed
C (4): 1004 SELECT "INBOX"
S (4): 1004 OK [READ-WRITE] SELECT completed
C (4): 1005 UID SEARCH ALL UNSEEN
S (4): 1005 OK Success
C (4): 1006 UID SEARCH UID 1:3,15 SUBJECT "test"
S (4): 1006 OK Success
C (4): 1007 UID COPY 15 "INBOX/Test"
S (4): 1007 OK Success
C (4): 1008 UID STORE 15 +FLAGS.SILENT (\Deleted)
S (4): 1008 OK Success
C (4): 1009 EXPUNGE
S (4): 1009 OK Success
1 messages moved from dummy@mydomain.com@[REDACTED]/INBOX to dummy@mydomain.com@[REDACTED]/INBOX/Test.
C (4): 100A IDLE
S (4): * 4 EXISTS
S (4): 100A OK IDLE terminated
C (4): 100B UID SEARCH ALL UNSEEN
S (4): 100B OK Success
C (4): 100C UID SEARCH UID 1:3,16 SUBJECT "test"
S (4): 100C OK Success
C (4): 100D IDLE
^Cimapfilter: killed by signal 2

I have experienced this with both 2.6.12 and 2.8.1

The while loop is a little different to some examples:

while true do
    recover(doIdle)
end

due the normal loop not working on 2.6.12 with this server however the behaviour persists with the normal loop on 2.8.1

2.6.12-debug-received-whilst-idle.log

[deatharse]

Upon further testing this looks like some form of off-by-one behaviour:

~$ imapfilter -vc .imapfilter/test/online.lua
S (3): * OK [REDACTED]
C (3): 1000 CAPABILITY
S (3): 1000 OK CAPABILITY completed
C (3): 1001 LOGIN "dummy@mydomain.com" *
S (3): 1001 OK Success
C (3): 1002 CAPABILITY
S (3): 1002 OK CAPABILITY completed
C (3): 1003 SELECT "INBOX"
S (3): 1003 OK [READ-WRITE] SELECT completed
C (3): 1004 UID SEARCH ALL UNSEEN
S (3): 1004 OK Success
C (3): 1005 UID SEARCH UID 1:3 SUBJECT "test"
S (3): 1005 OK Success
C (3): 1006 IDLE
S (3): * 4 EXISTS
S (3): 1006 OK IDLE terminated
C (3): 1007 UID SEARCH ALL UNSEEN
S (3): 1007 OK Success
C (3): 1008 UID SEARCH UID 1:3,21 SUBJECT "test"
S (3): 1008 OK Success
C (3): 1009 IDLE
S (3): * 5 EXISTS
S (3): 1009 OK IDLE terminated
C (3): 100A UID SEARCH ALL UNSEEN
S (3): 100A OK Success
C (3): 100B UID SEARCH UID 1:3,21:22 SUBJECT "test"
S (3): 100B OK Success
C (3): 100C UID COPY 21 "INBOX/Test"
S (3): 100C OK Success
C (3): 100D UID STORE 21 +FLAGS.SILENT (\Deleted)
S (3): 100D OK Success
C (3): 100E EXPUNGE
S (3): 100E OK Success
1 messages moved from dummy@mydomain.com@[REDACTED]/INBOX to ddummy@mydomain.com@[REDACTED]/INBOX/Test.
C (3): 100F IDLE
S (3): * 5 EXISTS
S (3): 100F OK IDLE terminated
C (3): 1010 UID SEARCH ALL UNSEEN
S (3): 1010 OK Success
C (3): 1011 UID SEARCH UID 1:3,22:23 SUBJECT "test"
S (3): 1011 OK Success
C (3): 1012 UID COPY 22:23 "INBOX/Test"
S (3): 1012 OK Success
C (3): 1013 UID STORE 22:23 +FLAGS.SILENT (\Deleted)
S (3): 1013 OK Success
C (3): 1014 EXPUNGE
S (3): 1014 OK Success
2 messages moved from dummy@mydomain.com@[REDACTED]/INBOX to dummy@mydomain.com@[REDACTED]/INBOX/Test.
C (3): 1015 IDLE
S (3): * 4 EXISTS
S (3): 1015 OK IDLE terminated
C (3): 1016 UID SEARCH ALL UNSEEN
S (3): 1016 OK Success
C (3): 1017 UID SEARCH UID 1:3,24 SUBJECT "test"
S (3): 1017 OK Success
C (3): 1018 IDLE
S (3): * 5 EXISTS
S (3): 1018 OK IDLE terminated
C (3): 1019 UID SEARCH ALL UNSEEN
S (3): 1019 OK Success
C (3): 101A UID SEARCH UID 1:3,24:25 SUBJECT "test"
S (3): 101A OK Success
C (3): 101B IDLE
S (3): * 6 EXISTS
S (3): 101B OK IDLE terminated
C (3): 101C UID SEARCH ALL UNSEEN
S (3): 101C OK Success
C (3): 101D UID SEARCH UID 1:3,24:26 SUBJECT "test"
S (3): 101D OK Success
C (3): 101E UID COPY 24:25 "INBOX/Test"
S (3): 101E OK Success
C (3): 101F UID STORE 24:25 +FLAGS.SILENT (\Deleted)
S (3): 101F OK Success
C (3): 1020 EXPUNGE
S (3): 1020 OK Success
2 messages moved from dummy@mydomain.com@[REDACTED]/INBOX to dummy@mydomain.com@[REDACTED]/INBOX/Test.
C (3): 1021 IDLE
imapfilter: reading data through SSL; Connection reset by peer
S (3): * OK [REDACTED]
C (3): 1022 CAPABILITY
S (3): 1022 OK CAPABILITY completed
C (3): 1023 LOGIN "dummy@mydomain.com" *
S (3): 1023 OK Success
C (3): 1024 CAPABILITY
S (3): 1024 OK CAPABILITY completed
C (3): 1025 SELECT "INBOX"
S (3): 1025 OK [READ-WRITE] SELECT completed
C (3): 1026 IDLE
^C
~$ imapfilter -vc .imapfilter/test/online.lua
S (3): * OK [REDACTED]
C (3): 1000 CAPABILITY
S (3): 1000 OK CAPABILITY completed
C (3): 1001 LOGIN "dummy@mydomain.com" *
S (3): 1001 OK Success
C (3): 1002 CAPABILITY
S (3): 1002 OK CAPABILITY completed
C (3): 1003 SELECT "INBOX"
S (3): 1003 OK [READ-WRITE] SELECT completed
C (3): 1004 UID SEARCH ALL UNSEEN
S (3): 1004 OK Success
C (3): 1005 UID SEARCH UID 1:3,26 SUBJECT "test"
S (3): 1005 OK Success
C (3): 1006 UID COPY 26 "INBOX/Test"
S (3): 1006 OK Success
C (3): 1007 UID STORE 26 +FLAGS.SILENT (\Deleted)
S (3): 1007 OK Success
C (3): 1008 EXPUNGE
S (3): 1008 OK Success
1 messages moved from dummy@mydomain.com@[REDACTED]/INBOX to dummy@mydomain.com@[REDACTED]/INBOX/Test.
C (3): 1009 IDLE
^C

As there's times it picks up a mail coming in and does nothing with it until another comes in and then it may move both or only move the first one.

[lefcha]

I think the verbose output doesn't give us enough info as it only lists the command and the tagged result (ie. OK, or BAD or NO). So it hides the messages that matched the SEARCH command.

So for example in the debug log you provided, it's obvious that the 1st SEARCH returned a few messages, but the 2nd didn't return any:

sending command (4):

100B UID SEARCH ALL UNSEEN

getting response (4):

* SEARCH 1 2 3 16
100B OK Success

sending command (4):

100C UID SEARCH UID 1:3,16 SUBJECT "test"

getting response (4):

* SEARCH 
100C OK Success

For this reason there was nothing to do and it went back to IDLE.

Do you have a debug log from an execution that you did right after SEARCH returned nothing, where moving took place?

It would be useful to always run imapfilter with something like -d debug-$(date +%FT%T%Z).log to get a debug in a separate file.