How to debug hangs during message fetching

How to debug hangs during message fetching

[Tassilo Horn]

Hi,

I have this

  (require 'gnus-demon)
  (gnus-demon-add-handler 'gnus-demon-scan-news 15 5)

in my ~/.gnus.el to let Gnus regularily fetch news and mail.
Unfortunately, sometimes the fetching process seems to hang.  In the
echo area, I can read something like

  nnimap read 76k

and emacs hangs until I hit C-g.  I've tried setting `debug-on-quit' to
t, but in that case, C-g doesn't provide a meaningful backtrace, only

  Debugger entered--Lisp error: (quit)

and nothing more.  Incidentially, that hang really often occurs when
exactly 76k are read, whatever that means.  And it seems to only occur
with nnimap...

Any hints how I can debug the issue?

Bye,
Tassilo
-- 
Sent from my Emacs

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

Tassilo Horn <tassilo@member.fsf.org> writes:

> Any hints how I can debug the issue?

Look in the nnimap server buffer when this happens and look what's in
there.

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

Re: How to debug hangs during message fetching

[Tassilo Horn]

Lars Ingebrigtsen <larsi@gnus.org> writes:

Hi Lars,

>> Any hints how I can debug the issue?
>
> Look in the nnimap server buffer when this happens and look what's in
> there.

Ok, I'll do so.  Is there a way to check what's the hanging server?  I
have three imap servers.

(If not, I'll simply post the last contents of all three buffers.)

Bye,
Tassilo
-- 
Sent from my Emacs

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

Tassilo Horn <tassilo@member.fsf.org> writes:

> Ok, I'll do so.  Is there a way to check what's the hanging server?  I
> have three imap servers.

You might be able to tell by the length of the buffer.

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

Re: How to debug hangs during message fetching

[Tassilo Horn]

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

Lars Ingebrigtsen <larsi@gnus.org> writes:

Hi Lars,

>> Ok, I'll do so.  Is there a way to check what's the hanging server?
>> I have three imap servers.
>
> You might be able to tell by the length of the buffer.

I was, because I have now 6 nnimap buffers for my university imap
server.  That approximatively matches the number of hangs. ;-)

Attached 2 files: nnimap_hang.log contains the last contents of the

  *nnimap mail.uni-koblenz.de nil  *nntpd**<5>

which hung and I had to hit C-g.  The file nnimap_no_hang shows the
contents of the

  *nnimap mail.uni-koblenz.de nil  *nntpd**<6>

after hitting `g' in *Group* with no hang while fetching.

But they look pretty identical.  And the hang seems to occur after
fetching has completed anyway...


[-- Attachment #2: nnimap_hang.log --]
[-- Type: text/plain, Size: 4829 bytes --]

* FLAGS (\Answered \Flagged \Draft \Deleted \Seen KMAILFORWARDED KMAILTODO KMAILWATCHED KMAILIGNORED $FORWARDED $TODO $WATCHED $IGNORED gnus-forward gnus-expire)
* OK [PERMANENTFLAGS ()]  
* 6814 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1212391594]  
* OK [UIDNEXT 7786]  
1569 OK [READ-ONLY] Completed
* 6719 FETCH (FLAGS (\Seen) UID 7685)
* 6720 FETCH (FLAGS (\Answered \Seen) UID 7686)
* 6721 FETCH (FLAGS (\Seen) UID 7687)
* 6722 FETCH (FLAGS (\Answered \Seen) UID 7688)
* 6723 FETCH (FLAGS (\Seen) UID 7689)
* 6724 FETCH (FLAGS (\Seen) UID 7690)
* 6725 FETCH (FLAGS (\Answered \Seen) UID 7691)
* 6726 FETCH (FLAGS (\Seen) UID 7692)
* 6727 FETCH (FLAGS (\Seen) UID 7693)
* 6728 FETCH (FLAGS (\Answered \Seen) UID 7694)
* 6729 FETCH (FLAGS (\Seen) UID 7695)
* 6730 FETCH (FLAGS (\Answered \Seen) UID 7696)
* 6731 FETCH (FLAGS (\Seen) UID 7697)
* 6732 FETCH (FLAGS (\Answered \Seen) UID 7698)
* 6733 FETCH (FLAGS (\Seen) UID 7699)
* 6734 FETCH (FLAGS (\Answered \Seen) UID 7700)
* 6735 FETCH (FLAGS (\Seen) UID 7701)
* 6736 FETCH (FLAGS (\Flagged \Seen) UID 7702)
* 6737 FETCH (FLAGS (\Seen) UID 7704)
* 6738 FETCH (FLAGS (\Seen) UID 7705)
* 6739 FETCH (FLAGS (\Answered \Seen) UID 7706)
* 6740 FETCH (FLAGS (\Answered \Seen) UID 7707)
* 6741 FETCH (FLAGS (\Seen) UID 7708)
* 6742 FETCH (FLAGS (\Seen) UID 7709)
* 6743 FETCH (FLAGS (\Answered \Seen) UID 7710)
* 6744 FETCH (FLAGS (\Seen) UID 7711)
* 6745 FETCH (FLAGS (\Seen) UID 7712)
* 6746 FETCH (FLAGS (\Answered \Seen) UID 7713)
* 6747 FETCH (FLAGS (\Seen) UID 7714)
* 6748 FETCH (FLAGS (\Seen) UID 7715)
* 6749 FETCH (FLAGS (\Answered \Seen) UID 7716)
* 6750 FETCH (FLAGS (\Seen) UID 7717)
* 6751 FETCH (FLAGS (\Seen) UID 7718)
* 6752 FETCH (FLAGS (\Seen) UID 7719)
* 6753 FETCH (FLAGS (\Answered \Seen) UID 7720)
* 6754 FETCH (FLAGS (\Seen) UID 7722)
* 6755 FETCH (FLAGS (\Answered \Seen) UID 7723)
* 6756 FETCH (FLAGS (\Seen) UID 7724)
* 6757 FETCH (FLAGS (\Answered \Seen) UID 7725)
* 6758 FETCH (FLAGS (\Seen) UID 7726)
* 6759 FETCH (FLAGS (\Seen) UID 7727)
* 6760 FETCH (FLAGS (\Answered \Seen) UID 7728)
* 6761 FETCH (FLAGS (\Seen) UID 7729)
* 6762 FETCH (FLAGS (\Answered \Seen) UID 7730)
* 6763 FETCH (FLAGS (\Answered \Seen) UID 7731)
* 6764 FETCH (FLAGS (\Seen) UID 7732)
* 6765 FETCH (FLAGS (\Seen) UID 7733)
* 6766 FETCH (FLAGS (\Seen) UID 7734)
* 6767 FETCH (FLAGS (\Answered \Seen) UID 7735)
* 6768 FETCH (FLAGS (\Answered \Seen) UID 7737)
* 6769 FETCH (FLAGS (\Seen) UID 7738)
* 6770 FETCH (FLAGS (\Seen) UID 7739)
* 6771 FETCH (FLAGS (\Seen) UID 7740)
* 6772 FETCH (FLAGS (\Seen) UID 7741)
* 6773 FETCH (FLAGS (\Seen) UID 7742)
* 6774 FETCH (FLAGS (\Answered \Seen) UID 7743)
* 6775 FETCH (FLAGS (\Seen) UID 7744)
* 6776 FETCH (FLAGS (\Answered \Seen) UID 7747)
* 6777 FETCH (FLAGS (\Seen) UID 7748)
* 6778 FETCH (FLAGS (\Answered \Seen) UID 7749)
* 6779 FETCH (FLAGS (\Answered \Seen) UID 7750)
* 6780 FETCH (FLAGS (\Seen) UID 7751)
* 6781 FETCH (FLAGS (\Seen) UID 7752)
* 6782 FETCH (FLAGS (\Answered \Seen) UID 7753)
* 6783 FETCH (FLAGS (\Seen) UID 7754)
* 6784 FETCH (FLAGS (\Answered \Seen) UID 7755)
* 6785 FETCH (FLAGS (\Seen) UID 7756)
* 6786 FETCH (FLAGS (\Answered \Seen) UID 7757)
* 6787 FETCH (FLAGS (\Seen) UID 7758)
* 6788 FETCH (FLAGS (\Answered \Seen) UID 7759)
* 6789 FETCH (FLAGS (\Seen) UID 7760)
* 6790 FETCH (FLAGS (\Seen) UID 7761)
* 6791 FETCH (FLAGS (\Seen) UID 7762)
* 6792 FETCH (FLAGS (\Seen) UID 7763)
* 6793 FETCH (FLAGS (\Answered \Seen) UID 7764)
* 6794 FETCH (FLAGS (\Answered \Seen) UID 7765)
* 6795 FETCH (FLAGS (\Seen) UID 7766)
* 6796 FETCH (FLAGS (\Seen) UID 7767)
* 6797 FETCH (FLAGS (\Answered \Seen) UID 7768)
* 6798 FETCH (FLAGS (\Answered \Seen) UID 7769)
* 6799 FETCH (FLAGS (\Answered \Seen) UID 7770)
* 6800 FETCH (FLAGS (\Seen) UID 7771)
* 6801 FETCH (FLAGS (\Seen) UID 7772)
* 6802 FETCH (FLAGS (\Seen) UID 7773)
* 6803 FETCH (FLAGS (\Answered \Seen) UID 7774)
* 6804 FETCH (FLAGS (\Seen) UID 7775)
* 6805 FETCH (FLAGS (\Answered \Seen) UID 7776)
* 6806 FETCH (FLAGS (\Seen) UID 7777)
* 6807 FETCH (FLAGS (\Seen) UID 7778)
* 6808 FETCH (FLAGS (\Answered \Seen) UID 7779)
* 6809 FETCH (FLAGS (\Seen) UID 7780)
* 6810 FETCH (FLAGS (\Answered \Seen) UID 7781)
* 6811 FETCH (FLAGS (\Flagged \Seen) UID 7782)
* 6812 FETCH (FLAGS (\Seen) UID 7783)
* 6813 FETCH (FLAGS (\Answered \Seen) UID 7784)
* 6814 FETCH (FLAGS (\Seen) UID 7785)
1570 OK Completed (0.000 sec)
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen KMAILFORWARDED KMAILTODO KMAILWATCHED KMAILIGNORED $FORWARDED $TODO $WATCHED $IGNORED)
* OK [PERMANENTFLAGS ()]  
* 0 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1212391594]  
* OK [UIDNEXT 5]  
1571 OK [READ-ONLY] Completed
1572 OK Completed (0.000 sec)
1573 OK Completed

Process *nnimap* killed

[-- Attachment #3: nnimap_no_hang.log --]
[-- Type: text/plain, Size: 4732 bytes --]

* FLAGS (%Answered %Flagged %Draft %Deleted %Seen KMAILFORWARDED KMAILTODO KMAILWATCHED KMAILIGNORED $FORWARDED $TODO $WATCHED $IGNORED gnus-forward gnus-expire)
* OK [PERMANENTFLAGS ()]  
* 6815 EXISTS
* 1 RECENT
* OK [UNSEEN 6815]  
* OK [UIDVALIDITY 1212391594]  
* OK [UIDNEXT 7787]  
1673 OK [READ-ONLY] Completed
* 6719 FETCH (FLAGS (%Seen) UID 7685)
* 6720 FETCH (FLAGS (%Answered %Seen) UID 7686)
* 6721 FETCH (FLAGS (%Seen) UID 7687)
* 6722 FETCH (FLAGS (%Answered %Seen) UID 7688)
* 6723 FETCH (FLAGS (%Seen) UID 7689)
* 6724 FETCH (FLAGS (%Seen) UID 7690)
* 6725 FETCH (FLAGS (%Answered %Seen) UID 7691)
* 6726 FETCH (FLAGS (%Seen) UID 7692)
* 6727 FETCH (FLAGS (%Seen) UID 7693)
* 6728 FETCH (FLAGS (%Answered %Seen) UID 7694)
* 6729 FETCH (FLAGS (%Seen) UID 7695)
* 6730 FETCH (FLAGS (%Answered %Seen) UID 7696)
* 6731 FETCH (FLAGS (%Seen) UID 7697)
* 6732 FETCH (FLAGS (%Answered %Seen) UID 7698)
* 6733 FETCH (FLAGS (%Seen) UID 7699)
* 6734 FETCH (FLAGS (%Answered %Seen) UID 7700)
* 6735 FETCH (FLAGS (%Seen) UID 7701)
* 6736 FETCH (FLAGS (%Flagged %Seen) UID 7702)
* 6737 FETCH (FLAGS (%Seen) UID 7704)
* 6738 FETCH (FLAGS (%Seen) UID 7705)
* 6739 FETCH (FLAGS (%Answered %Seen) UID 7706)
* 6740 FETCH (FLAGS (%Answered %Seen) UID 7707)
* 6741 FETCH (FLAGS (%Seen) UID 7708)
* 6742 FETCH (FLAGS (%Seen) UID 7709)
* 6743 FETCH (FLAGS (%Answered %Seen) UID 7710)
* 6744 FETCH (FLAGS (%Seen) UID 7711)
* 6745 FETCH (FLAGS (%Seen) UID 7712)
* 6746 FETCH (FLAGS (%Answered %Seen) UID 7713)
* 6747 FETCH (FLAGS (%Seen) UID 7714)
* 6748 FETCH (FLAGS (%Seen) UID 7715)
* 6749 FETCH (FLAGS (%Answered %Seen) UID 7716)
* 6750 FETCH (FLAGS (%Seen) UID 7717)
* 6751 FETCH (FLAGS (%Seen) UID 7718)
* 6752 FETCH (FLAGS (%Seen) UID 7719)
* 6753 FETCH (FLAGS (%Answered %Seen) UID 7720)
* 6754 FETCH (FLAGS (%Seen) UID 7722)
* 6755 FETCH (FLAGS (%Answered %Seen) UID 7723)
* 6756 FETCH (FLAGS (%Seen) UID 7724)
* 6757 FETCH (FLAGS (%Answered %Seen) UID 7725)
* 6758 FETCH (FLAGS (%Seen) UID 7726)
* 6759 FETCH (FLAGS (%Seen) UID 7727)
* 6760 FETCH (FLAGS (%Answered %Seen) UID 7728)
* 6761 FETCH (FLAGS (%Seen) UID 7729)
* 6762 FETCH (FLAGS (%Answered %Seen) UID 7730)
* 6763 FETCH (FLAGS (%Answered %Seen) UID 7731)
* 6764 FETCH (FLAGS (%Seen) UID 7732)
* 6765 FETCH (FLAGS (%Seen) UID 7733)
* 6766 FETCH (FLAGS (%Seen) UID 7734)
* 6767 FETCH (FLAGS (%Answered %Seen) UID 7735)
* 6768 FETCH (FLAGS (%Answered %Seen) UID 7737)
* 6769 FETCH (FLAGS (%Seen) UID 7738)
* 6770 FETCH (FLAGS (%Seen) UID 7739)
* 6771 FETCH (FLAGS (%Seen) UID 7740)
* 6772 FETCH (FLAGS (%Seen) UID 7741)
* 6773 FETCH (FLAGS (%Seen) UID 7742)
* 6774 FETCH (FLAGS (%Answered %Seen) UID 7743)
* 6775 FETCH (FLAGS (%Seen) UID 7744)
* 6776 FETCH (FLAGS (%Answered %Seen) UID 7747)
* 6777 FETCH (FLAGS (%Seen) UID 7748)
* 6778 FETCH (FLAGS (%Answered %Seen) UID 7749)
* 6779 FETCH (FLAGS (%Answered %Seen) UID 7750)
* 6780 FETCH (FLAGS (%Seen) UID 7751)
* 6781 FETCH (FLAGS (%Seen) UID 7752)
* 6782 FETCH (FLAGS (%Answered %Seen) UID 7753)
* 6783 FETCH (FLAGS (%Seen) UID 7754)
* 6784 FETCH (FLAGS (%Answered %Seen) UID 7755)
* 6785 FETCH (FLAGS (%Seen) UID 7756)
* 6786 FETCH (FLAGS (%Answered %Seen) UID 7757)
* 6787 FETCH (FLAGS (%Seen) UID 7758)
* 6788 FETCH (FLAGS (%Answered %Seen) UID 7759)
* 6789 FETCH (FLAGS (%Seen) UID 7760)
* 6790 FETCH (FLAGS (%Seen) UID 7761)
* 6791 FETCH (FLAGS (%Seen) UID 7762)
* 6792 FETCH (FLAGS (%Seen) UID 7763)
* 6793 FETCH (FLAGS (%Answered %Seen) UID 7764)
* 6794 FETCH (FLAGS (%Answered %Seen) UID 7765)
* 6795 FETCH (FLAGS (%Seen) UID 7766)
* 6796 FETCH (FLAGS (%Seen) UID 7767)
* 6797 FETCH (FLAGS (%Answered %Seen) UID 7768)
* 6798 FETCH (FLAGS (%Answered %Seen) UID 7769)
* 6799 FETCH (FLAGS (%Answered %Seen) UID 7770)
* 6800 FETCH (FLAGS (%Seen) UID 7771)
* 6801 FETCH (FLAGS (%Seen) UID 7772)
* 6802 FETCH (FLAGS (%Seen) UID 7773)
* 6803 FETCH (FLAGS (%Answered %Seen) UID 7774)
* 6804 FETCH (FLAGS (%Seen) UID 7775)
* 6805 FETCH (FLAGS (%Answered %Seen) UID 7776)
* 6806 FETCH (FLAGS (%Seen) UID 7777)
* 6807 FETCH (FLAGS (%Seen) UID 7778)
* 6808 FETCH (FLAGS (%Answered %Seen) UID 7779)
* 6809 FETCH (FLAGS (%Seen) UID 7780)
* 6810 FETCH (FLAGS (%Answered %Seen) UID 7781)
* 6811 FETCH (FLAGS (%Flagged %Seen) UID 7782)
* 6812 FETCH (FLAGS (%Seen) UID 7783)
* 6813 FETCH (FLAGS (%Answered %Seen) UID 7784)
* 6814 FETCH (FLAGS (%Seen) UID 7785)
* 6815 FETCH (FLAGS (%Recent) UID 7786)
1674 OK Completed (0.000 sec)
* FLAGS (%Answered %Flagged %Draft %Deleted %Seen KMAILFORWARDED KMAILTODO KMAILWATCHED KMAILIGNORED $FORWARDED $TODO $WATCHED $IGNORED)
* OK [PERMANENTFLAGS ()]  
* 0 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1212391594]  
* OK [UIDNEXT 5]  
1675 OK [READ-ONLY] Completed
1676 OK Completed (0.000 sec)

[-- Attachment #4: Type: text/plain, Size: 37 bytes --]


Bye,
Tassilo
-- 
Sent from my Emacs

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

Tassilo Horn <tassilo@member.fsf.org> writes:

> 1675 OK [READ-ONLY] Completed
> 1676 OK Completed (0.000 sec)

Compare these command numbers with the commands in *imap log* to see
whether there are later commands that we're not getting any responses
for. 

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

Re: How to debug hangs during message fetching

[Tassilo Horn]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Tassilo Horn <tassilo@member.fsf.org> writes:
>
>> 1675 OK [READ-ONLY] Completed
>> 1676 OK Completed (0.000 sec)
>
> Compare these command numbers with the commands in *imap log* to see
> whether there are later commands that we're not getting any responses
> for.

Is it that what you mean?

--8<---------------cut here---------------start------------->8---
13:12:31 1670 UID FETCH 129:* FLAGS
13:12:31 1671 EXAMINE "Junk"
13:12:31 1672 UID FETCH 282:* FLAGS
13:12:31 1673 EXAMINE "INBOX"
13:12:31 1674 UID FETCH 7685:* FLAGS
13:12:31 1675 EXAMINE "Drafts"
13:12:31 1676 UID FETCH 1:* FLAGS
13:17:15 1677 SELECT "INBOX.Sent Items"
13:17:15 1678 APPEND "INBOX.Sent Items" {11468}
13:17:16 1679 SELECT "INBOX.Sent Items"
13:17:16 1680 UID FETCH 1:* FLAGS
13:17:17 1681 UID STORE 1:1263 +FLAGS.SILENT (\Seen)
13:17:18 1682 SELECT "INBOX.mailinglists.ding"
--8<---------------cut here---------------end--------------->8---

But 1676 was the last number in the nnimap_no_hang.log.  That was the
command that did not hang.  The last number in nnimap_hang.log was 1573,
and here I have some NOOPs in *imap log*.

--8<---------------cut here---------------start------------->8---
13:04:02 1568 UID FETCH 282:* FLAGS
13:04:02 1569 EXAMINE "INBOX"
13:04:02 1570 UID FETCH 7685:* FLAGS
13:04:02 1571 EXAMINE "Drafts"
13:04:02 1572 UID FETCH 1:* FLAGS
13:04:04 1573 NOOP
13:04:04 1574 NOOP
13:09:09 1575 SELECT "INBOX.mailinglists.ding"
13:09:09 1576 UID FETCH 10962:10963 (UID RFC822.SIZE BODYSTRUCTURE BODY.PEEK[HEADER.FIELDS (Subject From Date Message-Id References In-Reply-To Xref Cc To Newsgroups)])
13:09:10 1577 UID FETCH 10962 BODY.PEEK[]
13:09:11 1578 UID FETCH 10963 BODY.PEEK[]
--8<---------------cut here---------------end--------------->8---

Bye,
Tassilo
-- 
Sent from my Emacs

Re: How to debug hangs during message fetching

[Tassilo Horn]

Hi again,

the next hang occured, and the *nnimap* buffer contained

--8<---------------cut here---------------start------------->8---
* 0 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1212391594]  
* OK [UIDNEXT 5]  
2113 OK [READ-ONLY] Completed
2114 OK Completed (0.000 sec)
2115 OK Completed
--8<---------------cut here---------------end--------------->8---

and the *imap log* buffer contained

--8<---------------cut here---------------start------------->8---
13:49:02 2112 UID FETCH 7690:* FLAGS
13:49:02 2113 EXAMINE "Drafts"
13:49:02 2114 UID FETCH 1:* FLAGS
13:49:04 2115 NOOP
13:49:04 2116 NOOP
--8<---------------cut here---------------end--------------->8---

So the NOOP, NOOP pattern seems to trigger the hang for me.

Bye,
Tassilo
-- 
Sent from my Emacs

Re: How to debug hangs during message fetching

[Ludovic Courtès]

Hi,

Tassilo Horn <tassilo@member.fsf.org> writes:

> in my ~/.gnus.el to let Gnus regularily fetch news and mail.
> Unfortunately, sometimes the fetching process seems to hang.  In the
> echo area, I can read something like
>
>   nnimap read 76k
>
> and emacs hangs until I hit C-g.  I've tried setting `debug-on-quit' to
> t, but in that case, C-g doesn't provide a meaningful backtrace, only

It could be the infamous QRESYNC bug.  E.g., Zimbra’s IMAP daemon (or at
least some versions of it) require a space between “QRESYNC” and the
following opening bracket, but Gnus fails to do the right thing out of
the box because it doesn’t detect that it’s talking to the broken Zimbra
thing.

Thanks,
Ludo’.

Re: How to debug hangs during message fetching

[Michael Welsh Duggan]

ludo@gnu.org (Ludovic Courtès) writes:

> Hi,
>
> Tassilo Horn <tassilo@member.fsf.org> writes:
>
>> in my ~/.gnus.el to let Gnus regularily fetch news and mail.
>> Unfortunately, sometimes the fetching process seems to hang.  In the
>> echo area, I can read something like
>>
>>   nnimap read 76k
>>
>> and emacs hangs until I hit C-g.  I've tried setting `debug-on-quit' to
>> t, but in that case, C-g doesn't provide a meaningful backtrace, only
>
> It could be the infamous QRESYNC bug.  E.g., Zimbra’s IMAP daemon (or
> at least some versions of it) require a space between “QRESYNC” and
> the following opening bracket, but Gnus fails to do the right thing
> out of the box because it doesn’t detect that it’s talking to the
> broken Zimbra thing.

It is not.  The servers are Exchange and Cyrus servers.  Neither support
QRESYNC.  (Well, Cyrus 2.4 does, but it isn't release on most distros
just yet.)

-- 
Michael Welsh Duggan
(md5i@md5i.com)

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

ludo@gnu.org (Ludovic Courtès) writes:

> It could be the infamous QRESYNC bug.  E.g., Zimbra’s IMAP daemon (or at
> least some versions of it) require a space between “QRESYNC” and the
> following opening bracket, but Gnus fails to do the right thing out of
> the box because it doesn’t detect that it’s talking to the broken Zimbra
> thing.

No, there's a quirk in nnimap.el that does the right thing to work
around the Zimbra bug.

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

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

Tassilo Horn <tassilo@member.fsf.org> writes:

> 13:49:04 2115 NOOP
> 13:49:04 2116 NOOP
> So the NOOP, NOOP pattern seems to trigger the hang for me.

This should probably be fixed now.  

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

Re: How to debug hangs during message fetching

[Tassilo Horn]

Lars Ingebrigtsen <larsi@gnus.org> writes:

>> 13:49:04 2115 NOOP
>> 13:49:04 2116 NOOP
>> So the NOOP, NOOP pattern seems to trigger the hang for me.
>
> This should probably be fixed now.  

I've reactivated my mail fetching demon, and till now I didn't get any
hangs.  So it seems to work fine for me.

Thanks a lot,
Tassilo
-- 
Sent from my Emacs

Re: How to debug hangs during message fetching

[Emilio Jesús Gallego Arias]

After a pull today I'm getting fairly similar hangs, I'm not using
daemon or anything fancy, the hang just happens when starting gnus.

I'm using current git master, I've bisected and this commit seems the
culprit:

$ git bisect bad
894b2ac5b356510bd62b23597abc20badb7b27e8 is the first bad commit
commit 894b2ac5b356510bd62b23597abc20badb7b27e8
Author: Lars Ingebrigtsen <larsi@gnus.org>
Date:   Thu Feb 3 07:36:03 2011 -0800

    Request active files from primary/secondary methods that have no groups (yet).

:040000 040000 b309a842a98585ed43219e9e944ffb753506d9f7 4a2ea41728c86e5a3beb3fe8203d5dbb82ee0428 M	lisp

Backing out that particular change in top of current head fixes the hang
for me.

This happens in a dovecot server using nnimap. It happens at start and
whenever I press g or M-g. Then I need to press C-g in order to get out
of the hang. debug-on-quit does not work.

Regarding the buffer contents:

,----[ imap log: ]
| 22:16:07 679 EXAMINE "#mailman.slam"
| 22:16:07 680 EXAMINE "#mailman.mtp-dev"
`----

,----[ *nnimap buffer*: ]
| 679 OK [READ-ONLY] Select completed.
| * OK [CLOSED] Previous mailbox closed.
| * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
| * OK [PERMANENTFLAGS ()] Read-only mailbox.
| * 3350 EXISTS
| * 0 RECENT
| * OK [UIDVALIDITY 1257814760] UIDs valid
| * OK [UIDNEXT 3351] Predicted next UID
| * OK [HIGHESTMODSEQ 2] Highest
| 680 OK [READ-ONLY] Select completed.
| 
| Process *nnimap* terminado (killed)
`----

,----[ relevant gnus config: ]
|
| (setq gnus-select-method '(nntp "news.gmane.org"
|                            (nntp-address "news.gmane.org")))
|
| (setq gnus-secondary-select-methods
|       '((nnimap "dovecot"
|                 (nnimap-address "dovecot")
|                 (nnimap-stream ssl))))
|
| (setq nnimap-inbox "INBOX")
| (setq nnimap-split-crosspost t)
| (setq nnimap-split-methods 'default)
| (setq nnmail-split-methods 'nnmail-split-fancy)
| (setq nnmail-split-fancy ...)
`----

Regards,
Emilio

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

egallego@babel.ls.fi.upm.es (Emilio Jesús Gallego Arias) writes:

>     Request active files from primary/secondary methods that have no
> groups (yet).

[...]

> Backing out that particular change in top of current head fixes the hang
> for me.
>
> This happens in a dovecot server using nnimap. It happens at start and
> whenever I press g or M-g. Then I need to press C-g in order to get out
> of the hang. debug-on-quit does not work.

Hm.  Hm.  That change shouldn't affect the code path for `M-g' at all,
so I don't understand why reverting that change would make `M-g' work.

But it does, very much, affect what `g' does.  It basically makes nnimap
issue an EXAMINE for all the mailboxes on (secondary) backends that have
no groups subscribed.

[...]

> | 680 OK [READ-ONLY] Select completed.
> | 
> | Process *nnimap* terminado (killed)

Hm.

If you go to the "*nnimap dovecot ...*" buffer and eval

(nnimap-send-command "EXAMINE %S" "#mailman.mtp-dev")

what happens?

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

Re: How to debug hangs during message fetching

[Emilio Jesús Gallego Arias]

Lars Ingebrigtsen <larsi@gnus.org> writes:

>> This happens in a dovecot server using nnimap. It happens at start and
>> whenever I press g or M-g. Then I need to press C-g in order to get out
>> of the hang. debug-on-quit does not work.
>
> Hm.  Hm.  That change shouldn't affect the code path for `M-g' at all,
> so I don't understand why reverting that change would make `M-g' work.
>
> But it does, very much, affect what `g' does.  It basically makes nnimap
> issue an EXAMINE for all the mailboxes on (secondary) backends that have
> no groups subscribed.

g and M-g works OK, but I have to press C-g in order for them to finish,
otherwise I get messages "nnimap read 24k [800 times]" etc...

Then after the C-g I can proceed almost as normal. debug-on-quit reports
nothing useful :(

>> | 680 OK [READ-ONLY] Select completed.
>> | 
>> | Process *nnimap* terminado (killed)
>
> Hm.
>
> If you go to the "*nnimap dovecot ...*" buffer and eval
>
> (nnimap-send-command "EXAMINE %S" "#mailman.mtp-dev")
>
> what happens?

Sorry Lars, should I do this with the code enabled (hang happens) or
with the code commented out?

Keep in mind that #mailman.mtp-dev is read-only IMAP group.

Thanks for your help,
Emilio

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

egallego@babel.ls.fi.upm.es (Emilio Jesús Gallego Arias) writes:

> g and M-g works OK, but I have to press C-g in order for them to finish,
> otherwise I get messages "nnimap read 24k [800 times]" etc...

Oh.  Huh.  Hm.

>> If you go to the "*nnimap dovecot ...*" buffer and eval
>>
>> (nnimap-send-command "EXAMINE %S" "#mailman.mtp-dev")
>>
>> what happens?
>
> Sorry Lars, should I do this with the code enabled (hang happens) or
> with the code commented out?
>
> Keep in mind that #mailman.mtp-dev is read-only IMAP group.

When the hang happens, I think, but both might be interesting.

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

Re: How to debug hangs during message fetching

[Emilio Jesús Gallego Arias]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> egallego@babel.ls.fi.upm.es (Emilio Jesús Gallego Arias) writes:

>> Sorry Lars, should I do this with the code enabled (hang happens) or
>> with the code commented out?
>>
>> Keep in mind that #mailman.mtp-dev is read-only IMAP group.
>
> When the hang happens, I think, but both might be interesting.

This is with the code commented out (no hang):

00:52:56 396 EXAMINE "#mailman.mtp-dev"

* OK [CLOSED] Previous mailbox closed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS ()] Read-only mailbox.
* 3350 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1257814760] UIDs valid
* OK [UIDNEXT 3351] Predicted next UID
* OK [HIGHESTMODSEQ 2] Highest
396 OK [READ-ONLY] Select completed.

This is with the code enabled (as it is in the git repos)

01:24:39 218 EXAMINE "#mailman.mtp-dev"

* OK [CLOSED] Previous mailbox closed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS ()] Read-only mailbox.
* 3350 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1257814760] UIDs valid
* OK [UIDNEXT 3351] Predicted next UID
* OK [HIGHESTMODSEQ 2] Highest
218 OK [READ-ONLY] Select completed.

Virtually identical...

Regards,
Emilio

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

egallego@babel.ls.fi.upm.es (Emilio Jesús Gallego Arias) writes:

> This is with the code commented out (no hang):
>
> 00:52:56 396 EXAMINE "#mailman.mtp-dev"

Ok, so it isn't related to any one specific group.

Could you try evaling

(nnimap-request-list "dovecot")

and see whether that works at all?

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

Re: How to debug hangs during message fetching

[Vincent Bernat]

Hi!

I have similar problem when using `gnus-group-get-new-news'. However, It
does not  happen each  time. If  I ask for  new news  by hand,  it never
happens. It seems  to happen only when the refresh  is initiated by gnus
demon. I have something like this:

(defun vince-gnus-demon-scan-mail-and-update ()
  (vince-gnus-demon-scan-mail-or-news-and-update 2))
(gnus-demon-add-handler 'vince-gnus-demon-scan-mail-and-update 20 1)
(defun vince-gnus-demon-scan-news-and-update ()
  (vince-gnus-demon-scan-mail-or-news-and-update 3))
(gnus-demon-add-handler 'vince-gnus-demon-scan-news-and-update 30 20)

Running   by   hand  those   two   functions   does   not  trigger   the
bug. gnus-demon-handlers list only contain those two functions.

If I  refresh the I have  only one nnimap backend  so it is  easy to see
which  one  hangs.  The  hang  happens with  "nnimap  read  30k" in  the
minibuffer. This is  always the same "30k". The  nnimap buffer ends with
something like that:

14679 OK [READ-ONLY] Select completed.
* OK [CLOSED] Previous mailbox closed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS ()] Read-only mailbox.
* 77 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1176456138] UIDs valid
* OK [UIDNEXT 78] Predicted next UID
* OK [HIGHESTMODSEQ 1] Highest
14680 OK [READ-ONLY] Select completed.
* OK [CLOSED] Previous mailbox closed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft gnus-forward)
* OK [PERMANENTFLAGS ()] Read-only mailbox.
* 13108 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1169990978] UIDs valid
* OK [UIDNEXT 13463] Predicted next UID
* OK [HIGHESTMODSEQ 1] Highest
14681 OK [READ-ONLY] Select completed.
* OK [CLOSED] Previous mailbox closed.
* FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
* OK [PERMANENTFLAGS ()] Read-only mailbox.
* 7059 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1297203672] UIDs valid
* OK [UIDNEXT 7060] Predicted next UID
* OK [HIGHESTMODSEQ 7061] Highest
14682 OK [READ-ONLY] Select completed.
14683 OK NOOP completed.
14685 OK NOOP completed.
14687 OK NOOP completed.
14689 OK NOOP completed.

