possible imap.el bug

possible imap.el bug

[Ted Zlatanov]

I got this today while processing spam.  I'm not sure what the problem
is, unfortunately, but it looks like some data may be missing from the
overview?

Ted


Debugger entered--Lisp error: (wrong-type-argument stringp nil)
  string-to-number(nil)
  imap-message-copyuid-1("train")
  imap-message-copy("111169" "train" dontcreate nil " *nnimap* depot")
  nnimap-request-accept-article("train" "mail.lifelogs.com" t)
  gnus-request-accept-article("nnimap+mail.lifelogs.com:train" nil t t)
  eval((gnus-request-accept-article "nnimap+mail.lifelogs.com:train" (quote nil) t t))
  nnimap-request-move-article(111169 "spam" "mail.lifelogs.com" (gnus-request-accept-article "nnimap+mail.lifelogs.com:train" (quote nil) t t) t)
  gnus-request-move-article(111169 "nnimap+mail.lifelogs.com:spam" "mail.lifelogs.com" (gnus-request-accept-article "nnimap+mail.lifelogs.com:train" (quote nil) t t) t)
  gnus-summary-move-article(nil "nnimap+mail.lifelogs.com:train")
  spam-copy-or-move-routine(nil ("nnimap+mail.lifelogs.com:train") (111169 111168 111167 111166 111165 111164 111163 111162 111161 111160 111159 111158 111157 111156 111155 111154 111153 111152 111151 111150 111149 111148 111147 111146 111145 111144 111143 111142 111141) spam)
  spam-move-spam-routine((111169 111168 111167 111166 111165 111164 111163 111162 111161 111160 111159 111158 111157 111156 111155 111154 111153 111152 111151 111150 111149 111148 111147 111146 111145 111144 111143 111142 111141))
  spam-register-routine(spam spam-use-move)
  spam-summary-prepare-exit()
  run-hooks(gnus-summary-prepare-exit-hook)
  apply(run-hooks gnus-summary-prepare-exit-hook)
  gnus-run-hooks(gnus-summary-prepare-exit-hook)
  gnus-summary-exit()
  call-interactively(gnus-summary-exit)

Re: possible imap.el bug

[Simon Josefsson]

"Ted Zlatanov" <tzz@lifelogs.com> writes:

> I got this today while processing spam.  I'm not sure what the problem
> is, unfortunately, but it looks like some data may be missing from the
> overview?
>
> Ted
>
>
> Debugger entered--Lisp error: (wrong-type-argument stringp nil)
>   string-to-number(nil)
>   imap-message-copyuid-1("train")
>   imap-message-copy("111169" "train" dontcreate nil " *nnimap* depot")

Do (setq imap-log t) and get the last part from *imap-log*, it looks
like a protocol problem.

Re: possible imap.el bug

[Ted Zlatanov]

On Thu, 14 Oct 2004, jas@extundo.com wrote:

> "Ted Zlatanov" <tzz@lifelogs.com> writes:
> 
>> I got this today while processing spam.  I'm not sure what the problem
>> is, unfortunately, but it looks like some data may be missing from the
>> overview?
>>
>> Ted
>>
>>
>> Debugger entered--Lisp error: (wrong-type-argument stringp nil)
>>   string-to-number(nil)
>>   imap-message-copyuid-1("train")
>>   imap-message-copy("111169" "train" dontcreate nil " *nnimap* depot")
> 
> Do (setq imap-log t) and get the last part from *imap-log*, it looks
> like a protocol problem.

The error may be due to something unusual in the message (a mail
bounce here), so I'm attaching the headers of the bounce.  I've also
seen this error happen with spam, which may also have funny headers.
I edited the real address to nosuch@invalid.com.

The server is Courier IMAP.

Ted


