Number of unread articles suddenly incorrect with Exchange 2007

Number of unread articles suddenly incorrect with Exchange 2007

[Dave Goldberg]

In the group buffer.  Groups on the cyrus server show accurate number of articles.  Groups on Exchange 2007 do not.  The number shown is typically 2 to 3 times bigger than actual, but sometimes it's even further off.  This is essentially a regression to behavior I saw before all the changes started a couple months ago.  It had been fixed until a git pull this morning; my previous pull was some time last week.

The IMAP conversation appears to be showing accurate numbers.  Here is a sample from the relevant *nnimap...* buffer.  This after doing M-g on one group to narrow it down, however similar results show after doing g:

* 449 EXISTS
* 0 RECENT
* FLAGS (%Seen %Answered %Flagged %Deleted %Draft $MDNSent)
* OK [PERMANENTFLAGS (%Seen %Answered %Flagged %Deleted %Draft $MDNSent)] Permanent flags
* OK [UNSEEN 446] Is the first unseen message
* OK [UIDVALIDITY 1899] UIDVALIDITY value
* OK [UIDNEXT 583070] The next unique identifier value
1414 OK [READ-WRITE] SELECT completed.
* 1 FETCH (FLAGS (%Seen) UID 581195)

[...] same thing for each UID

* 446 FETCH (FLAGS () UID 583066)
* 447 FETCH (FLAGS () UID 583067)
* 448 FETCH (FLAGS () UID 583068)
* 449 FETCH (FLAGS (%Seen) UID 583069)
1415 OK FETCH completed.

And sure enough, there are indeed only three unseen/unread articles in the group, but the group buffer says 10.  This happens, with different numbers, of course, to every group on that server, including some that have 0 actual unread articles showing up as having several hundred unread.

I've started to figure out edebug as part of this process, but don't know what function to check here.  Please let me know and I'll give it a whirl.

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

Re: Number of unread articles suddenly incorrect with Exchange 2007

[Lars Magne Ingebrigtsen]

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

> I've started to figure out edebug as part of this process, but don't
> know what function to check here.  Please let me know and I'll give it
> a whirl.

It's `nnimap-update-info' that does most of the heavy lifting...

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

Re: Number of unread articles suddenly incorrect with Exchange 2007

[Dave Goldberg]

> Dave Goldberg <david.goldberg6@verizon.net> writes:
>> I've started to figure out edebug as part of this process, but don't
>> know what function to check here.  Please let me know and I'll give it
>> a whirl.

> It's `nnimap-update-info' that does most of the heavy lifting...

Strangely enough (and perhaps this is the problem) that function does
not seem to be entered, when doing M-g for a group on either the cyrus
nor Exchange IMAP server.  So I tried starting at
gnus-group-get-new-news-this-group, and then picking some of the
subsequent functions it calls.  What appears to be happening is that
the number of articles is being calculated based on data in
.newsrc.eld instead of what is being noted by the server itself.  That
seems to be happening for both cyrus and Exchange, but since cyrus'
UIDs are consecutive, the math is working; for Exchange it is not.  I
don't see any obvious configuration I might have set that triggers
this.

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

Re: Number of unread articles suddenly incorrect with Exchange 2007

[Lars Magne Ingebrigtsen]

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

> Strangely enough (and perhaps this is the problem) that function does
> not seem to be entered, when doing M-g for a group on either the cyrus
> nor Exchange IMAP server.

That's pretty bizarre.

`nnimap-request-group' isn't called at all when you `M-g'?  That's the
function that's suppose to request the data, parse it, and pass it on to
`nnimap-update-info'. 

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

Re: Number of unread articles suddenly incorrect with Exchange 2007

[Dave Goldberg]

> Dave Goldberg <david.goldberg6@verizon.net> writes:
>> Strangely enough (and perhaps this is the problem) that function does
>> not seem to be entered, when doing M-g for a group on either the cyrus
>> nor Exchange IMAP server.

> That's pretty bizarre.

> `nnimap-request-group' isn't called at all when you `M-g'?  That's the
> function that's suppose to request the data, parse it, and pass it on to
> `nnimap-update-info'. 

