[Dovecot] Strange Error after some hour of inactivity.
Hi, in near future planing migrate our E-mail server to new hardware. Decided try dovecot as IMAP and POP3 server. Compiled latest dovecot-1.0.beta8 version on Linux Fedora Core 3 machine (2.6 kernel). Users database are on PostgreSQL server. Everything working fine except some issues.
After some hour of inactivity (POP3 or IMAP) then connecting to check e-mail got this error: invalid I/O fd 8, callback 0x8064d30. Next connection without service restart working fine again but only when in dovecot.conf exsist this option: login_process_per_connection = yes. When "login_process_per_connection = no" , always got "invalid I/O fd 8, callback 0x8064d30" error.
from log file ( in dovecot.conf login_process_per_connection = yes): ... Jun 2 08:34:31 srv1 dovecot: auth(default): sql(ramas,192.168.0.3): Password query failed: Jun 2 08:34:31 srv1 dovecot: auth(default): invalid I/O fd 8, callback 0x8064d30 Jun 2 08:34:31 srv1 dovecot: auth(default): sql(ramas,192.168.0.3): Password query failed: Jun 2 08:34:31 srv1 dovecot: auth(default): file auth-request.c: line 347 (auth_request_verify_plain_callback): assertion failed:(request->state == AUTH_REQUEST_STATE_PASSDB) Jun 2 08:34:31 srv1 dovecot: pop3-login: Disconnected: method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 2 08:34:31 srv1 dovecot: child 12203 (auth) killed with signal 6 Jun 2 08:34:31 srv1 dovecot: auth(default): pgsql: Connected to hosting Jun 2 08:34:34 srv1 dovecot: pop3-login: Login: user=<ramas>, method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 2 08:34:34 srv1 dovecot: POP3(ramas): Disconnected: Logged out top=0/0, retr=2/3502, del=2/2, size=3468 ...
also have troubles with maildir quota on POP3 module (IMAP works fine):
mail log: ... Jun 1 20:29:40 srv1 dovecot: Dovecot v1.0.beta8 starting up Jun 1 20:29:41 srv1 dovecot: auth(default): pgsql: Connected to hosting Jun 1 20:29:44 srv1 dovecot: POP3(ramas): dlopen(/usr/lib/dovecot/lib01_quota_plugin.so) failed: /usr/lib/dovecot/lib01_quota_plugin.so: undefined symbol: mountpoint_get Jun 1 20:29:44 srv1 dovecot: pop3-login: Login: user=<ramas>, method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 1 20:29:44 srv1 dovecot: child 21465 (pop3) returned error 89 Jun 1 20:43:09 srv1 dovecot: Killed with signal 15 ...
For this issue i found solution with manual compilation POP3 module: appended dependence -o ../lib/mountpoint.o
Best regards,
Ramas Lithuania, Marijampole
On Fri, 2006-06-02 at 10:39 +0300, Ramunas wrote:
After some hour of inactivity (POP3 or IMAP) then connecting to check e-mail got this error: invalid I/O fd 8, callback 0x8064d30. Next connection without service restart working fine again but only when in dovecot.conf exsist this option: login_process_per_connection = yes. When "login_process_per_connection = no" , always got "invalid I/O fd 8, callback 0x8064d30" error.
Could you do this and show me the result:
gdb /usr/local/libexec/dovecot/imap-login x 0x8064d30
It should print the function name for that address.
Did you configure Dovecot with --ioloop=epoll? I think there have been some problems with that, which might be related.
Jun 2 08:34:31 srv1 dovecot: auth(default): file auth-request.c: line 347 (auth_request_verify_plain_callback): assertion failed:(request->state == AUTH_REQUEST_STATE_PASSDB) Jun 2 08:34:31 srv1 dovecot: child 12203 (auth) killed with signal 6
This doesn't look nice either. Could you get the gdb backtrace for it? It should have written core file to /var/run/dovecot (or wherever your base_dir is). If not, you probably need to do "ulimit -c unlimited" before starting Dovecot.
For this issue i found solution with manual compilation POP3 module: appended dependence -o ../lib/mountpoint.o
Right. I've done that in CVS too.
Hi Timo, thanks for your reply. I realy want use Dovecot on our e-mail server, but still same problem "invalid I/O fd 8, callback 0x80645f0". New callback address from previuous post, because upgraded gcc :)
From log file: Jun 11 20:53:25 srv1 dovecot: Dovecot v1.0.beta8 starting up Jun 11 20:53:26 srv1 dovecot: auth(default): pgsql: Connected to hosting Jun 11 20:53:29 srv1 dovecot: pop3-login: Login: user=<ramas>, method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 11 20:53:29 srv1 dovecot: POP3(ramas): Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0 Jun 11 20:53:40 srv1 dovecot: imap-login: Login: user=<ramas>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured Jun 11 20:53:40 srv1 dovecot: IMAP(ramas): Disconnected: Logged out Jun 11 20:53:41 srv1 dovecot: imap-login: Login: user=<ramas>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured Jun 11 20:53:41 srv1 dovecot: IMAP(ramas): Disconnected: Logged out Jun 11 20:53:41 srv1 dovecot: imap-login: Login: user=<ramas>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured Jun 11 20:53:41 srv1 dovecot: IMAP(ramas): Disconnected: Logged out Jun 11 23:00:37 srv1 dovecot: auth(default): sql(ramas,192.168.0.3): Password query failed: Jun 11 23:00:37 srv1 dovecot: auth(default): invalid I/O fd 8, callback 0x80645f0 Jun 11 23:01:37 srv1 dovecot: pop3-login: Disconnected: Inactivity: method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 11 23:08:08 srv1 dovecot: pop3-login: Disconnected: Inactivity: method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 11 23:09:32 srv1 dovecot: pop3-login: Disconnected: Inactivity: method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 11 23:20:01 srv1 last message repeated 7 times
Output from gdb:
[root@srv1 /]# gdb /usr/libexec/dovecot/pop3-login GNU gdb Red Hat Linux (6.3.0.0-1.122rh)
(gdb) x 0x80645f0 0x80645f0: Cannot access memory at address 0x80645f0 (gdb)
[root@srv1 /]# gdb /usr/libexec/dovecot/imap-login (gdb) x 0x80645f0 0x80645f0: Cannot access memory at address 0x80645f0 (gdb)
[root@srv1 /]# gdb /usr/libexec/dovecot/dovecot-auth
(gdb) x 0x80645f0
0x80645f0
Could you get the gdb backtrace for it? It should have written core file to /var/run/dovecot (or wherever your base_dir is). If not, you probably need to do "ulimit -c unlimited" before starting Dovecot. Core file not found, "ulimit -c unlimited" done.
But maybe this will be usefull: [root@srv1 log]# gdb /usr/libexec/dovecot/dovecot-auth 23127
0xffffe410 in __kernel_vsyscall () (gdb) bt
#0 0xffffe410 in __kernel_vsyscall () #1 0xb7df6e3e in __lll_mutex_lock_wait () from /lib/libc.so.6 #2 0xb7d7694c in _L_lock_100 () from /lib/libc.so.6 #3 0xb7d768ea in fflush () from /lib/libc.so.6 #4 0xb7e65973 in pqFlush () from /usr/lib/libpq.so.3 #5 0xb7e62cb0 in PQconsumeInput () from /usr/lib/libpq.so.3 #6 0x0806460c in get_result () #7 0x0806a008 in io_loop_handler_run () #8 0x080696ac in io_loop_run () #9 0x08058a85 in main () (gdb)
Did you configure Dovecot with --ioloop=epoll? I think there have been some problems with that, which might be related.
Configured with: --disable-ipv6 --with-notify=inotify --with-ldap --with-pgsql --with-ssl=openssl --with-ssldir=/etc/pki/dovecot --with-gssapi --with-static-userdb --with-prefetch-userdb --with-storages="maildir,mbox"
Also tryed --with-ioloop=epoll, got another error but i think its the same problem.
From log file (with option --with-ioloop=epoll): Jun 11 08:43:10 srv1 dovecot: pop3-login: Login: user=<ramas>, method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 11 08:43:18 srv1 dovecot: auth(default): io_loop_handle_add: epoll_ctl(3, 9): No such file or directory Jun 11 08:43:18 srv1 dovecot: pop3-login: Disconnected: method=PLAIN, rip=192.168.0.3, lip=192.168.0.6, TLS Jun 11 08:43:18 srv1 dovecot: child 32063 (auth) returned error 89
participants (2)
-
Ramunas
-
Timo Sirainen