[Greg Troxel] gnus/dovecot open transactions panic

[Greg Troxel] gnus/dovecot open transactions panic

[Greg Troxel]

[-- Attachment #1.1: Type: text/plain, Size: 700 bytes --]


I'm not sure if this is a dovecot or gnus issue.

The problem happens at:

  commit 18836c407ba5a49028cc957fa511195199dbbd77
  Author: Julien Danjou <julien@danjou.info>
  Date:   Mon Oct 25 17:40:10 2010 +0200

      Remove gnus-with-local-quit

      Signed-off-by: Julien Danjou <julien@danjou.info>

but seems not to at:

  commit bf9d34407b6ba1fdd35573efeb8f4de213273421
  Author: Lars Magne Ingebrigtsen <larsi@quimbies.gnus.org>
  Date:   Thu Oct 7 15:24:43 2010 +0200

      (shr-insert): Don't leave trailing spaces.


I don't mean to malign Julien - that commit is surely fine but I haven't
bisected the 210 in between.  And I think it's likely gnus is being
legal but more aggressive.




[-- Attachment #1.2: Type: message/rfc822, Size: 2704 bytes --]

[-- Attachment #1.2.1.1: Type: text/plain, Size: 1789 bytes --]


I have been using dovecot with gnus for a long time.  Recently, I
started getting failures, and I think it's a dovecot problem triggered
by gnus being more aggressive, but I'd like to hear opinions about
whether I should pursue this as a gnus bug.

The log shows:

Oct 25 19:27:36 gdtserver dovecot: IMAP(gdt): Panic: Trying to close mailbox foo.bar with open transactions
Oct 25 19:27:36 gdtserver dovecot: dovecot: child 26231 (imap) killed with signal 6 (core not dumped - set mail_drop_priv_before_exec=yes)

and this seems to be triggered when dovecot is going GCC: to a local
mailbox (not imap) when sending, but also semi-randomly.

most of dovecot -n: (I'm sure that I'm not having auth problems and
would rather not post that part):

  # 1.2.14: /usr/pkg/etc/dovecot.conf
  # OS: NetBSD 5.1_RC1 i386  
  protocols: imaps
  login_dir: /var/run/dovecot/login
  login_executable: /usr/pkg/libexec/dovecot/imap-login
  login_processes_count: 4
  login_max_processes_count: 16
  max_mail_processes: 32
  first_valid_uid: 128
  mail_location: maildir:~/IMAP

I have 162 mailboxes polled by gnus on this dovecot instance.
I get the panic on various mailboxes and I can't see a pattern.

I do get

  Checking new news...
  nnimap-send-command: SIGPIPE raised on process *nnimap*; closed it

From gnus.  I then look at the listed one in the panic, and *imap-log*
From gnus.  This just may be an artifact of pipelining, but the
panic-list mbox has 30 more after it that were sent, as in:

  19:35:43 506 EXAMINE "mbox.named-in-panic" (QRESYNC (1208908407 1))
  [30 more lines]

I'm guessing that this is a dovecot problem.  I realize I should update
to 1.2.15 :-) but I didn't see anything in the 1.2.15 release notes that
looks like a match.

[-- Attachment #1.2.1.2: Type: application/pgp-signature, Size: 194 bytes --]

[-- Attachment #2: Type: application/pgp-signature, Size: 194 bytes --]

Re: [Greg Troxel] gnus/dovecot open transactions panic

[Julien Danjou]

On Tue, Oct 26 2010, Greg Troxel wrote:
> I don't mean to malign Julien - that commit is surely fine but I haven't
> bisected the 210 in between.  And I think it's likely gnus is being
> legal but more aggressive.

Someone already reported a problem and bissected it to:
commit aeb7ed491090b5e9e372b6bbd1b2c90c814b6408
Author: Lars Magne Ingebrigtsen <larsi@quimbies.gnus.org>
Date:   Sun Oct 24 19:01:16 2010 +0200

    Make internal nnimap moving slightly faster.

IIRC. Could you check?

-- 
Julien Danjou
// ᐰ <julien@danjou.info>   http://julien.danjou.info

Re: [Greg Troxel] gnus/dovecot open transactions panic

[Greg Troxel]

[-- Attachment #1: Type: text/plain, Size: 1257 bytes --]


  On Tue, Oct 26 2010, Greg Troxel wrote:
  > I don't mean to malign Julien - that commit is surely fine but I haven't
  > bisected the 210 in between.  And I think it's likely gnus is being
  > legal but more aggressive.

  Someone already reported a problem and bissected it to:
  commit aeb7ed491090b5e9e372b6bbd1b2c90c814b6408
  Author: Lars Magne Ingebrigtsen <larsi@quimbies.gnus.org>
  Date:   Sun Oct 24 19:01:16 2010 +0200

      Make internal nnimap moving slightly faster.

  IIRC. Could you check?

Thanks; that motivated me to bisect myself which only took 30 minutes
even with manual testing of each one.

I bisected and ended up doing it twice because the failure is somewhat
random.  I am now pretty confident that gnus at commit is ok for me:

  commit c16f36e878d299b657219ef8f77069a533baf80b
  Author: Lars Magne Ingebrigtsen <larsi@quimbies.gnus.org>
  Date:   Sun Oct 10 15:59:03 2010 +0200

      (nnimap-update-info): Prefer old info over start-article.

and at this one is not:

  commit d94b7a5c0467749d9f4b8273db197992b379ddf7
  Author: Lars Magne Ingebrigtsen <larsi@quimbies.gnus.org>
  Date:   Sun Oct 10 16:32:20 2010 +0200

      (nnimap-update-qresync-info): Finish implementing QRESYNC.


I have not studied the diff yet.


[-- Attachment #2: Type: application/pgp-signature, Size: 194 bytes --]

Re: [Greg Troxel] gnus/dovecot open transactions panic

[Lars Magne Ingebrigtsen]

Greg Troxel <gdt@work.lexort.com> writes:

> I have not studied the diff yet.

Did you look into this any further?

-- 
(domestic pets only, the antidote for overdose, milk.)
  larsi@gnus.org * Lars Magne Ingebrigtsen

Re: [Greg Troxel] gnus/dovecot open transactions panic

[Greg Troxel]

[-- Attachment #1: Type: text/plain, Size: 2017 bytes --]


Lars Magne Ingebrigtsen <larsi@gnus.org> writes:

> Greg Troxel <gdt@work.lexort.com> writes:
>
>> I have not studied the diff yet.
>
> Did you look into this any further?

I read the diff and concluded that I did not understand it, or rather I
don't really understand the lisp code to use QRESYNC.  But, I have tried
disabling the use of QRESYNC (although it still gets enabled) and with
the commit at end gnus head seems to work fine with dovecot 1.2.14.
Without this commit (e.g. at 29e6eda39d4ff7e4a3fb82caf710446582ef3c03) I
get things like

  Oct 29 19:58:23 linuxpal dovecot: IMAP(gdt): Panic: Trying to close mailbox foo.bar with open transactions
  Oct 29 19:58:23 linuxpal dovecot: dovecot: child 28914 (imap) killed with signal 6 (core not dumped - set mail_drop_priv_before_exec=yes)

and in *imap log*

  19:58:23 1537 EXAMINE "foo.bar" (QRESYNC (1153316454 1))

followed by 109 more EXAMINE lines, all with qresync params.
Given that it's dovecot that's crashing, this is feeling like a dovecot bug.

commit 22437dbdecdae0e5c18b792686a5b42c0dbb1ff4
Author: Greg Troxel <gdt@lexort.com>
Date:   Fri Oct 29 19:34:31 2010 -0400

    disable use of QRESYNC (dovecot bug)?

diff --git a/lisp/nnimap.el b/lisp/nnimap.el
index 5c4476f..bea47f9 100644
--- a/lisp/nnimap.el
+++ b/lisp/nnimap.el
@@ -1031,7 +1031,7 @@ textual parts.")
     (with-current-buffer (nnimap-buffer)
       (erase-buffer)
       (setf (nnimap-group nnimap-object) nil)
-      (let ((qresyncp (member "QRESYNC" (nnimap-capabilities nnimap-object)))
+      (let ((qresyncp (member "notQRESYNC" (nnimap-capabilities nnimap-object)))
 	    params groups sequences active uidvalidity modseq group)
 	;; Go through the infos and gather the data needed to know
 	;; what and how to request the data.


which is on top of

commit 29e6eda39d4ff7e4a3fb82caf710446582ef3c03
Author: Lars Magne Ingebrigtsen <larsi@quimbies.gnus.org>
Date:   Sat Oct 30 01:30:55 2010 +0200

    Allow the user to say whether to split old messages or not in nnimap.

[-- Attachment #2: Type: application/pgp-signature, Size: 194 bytes --]

Re: [Greg Troxel] gnus/dovecot open transactions panic

[Lars Magne Ingebrigtsen]

Greg Troxel <gdt@work.lexort.com> writes:

>   Oct 29 19:58:23 linuxpal dovecot: IMAP(gdt): Panic: Trying to close mailbox foo.bar with open transactions
>   Oct 29 19:58:23 linuxpal dovecot: dovecot: child 28914 (imap) killed with signal 6 (core not dumped - set mail_drop_priv_before_exec=yes)
>
> and in *imap log*
>
>   19:58:23 1537 EXAMINE "foo.bar" (QRESYNC (1153316454 1))
>
> followed by 109 more EXAMINE lines, all with qresync params.
> Given that it's dovecot that's crashing, this is feeling like a dovecot bug.

It sounds like it, but there might be a Gnus pattern that triggers the
bug, and perhaps Gnus could work around that.  Do you see anything in
particular that makes dovecot panic?  Is there a specific mailbox that
triggers this, or, uhm.  Something?  :-)

-- 
(domestic pets only, the antidote for overdose, milk.)
  larsi@gnus.org * Lars Magne Ingebrigtsen

Re: [Greg Troxel] gnus/dovecot open transactions panic

[Greg Troxel]

[-- Attachment #1: Type: text/plain, Size: 1291 bytes --]


Lars Magne Ingebrigtsen <larsi@gnus.org> writes:

> Greg Troxel <gdt@work.lexort.com> writes:
>
>>   Oct 29 19:58:23 linuxpal dovecot: IMAP(gdt): Panic: Trying to close mailbox foo.bar with open transactions
>>   Oct 29 19:58:23 linuxpal dovecot: dovecot: child 28914 (imap) killed with signal 6 (core not dumped - set mail_drop_priv_before_exec=yes)
>>
>> and in *imap log*
>>
>>   19:58:23 1537 EXAMINE "foo.bar" (QRESYNC (1153316454 1))
>>
>> followed by 109 more EXAMINE lines, all with qresync params.
>> Given that it's dovecot that's crashing, this is feeling like a dovecot bug.
>
> It sounds like it, but there might be a Gnus pattern that triggers the
> bug, and perhaps Gnus could work around that.  Do you see anything in
> particular that makes dovecot panic?  Is there a specific mailbox that
> triggers this, or, uhm.  Something?  :-)

No, it's pretty random. Sometimes there are 30 EXAMINEs in the log after
the one that fails, sometimes 100.  Sometimes everything works fine.  I
can push 'g' several times in a row and tehn it fails.  I have about 160
mailboxes.

It seems legit to make 160 EXAMINE calls in a row.  But I didn't hear
anything from my post to dovecot, and I haven't stepped into dovecot
debugging.


Is anyone else using dovecot 1.2 with lots of mailboxes?

[-- Attachment #2: Type: application/pgp-signature, Size: 194 bytes --]

Re: [Greg Troxel] gnus/dovecot open transactions panic

[Greg Troxel]

[-- Attachment #1: Type: text/plain, Size: 1028 bytes --]


Lars Magne Ingebrigtsen <larsi@gnus.org> writes:

> Greg Troxel <gdt@work.lexort.com> writes:
>
>>   Oct 29 19:58:23 linuxpal dovecot: IMAP(gdt): Panic: Trying to
>> close mailbox foo.bar with open transactions Oct 29 19:58:23
>> linuxpal dovecot: dovecot: child 28914 (imap) killed with signal 6
>> (core not dumped - set mail_drop_priv_before_exec=yes)
>> and in *imap log*
>> 19:58:23 1537 EXAMINE "foo.bar" (QRESYNC (1153316454 1))
>> followed by 109 more EXAMINE lines, all with qresync params.  Given
>> that it's dovecot that's crashing, this is feeling like a dovecot
>> bug.
>
> It sounds like it, but there might be a Gnus pattern that triggers the
> bug, and perhaps Gnus could work around that.  Do you see anything in
> particular that makes dovecot panic?  Is there a specific mailbox that
> triggers this, or, uhm.  Something?  :-)

Dovecot author says this is the fix.  I'll try it when I get a chance.
I don't think any gnus workaround would be reasonable.

http://hg.dovecot.org/dovecot-1.2/rev/b30af25c622d


[-- Attachment #2: Type: application/pgp-signature, Size: 194 bytes --]

Re: [Greg Troxel] gnus/dovecot open transactions panic

[Greg Troxel]

[-- Attachment #1: Type: text/plain, Size: 167 bytes --]


This was a bug in dovecot, and Timo fixed it very quickly.  I have
updated dovecot to 1.2.16, and the problem with QRESYNC is fixed, so
this never was a gnus issue.


[-- Attachment #2: Type: application/pgp-signature, Size: 194 bytes --]