gcc-mark-as-read sometimes broken on Exchange

gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

Since doing a pull to deal with my earlier issue (latest commit is ca8599c49933f974e07ce3ece5d4694bd1956b06) I've been noticing that periodically the code to mark gcc's as read is generating this backtrace on my Exchange server.

Debugger entered--Lisp error: (wrong-type-argument number-char-or-marker-p nil)
  gnus-add-to-range(((1 . 28007)) (nil))
  gnus-compute-read-articles("nnimap+exchange:Sent Items" (nil))
  gnus-group-make-articles-read("nnimap+exchange:Sent Items" (nil))
  gnus-group-mark-article-read("nnimap+exchange:Sent Items" nil)
  gnus-inews-do-gcc()
  gnus-agent-possibly-do-gcc()
  run-hooks(gnus-agent-possibly-do-gcc)
  message-send(nil)
  message-send-and-exit(nil)
  call-interactively(message-send-and-exit)

The gcc has indeed succeeded, and both gcc and marking as read has succeeded on my cyrus server (I gcc to both) and most of the time marking as read succeeds on Exchange too.  So repeating this is not easy.  I assume that the `nil' there is supposed to have the article number.  A quick look at the code doesn't really tell me why it might be calculated as nil, but I'm no lisp expert.  This could have been introduced any time in the last two to two and a half weeks as that's the previous time I updated.

Thanks,
-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Lars Magne Ingebrigtsen]

Dave Goldberg <david.goldberg6@verizon.net> writes:

>   gnus-group-mark-article-read("nnimap+exchange:Sent Items" nil)
>   gnus-inews-do-gcc()

The only way this could happen, I think, is if
`nnimap-request-accept-article' returns nil as the article number.  It
would be interesting to find out why or how that happens.  And whether
that is what's happening.  :-)

