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 permittedThat'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@msapiro.net The highway is for gamblers, San Francisco Bay Area, California better use your sense - B. Dylan