On 5/14/2008, Peter Eriksson (peter@ifm.liu.se) wrote:

...

Also, output of dovecot -n, and more platform details (ie, are you using NFS?) will make it easier for someone (else) to help...

NFS: Yes.

Ok, then dovecot -n output may be necessary... there are some issues with NFS on the 1.0.x versions that are supposedly fixed properly in 1.1...

Timo has said more than once that if you are using NFS, then you really should be using 1.1

--

Best regards,

Charles

On 5/14/2008, Peter Eriksson (peter@ifm.liu.se) wrote:

I hope the performance is better since 1.0's performance (on our system) is really bad (so bad that some of my users have been complaining since it feels more sluggish than the older UW-Imap-based system (which granted had it mail spool on local disks). Another thing I'm thinking about is going back to have the mail spool on local disks but I'd rather avoid that if I can.

then something is not right in your setup, becasue dovecots performance is much better than courier-iamp or UW...

How many times do I have to ask for dovecot -n output?? That might point to where your config is fubared and causing your performance problems - but it is most likely a configuration issue related to NFS...

Just try 1.1 - I think you'll just end up asking yourself why you waited so long...

;)

--

Best regards,

Charles

Timo Sirainen wrote:

On Wed, 2008-05-14 at 12:29 +0200, Peter Eriksson wrote:

...

May 14 11:46:51 ifm.liu.se dovecot: [ID 107833 mail.error] IMAP(joher): file maildir-uidlist.c: line 143: assertion failed: (UIDLIS T_IS_LOCKED(uidlist))

If this still hapens with 1.0.13, it would help to get a gdb backtrace. http://dovecot.org/bugreport.html

Now 1.0.13 crashed for me. Here's the relevant parts of the syslog file:

May 20 15:16:30 ifm.liu.se dovecot: [ID 107833 mail.info] auth(default): new auth connection: pid=11109 May 20 15:16:30 ifm.liu.se dovecot: [ID 107833 mail.info] auth(default): new auth connection: pid=11108 May 20 15:16:32 ifm.liu.se dovecot: [ID 107833 mail.error] IMAP(inand): file mail-index-view-sync.c: line 666: assertion failed: (v iew->log_file_offset >= view->map->hdr.log_file_int_offset) May 20 15:16:32 ifm.liu.se dovecot: [ID 107833 mail.error] IMAP(inand): Raw backtrace: 0x100082ee8 -> 0x1000630d4 -> 0x10004b484 -> 0x1000203e8 -> 0x1000209dc -> 0x100011f90 -> 0x100016e74 -> 0x100017294 -> 0x10008ac90 -> 0x10008a170 -> 0x100022cc8 -> 0x10001003 c May 20 15:16:32 ifm.liu.se dovecot: [ID 684838 mail.error] child 11097 (imap) killed with signal 6 May 20 15:16:32 ifm.liu.se dovecot: [ID 107833 mail.warning] IMAP(natro): Killed with signal 15 May 20 15:16:32 ifm.liu.se dovecot: [ID 107833 mail.warning] IMAP(inand): Killed with signal 15 May 20 15:16:32 ifm.liu.se dovecot: [ID 107833 mail.info] IMAP(inand): Server shutting down May 20 15:16:32 ifm.liu.se dovecot: [ID 107833 mail.warning] imap-login: Killed with signal 15 May 20 15:16:32 ifm.liu.se dovecot: [ID 107833 mail.info] IMAP(natro): Server shutting down

...

Output from "dovecot-n" attached.

Dovecot version: 1.0.13 (yes yes, I will try out 1.1 soon :-) Operating system: Solaris 10 CPU: SPARC Hardware: Sun Fire T1000 Filesystem: NFSv4 from a Sun Fire X4500 (Thumper) server with ZFS. Mailstore: Maildir

Exactly what was being done when it crashes is unclear (typically we have around 220 imap processes running)

I checked out that users Maildir folder but couldn't really see anything special. I know that user has been trying out Microsoft Outlook lately (we normally use Thunderbird, Eudora or Outlook Express).

No core dump for now.

• Peter

1.0.13: /etc/dovecot.conf

