bug#8959: 24.0.50; [nnimap/Gnus] Dovecot panics trying to close mailboxes

bug#8959: 24.0.50; [nnimap/Gnus] Dovecot panics trying to close mailboxes

[Luca Capello]

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

Hi there!

I did not have time before to report this, sorry.

At least from 20110226 (emacs-snapshot_1:20110210-1 according to my
dpkg.log) sometime while checking for new emails Gnus hangs on the
message "nnimap read $KILOBYTES".  The remote Dovecot log shows the
following:
=====
Jun 29 21:10:08 mantissa dovecot: imap-login: Login: user=<luca.capello>, \
 method=PLAIN, rip=[REMOVED], lip=[REMOVED, TLS
Jun 29 21:10:10 mantissa dovecot: IMAP(luca.capello): Panic: Trying to close mailbox \
 lists.Debian.pkg.CL-Debian with open transactions
Jun 29 21:10:10 mantissa dovecot: IMAP(luca.capello): Raw backtrace: \
 imap() [0x4a518a] -> imap() [0x4a51f3] -> imap() [0x4a48f6] -> \
 imap() [0x46c5b4] -> imap() [0x420e15] -> imap(cmd_select_full+0xd1) [0x420f91] -> \
 imap() [0x423a6d] -> imap() [0x423b4d] -> imap(client_handle_input+0x135) [0x423d75] -> \
 imap(client_input+0x5c) [0x42462c] -> imap(io_loop_handler_run+0xbd) [0x4ad22d] -> \
 imap(io_loop_run+0x18) [0x4ac6a8] -> imap(main+0x531) [0x42c371] -> \
 /lib/libc.so.6(__libc_start_main+0xfd) [0x7fe5710aec4d] -> imap() [0x41c709]
Jun 29 21:10:10 mantissa dovecot: dovecot: child 25848 (imap) killed with signal 6 \
 (core dumps disabled)
[...]
Jun 29 21:10:32 mantissa dovecot: imap-login: Login: user=<luca.capello>, \
 method=PLAIN, rip=[REMOVED], lip=[REMOVED], TLS
Jun 29 21:10:33 mantissa dovecot: IMAP(luca.capello): Panic: Trying to close mailbox \
 people.JeromeRandall with open transactions
Jun 29 21:10:33 mantissa dovecot: IMAP(luca.capello): Raw backtrace: \
 imap() [0x4a518a] -> imap() [0x4a51f3] -> imap() [0x4a48f6] -> imap() [0x46c5b4] -> \
 imap() [0x420e15] -> imap(cmd_select_full+0xd1) [0x420f91] -> imap() [0x423a6d] -> \
 imap() [0x423b4d] -> imap(client_handle_input+0x135) [0x423d75] -> \
 imap(client_input+0x5c) [0x42462c] -> imap(io_loop_handler_run+0xbd) [0x4ad22d] -> \
 imap(io_loop_run+0x18) [0x4ac6a8] -> imap(main+0x531) [0x42c371] -> \
 /lib/libc.so.6(__libc_start_main+0xfd) [0x7f83dece0c4d] -> imap() [0x41c709]
Jun 29 21:10:33 mantissa dovecot: dovecot: child 25853 (imap) killed with signal 6 \
 (core dumps disabled)
[...]

Jun 29 21:28:35 mantissa dovecot: imap-login: Login: user=<luca.capello>, \
 method=PLAIN, rip=[REMOVED], lip=[REMOVED], TLS
Jun 29 21:28:36 mantissa dovecot: IMAP(luca.capello): Panic: Trying to close mailbox \
 support.it.Euronet-Genesi with open transactions
Jun 29 21:28:36 mantissa dovecot: IMAP(luca.capello): Raw backtrace: \
 imap() [0x4a518a] -> imap() [0x4a51f3] -> imap() [0x4a48f6] -> imap() [0x46c5b4] -> \
 imap() [0x420e15] -> imap(cmd_select_full+0xd1) [0x420f91] -> imap() [0x423a6d] -> \
 imap() [0x423b4d] -> imap(client_handle_input+0x135) [0x423d75] -> \
 imap(client_input+0x5c) [0x42462c] -> imap(io_loop_handler_run+0xbd) [0x4ad22d] -> \
 imap(io_loop_run+0x18) [0x4ac6a8] -> imap(main+0x531) [0x42c371] -> \
 /lib/libc.so.6(__libc_start_main+0xfd) [0x7fd2bb4f7c4d] -> imap() [0x41c709]
Jun 29 21:28:36 mantissa dovecot: dovecot: child 26171 (imap) killed with signal 6 \
 (core dumps disabled)
[...]

Jun 29 21:28:38 mantissa dovecot: imap-login: Login: user=<luca.capello>, \
 method=PLAIN, rip=[REMOVED], lip=[REMOVED], TLS
Jun 29 21:28:43 mantissa dovecot: IMAP(luca.capello): Connection closed bytes=21/325
Jun 29 21:30:03 mantissa dovecot: IMAP(luca.capello): Disconnected: Logged out bytes=49/47763
=====

For the Gnus side, I have attached the `*imap log*' buffer as well as
the 4 `*nnimap home.pca.it nil *nntpd**' ones.  About the latter, given
that I use hibernation quite extensively (usually at least for more than
10 days), I remember that I saw even more than 20 of them...  Moreover,
why they are called 'nntpd' for IMAP?

Please note that I have never experienced similar bugs with the old
nnimap implementation.

Thx, bye,
Gismo / Luca


In GNU Emacs 24.0.50.1 (x86_64-pc-linux-gnu, GTK+ Version 2.24.3)
 of 2011-04-08 on cigue, modified by Debian
 (emacs-snapshot package, version 1:20110408-1)
configured using `configure  '--build' 'x86_64-linux-gnu' '--host' 'x86_64-linux-gnu' '--prefix=/usr' '--sharedstatedir=/var/lib' '--libexecdir=/usr/lib' '--localstatedir=/var' '--infodir=/usr/share/info' '--mandir=/usr/share/man' '--with-pop=yes' '--enable-locallisppath=/etc/emacs-snapshot:/etc/emacs:/usr/local/share/emacs/24.0.50/site-lisp:/usr/local/share/emacs/site-lisp:/usr/share/emacs/24.0.50/site-lisp:/usr/share/emacs/site-lisp' '--without-compress-info' '--with-x=yes' '--with-x-toolkit=gtk' '--with-imagemagick=yes' 'build_alias=x86_64-linux-gnu' 'host_alias=x86_64-linux-gnu' 'CFLAGS=-DDEBIAN -DSITELOAD_PURESIZE_EXTRA=5000 -g -O2' 'LDFLAGS=-g -Wl,--as-needed' 'CPPFLAGS=''

Important settings:
  value of $LC_ALL: nil
  value of $LC_COLLATE: nil
  value of $LC_CTYPE: nil
  value of $LC_MESSAGES: en_US.UTF-8
  value of $LC_MONETARY: nil
  value of $LC_NUMERIC: en_US.UTF-8
  value of $LC_TIME: nil
  value of $LANG: en_US.UTF-8
  value of $XMODIFIERS: nil
  locale-coding-system: utf-8-unix
  default enable-multibyte-characters: t

Major mode: Fundamental

Minor modes in effect:
  gpm-mouse-mode: t
  display-battery-mode: t
  display-time-mode: t
  show-paren-mode: t
  mouse-wheel-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  column-number-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent input:
C-c ESC f g ESC [ B ESC [ B ESC [ A ESC [ A g C-x b 
n n i m RET ESC x r e p o r t TAB e m TAB b TAB RE
T

Recent messages:
nnimap read 14k [10 times]
nnimap read 15k [7 times]
nnimap read 16k [11 times]
nnimap read 17k [10 times]
nnimap read 18k [12 times]
nnimap read 19k [10 times]
nnimap read 20k [6 times]
nnimap read 21k [10 times]
Reading active file via nndraft...done
Checking new news...done

Load-path shadows:
/usr/share/emacs/24.0.50/site-lisp/auctex/context-en hides /usr/share/emacs/site-lisp/auctex/context-en
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-style hides /usr/share/emacs/site-lisp/auctex/tex-style
/usr/share/emacs/24.0.50/site-lisp/auctex/texmathp hides /usr/share/emacs/site-lisp/auctex/texmathp
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-jp hides /usr/share/emacs/site-lisp/auctex/tex-jp
/usr/share/emacs/24.0.50/site-lisp/auctex/font-latex hides /usr/share/emacs/site-lisp/auctex/font-latex
/usr/share/emacs/24.0.50/site-lisp/auctex/latex hides /usr/share/emacs/site-lisp/auctex/latex
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-buf hides /usr/share/emacs/site-lisp/auctex/tex-buf
/usr/share/emacs/24.0.50/site-lisp/auctex/context-nl hides /usr/share/emacs/site-lisp/auctex/context-nl
/usr/share/emacs/24.0.50/site-lisp/auctex/toolbar-x hides /usr/share/emacs/site-lisp/auctex/toolbar-x
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-fold hides /usr/share/emacs/site-lisp/auctex/tex-fold
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-info hides /usr/share/emacs/site-lisp/auctex/tex-info
/usr/share/emacs/24.0.50/site-lisp/auctex/tex hides /usr/share/emacs/site-lisp/auctex/tex
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-font hides /usr/share/emacs/site-lisp/auctex/tex-font
/usr/share/emacs/24.0.50/site-lisp/auctex/context hides /usr/share/emacs/site-lisp/auctex/context
/usr/share/emacs/24.0.50/site-lisp/auctex/multi-prompt hides /usr/share/emacs/site-lisp/auctex/multi-prompt
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-fptex hides /usr/share/emacs/site-lisp/auctex/tex-fptex
/usr/share/emacs/24.0.50/site-lisp/auctex/bib-cite hides /usr/share/emacs/site-lisp/auctex/bib-cite
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-bar hides /usr/share/emacs/site-lisp/auctex/tex-bar
/usr/share/emacs/24.0.50/site-lisp/auctex/tex-mik hides /usr/share/emacs/site-lisp/auctex/tex-mik
/usr/share/emacs/24.0.50/site-lisp/debian-startup hides /usr/share/emacs/site-lisp/debian-startup
~/.emacs.d/elisp/fortune hides /usr/share/emacs/24.0.50/lisp/play/fortune

Features:
(shadow sort bbdb-hooks epa-mail gnus-cite footnote mail-extr emacsbug
gnus-topic nndraft nnmh nndoc utf-7 rot13 disp-table network-stream
starttls nnimap parse-time tls utf7 netrc nnml nnfolder nnnil gnus-agent
gnus-srvr gnus-score score-mode nnvirtual gnus-cache ielm comint ring
t-mouse server gismo-full-emacs ratpoison ratpoisonrc-mode generic
generic-x gismo-emacs gismo-modes battery time ido paren eldoc gismo-w3m
w3m-search w3m-session gismo-popup gismo-planner bbdb-anniv timeclock
view cal-china lunar solar cal-dst cal-bahai cal-islam cal-hebrew
holidays hol-loaddefs appt diary-lib diary-loaddefs icalendar cal-menu
calendar cal-loaddefs gismo-keybindings nroff-mode under dictionary link
connection w3m doc-view jka-compr image-mode w3m-hist w3m-fb
bookmark-w3m w3m-ems w3m-ccl ccl w3m-favicon w3m-image w3m-proc w3m-util
dired gismo-gnus gnus-demon nntp spam spam-stat gnus-uu yenc gnus-msg
gnus-art mm-uu mml2015 mm-view mml-smime smime dig nnir gnus-sum
gnus-group gnus-undo gnus-start gnus-spec gnus-win browse-url nnrss xml
mm-url url url-proxy url-privacy url-expand url-methods url-history
url-cookie url-util url-parse auth-source eieio byte-opt bytecomp
byte-compile cconv macroexp assoc password-cache url-vars mailcap nnmail
gnus-int gnus-range mail-source message sendmail rfc822 mml mml-sec
mm-decode mm-bodies mm-encode mail-parse rfc2231 gmm-utils mailheader
nnoo gnus gnus-ems nnheader gnus-util time-date mail-utils gnus-BTS
gismo-files gismo-eudc eudcb-ldap eudcb-bbdb bbdb-com mailabbrev cl eudc
eudc-options-file cus-edit cus-start cus-load eudc-vars wid-edit ldap
gismo-eshell gismo-erc erc-stamp erc-log erc-dcc erc-goodies erc
erc-backend erc-compat format-spec thingatpt pp gismo-easypg epa derived
epg epg-config gismo-dired gismo-debian debian-bug rfc2047 rfc2045
ietf-drums mm-util mail-prsvr gismo-broken gismo-bbdb bbdb timezone
gismo-auctex latex tex-style tex regexp-opt advice help-fns
advice-preload easymenu gismo-functions-insert gismo-functions
unicode-helper edmacro kmacro debian-el debian-el-loaddefs w3m-load
emacs-goodies-el emacs-goodies-custom emacs-goodies-loaddefs easy-mmode
dpkg-dev-el dpkg-dev-el-loaddefs bbdb-autoloads preview-latex tex-site
auto-loads tooltip ediff-hook vc-hooks lisp-float-type mwheel x-win
x-dnd tool-bar dnd fontset image fringe lisp-mode register page menu-bar
rfn-eshadow timer select scroll-bar mouse jit-lock font-lock syntax
facemenu font-core frame cham georgian utf-8-lang misc-lang vietnamese
tibetan thai tai-viet lao korean japanese hebrew greek romanian slovak
czech european ethiopic indian cyrillic chinese case-table epa-hook
jka-cmpr-hook help simple abbrev minibuffer loaddefs button faces
cus-face files text-properties overlay md5 base64 format env code-pages
mule custom widget hashtable-print-readable backquote
make-network-process dbusbind dynamic-setting font-render-setting
move-toolbar gtk x-toolkit x multi-tty emacs)


[-- Attachment #1.2: imap.log.gz --]
[-- Type: application/octet-stream, Size: 47291 bytes --]

[-- Attachment #1.3: nnimap_home.pca.it_nntpd.log.gz --]
[-- Type: application/octet-stream, Size: 15128 bytes --]

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

bug#8959: 24.0.50; [nnimap/Gnus] Dovecot panics trying to close mailboxes

[Lars Magne Ingebrigtsen]

Luca Capello <luca@pca.it> writes:

> At least from 20110226 (emacs-snapshot_1:20110210-1 according to my
> dpkg.log) sometime while checking for new emails Gnus hangs on the
> message "nnimap read $KILOBYTES".  The remote Dovecot log shows the
> following:
> =====
> Jun 29 21:10:08 mantissa dovecot: imap-login: Login: user=<luca.capello>, \
>  method=PLAIN, rip=[REMOVED], lip=[REMOVED, TLS
> Jun 29 21:10:10 mantissa dovecot: IMAP(luca.capello): Panic: Trying to close mailbox \
>  lists.Debian.pkg.CL-Debian with open transactions
> Jun 29 21:10:10 mantissa dovecot: IMAP(luca.capello): Raw backtrace: \
>  imap() [0x4a518a] -> imap() [0x4a51f3] -> imap() [0x4a48f6] -> \

[...]

> 21:28:36 2443 EXAMINE "lists.Debian.NewMaint" (QRESYNC (1277923816 1)).
> 21:28:36 2444 EXAMINE "lists.Debian.devel.general.2005" (QRESYNC (1277904533 1)).
> 21:28:36 2445 EXAMINE "lists.Debian.DebConf.Italian" (QRESYNC (1277903571 1)).
> 21:28:36 2446 EXAMINE "lists.Debian.pkg.CL-Debian" (QRESYNC (1277887546 1)).
> 21:28:36 2447 EXAMINE "lists.Debian.Hurd" (QRESYNC (1277899901 1)).
> 21:28:36 2448 EXAMINE "lists.DHCP-client" (QRESYNC (1277856131 1)).
> 21:28:36 2449 EXAMINE "lists.Linux.BlueZ-devel" (QRESYNC (1277835700 1)).

[...]

> * OK [UIDVALIDITY 1285242750] UIDs valid.
> * OK [UIDNEXT 9] Predicted next UID.
> * OK [HIGHESTMODSEQ 1] Highest.
> 1831 OK [READ-ONLY] Select completed..
> * OK [CLOSED] Previous mail*** Fatal error: A TLS packet with unexpected length was received.
> *** Server has terminated the connection abnormally.
>
> Process *nnimap* exited abnormally with code 1
> =====
>
> ===== [buffer: `*nnimap home.pca.it nil  *nntpd**<4>']
> * ENABLED QRESYNC.
> 2539 OK Enabled..
>
> Process *nnimap* killed
> =====

There seems to be two problems here.

1) Your dovecot is apparently segfaulting because of something Gnus is
doing.  Does it stop doing that if you `M-g' the
"lists.Debian.pkg.CL-Debian" group?  I have a suspicion that dovecot's
QRESYNC support is fragile, but I'm not sure what nnimap can do about
that except blacklist Dovecot from using QRESYNC.  Which kinda sucks.

2) When dovecot shut down the connection, nnimap seemed to open up a new
connection buffer, and starts waiting for the response to the previous
command there.  That's obviously an nnimap bug, and I'll see whether I
can chase that one down, but it's kinda difficult to reproduce...
hm...  perhaps if I use an external TLS connection, I can kill the
external program while it's working.  

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

bug#8959: 24.0.50; [nnimap/Gnus] Dovecot panics trying to close mailboxes

[Lars Magne Ingebrigtsen]

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

> 2) When dovecot shut down the connection, nnimap seemed to open up a new
> connection buffer, and starts waiting for the response to the previous
> command there.  That's obviously an nnimap bug, and I'll see whether I
> can chase that one down, but it's kinda difficult to reproduce...
> hm...  perhaps if I use an external TLS connection, I can kill the
> external program while it's working.  

It was easy enough to reproduce artificially.

I think I've now fixed this part in No Gnus.

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

bug#8959: 24.0.50; [nnimap/Gnus] Dovecot panics trying to close mailboxes

[Luca Capello]

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

Hi there!

On Thu, 30 Jun 2011 01:10:44 +0200, Lars Magne Ingebrigtsen wrote:
> Lars Magne Ingebrigtsen <larsi@gnus.org> writes:
>
>> 2) When dovecot shut down the connection, nnimap seemed to open up a new
>> connection buffer, and starts waiting for the response to the previous
>> command there.  That's obviously an nnimap bug, and I'll see whether I
>> can chase that one down, but it's kinda difficult to reproduce...
>> hm...  perhaps if I use an external TLS connection, I can kill the
>> external program while it's working.  
>
> It was easy enough to reproduce artificially.
>
> I think I've now fixed this part in No Gnus.

Thank you!  Anyway I will switch soon to OfflineIMAP+Dovecot(local): the
nnmaildir support is sub-optimal (#8055) and I want my emails accessible
outside Gnus as well (thus using the Gnus agent is a no-op).

Thx, bye,
Gismo / Luca

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

bug#8959: 24.0.50; [nnimap/Gnus] Dovecot panics trying to close mailboxes

[Luca Capello]

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

Hi there!

Thank you for the quick reply.

On Thu, 30 Jun 2011 00:55:47 +0200, Lars Magne Ingebrigtsen wrote:
> There seems to be two problems here.
>
> 1) Your dovecot is apparently segfaulting because of something Gnus is
> doing.  Does it stop doing that if you `M-g' the
> "lists.Debian.pkg.CL-Debian" group?