No it is indeed called.  Strange, when I went into nnimap.el and did
edebug-defun on nnimap-update-info M-g ran to completion without ever
having me step through that function.  However I tried debug-on-entry
both for that and nnimap-request-group and sure enough the debugger
took over as expected.  I tried stepping through.  I can see that the
results of the IMAP command (I think it's the FETCH) are being turned
into a list and that list is being stepped through. The list itself
clearly shows (at least in a previous return; now there's all those
...'s), only 11 articles that are not in the group flagged as Seen but
somehow the return for number of unread articles is being set to 40.
Here is the backtrace at the point I first (I think, might have been
one more recent call on the stack) see the 40 as a function result.  I
cannot figure out how it got there.

Debugger entered--returning value: 40
  gnus-group-set-parameter(("nnimap+exchange:INBOX" 2 ((1 . 583722)) ((seen 581195 ... 581205 581211 581216 581226 581229 581232 581236 581241 581247 581252 581255 581258 581262 ... 581272 ... 581283 581293 581297 581302 581306 581315 581319 581323 ... 581334 581346 581354 581359 581365 ... 581376 581380 581383 581387 581391 581396 ... 581406 581409 581414 581417 581423 581427 581431 581435 581439 ... ...)) "nnimap:exchange" ((permanent-flags) (modseq) (uidvalidity . "1899") (active 581195 . 583739) (imap-status . "574561 574023 574560"))) permanent-flags nil)
* (if (eq permanent-flags (quote not-scanned)) nil (gnus-group-set-parameter info (quote permanent-flags) (if ... t nil)))
* (unless (eq permanent-flags (quote not-scanned)) (gnus-group-set-parameter info (quote permanent-flags) (if ... t nil)))
* (let* ((group ...) (completep ...) (active ...)) (when uidnext (setq high ...)) (if (or completep ...) (gnus-set-active group ...) (gnus-set-active group ...)) (unless (eq permanent-flags ...) (gnus-group-set-parameter info ... ...)) (when (cdr ...) (if ... ... ...)) (gnus-group-set-parameter info (quote active) (gnus-active group)) (gnus-group-set-parameter info (quote uidvalidity) uidvalidity) (gnus-group-set-parameter info (quote modseq) highestmodseq) (nnimap-store-info info (gnus-active group)))
* (cond ((and ... ...) (let ... ...)) ((let ... ...) (gnus-group-remove-parameter info ...) (gnus-group-remove-parameter info ...)) (t (let* ... ... ... ... ... ... ... ... ...)))
* (let* ((--rest--59959 marks) (existing ...) (flags ...) (high ...) (low ...) (uidnext ...) (start-article ...) (permanent-flags ...) (uidvalidity ...) (vanished ...) (highestmodseq ...)) (cond (... ...) (... ... ...) (t ...)))
* (progn (let* (... ... ... ... ... ... ... ... ... ... ...) (cond ... ... ...)))
* (destructuring-bind (existing flags high low uidnext start-article permanent-flags uidvalidity vanished highestmodseq) marks (cond (... ...) (... ... ...) (t ...)))
* nnimap-update-info(("nnimap+exchange:INBOX" 2 ((1 . 583722)) ((seen 581195 ... 581205 581211 581216 581226 581229 581232 581236 581241 581247 581252 581255 581258 581262 ... 581272 ... 581283 581293 581297 581302 581306 581315 581319 581323 ... 581334 581346 581354 581359 581365 ... 581376 581380 581383 581387 581391 581396 ... 581406 581409 581414 581417 581423 581427 581431 581435 581439 ... ...)) "nnimap:exchange" ((permanent-flags) (modseq) (uidvalidity . "1899") (active 581195 . 583739) (imap-status . "574561 574023 574560"))) ((581195 581201 581202 581205 581211 581216 581226 581229 581232 581236 581241 581247 581252 581255 581258 581262 581266 581267 581272 581277 581278 581283 581293 581297 581302 581306 581315 581319 581323 581328 581329 581334 581346 581354 581359 581365 581370 581371 581376 581380 581383 581387 581391 581396 581399 581400 581406 581409 581414 581417 581423 ...) ((%Answered 581504) (%Seen 581195 581201 581202 581205 581211 581216 581226 581229 581232 581236 581241 581247 581252 581255 581258 581262 581266 581267 581272 581277 581278 581283 581293 581297 581302 581306 581315 581319 581323 581328 581329 581334 581346 581354 581359 581365 581370 581371 581376 581380 581383 581387 581391 581396 581399 581400 581406 581409 581414 581417 ...) (%Recent 583762)) 583762 581195 583763 1 (%Seen %Answered %Flagged %Deleted %Draft $MDNSent) "1899" nil nil))
  (if marks (nnimap-update-info info marks))
  (when marks (nnimap-update-info info marks))
  (let* ((group ...) (marks ...)) (when marks (nnimap-update-info info marks)))
  (while --dolist-temp--59957 (setq info (car --dolist-temp--59957)) (let* (... ...) (when marks ...)) (setq --dolist-temp--59957 (cdr --dolist-temp--59957)))
  (let ((--dolist-temp--59957 infos) info) (while --dolist-temp--59957 (setq info ...) (let* ... ...) (setq --dolist-temp--59957 ...)) nil)
  (catch (quote --cl-block-nil--) (let (... info) (while --dolist-temp--59957 ... ... ...) nil))
  (cl-block-wrapper (catch (quote --cl-block-nil--) (let ... ... nil)))
  (block nil (let (... info) (while --dolist-temp--59957 ... ... ...) nil))
  (dolist (info infos) (let* (... ...) (when marks ...)))
  nnimap-update-infos((("INBOX" (581195 581201 581202 581205 581211 581216 581226 581229 581232 581236 581241 581247 581252 581255 581258 581262 581266 581267 581272 581277 581278 581283 581293 581297 581302 581306 581315 581319 581323 581328 581329 581334 581346 581354 581359 581365 581370 581371 581376 581380 581383 581387 581391 581396 581399 581400 581406 581409 581414 581417 581423 ...) (... ... ...) 583762 581195 583763 1 (%Seen %Answered %Flagged %Deleted %Draft $MDNSent) "1899" nil nil)) (("nnimap+exchange:INBOX" 2 (...) (...) "nnimap:exchange" (... ... ... ... ...))))
  (if (and info marks) (nnimap-update-infos marks (list info)))
  (when (and info marks) (nnimap-update-infos marks (list info)))
  (let ((group-sequence ...) (flag-sequence ...)) (nnimap-wait-for-response flag-sequence) (setq marks (nnimap-flags-to-marks ...)) (when (and info marks) (nnimap-update-infos marks ...)) (goto-char (point-max)) (let (...) (setq high ... low ...)))
  (save-current-buffer (set-buffer (nnimap-buffer)) (erase-buffer) (let (... ...) (nnimap-wait-for-response flag-sequence) (setq marks ...) (when ... ...) (goto-char ...) (let ... ...)))
  (with-current-buffer (nnimap-buffer) (erase-buffer) (let (... ...) (nnimap-wait-for-response flag-sequence) (setq marks ...) (when ... ...) (goto-char ...) (let ... ...)))
  (if (and dont-check (setq active ...)) (insert (format "211 %d %d %d %S\n" ... ... ... group)) (with-current-buffer (nnimap-buffer) (erase-buffer) (let ... ... ... ... ... ...)) (erase-buffer) (insert (format "211 %d %d %d %S\n" ... low high group)))
  (progn (if (and dont-check ...) (insert ...) (with-current-buffer ... ... ...) (erase-buffer) (insert ...)) t)
  (if result (progn (if ... ... ... ... ...) t))
  (when result (if (and dont-check ...) (insert ...) (with-current-buffer ... ... ...) (erase-buffer) (insert ...)) t)
  (save-current-buffer (set-buffer nntp-server-buffer) (when result (if ... ... ... ... ...) t))
  (with-current-buffer nntp-server-buffer (when result (if ... ... ... ... ...) t))
  (let ((result ...) articles active marks high low) (with-current-buffer nntp-server-buffer (when result ... t)))
  nnimap-request-group("INBOX" "exchange" nil ("nnimap+exchange:INBOX" 2 ((1 . 583722)) ((seen 581195 ... 581205 581211 581216 581226 581229 581232 581236 581241 581247 581252 581255 581258 581262 ... 581272 ... 581283 581293 581297 581302 581306 581315 581319 581323 ... 581334 581346 581354 581359 581365 ... 581376 581380 581383 581387 581391 581396 ... 581406 581409 581414 581417 581423 581427 581431 581435 581439 ... ...)) "nnimap:exchange" ((permanent-flags) (modseq) (uidvalidity . "1899") (active 581195 . 583739) (imap-status . "574561 574023 574560"))))
  byte-code("..." [dont-sub-check info dont-check gname group gnus-command-method 2 intern-soft gnus-find-method-for-group gnus-server-to-method gnus-get-function request-group string-match "^[^:]+:" 0 nil 1 method gnus-newsrc-hashtb] 8)
  gnus-activate-group("nnimap+exchange:INBOX" scan nil (nnimap "exchange" (nnimap-address "exchange.mywork.org") (nnimap-stream starttls) (nnimap-need-unselect-to-notice-new-mail t) (nnir-search-engine (quote imap)) (nnir-mail-backend "nnimap:exchange") (nnimap-nov-is-evil t)))
  gnus-group-get-new-news-this-group(nil)
  gnus-topic-get-new-news-this-topic(nil)
  call-interactively(gnus-topic-get-new-news-this-topic)


-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: Number of unread articles suddenly incorrect with Exchange 2007

[James Cloos]

I've not debugged it, but am also seeing inaccurate *Group* numbers
again.  I'm currently at 12b9276adbac1bd4d472aa16197f4fe4a1179365.

And like Dave reported, this is a regression.  The new nnimap used
to get this right, unlike the old nnimap.

The last it worked was before you wrote that you had broken nnimap;
0261fd46d2dd0ee6087bca2abd55cbb0a2b479c3 is known good.  That is a
range of 46 commits, so it should take about 6 iterations to narrow
down to the commit which broke the *Group* counts.

Until I finish re-writing how dbmail does an imap LIST, it will be
painful for me to bisect.

Dave (or anyone else): if you want to try a git bisect, you can use
commit 0261fd46 as a known good commit and 12b9276a as a known bad.

The git-bisect(1) man page explains how to use git bisect.

-JimC
-- 
James Cloos <cloos@jhcloos.com>         OpenPGP: 1024D/ED7DAEA6

Re: Number of unread articles suddenly incorrect with Exchange 2007

[Lars Magne Ingebrigtsen]

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

> * nnimap-update-info(("nnimap+exchange:INBOX" 2 ((1 . 583722)) ((seen
> 581195 ...

The data here is truncated.

Could you

(setq print-length nil)
(setq print-level nil)

to give me complete lists, and repeat?  Just email me the result --
it'll probably be somewhat huge.

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

Re: Number of unread articles suddenly incorrect with Exchange 2007

[Dave Goldberg]

> Dave Goldberg <david.goldberg6@verizon.net> writes:
>> * nnimap-update-info(("nnimap+exchange:INBOX" 2 ((1 . 583722)) ((seen
>> 581195 ...

> The data here is truncated.

> Could you

> (setq print-length nil)
> (setq print-level nil)

Sigh.  Those are the defaults in XEmacs 21.4.22 apparently.  I haven't
figured out another way to eliminate truncation in the backtrace
there.  I've dug around the edebug manual and it looks like there's a
tracing capability that might be more flexible.  I'll give it a shot
either later tonight or tomorrow morning.

-- 
Dave Goldberg
david.goldberg6@verizon.net

Re: Number of unread articles suddenly incorrect with Exchange 2007

[Lars Magne Ingebrigtsen]

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

> Sigh.  Those are the defaults in XEmacs 21.4.22 apparently.  I haven't
> figured out another way to eliminate truncation in the backtrace
> there.  I've dug around the edebug manual and it looks like there's a
> tracing capability that might be more flexible.  I'll give it a shot
> either later tonight or tomorrow morning.

The C layer in Emacs set print-level to 3 unconditionally.  (Until I
fixed that a few weeks back.  :-))  Perhaps XEmacs does the same?

But we can cheat.

Start the debug-on-entry thing in nnimap-update-info, and then `M-g'.
Then go to the scratch buffer and eval the following:

(pp (list info marks) (current-buffer))

That should insert everything of interest in the scratch buffer.

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