C-C TB Enabling buffering for pop3 download (and possibly part of imap file operation)

NEW
Assigned to

Status

MailNews Core
Database
3 years ago
10 months ago

People

(Reporter: ISHIKAWA, Chiaki, Assigned: ISHIKAWA, Chiaki)

Tracking

(Depends on: 1 bug, Blocks: 2 bugs)

Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 4 obsolete attachments)

(Assignee)

Description

3 years ago
Created attachment 8625452 [details] [diff] [review]
One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman

Hi, 
This is a split from an existing bug:
a post comment 25 of bug 1116055 and specifically
its attachment.
https://bugzilla.mozilla.org/show_bug.cgi?id=1116055#c25

I have split this from the original bugzilla and created a new entry because I am planning to propose a series of patches and there is already a path in bug 1116055 and
the patch proposed in this bug can be applied safely ONLY AFTER patches explained below have been applied before.

TIA

========================================
ORDER
========================================

 1 A check_fileptr_change.patch: Bug 1116055: Check the unexpected change of file seek position and ask the user to report it
     bugzilla 1116055 

     This was considered a necessary step so that we can know that
     if any user experiences a strange seek position change.

 2 A fix-close-step-1.patch: Bug 1122698 Cleaning of incorrect Close, unchecked Flush, Write etc. in nsPop3Sink.cpp and friends (part 1 of  a series)

     bug 1122698

 3 A fix-close-part-2.patch: Bug 1134527 Add error value checking of Close() and Flush() (part-2 of a series)

     bug 1134527

 4 A fix-close-part-3-write-error-check.patch: Bug 1134529: Check Write failures (part-3 of a series)

     bug 1134529

 5 A removing-a-Seek.patch: C-C Thunderbird - Cleaning of incorrect Close, unchecked Flush, Write etc. in nsPop3Sink.cpp and friends. (step 4)

    NEW BUG to be submitted.

 6 A 1116055-acelist.patch: One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman

     This bugzilla entry (!)
     
     I will create a separate bug for this since it will be necessary to apply this patch
     only after other patches landed. (This is because enabling the
     buffering requires proper error checking of |Close()| and |Flush()|. These are only
     taken care of AFTER 1-5 patches above are applied.)
     
     Maybe about a month after the first patch above is applied, I can enable this patch.

 7 A add-short-read-handling.patch: Bug 1170606 - C-C T-B fixes to take care of short read
     11170606

     This is theoretically independent of 1-6, but my local patch assumes the changes
     in 1-6 to be in place. (The patch may not apply cleanly.)

     There are some additional shor-read issues UNDER M-C portion of the source tree.
     They can be applied indepdent of this series.
(Assignee)

Updated

3 years ago
Assignee: nobody → ishikawa
(Assignee)

Comment 1

3 years ago
Comment on attachment 8625452 [details] [diff] [review]
One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman

This is going to be in a series of patches.