Process *nnimap* processus arr.t.

I  am currently  using  9adfe4a952f2b51c1080ab941930ef5e831cf1d9 but  it
happened with more recent checkouts  (I did downgrade because of Gcc and
auth-sources problem).  It happens with  this commit too  (for example):
37efc98493b86d09a0a2d198030884ebedeafc75.

The IMAP server is dovecot.
-- 
BOFH excuse #195:
We only support a 28000 bps connection.

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

Vincent Bernat <bernat@luffy.cx> writes:

> 14682 OK [READ-ONLY] Select completed.
> 14683 OK NOOP completed.

I think this was fixed recently.

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

Re: How to debug hangs during message fetching

[Vincent Bernat]

OoO En  cette nuit  striée d'éclairs du  dimanche 20 février  2011, vers
02:22, Lars Ingebrigtsen <larsi@gnus.org> disait :

>> 14682 OK [READ-ONLY] Select completed.
>> 14683 OK NOOP completed.

> I think this was fixed recently.

Yes, it is fixed. Thanks.
-- 
10.0 times 0.1 is hardly ever 1.0.
            - The Elements of Programming Style (Kernighan & Plauger)

Re: How to debug hangs during message fetching

[Emilio Jesús Gallego Arias]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Could you try evaling
>
> (nnimap-request-list "dovecot")
>
> and see whether that works at all?