base_dir: /var/run/dovecot/ protocols: imap pop3 imaps pop3s ssl_ca_file: /ifm/etc/certs/dovecot-CA.cert.pem ssl_cert_file: /ifm/etc/certs/dovecot-ifm.cert.pem ssl_key_file: /ifm/etc/certs/dovecot-ifm.key.pem login_dir: /var/run/dovecot/login login_executable(default): /ifm/libexec/dovecot/imap-login login_executable(imap): /ifm/libexec/dovecot/imap-login login_executable(pop3): /ifm/libexec/dovecot/pop3-login login_greeting: Welcome to the IFM Dovecot Server. first_valid_uid: 100 mail_location: maildir:Maildir mmap_disable: yes maildir_copy_with_hardlinks: yes mbox_write_locks: fcntl mail_executable(default): /ifm/libexec/dovecot/imap mail_executable(imap): /ifm/libexec/dovecot/imap mail_executable(pop3): /ifm/libexec/dovecot/pop3 mail_plugin_dir(default): /ifm/lib/dovecot/imap mail_plugin_dir(imap): /ifm/lib/dovecot/imap mail_plugin_dir(pop3): /ifm/lib/dovecot/pop3 imap_capability(default): CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS AUTH=PLAIN AUTH=LOGIN AUTH=GSSAPI imap_capability(imap): CAPABILITY IMAP4rev1 SASL-IR SORT THREAD=REFERENCES MULTIAPPEND UNSELECT LITERAL+ CHILDREN NAMESPACE LOGIN-REFERRALS STARTTLS AUTH=PLAIN AUTH=LOGIN AUTH=GSSAPI imap_capability(pop3): imap_client_workarounds(default): outlook-idle delay-newmail imap_client_workarounds(imap): outlook-idle delay-newmail imap_client_workarounds(pop3): outlook-idle pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %08Xu%08Xv pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh namespace: type: private separator: / inbox: yes namespace: type: private separator: / prefix: mail/ hidden: yes namespace: type: private separator: / prefix: Mail/ hidden: yes namespace: type: private separator: / prefix: ~/mail/ hidden: yes namespace: type: private separator: / prefix: ~/Mail/ hidden: yes namespace: type: private separator: / prefix: ~%u/mail/ hidden: yes namespace: type: private separator: / prefix: ~%u/Mail/ hidden: yes auth default: mechanisms: plain login gssapi executable: /ifm/libexec/dovecot/dovecot-auth verbose: yes debug: yes passdb: driver: pam userdb: driver: passwd

Noticed some more stuff this time:

May 20 19:37:38 ifm.liu.se dovecot: [ID 107833 mail.error] IMAP(joher): block_alloc(): Out of memory May 20 19:37:38 ifm.liu.se dovecot: [ID 961074 mail.error] child 10772 (imap) returned error 83 (Out of memory) May 20 19:40:47 ifm.liu.se dovecot: [ID 107833 mail.error] IMAP(joher): block_alloc(): Out of memory May 20 19:40:47 ifm.liu.se dovecot: [ID 961074 mail.error] child 11002 (imap) returned error 83 (Out of memory) May 20 19:42:25 ifm.liu.se dovecot: [ID 107833 mail.error] IMAP(jordi): file mail-index-view-sync.c: line 666: assertion failed: (view->log_file_offset >= vie w->map->hdr.log_file_int_offset) May 20 19:42:25 ifm.liu.se dovecot: [ID 107833 mail.error] IMAP(jordi): Raw backtrace: 0x100082ee8 -> 0x1000630d4 -> 0x10004b484 -> 0x1000203e8 -> 0x1000209dc -> 0x100011f90 -> 0x100016e74 -> 0x100017294 -> 0x10008ac90 -> 0x10008a170 -> 0x100022cc8 -> 0x10001003c May 20 19:42:25 ifm.liu.se dovecot: [ID 684838 mail.error] child 11281 (imap) killed with signal 6

It's always the same user causing these "Out of memory" errors (unlikely since this machine has 8GB of RAM and XXGB of swap and typically has plenty of memory free. His maildir directory is 1.4GB in size.

Hmm... He seems to have a *huge* Trash folder... About 3.5 _milllion_ mails in it... I wonder...

I bet his imap process runs into a system limit (even though it is a 64 bit process). Yeah...

# plimit 17233 17233: imap resource current maximum time(seconds) unlimited unlimited file(blocks) unlimited unlimited data(kbytes) 262144 262144 stack(kbytes) 8192 unlimited coredump(blocks) unlimited unlimited nofiles(descriptors) 16384 16384 vmemory(kbytes) 262144 262144

I bet it's the stacksize that get's exhausted trying to lhandle all those 3.5 million emails.

Question: Should Dovecot handle this better somehow?

• Peter