The following is the updated list (with exact bugzilla #, etc.)

========================================
PLANNED ORDER
========================================

* 1 A check_fileptr_change.patch: Bug 1116055: Check the unexpected change of file seek position and ask the user to report it

   bug 1116055 

   This was considered a necessary step so that we can know that if
   any user experiences a strange seek position change.

* 2 A fix-close-step-1.patch: Bug 1122698 Cleaning of incorrect Close, unchecked Flush, Write etc. in nsPop3Sink.cpp and friends (part 1 of  a series)

   bug 1122698

* 3 A fix-close-part-2.patch: Bug 1134527 Add error value checking of Close() and Flush() (part-2 of a series)

   bug 1134527

* 4 A fix-close-part-3-write-error-check.patch: Bug 1134529: Check Write failures (part-3 of a series)

   bug 1134529

* 5 A removing-a-Seek.patch: C-C Thunderbird - Cleaning of incorrect Close, unchecked Flush, Write etc. in nsPop3Sink.cpp and friends. (step 4)

   bug 1174500 [was mistyped as 1117450 in a few bugzilla entries. :-( ]

6 A 1116055-acelist.patch: One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman

   This bugzilla entry.
   Bug 1176857 - C-C TB Enabling buffering for pop3 download (and possibly part of imap file operation)

   I have created a separate bug for this since it will be necessary
   to apply this patch only after other patches landed. (This is
   because enabling the buffering requires proper error checking of
   |Close()| and |Flush()|. These are only taken care of AFTER 1-5
   patches above are applied.)

   Maybe about a month after the first patch (bug 1116055) above is
   applied, and other patches 2-5 have been applied, I can enable this
   patch. (Assuming there is NO ONE who reports strange seek position
   change on their computer.)

7 A add-short-read-handling.patch: Bug 1170606 - C-C T-B fixes to take care of short read

   Bug 1170606

   This is theoretically independent of 1-6, but my local patch
   assumes the changes in 1-6 to be in place. (The patch may not apply
   cleanly without 1-6 in advance.)

  There are some additional shor-read issues UNDER M-C portion of the
  source tree.  They can be applied indepdent of this series.

Please feel free to take up the review or move it to somebody else
based on the workload of the potential reviewers.

TIA
Attachment #8625452 - Flags: review?(mkmelin+mozilla)

Comment 2

3 years ago
Comment on attachment 8625452 [details] [diff] [review]
One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman

Review of attachment 8625452 [details] [diff] [review]:
-----------------------------------------------------------------

I'm not a good reviewer for this. 
But since it's to be applied after a bunch of the other have landed, maybe hold on asking for review until later
Attachment #8625452 - Flags: review?(mkmelin+mozilla)
(Assignee)

Comment 3

3 years ago
(In reply to Magnus Melin from comment #2)
> Comment on attachment 8625452 [details] [diff] [review]
> One liner patch posted in Bug 1116055 to return a buffered stream from
> mbox::getNewOutputStream by aceman
> 
> Review of attachment 8625452 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'm not a good reviewer for this. 
> But since it's to be applied after a bunch of the other have landed, maybe
> hold on asking for review until later

Thank you for the response.
Your name came up in the suggested reviewers list.

I will ask again when other patches have landed.
(Assignee)

Updated

3 years ago
(Assignee)

Updated

3 years ago
Blocks: 1170606

Comment 4

2 years ago
(In reply to Magnus Melin from comment #2)
> Comment on attachment 8625452 [details] [diff] [review]
> One liner patch posted in Bug 1116055 to return a buffered stream from
> mbox::getNewOutputStream by aceman
> 
> Review of attachment 8625452 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'm not a good reviewer for this. 
> But since it's to be applied after a bunch of the other have landed, maybe
> hold on asking for review until later

As discussed privately with Chiaki, I think we should revisit the order of patches. Given that 
- in 6 months only 1 of the patches (bug 1116055) in the 5 blocking bugs is reviewed
- version 45 pretty much freezes in 2 weeks, so the probability of getting these patches into version 45 is slim to none
- the patch in this bug is simple and *really* does not depend on the others - we just ordered them that way to 
- I'm coming to reconsider that the value in getting this patch outweighs the theoretical increase risk of dataloss connected to the other bug reports

Chiaki can perhaps speak to whether any of the "blocking" patches are going to be reviewed in this week or not, mostly waiting on jcranmer. But I am in favor of forging ahead now with this patch for version 45, and getting magnus' review. Although doing so will bitrot some of the other patches.
Flags: needinfo?(ishikawa)
(Assignee)

Comment 5

2 years ago
(In reply to Wayne Mery (:wsmwk, use Needinfo for questions) from comment #4)
> (In reply to Magnus Melin from comment #2)
> > Comment on attachment 8625452 [details] [diff] [review]
> > One liner patch posted in Bug 1116055 to return a buffered stream from
> > mbox::getNewOutputStream by aceman
> > 
> > Review of attachment 8625452 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > I'm not a good reviewer for this. 
> > But since it's to be applied after a bunch of the other have landed, maybe
> > hold on asking for review until later
> 
> As discussed privately with Chiaki, I think we should revisit the order of
> patches. Given that 
> - in 6 months only 1 of the patches (bug 1116055) in the 5 blocking bugs is
> reviewed
> - version 45 pretty much freezes in 2 weeks, so the probability of getting
> these patches into version 45 is slim to none
> - the patch in this bug is simple and *really* does not depend on the others
> - we just ordered them that way to 
> - I'm coming to reconsider that the value in getting this patch outweighs
> the theoretical increase risk of dataloss connected to the other bug reports
> 
> Chiaki can perhaps speak to whether any of the "blocking" patches are going
> to be reviewed in this week or not, mostly waiting on jcranmer. But I am in
> favor of forging ahead now with this patch for version 45, and getting
> magnus' review. Although doing so will bitrot some of the other patches.

In the last few weesk, I have finally been able to compile
OS X and Windows binary and thus have been able to run tests on tryserver.
(It is not a smooth sailing: build breaks for no apparent reason due to hg issue, or strange time out.)
I have become fairly confident that OS X testing is OK. It only produced known intermittent errors and a few constant errors that are also seen in other builds of other people, too.

One suspicious issue is a few failures in xpcshell-tests under Windows.
It is hard why they fail. I considered a lot, but short of having a local windows
build and debug environment, it is rather difficult to diagnose.
But it hit upon me that some errors are known to occur only under debug build. So
I am testing only debug build so far. Today I am going to submit an optimize build test as well so that I can focus only bugs that occur in optimized build.

If the errors don't occur in debug build, I can honestly propose that the patches be reviewed (not exactly one by one, but maybe a few groups of a few patches.)

On my PC, the patches have been updated to be compatible with the latest C-C so far (whether it was a good idea or not, I am not sure.)

So when the windows test failure issues are sorted out in my mind, I will upload the renewed patches that can be merged to the latest C-C tree without many issues.

TIA
Flags: needinfo?(ishikawa)
(Assignee)

Comment 6

2 years ago
As for the failures, these are the ones that worry me:
In https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=440a88dcb0b6&selectedJob=12536
These happen in windows DEBUG build:
Only a portion:

TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_imapFilterActions.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolderBody - [MoveToFolderBody : 600] false == true
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolderBody - [MoveToFolderBody : 100] 3 == 2
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_offlineDraftDataloss.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_offlineDraftDataloss.js | checkResult - [checkResult : 109] 0 == 1
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_offlineDraftDataloss.js | _async_driver - TypeError: ex.stack is undefined at ../../../resources/asyncTestUtils.js:169
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_downloadOffline.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_bug460636.js | xpcshell return code: 0  
...
(Assignee)

Comment 7

2 years ago
To be honest, I am not even sure how to diagnose the error.
To wit, this is the raw log lines that follows the first error above:

It looks that the test is run using "Maildir". This is not what
something I have used myself.

In this particular log, I get an unexpected exception, but it is not
entirely clear what goes on.

The test has the comment in the beginning.

/*
 * This file tests imap filter actions, particularly as affected by the
 * addition of body searches in bug 127250. Actions that involves sending
 * mail are not tested. The tests check various counts, and the effects
 * on the message database of the filters. Effects on IMAP server
 * flags, if any, are not tested.
 *
 * Original author: Kent James <kent@caspia.com>
 * adapted from test_localToImapFilter.js
 */

It is hard to see why my patches affects this, but
since it involves I/O handling, it could possibly, but I am not
entirely certain.


The log below complains that something was asserted in line 600 of
test_imapFilterActions.js.


    function testCounts(aHasNew, aUnreadDelta, aFolderNewDelta, aDbNewDelta)
    {
      try {
      let folderNew = IMAPPump.inbox.getNumNewMessages(false);
      let hasNew = IMAPPump.inbox.hasNewMessages;
      let unread = IMAPPump.inbox.getNumUnread(false);
      let countOut = {};
      let arrayOut = {};
      db().getNewList(countOut, arrayOut);
      let dbNew = countOut.value ? countOut.value : 0;
      let folderNewFlag = IMAPPump.inbox.getFlag(Ci.nsMsgFolderFlags.GotNew);
      dump(" hasNew: " + hasNew +
           " unread: " + unread +
           " folderNew: " + folderNew +
           " folderNewFlag: " + folderNewFlag +
           " dbNew: " + dbNew +
           " prevUnread " + gPreviousUnread +
           "\n");
==>   Assert.equal(aHasNew, hasNew);
      Assert.equal(aUnreadDelta, unread - gPreviousUnread);

So this means aHasNew and hasNew ought to be the same, but somehow
not, and thus an error is triggered.

To be honest, I got stuck there.
Why don't linux and OS X build show the same errors?
Hmm...


--- log ---


 21:16:31  WARNING -  TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_imapFilterActions.js | xpcshell return code: 0
 21:16:31     INFO -  TEST-INFO took 1503ms
 21:16:31     INFO -  >>>>>>>
 21:16:31     INFO -  "Running test with maildir"
 21:16:31     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
 21:16:31     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
 21:16:31     INFO -  running event loop
 21:16:31     INFO -  mailnews/imap/test/unit/test_imapFilterActions.js | Starting setupIMAPPump
 21:16:31     INFO -  (xpcshell/head.js) | test setupIMAPPump pending (2)
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
 21:16:31     INFO -  (xpcshell/head.js) | test setupIMAPPump finished (2)
 21:16:31     INFO -  mailnews/imap/test/unit/test_imapFilterActions.js | Starting setupFilters
 21:16:31     INFO -  (xpcshell/head.js) | test setupFilters pending (2)
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
 21:16:31     INFO -  (xpcshell/head.js) | test setupFilters finished (2)
 21:16:31     INFO -  mailnews/imap/test/unit/test_imapFilterActions.js | Starting MoveToFolder
 21:16:31     INFO -  (xpcshell/head.js) | test MoveToFolder pending (2)
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 554] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 554] 0 == 0
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
 21:16:31     INFO -  PROCESS | 6908 | AUTH PLAIN line -AHVzZXIAcGFzc3dvcmQ=-
 21:16:31     INFO -  PROCESS | 6908 | authorize-id: --, username: -user-, password: -password-
 21:16:31     INFO -  PROCESS | 6908 | received folder event FolderCreateCompleted folder Trash
 21:16:31     INFO -  PROCESS | 6908 | received folder event FiltersApplied folder Inbox
 21:16:31     INFO -  PROCESS | 6908 | received folder event FolderLoaded folder Inbox
 21:16:31     INFO -  PROCESS | 6908 | received folder event DeleteOrMoveMsgCompleted folder Inbox
 21:16:31     INFO -  PROCESS | 6908 | received folder event DeleteOrMoveMsgCompleted folder Inbox
 21:16:31     INFO -  PROCESS | 6908 |	hasNew: false unread: 0 folderNew: 0 folderNewFlag: false dbNew: 0 prevUnread 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 600] false == false
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 601] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 611] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 554] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 76] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 554] 1 == 1
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder - [MoveToFolder : 77] 1 == 1
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
 21:16:31     INFO -  (xpcshell/head.js) | test MoveToFolder finished (2)
 21:16:31     INFO -  mailnews/imap/test/unit/test_imapFilterActions.js | Starting MoveToFolder2
 21:16:31     INFO -  (xpcshell/head.js) | test MoveToFolder2 pending (2)
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 554] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 554] 1 == 1
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
 21:16:31     INFO -  PROCESS | 6908 | received folder event FiltersApplied folder Inbox
 21:16:31     INFO -  PROCESS | 6908 | received folder event FolderLoaded folder Inbox
 21:16:31     INFO -  PROCESS | 6908 | received folder event DeleteOrMoveMsgCompleted folder Inbox
 21:16:31     INFO -  PROCESS | 6908 | received folder event DeleteOrMoveMsgCompleted folder Inbox
 21:16:31     INFO -  PROCESS | 6908 |	hasNew: false unread: 0 folderNew: 0 folderNewFlag: false dbNew: 0 prevUnread 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 600] false == false
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 601] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 611] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 554] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 88] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 554] 2 == 2
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolder2 - [MoveToFolder2 : 89] 2 == 2
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 4 pending (2)
 21:16:31     INFO -  (xpcshell/head.js) | test MoveToFolder2 finished (2)
 21:16:31     INFO -  mailnews/imap/test/unit/test_imapFilterActions.js | Starting MoveToFolderBody
 21:16:31     INFO -  (xpcshell/head.js) | test MoveToFolderBody pending (2)
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolderBody - [MoveToFolderBody : 554] 0 == 0
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolderBody - [MoveToFolderBody : 554] 2 == 2
 21:16:31     INFO -  (xpcshell/head.js) | test run_next_test 4 finished (2)
 21:16:31     INFO -  PROCESS | 6908 | received folder event FiltersApplied folder Inbox
 21:16:31     INFO -  PROCESS | 6908 | received folder event FolderLoaded folder Inbox
 21:16:31     INFO -  PROCESS | 6908 |	hasNew: true unread: 1 folderNew: 1 folderNewFlag: false dbNew: 1 prevUnread 0
 21:16:31  WARNING -  TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolderBody - [MoveToFolderBody : 600] false == true
 21:16:31     INFO -	  C:/slave/test/build/tests/xpcshell/tests/mailnews/imap/test/unit/test_imapFilterActions.js:testCounts:600
 21:16:31     INFO -	  C:/slave/test/build/tests/xpcshell/tests/mailnews/imap/test/unit/test_imapFilterActions.js:MoveToFolderBody:99
 21:16:31     INFO -	  _run_next_test@C:\slave\test\build\tests\xpcshell\head.js:1468:9
 21:16:31     INFO -	  do_execute_soon/<.run@C:\slave\test\build\tests\xpcshell\head.js:660:9
 21:16:31     INFO -	  _do_main@C:\slave\test\build\tests\xpcshell\head.js:208:5
 21:16:31     INFO -	  _execute_test@C:\slave\test\build\tests\xpcshell\head.js:520:5
 21:16:31     INFO -	  @-e:1:1
 21:16:31     INFO -  exiting test
 21:16:31     INFO -  PROCESS | 6908 | 2147500036
 21:16:31     INFO -  TEST-PASS | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolderBody - [MoveToFolderBody : 554] 2 == 2
 21:16:31  WARNING -  TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_imapFilterActions.js | MoveToFolderBody - [MoveToFolderBody : 100] 3 == 2
 21:16:31     INFO -	  C:/slave/test/build/tests/xpcshell/tests/mailnews/imap/test/unit/test_imapFilterActions.js:MoveToFolderBody:100
 21:16:31     INFO -	  _run_next_test@C:\slave\test\build\tests\xpcshell\head.js:1468:9
 21:16:31     INFO -	  do_execute_soon/<.run@C:\slave\test\build\tests\xpcshell\head.js:660:9
 21:16:31     INFO -	  _do_main@C:\slave\test\build\tests\xpcshell\head.js:208:5
 21:16:31     INFO -	  _execute_test@C:\slave\test\build\tests\xpcshell\head.js:520:5
 21:16:31     INFO -	  @-e:1:1
 21:16:31     INFO -  exiting test
 21:16:31     INFO -  Unexpected exception 2147500036
 21:16:31     INFO -  undefined
 21:16:31     INFO -  exiting test
 21:16:31     INFO -   A promise chain failed to handle a rejection: 2147500036 - rejection date: Sun Nov 29 2015 21:16:31 GMT-0800 (Pacific Standard Time)
 21:16:31     INFO -  JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: PendingErrors.register :: line 191
 21:16:31     INFO -  JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.completePromise :: line 715
 21:16:31     INFO -  JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: Handler.prototype.process :: line 970
 21:16:31     INFO -  JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: this.PromiseWalker.walkerLoop :: line 813
 21:16:31     INFO -  <<<<<<<
 21:16:31     INFO -  TEST-START | mailnews/imap/test/unit/test_offlineDraftDataloss.js
 21:16:34  WARNING -  TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_offlineDraftDataloss.js | xpcshell return code: 0
 21:16:34     INFO -  TEST-INFO took 2837ms
 21:16:34     INFO -  >>>>>>>
 21:16:34     INFO -  "Running test with maildir"

