Problems recovering failed connection when idling (ie. IMAP server restart)

[alexhk]

I apologize if this is long winded, I wanted to post this for years and it seems today is the day!

I have imapfilter running at a box that is local to the IMAP server and I am using a loop with idle.

I've been using it for a few years but it exits when the connection to the server gets interrupted (say mail server restart etc).

I tried the available options but I may have misunderstood something, since I am getting strange errors.

This is also with the latest version 2.7.5 from Github freshly built, so I don't think it's an old bug.

Ubuntu 18.04 Server
IMAPFilter 2.7.5  Copyright (c) 2001-2020 Eleftherios Chatzimparmpas

To illustrate, here my loop is running fine and I am intentionally shutting down the mail server for a few seconds before I start it up again.

Debug log:

1135 OK SEARCH completed

sending command (7):

1136 IDLE

getting response (7):

+ idling

recovering connection: imaps://alex@server.com@mail.servercom:993/INBOX
getting response (7):

* OK mail.server.com IMAP4rev1 ready

sending command (7):

1137 NOOP

recovering connection: imaps://alex@server.com@D:993/
recovering connection: imaps://alex@server.com@(null):D/
recovering connection: imaps://alex@server.com@(null):pa^E_�U/
recovering connection: imaps://alex@server.com@(null):050 /

These "special" characters are not a copy and paste error, that's what I have in the log. It also doens't seem a terminal issue, it's what I get in the log.

Error log:

Sat Jun 26 08:14:32 2021: reading data through SSL; the connection has been closed cleanly
Sat Jun 26 08:14:32 2021: unexpected network error for alex@server.com@mail.server.com
Sat Jun 26 08:14:34 2021: reading data through SSL; the connection has been closed cleanly
Sat Jun 26 08:15:34 2021: error while initiating connection to  at port p��^W>^?

At this point imapfilter exits.

I tried using the internal IP addresses instead of the mail server's domain names (mail.server.com) with options.hostnames = false but I get the same result.

These are my options and structure of the script:

---------------
--  Options  --
---------------

options.timeout = 60
options.subscribe = true
options.info = true
options.reenter = false
options.persist = true
options.wakeonany = true
options.charset = 'UTF-8'

----------------
--  Accounts  --
----------------

account1 = IMAP {
    server = 'mail.server.com',
    username = 'alex@server.com',
    password = string1,
    ssl = 'auto',
}

account2 = IMAP {
    server = 'mail.server.com',
    username = 'support@server.com',
    password = string2,
    ssl = 'auto',
}

------------------
--  Main Loop --
------------------

local i = 1              -- counting rounds

repeat

print("Starting loop " .. i .. ".")

dofile('imapfilter_rules.lua')

i = i + 1

print("Done processing this round, waiting for mail server to return from idle.")

account1.INBOX:enter_idle()

until not true

With options.reenter = true I get the following (imapfilter doesn't exit):

[...]
* SEARCH
1112 OK SEARCH completed

conversion: 'Postmaster' -> 'Postmaster'
sending command (7):

1113 SELECT "Postmaster"

recovering connection: imaps://alex@server.com@172.31.42.100:993/INBOX (using IP addresses this time)
getting response (7):

* OK mail.server.com IMAP4rev1 ready

sending command (7):

1114 NOOP

recovering connection: imaps://alex@server.com@69]:993/
recovering connection: imaps://alex@server.com@(null):69]/
recovering connection: imaps://alex@server.com@(null):pQ��JV/
recovering connection: imaps://alex@server.com@(null):/
recovering connection: imaps://alex@server.com@(null):/
recovering connection: imaps://alex@server.com@(null):/
recovering connection: imaps://alex@server.com@(null):/

Debug log:

Sat Jun 26 08:29:24 2021: reading data through SSL; the connection has been closed cleanly
Sat Jun 26 08:29:24 2021: unexpected network error for alex@server.com@172.31.42.100
Sat Jun 26 08:29:26 2021: reading data through SSL; the connection has been closed cleanly
Sat Jun 26 08:30:26 2021: gettaddrinfo; Temporary failure in name resolution
Sat Jun 26 08:31:26 2021: gettaddrinfo; Servname not supported for ai_socktype
Sat Jun 26 08:32:26 2021: gettaddrinfo; Servname not supported for ai_socktype
Sat Jun 26 08:33:26 2021: error while initiating connection to  at port
Sat Jun 26 08:34:26 2021: error while initiating connection to  at port
Sat Jun 26 08:35:26 2021: error while initiating connection to  at port
Sat Jun 26 08:36:26 2021: error while initiating connection to  at port

imapfilter won't exit this way, but continue like this.

Any idea what the problem could be and how I could get this sorted out ?

[acarrico]

Take a look at my configuration in the last comment of the following issue: https://github.com/lefcha/imapfilter/issues/211#

[lefcha]

This is a bug, and the incorrect recovering connection print outs is a proof of that. I know where the problem is and will have a fix soon.

[lefcha]

@alexhk I pushed a fix, could you try with the latest Git version?

[vaygr]

I experience a similar issue when imapfilter dies once in a while (a couple of times per month) and gets restarted by systemd.

Here's my setup (relevant details):

…

while true do
  inbox = account.INBOX

  …

  if not inbox:enter_idle() then
    sleep(60)
  end
end

and here's the systemd log:

Mar 08 22:34:56 sajuuk imapfilter[2314]: imapfilter: idle request to user@domain.tld failed
Mar 08 22:34:56 sajuuk imapfilter[2314]: stack traceback:
Mar 08 22:34:56 sajuuk imapfilter[2314]:         [C]: in ?
Mar 08 22:34:56 sajuuk imapfilter[2314]:         [C]: in function 'error'
Mar 08 22:34:56 sajuuk imapfilter[2314]:         /usr/share/imapfilter/mailbox.lua:41: in field '_check_result'
Mar 08 22:34:56 sajuuk imapfilter[2314]:         /usr/share/imapfilter/mailbox.lua:1070: in method 'enter_idle'
Mar 08 22:34:56 sajuuk imapfilter[2314]:         /home/stealth/.imapfilter/config.lua:37: in main chunk
Mar 08 22:34:56 sajuuk systemd[2104]: imapfilter.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Mar 08 22:34:56 sajuuk systemd[2104]: imapfilter.service: Failed with result 'exit-code'.

systemd unit:

Description=Imapfilter Mail Filter
Documentation="man:imapfilter(1)" "man:imapfilter_config(5)"
ConditionPathExists=%h/.imapfilter/config.lua

[Service]
Type=simple
ExecStart=/usr/bin/imapfilter -c %h/.imapfilter/config.lua
RestartSec=60
Restart=on-failure

[Install]
WantedBy=default.target

I can probably re-run impafilter with debug file enabled, but maybe these details can give you an idea on where to look.

[lefcha]

Version 2.8.0 and onward has a new recovery mechanism that is a lot more powerful and flexible:

https://github.com/lefcha/imapfilter/blob/9e6661278572009a92a8e125c9b339232a9735a1/NEWS#L11-L13

Have you tried using that instead? There's an example here:

https://github.com/lefcha/imapfilter/blob/9e6661278572009a92a8e125c9b339232a9735a1/samples/extend.lua#L131-L190