Timo Sirainen wrote:

On May 20, 2008, at 10:53 PM, Peter Eriksson wrote:

...

It's always the same user causing these "Out of memory" errors (unlikely since this machine has 8GB of RAM and XXGB of swap and typically has plenty of memory free. His maildir directory is 1.4GB in size.

Hmm... He seems to have a *huge* Trash folder... About 3.5 _milllion_ mails in it... I wonder...

I bet his imap process runs into a system limit (even though it is a 64 bit process). Yeah...

mail_process_size setting limits this to 256 MB by default. You could increase it or drop it completely. It's there mainly to catch memory leaks and such because users rarely reach this limit.

...

Question: Should Dovecot handle this better somehow?

Perhaps the error message could mention mail_process_size setting. :)

Perhaps. Or some sizing guidelines next to that setting in the config file so one can make some decision on how many mails you wish to support per folder... (Ie, 256MB -> max 471142 mails). Might be difficult to get an exakt number depending on CPU limits (alignment of data types in structs and stuff).

Btw, why is the whole Dovecot system shutting down due to a bug in the 'imap' subprocess? It's rather annoying for the rest of the users...

• Peter

...

Btw, why is the whole Dovecot system shutting down due to a bug in the 'imap' subprocess? It's rather annoying for the rest of the users...

It shouldnt' be.

...

May 20 15:16:32 ifm.liu.se dovecot: [ID 107833 mail.info] IMAP(inand): Server shutting down

Do you mean you didn't cause this manually?

Right.

Hmm.. I wonder if it might be due to the Solaris SMF system seeing the coredump (and/or signals) and deciding that the system it is monitoring has failed and thus shuts it down. (I use SMF to handle Dovecot).

Ah! Yes, that's why!

# tail -18 /var/svc/log/network-dovecot:default.log [ May 20 15:16:32 Stopping because process dumped core. ] [ May 20 15:16:32 Executing stop method (:kill) ] [ May 20 15:17:02 Method or service exit timed out. Killing contract 6893 ] [ May 20 15:24:03 Leaving maintenance because clear requested. ] [ May 20 15:24:03 Enabled. ] [ May 20 15:24:04 Executing start method ("/ifm/sbin/start_dovecot") ] [ May 20 15:24:04 Method "start" exited with status 0 ] [ May 20 19:42:25 Stopping because process dumped core. ] [ May 20 19:42:25 Executing stop method (:kill) ] [ May 20 19:42:56 Method or service exit timed out. Killing contract 7854 ] [ May 20 21:26:45 Leaving maintenance because clear requested. ] [ May 20 21:26:45 Enabled. ] [ May 20 21:26:46 Executing start method ("/ifm/sbin/start_dovecot") ] [ May 20 21:26:46 Method "start" exited with status 0 ] [ May 21 08:35:34 Stopping because process dumped core. ] [ May 21 08:35:34 Executing stop method (:kill) ] [ May 21 08:35:34 Executing start method ("/ifm/sbin/start_dovecot") ] [ May 21 08:35:34 Method "start" exited with status 0 ]

Hmm...

Ah! The Solaris SMF FAQ 4.5 has a good answer on how to fix that. Add the following to the Solaris SMF manifest that controls Dovecot:

<propval name='ignore_error' type='astring' value='core,signal' />

Please find enclosed an updated Solaris SMF manifest that others might be interested in using on Solaris 10/OpenSolaris systems...

• Peter

Somehow I don't think "usr/bin/krb5-config: Unknown option gssapi' -- use --help' for usage" is a valid C compiler option. :-)

I've been looking at the configure code in an attempt to fix this. It feels a bit "kludgy". First stepI think should be to modify the code in "configure.in" on line 1619 from:

if krb5-config --version|grep -v '1\.2' > /dev/null; then

to:

if krb5-config --version gssapi|grep -v '1\.2' > /dev/null; then

since it is the "gssapi" stuff that is checked later down in that code section using "krb5-config --cflags gssapi" and "--libs gssapi".