10844 UID FETCH 32361 BODY.PEEK[].
* 9 FETCH (UID 32361 BODY[] {3247}.
Return-Path: <>.
Delivered-To: lifelogs-lifelogs:com-tzz@lifelogs.com.
X-Envelope-To: tzz@lifelogs.com.
Received: (qmail 56231 invoked from network); 15 Oct 2004 14:50:44 -0000.
Received: from sysblade0.bwh.harvard.edu (HELO mail.bwh.harvard.edu) (134.174.9.44).
  by saghotta.pair.com with SMTP; 15 Oct 2004 14:50:44 -0000.
Received: (qmail 18054 invoked for bounce); 15 Oct 2004 14:40:53 -0000.
Date: 15 Oct 2004 14:40:53 -0000.
From: MAILER-DAEMON@mail.bwh.harvard.edu.
To: tzz@lifelogs.com.
Subject: failure notice.
X-Spam-Filtered: f9609c3ab574f6a5d7c7e6b6300efd2a.
X-Spam-Status: No, hits=-34.8 required=4.0 tests=NO_REAL_NAME,BAYES_00.
X-Spam-Flag: NO.
X-Spam-Level: .
.
Hi. This is the qmail-send program at mail.bwh.harvard.edu..
I'm afraid I wasn't able to deliver your message to the following addresses..
This is a permanent error; I've given up. Sorry it didn't work out..
.
<nosuch@invalid.com>:.
Sorry, I couldn't find any host named invalid.com. (#5.1.2).
.
--- Below this line is a copy of the message..
.
10844 OK UID FETCH completed.
10845 UID COPY 32361 "soccer".
10845 OK UID COPY completed.

Re: possible imap.el bug

[Simon Josefsson]

"Ted Zlatanov" <tzz@lifelogs.com> writes:

> On Thu, 14 Oct 2004, jas@extundo.com wrote:
>
>> "Ted Zlatanov" <tzz@lifelogs.com> writes:
>> 
>>> I got this today while processing spam.  I'm not sure what the problem
>>> is, unfortunately, but it looks like some data may be missing from the
>>> overview?
>>>
>>> Ted
>>>
>>>
>>> Debugger entered--Lisp error: (wrong-type-argument stringp nil)
>>>   string-to-number(nil)
>>>   imap-message-copyuid-1("train")
>>>   imap-message-copy("111169" "train" dontcreate nil " *nnimap* depot")
>> 
>> Do (setq imap-log t) and get the last part from *imap-log*, it looks
>> like a protocol problem.
>
> The error may be due to something unusual in the message (a mail
> bounce here), so I'm attaching the headers of the bounce.  I've also
> seen this error happen with spam, which may also have funny headers.
> I edited the real address to nosuch@invalid.com.
...
> 10845 UID COPY 32361 "soccer".
> 10845 OK UID COPY completed.

Could you get the CAPABILITY line from that server too?  First lines
when connecting to the server.

The imap.el code check for the UIDPLUS capability (RFC 2359) and uses
some special code if present, and it is the code that crashes.  If the
server really supported UIDPLUS, the UID COPY response should be
something like:

A003 OK [COPYUID 4711] Done

If the capability line includes UIDPLUS, then this is a server bug.

Re: possible imap.el bug

[Ted Zlatanov]

On Fri, 15 Oct 2004, jas@extundo.com wrote:

> "Ted Zlatanov" <tzz@lifelogs.com> writes:

>> 10845 UID COPY 32361 "soccer".
>> 10845 OK UID COPY completed.
> 
> Could you get the CAPABILITY line from that server too?  First lines
> when connecting to the server.

* CAPABILITY IMAP4 IMAP4REV1 NAMESPACE IDLE SCAN SORT MAILBOX-REFERRALS LOGIN-REFERRALS AUTH=LOGIN THREAD=ORDEREDSUBJECT

> The imap.el code check for the UIDPLUS capability (RFC 2359) and uses
> some special code if present, and it is the code that crashes.  If the
> server really supported UIDPLUS, the UID COPY response should be
> something like:
> 
> A003 OK [COPYUID 4711] Done
> 
> If the capability line includes UIDPLUS, then this is a server bug.

So maybe imap.el tried UIDPLUS even though it shouldn't...

Thanks
Ted

Re: possible imap.el bug

[Simon Josefsson]

"Ted Zlatanov" <tzz@lifelogs.com> writes:

> On Fri, 15 Oct 2004, jas@extundo.com wrote:
>
>> "Ted Zlatanov" <tzz@lifelogs.com> writes:
>
>>> 10845 UID COPY 32361 "soccer".
>>> 10845 OK UID COPY completed.
>> 
>> Could you get the CAPABILITY line from that server too?  First lines
>> when connecting to the server.
>
> * CAPABILITY IMAP4 IMAP4REV1 NAMESPACE IDLE SCAN SORT MAILBOX-REFERRALS LOGIN-REFERRALS AUTH=LOGIN THREAD=ORDEREDSUBJECT
>
>> The imap.el code check for the UIDPLUS capability (RFC 2359) and uses
>> some special code if present, and it is the code that crashes.  If the
>> server really supported UIDPLUS, the UID COPY response should be
>> something like:
>> 
>> A003 OK [COPYUID 4711] Done
>> 
>> If the capability line includes UIDPLUS, then this is a server bug.
>
> So maybe imap.el tried UIDPLUS even though it shouldn't...

Weird.  The code says:

(defun imap-message-copyuid-1 (mailbox)
  (if (imap-capability 'UIDPLUS)
      (list (nth 0 (imap-mailbox-get-1 'copyuid mailbox))
	    (string-to-number (nth 2 (imap-mailbox-get-1 'copyuid mailbox))))
    (let ((old-mailbox imap-current-mailbox)
	  (state imap-state)
	  (imap-message-data (make-vector 2 0)))
      (when (imap-mailbox-examine-1 mailbox)
	(prog1
	    (and (imap-fetch "*" "UID")
		 (list (imap-mailbox-get-1 'uidvalidity mailbox)
		       (apply 'max (imap-message-map
				    (lambda (uid prop) uid) 'UID))))
	  (if old-mailbox
	      (imap-mailbox-select old-mailbox (eq state 'examine))
	    (imap-mailbox-unselect)))))))

Could you (load "imap.el") to get a more detailed backtrace, perhaps?
I thought it was the string-to-number in the UIDPLUS part of the big
if that crashed, but maybe it is some other call, hidden inside the
rest of the function.

Or the UIDPLUS capability has leaked between buffers.

Re: possible imap.el bug

[Ted Zlatanov]

On Fri, 15 Oct 2004, jas@extundo.com wrote:

> Could you (load "imap.el") to get a more detailed backtrace, perhaps?
> I thought it was the string-to-number in the UIDPLUS part of the big
> if that crashed, but maybe it is some other call, hidden inside the
> rest of the function.
> 
> Or the UIDPLUS capability has leaked between buffers.

I'm almost positive it's the latter - I have two IMAP servers, one
Courier and one UW, set up.

By the way, I misspoke - the faulty server is UW, not Courier (where
the problem happens).

Ted

Re: possible imap.el bug

[Simon Josefsson]

"Ted Zlatanov" <tzz@lifelogs.com> writes:

> On Fri, 15 Oct 2004, jas@extundo.com wrote:
>
>> Could you (load "imap.el") to get a more detailed backtrace, perhaps?
>> I thought it was the string-to-number in the UIDPLUS part of the big
>> if that crashed, but maybe it is some other call, hidden inside the
>> rest of the function.
>> 
>> Or the UIDPLUS capability has leaked between buffers.
>
> I'm almost positive it's the latter - I have two IMAP servers, one
> Courier and one UW, set up.

So what is the content of the `imap-capability' variable inside the
two IMAP server buffers?  E.g., "*nnimap *foo" and "*nnimap *bar".

Re: possible imap.el bug

[Ted Zlatanov]

On Sun, 24 Oct 2004, jas@extundo.com wrote:

> Many functions in imap.el either take a buffer argument (and switch to
> that buffer), or assume it is in the correct buffer.  You could try to
> track down where it is called, to see if the Gnus move code somehow
> end up using it from the wrong buffer.

Simon,

I think I found the problem, the nnimap server buffer alist cleanup in
close-server was just doing a delq to remove the server, which didn't
work because a) strings are not necessarily eq, and b) the list was an
association list so each element was never eq to the server name.  Now
it iterates correctly, I think - I tested it for myself and it works
great, and it's in CVS.  Only nnimap.el was changed.

Let me know if there's problems.  I wanted to commit ASAP because it's
an important bug fix.  It should probably go into the 5.10 branch too,
if you approve of course.  Please look and see what you think.  I'm
cc-ing ding again in case anyone else has comments.

Thanks for the help with debugging this!
Ted

Re: possible imap.el bug

[Simon Josefsson]

"Ted Zlatanov" <tzz@lifelogs.com> writes:

> On Sun, 24 Oct 2004, jas@extundo.com wrote:
>
>> Many functions in imap.el either take a buffer argument (and switch to
>> that buffer), or assume it is in the correct buffer.  You could try to
>> track down where it is called, to see if the Gnus move code somehow
>> end up using it from the wrong buffer.
>
> Simon,
>
> I think I found the problem, the nnimap server buffer alist cleanup in
> close-server was just doing a delq to remove the server, which didn't
> work because a) strings are not necessarily eq, and b) the list was an
> association list so each element was never eq to the server name.  Now
> it iterates correctly, I think - I tested it for myself and it works
> great, and it's in CVS.  Only nnimap.el was changed.
>
> Let me know if there's problems.  I wanted to commit ASAP because it's
> an important bug fix.  It should probably go into the 5.10 branch too,
> if you approve of course.  Please look and see what you think.  I'm
> cc-ing ding again in case anyone else has comments.

It looks fine.  I wonder why it hasn't been discovered before.
Perhaps it actually will solve other hard-to-debug bug reports.

Thanks.

Re: possible imap.el bug

[Ted Zlatanov]

On Mon, 25 Oct 2004, jas@extundo.com wrote:

> It looks fine.  I wonder why it hasn't been discovered before.
> Perhaps it actually will solve other hard-to-debug bug reports.

I still get the wrong buffer associated with a server, it just doesn't
happen many times now.  I suspect this line:

  (if (not (imap-open nnimap-address nnimap-server-port nnimap-stream
		      nnimap-authenticator nnimap-server-buffer))

in nnimap-open-connection.

Does imap-open have to take a buffer argument?  I would make it always
create the buffer, to be safe, and because reusing the old buffer has
no obvious (to me) benefit.  At some point, it's called with
nnimap-server-buffer set to the wrong buffer but I don't know where.
I do know it happens when many articles are moved sequentially between
IMAP servers.

I'll keep investigating, but if we can eliminate the buffer argument
to imap-open I think that would make life much easier.

Thanks
Ted

Re: possible imap.el bug

[Gerd Flaig]

"Ted Zlatanov" <tzz@lifelogs.com> writes:

> Now it iterates correctly, I think - I tested it for myself and it
> works great, and it's in CVS.  Only nnimap.el was changed.

with CVS gnus from 2004/10/26 (Debian daily CVS package from [1]), I
could not connect to my default server any more. Downgrading to CVS
from 25. made it work again.

      Goodbyte, Gerd.

 [1] http://people.debian.org/~srivasta/

-- 
Gerd Flaig                     Technik                gerd@schlund.de
Bei Schlund + Partner AG       Brauerstraße 48      D-76135 Karlsruhe
 Physics is like sex: sure, it may give some practical results,
 but that's not why we do it. -- Richard Feynman

Re: possible imap.el bug

[Simon Josefsson]

"Ted Zlatanov" <tzz@lifelogs.com> writes:

> On Mon, 25 Oct 2004, jas@extundo.com wrote:
>
>> It looks fine.  I wonder why it hasn't been discovered before.
>> Perhaps it actually will solve other hard-to-debug bug reports.
>
> I still get the wrong buffer associated with a server, it just doesn't
> happen many times now.  I suspect this line:
>
>   (if (not (imap-open nnimap-address nnimap-server-port nnimap-stream
> 		      nnimap-authenticator nnimap-server-buffer))
>
> in nnimap-open-connection.

I have seen a new problem: when I open a server, it is immediately
denied, but if I try to open it again, it works fine, and it appears
to be re-using the server buffer created by the first server open.
Maybe some return value was accidentally changed to nil by your patch,
somehow?

Requiring two server open attempts is annoying; if I compose a long
message and the IMAP server kick me out, then the GCC fail.

> Does imap-open have to take a buffer argument?

If not, it will create a new unique one.  I think it is better to name
the server " *nnimap* foo", to mimic how nntp do things.

> I would make it always create the buffer, to be safe, and because
> reusing the old buffer has no obvious (to me) benefit.

Passwords, stream preferences, and possibly more useful data, are
stored in the buffer.  Those can be costly to discover again.
Especially since IMAP servers typically throw you out after 30
minutes.

> At some point, it's called with nnimap-server-buffer set to the
> wrong buffer but I don't know where.  I do know it happens when many
> articles are moved sequentially between IMAP servers.

Maybe the problem is in gnus-move.el?

> I'll keep investigating, but if we can eliminate the buffer argument
> to imap-open I think that would make life much easier.

Perhaps you could modify your local copy, temporarily?  If some code
is using the wrong buffer, perhaps renaming it will somehow trigger
the bug more easily.

Re: possible imap.el bug

[Simon Josefsson]

Gerd Flaig <gerd@schlund.de> writes:

> "Ted Zlatanov" <tzz@lifelogs.com> writes:
>
>> Now it iterates correctly, I think - I tested it for myself and it
>> works great, and it's in CVS.  Only nnimap.el was changed.
>
> with CVS gnus from 2004/10/26 (Debian daily CVS package from [1]), I
> could not connect to my default server any more. Downgrading to CVS
> from 25. made it work again.

I might be seeing the same, although if I try to connect to the server
twice, the second attempt work.  Try M-g on one of your nnimap group
to try to reconnect.

Re: possible imap.el bug

[Gerd Flaig]

Simon Josefsson <jas@extundo.com> writes:

> Gerd Flaig <gerd@schlund.de> writes:
>
>> "Ted Zlatanov" <tzz@lifelogs.com> writes:
>>
>>> Now it iterates correctly, I think - I tested it for myself and it
>>> works great, and it's in CVS.  Only nnimap.el was changed.
>>
>> with CVS gnus from 2004/10/26 (Debian daily CVS package from [1]), I
>> could not connect to my default server any more. Downgrading to CVS
>> from 25. made it work again.
>
> I might be seeing the same, although if I try to connect to the server
> twice, the second attempt work.  Try M-g on one of your nnimap group
> to try to reconnect.

ah. This works, thank you.

I also tried <Return> on my default IMAP server in the server buffer,
but that didn't help.

      Goodbyte, Gerd.
-- 
Gerd Flaig                     Technik                gerd@schlund.de
Bei Schlund + Partner AG       Brauerstraße 48      D-76135 Karlsruhe
 Physics is like sex: sure, it may give some practical results,
 but that's not why we do it. -- Richard Feynman

Re: possible imap.el bug

[CHENG Gao]

I think it's owing to Ted's latest commit (2004-10-25 21:07:52).

@@ -781,6 +789,10 @@
 		    (list "imap" "imaps"))))
       (if (imap-authenticate user passwd nnimap-server-buffer)
 	  (prog1 
+	      (setq nnimap-server-buffer-alist
+		    (nnimap-remove-server-from-buffer-alist 
+		     server
+		     nnimap-server-buffer-alist))
 	      (push (list server nnimap-server-buffer)
 		    nnimap-server-buffer-alist)
 	    (imap-id nnimap-id nnimap-server-buffer)

I think after these 4 lines added, `prog1 should be changed to `prog2.

You can try to change line 791 of nnimap.el from prog1 to prog2. I think
this should work.

HTH,

-- 
这去者，不能见他的脸，背影模糊。

Re: possible imap.el bug

[Ted Zlatanov]

On Wed, 27 Oct 2004, chenggao@gmail.com wrote:

> I think after these 4 lines added, `prog1 should be changed to `prog2.

That was the problem.  Thanks, Gao.  I put the fix in CVS.

Ted

Re: possible imap.el bug

[Ted Zlatanov]

On Tue, 26 Oct 2004, jas@extundo.com wrote:

>> Does imap-open have to take a buffer argument?
> 
> If not, it will create a new unique one.  I think it is better to name
> the server " *nnimap* foo", to mimic how nntp do things.
> 
>> I would make it always create the buffer, to be safe, and because
>> reusing the old buffer has no obvious (to me) benefit.
> 
> Passwords, stream preferences, and possibly more useful data, are
> stored in the buffer.  Those can be costly to discover again.
> Especially since IMAP servers typically throw you out after 30
> minutes.

Yes, but when it doesn't work that's tough to defend :)

I think that get-buffer-or-create will do the right thing anyhow based
on the server name in imap-open, so if the buffer already exists it
will be selected correctly.  In general, I don't understand why buffer
names are stored in the nnimap-server-buffer-alist instead of simply
generated on the fly.  If that buffer exists already, great.  If not,
it's no problem either.  The parameter to imap-open may be a "purpose"
parameter like 'nnimap, which can be used in making the buffer name
string, but there should be no chance for passing an incorrect buffer
as is happening now.

>> At some point, it's called with nnimap-server-buffer set to the
>> wrong buffer but I don't know where.  I do know it happens when many
>> articles are moved sequentially between IMAP servers.
> 
> Maybe the problem is in gnus-move.el?
> 
>> I'll keep investigating, but if we can eliminate the buffer argument
>> to imap-open I think that would make life much easier.
> 
> Perhaps you could modify your local copy, temporarily?  If some code
> is using the wrong buffer, perhaps renaming it will somehow trigger
> the bug more easily.

I'm not sure what you mean here, what should I debug?

Ted

Re: possible imap.el bug

[Simon Josefsson]

"Ted Zlatanov" <tzz@lifelogs.com> writes:

> On Tue, 26 Oct 2004, jas@extundo.com wrote:
>
>>> Does imap-open have to take a buffer argument?
>> 
>> If not, it will create a new unique one.  I think it is better to name
>> the server " *nnimap* foo", to mimic how nntp do things.
>> 
>>> I would make it always create the buffer, to be safe, and because
>>> reusing the old buffer has no obvious (to me) benefit.
>> 
>> Passwords, stream preferences, and possibly more useful data, are
>> stored in the buffer.  Those can be costly to discover again.
>> Especially since IMAP servers typically throw you out after 30
>> minutes.
>
> Yes, but when it doesn't work that's tough to defend :)

Right, although is anyone but you seeing this?  It could be some weird
interaction with some customization.  Anyway, it doesn't seem right to
change something without knowing what was wrong in the old code.  On
the other hand, if you can come up with a patch that works for you,
and seem harmless, and works for others, I guess there is no major
reason not to apply it, although I feel a bit uneasy about such
changes in general.

> I think that get-buffer-or-create will do the right thing anyhow based
> on the server name in imap-open, so if the buffer already exists it
> will be selected correctly.

I'm not sure.  imap-open name the buffers after the network address,
not after the virtual server name.  Imagine:

(setq gnus-secondary-select-methods
       '((nnimap "foo" (nnimap-address "mail"))
         (nnimap "bar" (nnimap-address "mail"))))

Where, for example, "foo" and "bar" could map to different user names
in ~/.authinfo.  Then there would be a collision of buffer names,
since imap.el would pick the same buffer for both servers.

Only nnimap.el have the virtual server name, that is why it create the
buffer.  Which must be unique among nnimap servers, so it can be
assumed to correspond to the same server later on.  Network addresses
aren't unique enough.

> In general, I don't understand why buffer
> names are stored in the nnimap-server-buffer-alist instead of simply
> generated on the fly.  If that buffer exists already, great.  If not,
> it's no problem either.  The parameter to imap-open may be a "purpose"
> parameter like 'nnimap, which can be used in making the buffer name
> string, but there should be no chance for passing an incorrect buffer
> as is happening now.

Is nnimap passing the incorrect buffer to imap-open?

>>> At some point, it's called with nnimap-server-buffer set to the
>>> wrong buffer but I don't know where.  I do know it happens when many
>>> articles are moved sequentially between IMAP servers.
>> 
>> Maybe the problem is in gnus-move.el?
>> 
>>> I'll keep investigating, but if we can eliminate the buffer argument
>>> to imap-open I think that would make life much easier.
>> 
>> Perhaps you could modify your local copy, temporarily?  If some code
>> is using the wrong buffer, perhaps renaming it will somehow trigger
>> the bug more easily.
>
> I'm not sure what you mean here, what should I debug?

You could modify nnimap and imap locally, to generate buffer names on
the fly, to see if that solve your problem.