I wonder what is the best course of debugging this.

TIA
(Assignee)

Comment 8

2 years ago
Dear rkent,

Since you were the original author of the test, can you suggest a possible debugging approach?
Flags: needinfo?(rkent)

Comment 9

2 years ago
These issues are not simple to debug. What it is saying is that, in a move, you do not expect the move of a message into that folder to trigger hasNewMessages for that folder. For some reason, it is now doing so.

These issues are complex because the whole concept of "new messages" is conflated with lots of different meanings, and set in multiple ways. If can also be quite difficult to trace out when and why these are being set, and convince yourself that it is working correctly or not.

As for approach to debugging, I would set lots of prints around the affected tests, making sure that I understand all of the variables affected. Then I would try the tested concept in a real Thunderbird installation, and see if the issue is actually one that appears. If the issue is real, then it is dump statements, printf statements, and debugger breakpoints to figure it out.

This is a great example of an area of technical debt that can make Thunderbird really hard to work on.
Flags: needinfo?(rkent)
(Assignee)

Comment 10

2 years ago
(In reply to Kent James (:rkent) from comment #9)
> These issues are not simple to debug. What it is saying is that, in a move,
> [... omitted ...]

Oh well, thank you for the great tips, which 
actually I did not want to hear to be frank ! :-)