It works in both cases (returs t) No hang. Hang happening in g or M-g.

The only difference is the two first lines are only in the bad version:

03:08:48 (inhibited)
03:08:48 3268 ENABLE QRESYNC

From there on, both outputs identical.

03:08:48 3269 LIST "" "*"
03:08:49 3270 EXAMINE "Trash"
[...]

Regards,
Emilio

Re: How to debug hangs during message fetching

[Emilio Jesús Gallego Arias]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Could you try evaling
>
> (nnimap-request-list "dovecot")
>
> and see whether that works at all?

When I press g in the "bad" version, the equivalent of
(nnimap-request-list "dovecot") happens. In the form of:

03:15:58 4013 LIST "" "*"
03:15:58 4014 SELECT "INBOX"
03:15:58 4015 UID FETCH 1:* FLAGS
03:15:58 4016 EXAMINE "INBOX"
03:15:58 4017 UID FETCH 1:* FLAGS
03:15:58 4018 LIST "" "*"
03:15:58 4019 SELECT "INBOX"
03:15:58 4020 UID FETCH 1:* FLAGS
03:15:58 4021 EXAMINE "Spam"
03:15:58 4022 UID FETCH 42:* FLAGS
03:15:58 4023 EXAMINE "Sent"
03:15:58 4024 UID FETCH 1:* FLAGS
03:15:58 4025 EXAMINE "INBOX"
03:15:58 4026 UID FETCH 33181:* FLAGS
03:15:58 4027 LIST "" "*"
03:15:58 4028 SELECT "INBOX"
03:15:58 4029 UID FETCH 1:* FLAGS
03:15:58 4030 EXAMINE "INBOX" (QRESYNC (1240303625 27))
03:15:58 4031 LIST "" "*"
03:15:58 4032 SELECT "INBOX"
03:15:58 4033 UID FETCH 1:* FLAGS
03:15:58 4034 UID FETCH 287 (UID BODY.PEEK[HEADER] BODY.PEEK[1])
03:15:58 4035 EXAMINE "Sent" (QRESYNC (1252931194 1))
03:15:58 4036 EXAMINE "INBOX" (QRESYNC (1252931192 88))
03:15:58 4037 LIST "" "*"
03:15:58 4038 SELECT "INBOX"
03:15:59 4039 UID FETCH 1:* FLAGS
03:15:59 4040 EXAMINE "folder1" (QRESYNC (1258000258 14))
[... Identical for all the folders ...]
03:15:59 4099 EXAMINE "folder90" (QRESYNC (1258000252 1))
03:15:59 4100 LIST "" "*"
03:15:59 4101 SELECT "INBOX"
03:15:59 4102 UID FETCH 1:* FLAGS
03:15:59 4103 LIST "" "*"
03:15:59 4104 EXAMINE "folder1"
[... Identical for all the folders ...]
03:15:59 4171 EXAMINE "folder90"

