[Dovecot] pop3-login: Fatal: io_loop_handle_add: epoll_ctl(1, 5):

[Mark Sapiro]

Timo Sirainen wrote:

>On Sep 23, 2009, at 11:17 AM, Marco Nenciarini wrote:
>
>> First failure is:
>>
>> Sep 23 06:26:14 server dovecot: pop3-login: Fatal:  
>> io_loop_handle_add: epoll_ctl(1, 5): Operation not permitted
>
>That's really the first one, and there's no kind of an error from  
>dovecot master process? This sounds like wrong fd is being passed to  
>pop3-login, but why it's being done only randomly I can't really think  
>of..


In my case, I see a few different kinds of messages. I posted a
sequence earlier. Here it is again. At least one of each unusual
message I see is included in this two minute period, and these are all
the dovecot messages in that period and the initial message is the
first unusual one that occurred.

Sep 22 19:07:15 sbh16 dovecot: dovecot: Temporary failure in creating
login processes, slowing down for now
Sep 22 19:07:15 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted
Sep 22 19:07:48 sbh16 dovecot: pop3-login: Login: user=<mark>,
method=APOP, rip=68.183.193.239, lip=72.52.113.16, TLS
Sep 22 19:07:48 sbh16 dovecot: POP3(mark): Disconnected: Logged out
top=0/0, retr=0/0, del=0/218, size=2550090
Sep 22 19:08:15 sbh16 dovecot: dovecot: Created login processes
successfully, unstalling
Sep 22 19:08:15 sbh16 dovecot: dovecot: Temporary failure in creating
login processes, slowing down for now
Sep 22 19:08:15 sbh16 dovecot: dovecot: child 21735 (login) returned
error 89 (Fatal failure)
Sep 22 19:08:15 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted
Sep 22 19:08:21 sbh16 dovecot: pop3-login: Login: user=<mark>,
method=APOP, rip=68.183.193.239, lip=72.52.113.16, TLS
Sep 22 19:08:22 sbh16 dovecot: POP3(mark): Disconnected: Logged out
top=0/0, retr=1/57566, del=0/218, size=2550090
Sep 22 19:09:15 sbh16 dovecot: dovecot: Created login processes
successfully, unstalling


Also, here are all the dovecot messages from a five minute period when
this first started. The scenario here is a remote machine connects
every five minutes via an SSH tunnel and retrieves and deletes (with
fetchmail pop3) all the mail for 4 users.


Sep 21 03:28:17 sbh16 dovecot: pop3-login: Login: user=<fran>,
method=PLAIN, rip=72.52.113.36, lip=72.52.113.36, secured
Sep 21 03:28:17 sbh16 dovecot: POP3(fran): Disconnected: Logged out
top=0/0, retr=0/0, del=0/0, size=0
Sep 21 03:28:17 sbh16 dovecot: pop3-login: Login: user=<dma>,
method=PLAIN, rip=72.52.113.36, lip=72.52.113.36, secured
Sep 21 03:28:17 sbh16 dovecot: POP3(dma): Disconnected: Logged out
top=0/0, retr=0/0, del=0/0, size=0
Sep 21 03:28:17 sbh16 dovecot: pop3-login: Login: user=<abriz>,
method=PLAIN, rip=72.52.113.36, lip=72.52.113.36, secured
Sep 21 03:28:17 sbh16 dovecot: dovecot: Temporary failure in creating
login processes, slowing down for now
Sep 21 03:28:28 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted
Sep 21 03:28:28 sbh16 dovecot: pop3-login: Login: user=<aaron>,
method=PLAIN, rip=72.52.113.36, lip=72.52.113.36, secured
Sep 21 03:28:28 sbh16 dovecot: POP3(aaron): Disconnected: Logged out
top=0/0, retr=0/0, del=0/0, size=0
Sep 21 03:29:28 sbh16 dovecot: dovecot: Created login processes
successfully, unstalling
Sep 21 03:29:28 sbh16 dovecot: dovecot: Temporary failure in creating
login processes, slowing down for now
Sep 21 03:29:28 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted
Sep 21 03:30:28 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted
Sep 21 03:31:28 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted
Sep 21 03:32:28 sbh16 dovecot: dovecot: child 25038 (login) returned
error 89 (Fatal failure)
Sep 21 03:32:28 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted
Sep 21 03:33:28 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted
Sep 21 03:33:36 sbh16 dovecot: pop3-login: Login: user=<fran>,
method=PLAIN, rip=72.52.113.36, lip=72.52.113.36, secured
Sep 21 03:33:36 sbh16 dovecot: POP3(fran): Disconnected: Logged out
top=1/21613, retr=0/0, del=1/1, size=21607
Sep 21 03:33:36 sbh16 dovecot: pop3-login: Login: user=<dma>,
method=PLAIN, rip=72.52.113.36, lip=72.52.113.36, secured
Sep 21 03:33:36 sbh16 dovecot: POP3(dma): Disconnected: Logged out
top=1/21607, retr=0/0, del=1/1, size=21601


I have installed the patch adding fd_debug_verify_leaks(io->fd,
io->fd); and I will report any recurrence.

-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan