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

[Mark Sapiro-3]

I have been running Dovecot 1.2.5 since Sept 14. Beginning at about
03:28 on Sept 21 for no apparent (to me) reason and continuing through
the present, I am seeing log messages like the following and am
experiencing delays logging in.

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

Is this a dovecot issue, some other issue or perhaps some kind of
denial of service attack?

Here's my dovecot -n

# 1.2.5: /usr/local/etc/dovecot.conf
# OS: Linux 2.6.18-8.1.14.el5 i686 CentOS release 5 (Final)
protocols: pop3 pop3s imap imaps
ssl_cert_file: /etc/postfix/sbh16-cert.pem
ssl_key_file: /etc/postfix/sbh16-key.pem
login_dir: /usr/local/var/run/dovecot/login
login_executable(default): /usr/local/libexec/dovecot/imap-login
login_executable(imap): /usr/local/libexec/dovecot/imap-login
login_executable(pop3): /usr/local/libexec/dovecot/pop3-login
mail_privileged_group: mail
mail_location: mbox:~/Mail:INBOX=/var/spool/mail/%u
mbox_write_locks: fcntl dotlock
mail_executable(default): /usr/local/libexec/dovecot/imap
mail_executable(imap): /usr/local/libexec/dovecot/imap
mail_executable(pop3): /usr/local/libexec/dovecot/pop3
mail_plugin_dir(default): /usr/local/lib/dovecot/imap
mail_plugin_dir(imap): /usr/local/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3
lda:
  postmaster_address: postmaster@...
auth default:
  mechanisms: plain apop login
  worker_max_count: 5
  passdb:
    driver: passwd-file
    args: /usr/local/etc/dovecot.passwd
  passdb:
    driver: pam
  userdb:
    driver: passwd
  socket:
    type: listen
    client:
      path: /var/spool/postfix/private/auth
      mode: 432
      user: postfix
      group: postfix
[root@sbh16 ~]#
 
--
Mark Sapiro <mark@...>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan

[Mark Sapiro-3]

Mark Sapiro wrote:

>I have been running Dovecot 1.2.5 since Sept 14. Beginning at about
>03:28 on Sept 21 for no apparent (to me) reason and continuing through
>the present, I am seeing log messages like the following and am
>experiencing delays logging in.
>
>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
>
>Is this a dovecot issue, some other issue or perhaps some kind of
>denial of service attack?
>
>Here's my dovecot -n
>
># 1.2.5: /usr/local/etc/dovecot.conf
># OS: Linux 2.6.18-8.1.14.el5 i686 CentOS release 5 (Final)
>protocols: pop3 pop3s imap imaps
>ssl_cert_file: /etc/postfix/sbh16-cert.pem
>ssl_key_file: /etc/postfix/sbh16-key.pem
>login_dir: /usr/local/var/run/dovecot/login
>login_executable(default): /usr/local/libexec/dovecot/imap-login
>login_executable(imap): /usr/local/libexec/dovecot/imap-login
>login_executable(pop3): /usr/local/libexec/dovecot/pop3-login
>mail_privileged_group: mail
>mail_location: mbox:~/Mail:INBOX=/var/spool/mail/%u
>mbox_write_locks: fcntl dotlock
>mail_executable(default): /usr/local/libexec/dovecot/imap
>mail_executable(imap): /usr/local/libexec/dovecot/imap
>mail_executable(pop3): /usr/local/libexec/dovecot/pop3
>mail_plugin_dir(default): /usr/local/lib/dovecot/imap
>mail_plugin_dir(imap): /usr/local/lib/dovecot/imap
>mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3
>lda:
>  postmaster_address: postmaster@...
>auth default:
>  mechanisms: plain apop login
>  worker_max_count: 5
>  passdb:
>    driver: passwd-file
>    args: /usr/local/etc/dovecot.passwd
>  passdb:
>    driver: pam
>  userdb:
>    driver: passwd
>  socket:
>    type: listen
>    client:
>      path: /var/spool/postfix/private/auth
>      mode: 432
>      user: postfix
>      group: postfix
>[root@sbh16 ~]#