If you get a raw article buffer (`C-u C-u g'), and put that text in a
different buffer, and then eval

(nnimap-request-accept-article "group.name" "server-name")

what does it return?

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

Re: gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

> Dave Goldberg <david.goldberg6@verizon.net> writes:
>> gnus-group-mark-article-read("nnimap+exchange:Sent Items" nil)
>> gnus-inews-do-gcc()

> The only way this could happen, I think, is if
> `nnimap-request-accept-article' returns nil as the article number.  It
> would be interesting to find out why or how that happens.  And whether
> that is what's happening.  :-)

> If you get a raw article buffer (`C-u C-u g'), and put that text in a
> different buffer, and then eval

> (nnimap-request-accept-article "group.name" "server-name")

> what does it return?

Sorry, was away for a few days.  Still happens with a git pull this
morning.  I must be doing something wrong because when I try the above
I get this backtrace, with either server (cyrus or exchange):

Debugger entered--Lisp error: (wrong-type-argument processp nil)
  process-buffer(nil)
  proto-stream-get-response(nil 1 "\n")
  proto-stream-open-tls("*nnimap*" #<buffer "*nnimap nnimap:cyrus nil  *nntpd**<2>"> "nnimap:cyrus" "imaps" (:type ssl :shell-command "ssh %s imapd" :capability-command "1 CAPABILITY\n" :success " OK " :starttls-function #<compiled-function (capabilities) "...(21)" [match-data capabilities regexp string start "STARTTLS" nil match-data ... string-match "1 STARTTLS\n"] 4>))
  open-protocol-stream("*nnimap*" #<buffer "*nnimap nnimap:cyrus nil  *nntpd**<2>"> "nnimap:cyrus" "imaps" :type ssl :shell-command "ssh %s imapd" :capability-command "1 CAPABILITY\n" :success " OK " :starttls-function #<compiled-function (capabilities) "...(21)" [match-data capabilities regexp string start "STARTTLS" nil match-data (...) string-match "1 STARTTLS\n"] 4>)
  nnimap-open-connection-1(#<buffer " *nntpd*">)
  nnimap-open-connection(#<buffer " *nntpd*">)
  nnimap-open-server("nnimap:cyrus")
  nnimap-possibly-change-group(nil "nnimap:cyrus")
  nnimap-request-accept-article("INBOX" "nnimap:cyrus")
  eval((nnimap-request-accept-article "INBOX" "nnimap:cyrus"))
  #<compiled-function (expression &optional eval-expression-insert-value) "...(18)" [eval-expression-insert-value expression values eval prin1 t] 3 824197 (list (read-from-minibuffer "Eval: " nil read-expression-map t ...) current-prefix-arg)>((nnimap-request-accept-article "INBOX" "nnimap:cyrus") nil)
  call-interactively(eval-expression)

Thanks,

-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Lars Magne Ingebrigtsen]

david.goldberg6@verizon.net (Dave Goldberg) writes:

>   proto-stream-get-response(nil 1 "\n")

Ok; I've now added more error handling so you shouldn't get this
particular backtrace.

But that's not the real problem here:

[...]

>   nnimap-open-server("nnimap:cyrus")
>   nnimap-possibly-change-group(nil "nnimap:cyrus")
>   nnimap-request-accept-article("INBOX" "nnimap:cyrus")
>   eval((nnimap-request-accept-article "INBOX" "nnimap:cyrus"))
>   #<compiled-function (expression &optional eval-expression-insert-value) "...(18)" [eval-expression-insert-value expression values eval prin1 t] 3 824197 (list (read-from-minibuffer "Eval: " nil read-expression-map t ...) current-prefix-arg)>((nnimap-request-accept-article "INBOX" "nnimap:cyrus") nil)
>   call-interactively(eval-expression)

That should be "cyrus" and not "nnimap:cyrus".  I wonder where that's
coming from?  I can't really find anything in the Gcc code path that
would eval something like that.  And the backtrace is odd. because it
seems ...

Oh!  I asked you to eval something, and you did.  Tee hee.  Never mind.

But try evaling this:

(nnimap-request-accept-article "INBOX" "cyrus")

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

Re: gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

> Oh!  I asked you to eval something, and you did.  Tee hee.  Never mind.

> But try evaling this:

> (nnimap-request-accept-article "INBOX" "cyrus")

This works properly with both cyrus and exchange.  The return is a cons of the folder name and resulting article number.  No matter how many times I run it, I never get nil.  I'll try stepping through gnus-inews-do-gcc and see if I can find the glitch.

-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

>> Oh!  I asked you to eval something, and you did.  Tee hee.  Never mind.
>> But try evaling this:

>> (nnimap-request-accept-article "INBOX" "cyrus")

> This works properly with both cyrus and exchange.  The return is a
> cons of the folder name and resulting article number.  No matter how
> many times I run it, I never get nil.  I'll try stepping through
> gnus-inews-do-gcc and see if I can find the glitch.

OK, it took a long time (especially since stepping through every gcc with edebug, and then figuring out which functions to edebug-defun) to actually hit the problem and again it only happens on occasion with the Exchange server, but after several dozen gcc's I finally hit the bug.  The problem shows up around the bottom of nnimap-request-accept-article.

After successfully appending the article into the group, we get to this code:

	    (cons group
		  (or (nnimap-find-uid-response "APPENDUID" (car result))
		      (nnimap-find-article-by-message-id
		       group message-id)))))))))

And both return nil.  Unfortunately, I'm not sure which one is returning successfully when it does work because I wasn't stepping through nnimap-request-accept-article at the time.  I'll keep stepping through everything but it seems that it takes several tries before I hit the bug, once I do I hit it all the time.  On the plus side, I now know exactly which function to debug so I'll save a bit of time with further stepping.

Thanks,
-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

> After successfully appending the article into the group, we get to this code:

> 	    (cons group
> 		  (or (nnimap-find-uid-response "APPENDUID" (car result))
> 		      (nnimap-find-article-by-message-id
> 		       group message-id)))))))))

> And both return nil.  Unfortunately, I'm not sure which one is returning successfully when it does work because I wasn't stepping through nnimap-request-accept-article at the time.  I'll keep stepping through everything but it seems that it takes several tries before I hit the bug, once I do I hit it all the time.  On the plus side, I now know exactly which function to debug so I'll save a bit of time with further stepping.

So now I know - Exchange does not return APPENDUID like cyrus does so the first check always fails on Exchange.  It appears that sometimes the find-by-message-id works, and sometimes it doesn't.  I seem to recall that the last time this sort of problem with gcc came up it had something to do with CRLF handling.  Did anything change with that in the past month?  It's bizarre that it's inconsistent.

-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

>> After successfully appending the article into the group, we get to this
>  code:

>> (cons group
>> (or (nnimap-find-uid-response "APPENDUID" (car result))
>> (nnimap-find-article-by-message-id
>> group message-id)))))))))

>> And both return nil.  Unfortunately, I'm not sure which one is returning successfully when it does work because I wasn't stepping through nnimap-request-accept-article at the time.  I'll keep stepping through everything but it seems that it takes several tries before I hit the bug, once I do I hit it all the time.  On the plus side, I now know exactly which function to debug so I'll save a bit of time with further stepping.

> So now I know - Exchange does not return APPENDUID like cyrus does so
> the first check always fails on Exchange.  It appears that sometimes
> the find-by-message-id works, and sometimes it doesn't.  I seem to
> recall that the last time this sort of problem with gcc came up it had
> something to do with CRLF handling.  Did anything change with that in
> the past month?  It's bizarre that it's inconsistent.

It appears to be some sort of race condition.  If I step through nnimap-find-article-by-message-id I succeed all the time.  If I get impatient and press 'c' to continue through the function without stopping then some percentage of the time (I didn't really keep track) the function returns nil.

-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

> It appears to be some sort of race condition.  If I step through
> nnimap-find-article-by-message-id I succeed all the time.  If I get
> impatient and press 'c' to continue through the function without
> stopping then some percentage of the time (I didn't really keep track)
> the function returns nil.

Maybe it's not quite that bad.  I just noticed the following in my message log after a failure:

Result: (("BAD" "Command" "received" "in" "Invalid" "state."))

This at this spot in nnimap-find-article-by-message-id:

      (when (and result
		 (car (setq result (nnimap-parse-response))))

So perhaps something is going wrong with the connection to the Exchange server after the successful APPEND?  How would I check for that?  The *nnimap ...* buffer seems to get erased before the attempt at the search.

Thanks,
-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Lars Magne Ingebrigtsen]

david.goldberg6@verizon.net (Dave Goldberg) writes:

> Maybe it's not quite that bad.  I just noticed the following in my
> message log after a failure:
>
> Result: (("BAD" "Command" "received" "in" "Invalid" "state."))
>
> This at this spot in nnimap-find-article-by-message-id:
>
>       (when (and result
> 		 (car (setq result (nnimap-parse-response))))
>
> So perhaps something is going wrong with the connection to the
> Exchange server after the successful APPEND?  How would I check for
> that?  The *nnimap ...* buffer seems to get erased before the attempt
> at the search.

If you could look in the *nnimap ...* buffer just after the APPEND, that
might give us a clue to what the IMAP server is really complaining
about.  My guess is that there's some sort of encoding problem or a
problem with the length of the message or something.  Which might
explain why it's working sometimes, but not other times -- perhaps if
there are some non-ASCII characters in the message, APPEND fails, but
otherwise it works?

That just a guess, though.

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

Re: gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

> If you could look in the *nnimap ...* buffer just after the APPEND, that
> might give us a clue to what the IMAP server is really complaining
> about.  My guess is that there's some sort of encoding problem or a
> problem with the length of the message or something.  Which might
> explain why it's working sometimes, but not other times -- perhaps if
> there are some non-ASCII characters in the message, APPEND fails, but
> otherwise it works?

Found it, I think.  I don't fully understand the sequence so it might be another red herring but I've noticed the last couple failures that suddenly I end up working in a new *nnimap ...* buffer and the prior one looks like this:

1252 OK [READ-ONLY] EXAMINE completed.
* 401 FETCH (FLAGS (%Seen) UID 210486)

[...]

* 442 FETCH (FLAGS () UID 210577)

[...]

1253 OK FETCH completed.
* BYE Connection is closed. 13
*** Fatal error: A TLS packet with unexpected length was received.
*** Server has terminated the connection abnormally.

And then I get the

1364 BAD Command received in Invalid state.

in the subsequent *nnimap ...* buffer.

What's not clear to me is whether that TLS error message is generated by gnutls-cli or the server.

-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Lars Magne Ingebrigtsen]

david.goldberg6@verizon.net (Dave Goldberg) writes:

> 1252 OK [READ-ONLY] EXAMINE completed.
> * 401 FETCH (FLAGS (%Seen) UID 210486)
>
> [...]
>
> * 442 FETCH (FLAGS () UID 210577)
>
> [...]
>
> 1253 OK FETCH completed.
> * BYE Connection is closed. 13
> *** Fatal error: A TLS packet with unexpected length was received.
> *** Server has terminated the connection abnormally.
>
> And then I get the
>
> 1364 BAD Command received in Invalid state.
>
> in the subsequent *nnimap ...* buffer.

Hm.  Is that the first response in the new *nnimap ...* buffer?

> What's not clear to me is whether that TLS error message is generated
> by gnutls-cli or the server.

I think it's from gnutls-cli -- I think it just says that when the peer
closes the connection.

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

Re: gcc-mark-as-read sometimes broken on Exchange

[Dave Goldberg]

>> And then I get the
>> 
>> 1364 BAD Command received in Invalid state.
>> 
>> in the subsequent *nnimap ...* buffer.

> Hm.  Is that the first response in the new *nnimap ...* buffer?

Well, it's the only one in there at the time I look.  I am not stepping manually (I assume) through every function involved so there may be something beforehand followed by an erase-buffer.

>> What's not clear to me is whether that TLS error message is generated
>> by gnutls-cli or the server.

> I think it's from gnutls-cli -- I think it just says that when the peer
> closes the connection.

Which wouldn't surprise me.  I've always had issues with TLS and the Exchange server.  Prior to the rewrite of nnimap this typically resulted in the server being in a weird state and I wrote some hooks to detect it and go through a deny/close/open process.  After the rewrite I no longer have to do that as the new nnimap handles that much better.  It's odd that the issue with gcc just started showing up recently but given that it's not repeatable perhaps I was just getting lucky.

-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: gcc-mark-as-read sometimes broken on Exchange

[Tibor Simko]

On Thu, 16 Dec 2010, Dave Goldberg wrote:
> After the rewrite I no longer have to do that as the new nnimap
> handles that much better.  It's odd that the issue with gcc just
> started showing up recently but given that it's not repeatable perhaps
> I was just getting lucky.

FWIW, I've been having the same experience with Exchange 2010 and Gcc;
it used to work well with Oct-Nov gnus git versions but started to show
issues occasionally in Dec gnus git versions; lately it has become
relatively frequent for me, at least a few times per day.

Exchange IMAP is understandingly not among primary Gnus test platforms.
Thinking also of gnus agent nnimap features that have low TODO priority
such as moving email between folders when unplugged, perhaps it's time
to plug dovecot and offlineimap between gnus and Exchange so as not to
connect to Exchange directly?  This setup could be both (i) more robust
(since people using other MUAs like mutt are using offlineimap for
Exchange too, so any intricacies of Exchange IMAP may be better handled
there); and (ii) more advantageous offline-feature-wise (e.g. the
above-mentioned moving/triage of email between IMAP folders when
unplugged).  Though there were also some issues WRT offlineimap and
marks, for example, so dunno.

Does anyone with `corporate Exchange' have first-class experience with
such a gnus-dovecot-offlineimap-exchange setup for a reasonably long
period of time?  Personally I tested such a setup only briefly, and only
with old nnimap.  (I preferred to keep the gnus agent way of doing
things at the time.)

Best regards
-- 
Tibor Simko

Re: gcc-mark-as-read sometimes broken on Exchange

[Lars Magne Ingebrigtsen]

Tibor Simko <tibor.simko@cern.ch> writes:

> FWIW, I've been having the same experience with Exchange 2010 and Gcc;
> it used to work well with Oct-Nov gnus git versions but started to show
> issues occasionally in Dec gnus git versions; lately it has become
> relatively frequent for me, at least a few times per day.

I think it's likely that the problem is with

(nnimap-find-uid-response "APPENDUID" (car result))

in nnimap-request-accept-article.  It's a quite new thing, and it does
look like it breaks -- but only sometimes.  And apparently only on
Exchange, which I can't test, since I don't have a test account...

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

Re: gcc-mark-as-read sometimes broken on Exchange

[Tibor Simko]

On Fri, 17 Dec 2010, Lars Magne Ingebrigtsen wrote:
> It's a quite new thing, and it does look like it breaks -- but only
> sometimes.  And apparently only on Exchange, which I can't test, since
> I don't have a test account...

Unfortunately I cannot help in this domain...

Best regards
-- 
Tibor Simko

Re: gcc-mark-as-read sometimes broken on Exchange

[Lars Magne Ingebrigtsen]

david.goldberg6@verizon.net (Dave Goldberg) writes:

> Which wouldn't surprise me.  I've always had issues with TLS and the
> Exchange server.  Prior to the rewrite of nnimap this typically
> resulted in the server being in a weird state and I wrote some hooks
> to detect it and go through a deny/close/open process.

I don't think it's actually a TLS-related problem.  The Exchange server
says "BYE" and hangs up, and then gnutls-cli gives an error message.
But the question is why the exchange server says BYE.

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

Re: gcc-mark-as-read sometimes broken on Exchange

[Tibor Simko]

On Fri, 17 Dec 2010, Lars Magne Ingebrigtsen wrote:
> But the question is why the exchange server says BYE.

Considering the history of Exchange and IMAP standards, I think it is
probably advantageous not to investigate too deeply but rather recommend
gnus <-> dovecot <-> offlineimap <-> exchange setup.  I guess there are
more offlineimap <-> exchange users than gnus <-> exchange users in
order to debug these potential server-specific issues...

Best regards
-- 
Tibor Simko

Re: gcc-mark-as-read sometimes broken on Exchange

[Lars Magne Ingebrigtsen]

Tibor Simko <tibor.simko@cern.ch> writes:

> Considering the history of Exchange and IMAP standards, I think it is
> probably advantageous not to investigate too deeply but rather recommend
> gnus <-> dovecot <-> offlineimap <-> exchange setup. 

Well, I'd like Gnus to work with Exchange/IMAP out of the box, really.

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