In the "good" gnus version, command 4100 onwards are missing,
transmission stops at command 4099.

Regards

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

egallego@babel.ls.fi.upm.es (Emilio Jesús Gallego Arias) writes:

> 03:15:59 4099 EXAMINE "folder90" (QRESYNC (1258000252 1))
> 03:15:59 4100 LIST "" "*"
> 03:15:59 4101 SELECT "INBOX"
> 03:15:59 4102 UID FETCH 1:* FLAGS
> 03:15:59 4103 LIST "" "*"
> 03:15:59 4104 EXAMINE "folder1"
> [... Identical for all the folders ...]
> 03:15:59 4171 EXAMINE "folder90"
>
> In the "good" gnus version, command 4100 onwards are missing,
> transmission stops at command 4099.

Ah, right.  I think I (sort of) see why this may be happening, and it
may be fixed by some recent changes, but it may not be.

If this still isn't working for you, what are the values of your
gnus-select-method and gnus-secondary-select-methods variables?

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

Re: How to debug hangs during message fetching

[Emilio Jesús Gallego Arias]

Lars Ingebrigtsen <larsi@gnus.org> writes:

> Ah, right.  I think I (sort of) see why this may be happening, and it
> may be fixed by some recent changes, but it may not be.
>
> If this still isn't working for you, what are the values of your
> gnus-select-method and gnus-secondary-select-methods variables?