It may be too soon to know for sure, but I restarted Dovecot and that
seems to have solved the problem. However, I still don't know what may
have started the problem in the first place.

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

[Marco Nenciarini]

Mark Sapiro ha scritto:
> I have been running Dovecot 1.2.5 since Sept 14. Beginning at about
> 03:28 on Sept 21 for no apparent (to me) reason and continuing through
> the present, I am seeing log messages like the following and am
> experiencing delays logging in.
>

Same problem here, after about the same time from last server re start.

Last restart log is:

Sep 14 19:05:07 server dovecot: Dovecot v1.2.5 starting up (core dumps
disabled)

First failure is:

Sep 23 06:26:14 server dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted

After the attached piece of log, the mail log is full of the same
failure, and no customer can login using pop3 (imap works with no problems)

After a server restart the problem was vanished.

May be there is some kind of resource leakage.

Marco

P.S: This is my configuration is

# 1.2.5: /etc/dovecot/dovecot.conf
# OS: Linux 2.6.26-2-xen-amd64 x86_64 Debian 5.0.3
log_timestamp: %Y-%m-%d %H:%M:%S
protocols: imap imaps pop3 pop3s managesieve
ssl_cert_file: /etc/ssl/certs/server.pem
ssl_key_file: /etc/ssl/private/server.key
disable_plaintext_auth: no
login_dir: /var/run/dovecot/login
login_executable(default): /usr/lib/dovecot/imap-login
login_executable(imap): /usr/lib/dovecot/imap-login
login_executable(pop3): /usr/lib/dovecot/pop3-login
login_executable(managesieve): /usr/lib/dovecot/managesieve-login
first_valid_uid: 2000
last_valid_uid: 2000
first_valid_gid: 2000
last_valid_gid: 2000
mail_privileged_group: mail
mail_location: maildir:~/Maildir
mbox_write_locks: fcntl dotlock
mail_executable(default): /usr/lib/dovecot/imap
mail_executable(imap): /usr/lib/dovecot/imap
mail_executable(pop3): /usr/lib/dovecot/pop3
mail_executable(managesieve): /usr/lib/dovecot/managesieve
mail_plugins(default): quota imap_quota expire trash
mail_plugins(imap): quota imap_quota expire trash
mail_plugins(pop3): quota expire
mail_plugins(managesieve):
mail_plugin_dir(default): /usr/lib/dovecot/modules/imap
mail_plugin_dir(imap): /usr/lib/dovecot/modules/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/modules/pop3
mail_plugin_dir(managesieve): /usr/lib/dovecot/modules/managesieve
imap_client_workarounds(default): delay-newmail
imap_client_workarounds(imap): delay-newmail
imap_client_workarounds(pop3):
imap_client_workarounds(managesieve):
pop3_save_uidl(default): no
pop3_save_uidl(imap): no
pop3_save_uidl(pop3): yes
pop3_save_uidl(managesieve): no
pop3_uidl_format(default): %08Xu%08Xv
pop3_uidl_format(imap): %08Xu%08Xv
pop3_uidl_format(pop3): %f
pop3_uidl_format(managesieve): %08Xu%08Xv
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh
pop3_client_workarounds(managesieve):
namespace:
   type: private
   separator: .
   inbox: yes
   list: yes
   subscriptions: yes
namespace:
   type: private
   separator: .
   prefix: INBOX.
   hidden: yes
   list: no
   subscriptions: yes
lda:
   postmaster_address: postmaster@...
   mail_plugins: quota sieve expire
   auth_socket_path: /var/run/dovecot/auth-master
auth default:
   mechanisms: plain login
   passdb:
     driver: sql
     args: /etc/dovecot/dovecot-sql.conf
   userdb:
     driver: prefetch
   userdb:
     driver: sql
     args: /etc/dovecot/dovecot-sql.conf
   socket:
     type: listen
     client:
       path: /var/spool/postfix/private/auth
       mode: 432
       user: postfix
       group: postfix
     master:
       path: /var/run/dovecot/auth-master
       mode: 384
       user: vmail
       group: vmail