OK, at least, I will try to see what changes of mine would trigger the strange behavior
under Windows debug version now (I am removing some non-essential patches and then
will home on what particular change triggers this behavior in Windows Build.)

I have a general suspicion that Flush() semantics may be slightly different under Windows (?) especially when we may want to begin reading from a file to which we have been writing to...

Anyway, when I can home in the suspicious place, I will dump values under LINUX first and try to compare the values in windows debug build.

Let us see what I can find out.

TIA
(Assignee)

Comment 11

2 years ago
(In reply to Kent James (:rkent) from comment #9)
> These issues are not simple to debug. What it is saying is that, in a move,
> you do not expect the move of a message into that folder to trigger
> hasNewMessages for that folder. For some reason, it is now doing so.
> 
> These issues are complex because the whole concept of "new messages" is
> conflated with lots of different meanings, and set in multiple ways. If can
> also be quite difficult to trace out when and why these are being set, and
> convince yourself that it is working correctly or not.
> 
> As for approach to debugging, I would set lots of prints around the affected
> tests, making sure that I understand all of the variables affected. Then I
> would try the tested concept in a real Thunderbird installation, and see if
> the issue is actually one that appears. If the issue is real, then it is
> dump statements, printf statements, and debugger breakpoints to figure it
> out.
> 
> This is a great example of an area of technical debt that can make
> Thunderbird really hard to work on.


Hi, I finally managed to obtain windows build that dumps enough (I hope enough) context where the
failure occurs in test.
Can you kindly see what can stand out in the error log?

https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&selectedJob=14215

The first error seems to be caused by the failure of MoveToNativ() [under Windows]

an example: 
(debug) nsMsgMaildirStore::GetMsgInputStream: fromPath->MoveToNative(toPath, fileName); failed. rv=8052000e
(debug) nsMsgMaildirStore::GetMsgInputStream: fromPath->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\Mail\\Local Folders\\Subfolder\\tmp\\1451270575984000>>
(debug) nsMsgMaildirStore::GetMsgInputStream: toPath->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\Mail\\Local Folders\\Subfolder\\cur>>
(debug) fileName = <<1451270575984000>>

Let us take a look at the first failure of windows XP test run of
xpcshell tests.

e.g.:
 18:42:56  WARNING -  TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_imapFilterActions.js | xpcshell return code: 0
 18:42:56     INFO -  TEST-INFO took 1640ms
 18:42:56     INFO -  >>>>>>>
 18:42:56     INFO -  PROCESS | 6672 | (debug) EnsureShortPath: mShortWorkingPath was non-empty (return without extra work)
 18:42:56     INFO -  PROCESS | 6672 | [6672] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file c:/builds/moz2_slave/tb-try-c-cen-w32-d-00000000000/build/mozilla/toolkit/crashreporter/nsExceptionHandler.cpp, line 2339
 18:42:56     INFO -  "Running test with maildir"
 18:42:56     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)