I tried with four other folders and it seems that the second time
Dovecot does not segfault, even in the fourth case where I had to
unfreeze Gnus with `C-g' before hitting `M-g'.

> I have a suspicion that dovecot's QRESYNC support is fragile, but I'm
> not sure what nnimap can do about that except blacklist Dovecot from
> using QRESYNC.  Which kinda sucks.

I did not search it before because I was ignorant about what to search,
thank you for the hint, I guess this is:

  <http://news.gmane.org/find-root.php?message_id=%3csmuvd4pdekg.fsf%40linuxpal.mit.edu%3e>

I have already backported the patch to the Debian stable package
(dovecot-imapd_1:1.2.15-7), so I will test it in the following days.

FYI, the only other QRESYNC problem I found seems to be fixed in Debian
squeeze as well, thus it should not be the right one, but still:

  <http://news.gmane.org/find-root.php?message_id=%3c1282166870.32196.9.camel%40macbook.infradead.org%3e>

Thx, bye,
Gismo / Luca

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

bug#8959: 24.0.50; [nnimap/Gnus] Dovecot panics trying to close mailboxes

[Lars Magne Ingebrigtsen]

Luca Capello <luca@pca.it> writes:

>> 1) Your dovecot is apparently segfaulting because of something Gnus is
>> doing.  Does it stop doing that if you `M-g' the
>> "lists.Debian.pkg.CL-Debian" group?
>
> I tried with four other folders and it seems that the second time
> Dovecot does not segfault, even in the fourth case where I had to
> unfreeze Gnus with `C-g' before hitting `M-g'.

Right.  I think the base issue is that if you QRESYNC with a sequence
number that's "too far back", Dovecot (before the patch) would
segfault.  If you `M-g' the groups, then that does a total (and slow)
resync of the flags, so that the next QRESYNC won't segfault dovecot.

> I have already backported the patch to the Debian stable package
> (dovecot-imapd_1:1.2.15-7), so I will test it in the following days.

Great.

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

bug#8959: 24.0.50; [nnimap/Gnus] Dovecot panics trying to close mailboxes

[Luca Capello]

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

Hi there!

On Thu, 30 Jun 2011 02:44:56 +0200, Lars Magne Ingebrigtsen wrote:
> Luca Capello <luca@pca.it> writes:
>> I have already backported the patch to the Debian stable package
>> (dovecot-imapd_1:1.2.15-7), so I will test it in the following days.
>
> Great.

Indeed, no more panics with the upstream fix, so I asked for it to be
included in a stable-update for the Debian dovecot-imapd package:

  <http://bugs.debian.org/632844>

Thx, bye,
Gismo / Luca

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