Now, that will make the whole code section fail for later Solaris 10 releases (/usr/bin/krb5-config appeared in Solaris 10 8/07 I think (it's not there in 11/06), but that's better than the current behaviour.

I assume "krb5-config --version gssapi" will work on Linux systems.

Next step would be to modify the code to still check for GSSAPI headers and libraries even though krb5-config exists but doesn't support the "gssapi" argument...

• Peter

Timo Sirainen wrote:

On Fri, 2008-05-23 at 10:46 +0200, Peter Eriksson wrote:

...

Next step would be to modify the code to still check for GSSAPI headers and libraries even though krb5-config exists but doesn't support the "gssapi" argument...

Does this work? http://hg.dovecot.org/dovecot-1.1/rev/e6187b556b65

Almost. It still adds the incorrect flags to CFLAGS, but it checks the other stuff. Output from config.log:

## ----------------- ## ## Output variables. ## ## ----------------- ##

ACLOCAL='${SHELL} /home/peter/extsrc/dovecot/dovecot-1.1.rc5-ifm/missing --run aclocal-1.10' AMDEPBACKSLASH='\' AMDEP_FALSE='#' AMDEP_TRUE='' AMTAR='${SHELL} /home/peter/extsrc/dovecot/dovecot-1.1.rc5-ifm/missing --run tar' AR='ar' AUTH_CFLAGS=' /usr/bin/krb5-config: Unknown option gssapi'\'' -- use --help'\'' for usage' AUTH_LIBS=' -lpam -L/usr/lib -R/usr/lib -fast -m64 -L/ifm/lib/64 -R/ifm/lib/64 -L/ifm/lib/64 -R/ifm/lib/64 -L/usr/sfw/lib/64 -R/usr/sfw/lib/64 -I/usr/sfw/include -lkrb5 -lgss -lgss' AUTOCONF='${SHELL} /home/peter/extsrc/dovecot/dovecot-1.1.rc5-ifm/missing --run autoconf' AUTOHEADER='${SHELL} /home/peter/extsrc/dovecot/dovecot-1.1.rc5-ifm/missing --run autoheader' AUTOMAKE='${SHELL} /home/peter/extsrc/dovecot/dovecot-1.1.rc5-ifm/missing --run automake-1.10' AWK='gawk'

• Peter

Timo Sirainen wrote:

On Mon, 2008-05-26 at 10:37 +0200, Peter Eriksson wrote:

...

Timo Sirainen wrote:

...

On Fri, 2008-05-23 at 10:46 +0200, Peter Eriksson wrote:

...

Next step would be to modify the code to still check for GSSAPI headers and libraries even though krb5-config exists but doesn't support the "gssapi" argument... Does this work? http://hg.dovecot.org/dovecot-1.1/rev/e6187b556b65

Almost. It still adds the incorrect flags to CFLAGS, but it checks the other stuff. Output from config.log:

Oh, how about now: http://hg.dovecot.org/dovecot-1.1/rev/419b7cfc954c

Yep. Looking much better. Now things compile :-)

Btw, I got the following warnings from "autoconf" when I ran it on the updated configure.in file. (I have autoconf 2.62).

% autoconf aclocal.m4:16: warning: this file was generated for autoconf 2.61. You have another version of autoconf. It may work, but is not guaranteed to. If you have problems, you may need to regenerate the build system entirely. To do so, use the procedure documented by the package, typically `autoreconf'. configure.in:440: warning: AC_CACHE_VAL(epoll_works, ...): suspicious cache-id, must contain _cv_ to be cached ../../lib/autoconf/general.m4:1973: AC_CACHE_VAL is expanded from... ../../lib/autoconf/general.m4:1993: AC_CACHE_CHECK is expanded from... configure.in:440: the top level configure.in:492: warning: AC_CACHE_VAL(inotify_works, ...): suspicious cache-id, must contain _cv_ to be cached configure.in:492: the top level configure.in:812: warning: AC_CACHE_VAL(signed_size_t, ...): suspicious cache-id, must contain _cv_ to be cached configure.in:812: the top level configure.in:927: warning: AC_CACHE_VAL(gmtime_max_time_t, ...): suspicious cache-id, must contain _cv_ to be cached configure.in:927: the top level configure.in:967: warning: AC_CACHE_VAL(signed_time_t, ...): suspicious cache-id, must contain _cv_ to be cached configure.in:967: the top level configure.in:1054: warning: AC_CACHE_VAL(mmap_plays_with_write, ...): suspicious cache-id, must contain _cv_ to be cached configure.in:1054: the top level configure.in:1096: warning: AC_CACHE_VAL(fd_passing, ...): suspicious cache-id, must contain _cv_ to be cached configure.in:1096: the top level configure.in:1338: warning: AC_CACHE_VAL(c99_vsnprintf, ...): suspicious cache-id, must contain _cv_ to be cached configure.in:1338: the top level

• Peter