[omission]

 ...

 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMessengerWinIntegration::SetupInbox: server type is NEITHER imap NOR pop3 (maybe local folder, news accounts)
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMessengerWinIntegration::SetupInbox: server type is NEITHER imap NOR pop3 (maybe local folder, news accounts)
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMessengerWinIntegration::SetupInbox: server type is NEITHER imap NOR pop3 (maybe local folder, news accounts)
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMessengerWinIntegration::SetupInbox: server type is NEITHER imap NOR pop3 (maybe local folder, news accounts)
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: fromPath->MoveToNative(toPath, fileName); failed. rv=8052000e
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: fromPath->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\Mail\\Local Folders\\Subfolder\\tmp\\1451270575984000>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: toPath->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\Mail\\Local Folders\\Subfolder\\cur>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) fileName = <<1451270575984000>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: fromPath->MoveToNative(toPath, fileName); failed. rv=8052000e
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: fromPath->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\Mail\\Local Folders\\Subfolder\\tmp\\1451270576234000>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: toPath->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\Mail\\Local Folders\\Subfolder\\cur>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) fileName = <<1451270576234000>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: fromPath->MoveToNative(toPath, fileName); failed. rv=8052000e
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: fromPath->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\ImapMail\\localhost\\INBOX\\tmp\\1451270576468000>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: toPath->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\ImapMail\\localhost\\INBOX\\cur>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) fileName = <<1451270576468000>>
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: NS_NewLocalFileInputStream() failed. rv=80520012
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgMaildirStore::GetMsgInputStream: path->nativePath = <<c:\\docume~1\\cltbld~1.t-x\\locals~1\\temp\\xpc-profile-acux9r\\ImapMail\\localhost\\INBOX\\cur\\1451270576468000>>
 18:42:57     INFO -  PROCESS | 6672 | nsMsgDBFolder.cpp:899: nsMsgDBFolder::GetMsgInputStream: msgStore->GetMsgInputStream(this, ...) returned error rv=80520012
 18:42:57     INFO -  PROCESS | 6672 | [6672] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file c:/builds/moz2_slave/tb-try-c-cen-w32-d-00000000000/build/mailnews/base/util/nsMsgDBFolder.cpp, line 902
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgSearchScopeTerm::GetInputStream():m_folder->GetMsgInputStream failed returning rv=0x80520012
 18:42:57     INFO -  PROCESS | 6672 | [6672] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file c:/builds/moz2_slave/tb-try-c-cen-w32-d-00000000000/build/mailnews/base/search/src/nsMsgSearchTerm.cpp, line 1893
 18:42:57     INFO -  PROCESS | 6672 | (debug) nsMsgBodyHandler::OpenLocalFolder: returning early since m_scope->GetInputStream failed.
 18:42:57     INFO -  PROCESS | 6672 | [6672] WARNING: NS_ENSURE_SUCCESS_VOID(rv) failed with result 0x80520012: file c:/builds/moz2_slave/tb-try-c-cen-w32-d-00000000000/build/mailnews/base/search/src/nsMsgBodyHandler.cpp, line 148
 18:42:57     INFO -  PROCESS | 6672 | received folder event FiltersApplied folder Inbox
 18:42:57     INFO -  PROCESS | 6672 | received folder event FolderLoaded folder Inbox
 18:42:57     INFO -  PROCESS | 6672 |  hasNew: true unread: 1 folderNew: 1 folderNewFlag: false dbNew: 1 prevUnread 0