plugin:
   quota: dict:user::proxy::quota
   quota2: dict:domain:%d:proxy::quota_domain
   trash: /etc/dovecot/dovecot-trash.conf
   expire: Trash 7 Trash/* 7 Cestino 7 Cestino/* 7 Junk 30 Spam 30
   expire_dict: proxy::expire
   sieve: ~/.dovecot.sieve
   sieve_dir: ~/sieve
dict:
   quota: pgsql:/etc/dovecot/dovecot-dict-quota.conf
   quota_domain: pgsql:/etc/dovecot/dovecot-dict-quota-domain.conf
   expire: pgsql:/etc/dovecot/dovecot-dict-expire.conf


--
---------------------------------------------------------------------
|    Marco Nenciarini    | Debian/GNU Linux Developer - Plug Member |
| mnencia@... | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4


Sep 23 06:26:12 server dovecot: pop3-login: Login: user=<xxx@...>, method=PLAIN, rip=11.22.33.44 lip=11.22.33.44 TLS
Sep 23 06:26:13 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:26:14 server dovecot: pop3-login: Fatal: io_loop_handle_add: epoll_ctl(1, 5): Operation not permitted
Sep 23 06:26:14 server dovecot: dovecot: Temporary failure in creating login processes, slowing down for now
Sep 23 06:26:14 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:26:15 server dovecot: pop3-login: Login: user=<xxx@...>, method=PLAIN, rip=11.22.33.44 lip=11.22.33.44 TLS
Sep 23 06:26:15 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:26:15 server dovecot: pop3-login: Login: user=<xxx@...>, method=PLAIN, rip=11.22.33.44 lip=11.22.33.44 TLS
Sep 23 06:26:17 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:26:18 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:26:19 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:27:14 server dovecot: dovecot: Created login processes successfully, unstalling
Sep 23 06:27:14 server dovecot: pop3-login: Disconnected (no auth attempts): rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:27:14 server dovecot: pop3-login: Fatal: io_loop_handle_add: epoll_ctl(1, 5): Operation not permitted
Sep 23 06:27:14 server dovecot: dovecot: Temporary failure in creating login processes, slowing down for now
Sep 23 06:27:14 server dovecot: pop3-login: Login: user=<xxx@...>, method=PLAIN, rip=11.22.33.44 lip=11.22.33.44 TLS
Sep 23 06:27:17 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:28:14 server dovecot: dovecot: Created login processes successfully, unstalling
Sep 23 06:28:14 server dovecot: pop3-login: Disconnected (no auth attempts): rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:28:14 server dovecot: pop3-login: Fatal: io_loop_handle_add: epoll_ctl(1, 5): Operation not permitted
Sep 23 06:28:14 server dovecot: dovecot: Temporary failure in creating login processes, slowing down for now
Sep 23 06:28:14 server dovecot: dovecot: Created login processes successfully, unstalling
Sep 23 06:28:14 server dovecot: pop3-login: Disconnected (no auth attempts): rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:28:15 server dovecot: pop3-login: Fatal: io_loop_handle_add: epoll_ctl(1, 5): Operation not permitted
Sep 23 06:28:15 server dovecot: dovecot: Temporary failure in creating login processes, slowing down for now
Sep 23 06:28:15 server dovecot: dovecot: Created login processes successfully, unstalling
Sep 23 06:28:15 server dovecot: pop3-login: Disconnected (no auth attempts): rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:28:15 server dovecot: pop3-login: Login: user=<xxx@...>, method=PLAIN, rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:28:15 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:28:16 server dovecot: pop3-login: Fatal: io_loop_handle_add: epoll_ctl(1, 5): Operation not permitted
Sep 23 06:28:16 server dovecot: dovecot: Temporary failure in creating login processes, slowing down for now
Sep 23 06:28:16 server dovecot: pop3-login: Disconnected (no auth attempts): rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:28:16 server dovecot: dovecot: Created login processes successfully, unstalling
Sep 23 06:28:16 server dovecot: pop3-login: Disconnected (no auth attempts): rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:28:17 server dovecot: pop3-login: Fatal: io_loop_handle_add: epoll_ctl(1, 5): Operation not permitted
Sep 23 06:28:17 server dovecot: dovecot: Temporary failure in creating login processes, slowing down for now
Sep 23 06:28:17 server dovecot: dovecot: Created login processes successfully, unstalling
Sep 23 06:28:17 server dovecot: pop3-login: Login: user=<xxx@...>, method=PLAIN, rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:28:17 server dovecot: pop3-login: Disconnected (no auth attempts): rip=11.22.33.44 lip=11.22.33.44
Sep 23 06:28:17 server dovecot: POP3(xxx@...): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
Sep 23 06:28:18 server dovecot: pop3-login: Fatal: io_loop_handle_add: epoll_ctl(1, 5): Operation not permitted
Sep 23 06:28:18 server dovecot: dovecot: Temporary failure in creating login processes, slowing down for now
Sep 23 06:28:18 server dovecot: dovecot: Created login processes successfully, unstalling

[Timo Sirainen]

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..

[Timo Sirainen]

On Sep 23, 2009, at 11:27 AM, 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..

It could be useful to know what the fd actually is. See what it logs  
with the attached patch?

[Marco Nenciarini]

Timo Sirainen ha scritto:

> On Sep 23, 2009, at 11:27 AM, 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..
>
> It could be useful to know what the fd actually is. See what it logs
> with the attached patch?

Patch applied, now we must wait until the problem will show itself again
(may be a week or so).

Marco

--
---------------------------------------------------------------------
|    Marco Nenciarini    | Debian/GNU Linux Developer - Plug Member |
| mnencia@... | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4

[Marco Nenciarini]

Marco Nenciarini ha scritto:
>
> Patch applied, now we must wait until the problem will show itself again
> (may be a week or so).
>

The patch does not compile, need another parameter (may be 1024?)

Marco

--
---------------------------------------------------------------------
|    Marco Nenciarini    | Debian/GNU Linux Developer - Plug Member |
| mnencia@... | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4

[Timo Sirainen]

On Sep 23, 2009, at 12:11 PM, Marco Nenciarini wrote:

> Marco Nenciarini ha scritto:
>> Patch applied, now we must wait until the problem will show itself  
>> again (may be a week or so).
>
> The patch does not compile, need another parameter (may be 1024?)

Oh, sorry. Use io->fd for the second one too.

[Mark Sapiro-3]

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

[Marco Nenciarini]

Timo Sirainen ha scritto:

> On Sep 23, 2009, at 11:27 AM, 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..
>
> It could be useful to know what the fd actually is. See what it logs
> with the attached patch?

The problem happened again.

Sep 30 06:26:15 server dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted

There is no additional information from Timo's patch, but if you compare
it with the last one you can see a weird match on both time and weekday:

Sep 23 06:26:14 server dovecot: pop3-login: Fatal: io_loop_handle_add:
epoll_ctl(1, 5): Operation not permitted

After some investigation I've found that the daily cron scripts are
executed every day at 6:25 and the only thing related to dovecot in
/etc/cron.daily is the call to expire plugin

---------------------------------------------------------------------
server:~# cat /etc/cron.dailyclean-expired-messages
#!/bin/sh

dovecot --exec-mail ext /usr/lib/dovecot/expire-tool.sh

server:~# cat /usr/lib/dovecot/expire-tool.sh
#!/bin/bash
MAIL_PLUGINS=${MAIL_PLUGINS//imap_quota/}
MAIL_PLUGINS=${MAIL_PLUGINS//mail_log/}

exec ${0%.sh} "$@"
---------------------------------------------------------------------

Moreover my expire plugin configuration is

expire: Trash 7 Trash/* 7 Cestino 7 Cestino/* 7 Junk 30 Spam 30

so the weekly periodicity can be explained with something happened in a
Trash mailbox.

My configuration is

---------------------------------------------------------------------
# 1.2.5: /etc/dovecot/dovecot.conf
# OS: Linux 2.6.26-2-xen-amd64 x86_64 Debian 5.0.3
log_timestamp: %Y-%m-%d %H:%M:%S
protocols: imap imaps pop3 pop3s managesieve
ssl_cert_file: /etc/ssl/certs/delta01.pem
ssl_key_file: /etc/ssl/private/delta01.key
disable_plaintext_auth: no
login_dir: /var/run/dovecot/login
login_executable(default): /usr/lib/dovecot/imap-login
login_executable(imap): /usr/lib/dovecot/imap-login
login_executable(pop3): /usr/lib/dovecot/pop3-login
login_executable(managesieve): /usr/lib/dovecot/managesieve-login
first_valid_uid: 2000
last_valid_uid: 2000
first_valid_gid: 2000
last_valid_gid: 2000
mail_privileged_group: mail
mail_location: maildir:~/Maildir
mbox_write_locks: fcntl dotlock
mail_executable(default): /usr/lib/dovecot/imap
mail_executable(imap): /usr/lib/dovecot/imap
mail_executable(pop3): /usr/lib/dovecot/pop3
mail_executable(managesieve): /usr/lib/dovecot/managesieve
mail_plugins(default): quota imap_quota expire trash
mail_plugins(imap): quota imap_quota expire trash
mail_plugins(pop3): quota expire
mail_plugins(managesieve):
mail_plugin_dir(default): /usr/lib/dovecot/modules/imap
mail_plugin_dir(imap): /usr/lib/dovecot/modules/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/modules/pop3
mail_plugin_dir(managesieve): /usr/lib/dovecot/modules/managesieve
imap_client_workarounds(default): delay-newmail
imap_client_workarounds(imap): delay-newmail
imap_client_workarounds(pop3):
imap_client_workarounds(managesieve):
pop3_save_uidl(default): no
pop3_save_uidl(imap): no
pop3_save_uidl(pop3): yes
pop3_save_uidl(managesieve): no
pop3_uidl_format(default): %08Xu%08Xv
pop3_uidl_format(imap): %08Xu%08Xv
pop3_uidl_format(pop3): %f
pop3_uidl_format(managesieve): %08Xu%08Xv
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh
pop3_client_workarounds(managesieve):
namespace:
   type: private
   separator: .
   inbox: yes
   list: yes
   subscriptions: yes
namespace:
   type: private
   separator: .
   prefix: INBOX.
   hidden: yes
   list: no
   subscriptions: yes
lda:
   postmaster_address: postmaster@...
   mail_plugins: quota sieve expire
   auth_socket_path: /var/run/dovecot/auth-master
auth default:
   mechanisms: plain login
   passdb:
     driver: sql
     args: /etc/dovecot/dovecot-sql.conf
   userdb:
     driver: prefetch
   userdb:
     driver: sql
     args: /etc/dovecot/dovecot-sql.conf
   socket:
     type: listen
     client:
       path: /var/spool/postfix/private/auth
       mode: 432
       user: postfix
       group: postfix
     master:
       path: /var/run/dovecot/auth-master
       mode: 384
       user: vmail
       group: vmail
plugin:
   quota: dict:user::proxy::quota
   quota2: dict:domain:%d:proxy::quota_domain
   trash: /etc/dovecot/dovecot-trash.conf
   expire: Trash 7 Trash/* 7 Cestino 7 Cestino/* 7 Junk 30 Spam 30
   expire_dict: proxy::expire
   sieve: ~/.dovecot.sieve
   sieve_dir: ~/sieve
dict:
   quota: pgsql:/etc/dovecot/dovecot-dict-quota.conf
   quota_domain: pgsql:/etc/dovecot/dovecot-dict-quota-domain.conf
   expire: pgsql:/etc/dovecot/dovecot-dict-expire.conf
---------------------------------------------------------------------

The expire dictionary have the standard configuration taken from wiki
and the database have the required trigger.

Content of /etc/dovecot/dovecot-dict-expire.conf
---------------------------------------------------------------------
connect = host=localhost dbname=vmail user=vmail password=XXXXXXXX

map {
   pattern = shared/expire/$user/$mailbox
   table = expires
   value_field = expire_stamp

   fields {
     username = $user
     mailbox = $mailbox
   }
}
---------------------------------------------------------------------

I hope this is enough to catch the bug.

Ciao,
Marco

--
---------------------------------------------------------------------
|    Marco Nenciarini    | Debian/GNU Linux Developer - Plug Member |
| mnencia@... | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4

[Timo Sirainen]

On Wed, 2009-09-30 at 10:16 +0200, Marco Nenciarini wrote:
> Sep 30 06:26:15 server dovecot: pop3-login: Fatal: io_loop_handle_add:
> epoll_ctl(1, 5): Operation not permitted
>
> There is no additional information from Timo's patch,

Oh, annoying. There was a bug in the function it used, this fixes it:
http://hg.dovecot.org/dovecot-1.2/rev/401e023c8c29

> but if you compare
> it with the last one you can see a weird match on both time and weekday:
>
> Sep 23 06:26:14 server dovecot: pop3-login: Fatal: io_loop_handle_add:
> epoll_ctl(1, 5): Operation not permitted
>
> After some investigation I've found that the daily cron scripts are
> executed every day at 6:25 and the only thing related to dovecot in
> /etc/cron.daily is the call to expire plugin

That is interesting, but I can't really think of how they could be
related.. I also did a few tests and they didn't break it either. The
only thing I can think of is that somehow the --exec-mail added a second
dovecot master process running at the same time? Did you check the
process list?

The only thing related I can think of is
http://hg.dovecot.org/dovecot-1.2/rev/0f04c7da33f1 - did you have that
patch applied? Although I couldn't reproduce the problem even with that
reverted.

[Marco Nenciarini]

Timo Sirainen ha scritto:
> On Wed, 2009-09-30 at 10:16 +0200, Marco Nenciarini wrote:
>> Sep 30 06:26:15 server dovecot: pop3-login: Fatal: io_loop_handle_add:
>> epoll_ctl(1, 5): Operation not permitted
>>
>> There is no additional information from Timo's patch,
>
> Oh, annoying. There was a bug in the function it used, this fixes it:
> http://hg.dovecot.org/dovecot-1.2/rev/401e023c8c29
 >
 > [snip]
>
> The only thing related I can think of is
> http://hg.dovecot.org/dovecot-1.2/rev/0f04c7da33f1 - did you have that
> patch applied? Although I couldn't reproduce the problem even with that
> reverted.

Another day, another failure, now with both patches applied.

Oct  1 06:26:14 server dovecot: pop3-login: Panic: Leaked file fd 5: dev
0.12 inode 1005
Oct  1 06:26:14 server dovecot: dovecot: Temporary failure in creating
login processes, slowing down for now
Oct  1 06:26:14 server dovecot: dovecot: child 17609 (login) killed with
signal 6 (core dumps disabled)

Please note that the time is the same of previous days (just after daily
cron execution)

Regards,
Marco

--
---------------------------------------------------------------------
|    Marco Nenciarini    | Debian/GNU Linux Developer - Plug Member |
| mnencia@... | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4

[Timo Sirainen]

On Thu, 2009-10-01 at 09:28 +0200, Marco Nenciarini wrote:
> > The only thing related I can think of is
> > http://hg.dovecot.org/dovecot-1.2/rev/0f04c7da33f1 - did you have that
> > patch applied? Although I couldn't reproduce the problem even with that
> > reverted.
>
> Another day, another failure, now with both patches applied.
>
> Oct  1 06:26:14 server dovecot: pop3-login: Panic: Leaked file fd 5: dev
> 0.12 inode 1005

That's the pty's fd I think, probably from dovecot --exec-mail because
normally dovecot master process closes them at startup..

Did you check if two "dovecot" processes were running when this
happened?

[Timo Sirainen]

On Tue, 2009-09-22 at 20:23 -0700, Mark Sapiro wrote:
> Sep 22 19:07:15 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
> epoll_ctl(1, 5): Operation not permitted

Has this happened to you again? Do you run expire-tool or some other
dovecot --exec-mail command? Or was there anything else run in cron just
before the first of the above errors happened?

[Marco Nenciarini]

Timo Sirainen ha scritto:
> On Tue, 2009-09-22 at 20:23 -0700, Mark Sapiro wrote:
>> Sep 22 19:07:15 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
>> epoll_ctl(1, 5): Operation not permitted
>
> Has this happened to you again? Do you run expire-tool or some other
> dovecot --exec-mail command? Or was there anything else run in cron just
> before the first of the above errors happened?

No, it hasn't happened again.

The only errors I found in my logs is like the following one

Oct  1 09:20:29 delta01 dovecot: pop3-login: Disconnected (no auth
attempts): rip=213.136.170.137, lip=10.68.1.31
Oct  1 09:20:29 delta01 dovecot: pop3-login: Panic: Leaked file fd 5:
dev 0.12 inode 1005
Oct  1 09:20:29 delta01 dovecot: dovecot: Temporary failure in creating
login processes, slowing down for now
Oct  1 09:20:29 delta01 dovecot: pop3-login: Disconnected (no auth
attempts): rip=62.94.181.36, lip=10.68.1.31
Oct  1 09:20:29 delta01 dovecot: dovecot: child 12936 (login) killed
with signal 6 (core dumps disabled)

The only dovecot-related command run by cron daily is expire-tool

I've checked the list of running processes but there is only one
/usr/sbin/dovecot running with its children

Marco

--
---------------------------------------------------------------------
|    Marco Nenciarini    | Debian/GNU Linux Developer - Plug Member |
| mnencia@... | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4

[Mark Sapiro-3]

Timo Sirainen wrote:
>
>On Tue, 2009-09-22 at 20:23 -0700, Mark Sapiro wrote:
>> Sep 22 19:07:15 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
>> epoll_ctl(1, 5): Operation not permitted
>
>Has this happened to you again? Do you run expire-tool or some other
>dovecot --exec-mail command? Or was there anything else run in cron just
>before the first of the above errors happened?


Hi Timo,

No, this hasn't happened again. It is dovecot 2.1.5 with no extra
plugins. I don't run any dovecot related crons. The only crons that
ran just before it happened were unrelated

rotate two unrelated logs 23 minutes before
download and update some spamassassin rules 12 minutes before
update Mailman archive search indices 9 minutes before

All these run daily.

The problem occurred after upgrading from 2.1.4 to 2.1.5. 2.1.4 had
been running for weeks with no problem. The problem started with 2.1.5
when it had been running about 6 days and 20 hours. and continued
until I restarted dovecot a day and a half later.

There was a power outage at the server last Friday night when Dovecot
had been running only 4 days since the last restart, so at this point,
Dovecot has been running continuously for 5 days and 6 hours, so the
problem may or may not recur within the next few days.

My dovecot -n is at
<http://dovecot.org/pipermail/dovecot/2009-September/042943.html>, and
some more detail from my maillog is at
<http://dovecot.org/pipermail/dovecot/2009-September/042959.html>.

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

[tanstaafl_bh]

On 10/1/2009, Mark Sapiro (mark@...) wrote:
> No, this hasn't happened again. It is dovecot 2.1.5

Ok, at first I thought this was just a silly typo, but...

> The problem occurred after upgrading from 2.1.4 to 2.1.5. 2.1.4 had
> been running for weeks with no problem. The problem started with 2.1.5

Mark, you obviously just gave away the fact that you have access to a
time machine...

Please, if you would, post these future versions somewhere where I can
get at them!

lol ;)

[Mark Sapiro-3]

Mark Sapiro wrote:

>Timo Sirainen wrote:
>>
>>On Tue, 2009-09-22 at 20:23 -0700, Mark Sapiro wrote:
>>> Sep 22 19:07:15 sbh16 dovecot: pop3-login: Fatal: io_loop_handle_add:
>>> epoll_ctl(1, 5): Operation not permitted
>>
>>Has this happened to you again? Do you run expire-tool or some other
>>dovecot --exec-mail command? Or was there anything else run in cron just
>>before the first of the above errors happened?
>
>
>Hi Timo,
>
>No, this hasn't happened again. It is dovecot 2.1.5 with no extra
>plugins. I don't run any dovecot related crons. The only crons that
>ran just before it happened were unrelated
>
>rotate two unrelated logs 23 minutes before
>download and update some spamassassin rules 12 minutes before
>update Mailman archive search indices 9 minutes before
>
>All these run daily.
>
>The problem occurred after upgrading from 2.1.4 to 2.1.5. 2.1.4 had
>been running for weeks with no problem. The problem started with 2.1.5
>when it had been running about 6 days and 20 hours. and continued
>until I restarted dovecot a day and a half later.
>
>There was a power outage at the server last Friday night when Dovecot
>had been running only 4 days since the last restart, so at this point,
>Dovecot has been running continuously for 5 days and 6 hours, so the
>problem may or may not recur within the next few days.
>
>My dovecot -n is at
><http://dovecot.org/pipermail/dovecot/2009-September/042943.html>, and
>some more detail from my maillog is at
><http://dovecot.org/pipermail/dovecot/2009-September/042959.html>.
>

Also, FYI, I do not have the
http://hg.dovecot.org/dovecot-1.2/rev/0f04c7da33f1 patch installed.

I do have the patch installed to log the fd for this error, but I don't
have the fix http://hg.dovecot.org/dovecot-1.2/rev/401e023c8c29 for
the logging function installed.

Would you prefer that I just let Dovecot run a few days and see if the
problem recurs, or should I install the logging function fix now and
perhaps wait another 7 or 8 days before there may be another failure.

Also, as far as I know, the only dovecot processes running at the time
of the failure were a single master and it's auth and pop3 and imap
login children.

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

[Mark Sapiro-3]

Charles Marcus wrote:

>On 10/1/2009, Mark Sapiro (mark@...) wrote:
>> No, this hasn't happened again. It is dovecot 2.1.5
>
>Ok, at first I thought this was just a silly typo, but...
>
>> The problem occurred after upgrading from 2.1.4 to 2.1.5. 2.1.4 had
>> been running for weeks with no problem. The problem started with 2.1.5
>
>Mark, you obviously just gave away the fact that you have access to a
>time machine...
>
>Please, if you would, post these future versions somewhere where I can
>get at them!

Sorry, no time machine, no future versions. Just finger dyslexia. As
everyone probably knows, I meant 1.2.5 and 1.2.4.

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

[Marco Nenciarini]

Timo Sirainen ha scritto:
>
> That's the pty's fd I think, probably from dovecot --exec-mail because
> normally dovecot master process closes them at startup..
>
> Did you check if two "dovecot" processes were running when this
> happened?

This morning the problem showed again.

This is what I was able to discover:

1) There was only one master process.
2) Imap and managesieve login and worker processes were working normally.
3) There was no pop3/pop3-login.

After the last time I've modified my root crontab to execute the
expire-tool every minute, trying to trigger the problem in another time
of the day, but the first failure is

Oct  6 06:26:02 delta01 dovecot: imap-login: Panic: Leaked file fd 5:
dev 0.12 inode 1005
Oct  6 06:26:02 delta01 dovecot: dovecot: Temporary failure in creating
login processes, slowing down for now
Oct  6 06:26:02 delta01 dovecot: dovecot: child 21216 (login) killed
with signal 6 (core dumps disabled)

As you can see this time is the login process of an imap connection, so
I can state that the problem is not related to pop3 and nor to expire
plugin.

Probably the imap connections that I see were there before the problem
was triggered.

So the only remaining thing in daily log rotation that can be the
trigger of the problem is the heavy cpu/io load due to daily maintenance.

The last weird thing is that this time I have simply asked dovecot to
reload its configuration and the problem is vanished.

I hope this is enough to figure out what was happened.

Marco

--
---------------------------------------------------------------------
|    Marco Nenciarini    | Debian/GNU Linux Developer - Plug Member |
| mnencia@... | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4