No luck :( If at least I could debug this, but no luck ATM. I added some
debug to the culprit code and got this:

> (with-current-buffer nntp-server-buffer
>    (message "DEBUG: going to gnus-read-active-file-1 %s" method)
>    (gnus-read-active-file-1 method nil))))

,----
| nnimap babel splitting mail...
| DEBUG: going to gnus-read-active-file-1 (nnimap babel (nnimap-address babel.ls.fi.upm.es) (nnimap-stream ssl))
| Reading active file from babel via nnimap...
| nnimap babel splitting mail...
| Reading active file from babel via nnimap...done
| nnimap read 25k [224 times]
`----

Note it seems to do two times the same thing. Of course if I disable the
code the hang seems to stop. How could I check that the are no duplicate
methods?

Note the confusion about methods gnus has because of archive methods,
that could have something to do with this problem. Maybe we should fix
the confusion first and then see what happens.

(setq gnus-save-newsrc-file nil)
(setq gnus-read-newsrc-file nil)
(setq gnus-save-killed-list t)
(setq gnus-check-new-newsgroups 'ask-server)
(setq gnus-use-dribble-file nil)
(setq gnus-select-method '(nntp "news.gmane.org"
                                (nntp-address "news.gmane.org")))

(setq gnus-secondary-select-methods
      '((nnimap "babel"
                (nnimap-address "babel.ls.fi.upm.es")
                (nnimap-stream ssl))))

(setq gnus-message-archive-method '(nnimap "babel"))
(setq gnus-message-archive-group "nnimap+babel:archive.mail")

Re: How to debug hangs during message fetching

[Lars Ingebrigtsen]

egallego@babel.ls.fi.upm.es (Emilio Jesús Gallego Arias) writes:

>> If this still isn't working for you, what are the values of your
>> gnus-select-method and gnus-secondary-select-methods variables?
>
> No luck :(

I've now changed the order these things are done, so I think the hang
should probably be gone now.

> Note the confusion about methods gnus has because of archive methods,
> that could have something to do with this problem. Maybe we should fix
> the confusion first and then see what happens.

Yes, the base reason for the bug is that Gnus (stupidly) allows users to
have several select methods that are "similar", and they sometimes need
to be handled separately, and sometimes not.  Fixing that generally is
kinda "eek".

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