I have no idea why MoveToNative failed.
I am a little troubled at the mixture of short form paths (i.e.,
docume~1) and long form paths, but maybe it is OK.


I am beginning to suspect the incorrect order of test executions
due to async nature of test framework, and maybe the support code for
such async execution: I see "generator explosion" message in the later log,
and this message seems to come from the async-support routine of windows.
Also I noticed an error of NS_ERROR_FILE_IS_LOCKED: somehow
a file is still being used while other processes tries to either open (or write?)?
[Maybe there are semantic differences between linux/OS X and Windows when opened files
are accessed for another "open" or "write".

It seems that mostly imap-related tests seem to fail under Windows.
(linux tests run fine locally on my PC, and OS X debug tests pass
basically except for strange new errors seen by others, too.)


PS: I resort to old "insert print" style of debugging since
the error only occurs under Windows and I don't have windows development environment and have no idea how to run xpcshell tests under Windows even if I have one.

TIA
Flags: needinfo?(rkent)
(Assignee)

Comment 12

2 years ago
Created attachment 8711172 [details] [diff] [review]
Debug output with One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman buffering-1116055-acelist.patch

I have come to a tentative conclusion that the windows errors I see may be related to the failure of ASYNC testing support under windows. This is based on the observation that I see "Generator Explosion" which is printed by ASYNC support JS routine. I also saw NS_ERROR_FILE_LOCKED suggesting that a file was still in use when another test was invoked. This suggested that the proper syncing among testing was not quite handled well. I also noticed the strange errors during xpcshell-test on my local linux PC which suggested that the sync problem may also exist on linux, but it is OK to "OPEN" a file which was used by other process under linux/posix, I think. So the problem did not manifest under linux and OS X clearly.

Anyway, I will post a rational of the recent update and roadmap of the patches, 
I have added a dump for DEBUG build to print the name to which a buffered output stream is created. By tracing such buffered output stream creation, I have a suspicion that  this particular buffering may be  unnecessary.
But to eliminate this particular buffering requires more analysis.

TIA
Attachment #8625452 - Attachment is obsolete: true

Updated

2 years ago
Component: OS Integration → Database
Product: Thunderbird → MailNews Core

Comment 13

2 years ago
I'm trying to get to some old needinfo requests.

Looking at this bug, the only way I can help is to devote several hours to tracing through the problems. Unfortunately, applying the one-line patch in this bug does not show the issue. Also, your logs show issues in maildir, but the patch is in mbox, so I highly doubt that the patch in this bug is the source of your issues.

If you would like me to investigate when I get a chance, could you please prepare a patch that includes a diff of everything needed to reproduce from current trunk? It's too hard to try to figure out all of the patches you want me to land first, while a diff should be simple for you.
Flags: needinfo?(rkent)
(Assignee)

Comment 14

2 years ago
(In reply to Kent James (:rkent) from comment #13)
> I'm trying to get to some old needinfo requests.
> 
> Looking at this bug, the only way I can help is to devote several hours to
> tracing through the problems. Unfortunately, applying the one-line patch in
> this bug does not show the issue. Also, your logs show issues in maildir,
> but the patch is in mbox, so I highly doubt that the patch in this bug is
> the source of your issues.
> 
> If you would like me to investigate when I get a chance, could you please
> prepare a patch that includes a diff of everything needed to reproduce from
> current trunk? It's too hard to try to figure out all of the patches you
> want me to land first, while a diff should be simple for you.

Thank you for taking the time, rkent.

I have been trying to disect my patches to see which particular patch(es) cause this
discrepancy in the test output. Only windows show these errors.
(I have been hampered with other errors caused by mainly changes in M-C tree portion for the last few weeks as usual.)

Once I narrow down the relevant patch(es), I will ask you. 
Actually, if I can narrow the cause of the issues sufficiently, I may be able to
come up with potential theory to present to you, but maybe I am too optimistic :-)

TIA
(Assignee)

Comment 15

2 years ago
Also, I am sorry that the bugs in comment 11 are result of all the necessary patches
for enabling buffer (and prerequisite I/O error checks just in case), etc.
Sorry for not being clear about it.
I was talking about how to get the whole patch set included into C-C tree rather than
only this single patch.

Again, I will create a reduced patch set that can create the errors under windows. (and have been trying despite the build bustages now and then due to 
frantic pace of M-C changes).

Problem is compounded since the errors are not observed under linux and OSX.

TIA
(Assignee)

Comment 16

2 years ago
Created attachment 8721175 [details] [diff] [review]
Debug output with One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman buffering-1116055-acelist.patch

A full explanation of the updated patches and road map is in bug 116055 comment 107
https://bugzilla.mozilla.org/show_bug.cgi?id=1116055#c107

I am excerpting a relevant part for this bugzilla entry and a couple of other very related patches (one that comes before it, and one that comes after this.).



========================================
PLANNED ORDER of landing patches
========================================

bug 1116055
  -> bug 1242030 (consolidation of 1122698, 1134527, 1134529, 1174500)
    -> bug 1242042 
       -> bug 1176857
         -> bug 1242046
           -> bug 1242050
             -> bug 1170606

========================================
An overview of patches in bugzilla entries.
----------------------------------------

[In February 2016, I fixed the errors observed ONLY UNDER WINDOWS when
we use Maildir format for storage. Thus I needed to tweak my patch set
somewhat and added a patch to take care of this issue and so I updated
this write-up.]

......

[7] (New in 2016 ) Bug 1242042 - Enabling buffering for file stream to write message for C-C TB
A enable-buffering-1st-step.patch: Enabling buffering first step.

 I have extracted the code to enable buffering to be applied after
 the additional error checks in the preceding patches [1]-[6].

 After a couple of months of testing of the final patches, I realize
 a certain buffering operations that were in the patch are actually
 unnecessary, and so commented them out. (We can enable them back
 again if my understanding of the code flow is incorrect. There are
 many combination of execution paths, and I may misunderstood the
 nature of certain paths. My gripe about slow downloading of
 messages and saving of large attachment *ARE* handled properly by
 buffering now.)

 I have created the separate patch to enable buffering since it will
 be necessary to apply this patch ONLY AFTER previous patches to
 check for primitive I/O errors have landed. (This is because
 enabling the buffering requires proper error checking of |Close()|
 and |Flush()|. |Close| was never checked properly in the existing
 code.   These are only taken care of AFTER patches [1]-[6] above are
 applied.

 BTW, I have not had the time to fix this issue of missing error
 checks of |Close()| in files under mailnews/import directory
 completely yet. If you don't believe me, read the source!
 Fixing this issue would be a good student project.

[8] Bug 1176857
1116055-acelist.patch: One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman

 The patch has been posted to the following bugzilla entry.
 Bug 1176857 - C-C TB Enabling buffering for pop3 download (and possibly part of imap file operation)

 After the latest review of my local patches and testing, I realized
 that some buffering operations in my patch may be unnecessary for some
 operations. But I leave them as such.
 This patch from aceman could fall under that category, too.
 We may want to review the operation of the program more carefully
 to see if it is indeed unnecessary for some operations, but it does
 not hurt to have this buffering function for now.
 Lack of internal documentation of low-level protocol handling,
 etc. hurts.

[9] (NEW in 2016)
Bug 1242046:  	Removing unnecessary |Seek| that caused the C-C TB to operate slowly in terms of I/O 
  removing-a-Seek-rev02.patch: removing a Seek that is performance
  pig!  This was extracted into a new patch from the patches above [5]-[8].

  Even if buffering is properly enabled, one offending |Seek()|
  needs to be disabled so that the buffering is effective for
  writing messages to a local file. Otherwise, this |Seek()|
  interferes with buffering, and essentially we call system |write| 
  for EACH LINE of message, thus lowering output performance
  significantly.

  Killing this |Seek| did the trick. We now call ONE |Seek| per
  message, NOT one |Seek| per ONE LINE of message!

  This patch requires the landing of [1]-[8] before it.

...
Attachment #8711172 - Attachment is obsolete: true
(Assignee)

Updated

a year ago
Blocks: 1242046
(Assignee)

Updated

a year ago
Depends on: 1242042
(Assignee)

Updated

a year ago
Depends on: 1306914
(Assignee)

Updated

a year ago
No longer depends on: 1306914
(Assignee)

Comment 17

a year ago
Created attachment 8798564 [details] [diff] [review]
Debug output with One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman buffering-1116055-acelist.patch

Bitrot, rebase, etc.
(Assignee)

Updated

a year ago
Attachment #8721175 - Attachment is obsolete: true
(Assignee)

Comment 18

a year ago
I am sorry that forgot to mention the important solution to the bugs mentioned in comment 5
and which were solved in the early spring of 2016.

The bugs seen under windows which were experienced only when C-C TB uses "maildir"
were traced to the following issue in my patch set to enable buffered output (and making sure to recover from errors at least as IncorporateBegin, InborporteEnd, IncorporateAbort, etc.) [ See bug 1116055 and friends] caused the |Close()| .

My initial patches of file streams handling delayed the |Close()| call a little than the original unpatched C-C TB.
During this delay before the file stream was closed, C-C TB tries to move/delete/rename a directory or a file.
Under linux and OSX, such operations against a file/directory which has an open file stream is allowed.
So I did not see the errors on these platforms.
But under windows, it is a prohibited operation.
Thus the errors I observed.

I finally wised up after dumping file names and directory names related to the strange errors on windows test run on try-comm-central, and
modified my patches so that closing of the offending stream happens as early as the original code.
Voila, no more errors.

Currently, my attempts to enable buffered output for C-C TB requires the landing of the following patch series and the patch in this bugzilla entry is one of them.


bug 1116055  (this bugzilla that enables the check)
 => bug 939548 (could be split into two, one being merged into bug 1242030)
  -> bug 1242030 
     (extra |Seek()| is removed) 
    -> bug 1242042  Enabling buffering for file stream to write message for C-C TB
       (This enables buffering).
        *Note*: We will start to see the necessity of one |Seek()| in IncorporateBegin here.
*THIS  -> bug 1176857  C-C TB Enabling buffering for pop3 download (and possibly part of imap file operation)
          *Note*: this may be also the reason why we need one |Seek()| in IncorporateBegin.
         -> bug 1242046  Removing unnecessary |Seek| that caused the C-C TB to operate slowly in terms of I/O
            (seek position check is removed finally here.)
           -> bug 1242050 (already landed)
             -> bug 1170606 (this can wait)

The title of the patches are a little outdated (or off the mark from the patches posted there) after so many months (almost a year or two). I will clean them up tomorrow.

TIA
(Assignee)

Updated

a year ago
Attachment #8798564 - Attachment description: Debug output with One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman buffering-1116055-acelist.patchenable-buffering-1116055-acelist.patch → Debug output with One liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman buffering-1116055-acelist.patch
(Assignee)

Comment 19

10 months ago
Created attachment 8834483 [details] [diff] [review]
Additional debug output together with one liner patch posted in Bug 1116055 to return a buffered stream from mbox::getNewOutputStream by aceman buffering-1116055-acelist.patch

bitrot.
Attachment #8798564 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.