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

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 at example.com
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 at sbh16 ~]#
 
-- 
Mark Sapiro <mark at msapiro.net>        The highway is for gamblers,
San Francisco Bay Area, California    better use your sense - B. Dylan

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

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 at xcon.it
   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 at prato.linux.it | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4

-------------- next part --------------
A non-text attachment was scrubbed...
Name: dovecot.log
Type: text/x-log
Size: 4642 bytes
Desc: not available
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20090923/3609226c/attachment-0002.bin>

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

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.

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?

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20091001/b2dabf79/attachment-0002.bin>

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 at prato.linux.it | http://www.prato.linux.it/~mnencia       |
---------------------------------------------------------------------
Key fingerprint = FED9 69C7 9E67 21F5 7D95  5270 6864 730D F095 E5E4

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

Hi Marco,

On 10/22/09 1:50 AM, "Marco Nenciarini" <mnencia at
prato.linux.it> wrote:
> This morning it happened another time, another time during the daily
> cron execution.
> 
> Oct 22 06:26:57 server dovecot: pop3-login: Panic: Leaked file fd 5: dev
> 0.12 inode 1005
> Oct 22 06:26:57 server dovecot: dovecot: Temporary failure in creating
> login processes, slowing down for now
> Oct 22 06:26:57 server dovecot: dovecot: child 21311 (login) killed with
> signal 6 (core dumps disabled)
> 
> I have dovecot 1.2.6 with Timo's patch to check leaked descriptors.
I rebuilt the binaries on our hosts with optimization disabled, and I'm
still waiting for it to reoccur so I can gather file descriptor information
and a core. I don't have the leak-detect patch applied.

Let's see what Timo has to say about that log file bit. Since it seems to
happen to you fairly frequently, it might be worth enabling core dumps as
well?

-Brad

I'm having this same issue in one of my servers since I updated my Dovecot 
from 1.2.4 to 1.2.5. The problem still with 1.2.6 too.

I cannot find what is triggering the problem, but it happens aleatory and I 
need to restart the dovecot daemon to make the service run properly.

My info:
--------------------------------------------
$ dovecot -n
# 1.2.6: /etc/dovecot.conf
# OS: Linux 2.6.18-164.el5PAE i686 CentOS release 5.4 (Final)
protocols: imap imaps pop3 pop3s
listen: xx.xx.xx.xx
ssl_cert_file: /etc/httpd/conf/ssl.crt/server.crt
ssl_key_file: /etc/httpd/conf/ssl.key/server.key
disable_plaintext_auth: no
login_dir: /var/run/dovecot/login
login_executable(default): /usr/libexec/dovecot/imap-login
login_executable(imap): /usr/libexec/dovecot/imap-login
login_executable(pop3): /usr/libexec/dovecot/pop3-login
login_processes_count: 16
verbose_proctitle: yes
mail_access_groups: mail
mail_location: maildir:~/Maildir
mail_executable(default): /usr/libexec/dovecot/imap
mail_executable(imap): /usr/libexec/dovecot/imap
mail_executable(pop3): /usr/libexec/dovecot/pop3
mail_plugins(default): quota imap_quota
mail_plugins(imap): quota imap_quota
mail_plugins(pop3):
mail_plugin_dir(default): /usr/lib/dovecot/imap
mail_plugin_dir(imap): /usr/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/pop3
auth default:
  username_chars: 
abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890.-_@&
  verbose: yes
  passdb:
    driver: passwd-file
    args: username_format=%n /etc/virtual/%d/passwd
  userdb:
    driver: passwd-file
    args: username_format=%n /etc/virtual/%d/passwd
plugin:
  quota: maildir
  quota_rule: *:storage=200M
  quota_rule2: Trash:storage=100%%
--------------------------------------------

Something else I can help? Or additional information that I can provide?


-- 
Victor Benincasa