Open
Bug 1176857
Opened 9 years ago
Updated 2 years ago
C-C TB Enabling buffering for pop3 download (and possibly part of imap file operation)
Categories
(MailNews Core :: Database, defect)
MailNews Core
Database
Tracking
(Not tracked)
NEW
People
(Reporter: ishikawa, Assigned: ishikawa)
References
(Depends on 1 open bug, Blocks 2 open bugs)
Details
(Keywords: perf)
Attachments
(1 file, 4 obsolete files)
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•9 years ago
|
Assignee: nobody → ishikawa
|
|
Assignee | |
Comment 1•9 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•9 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•9 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•9 years ago
|
|
||
Comment 4•9 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•9 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•9 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•9 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•9 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•9 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•9 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•8 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•8 years ago
|
||
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•8 years ago
|
Component: OS Integration → Database
Product: Thunderbird → MailNews Core
|
|
||
Comment 13•8 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•8 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•8 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•8 years ago
|
||
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 | |
Comment 17•8 years ago
|
||
Bitrot, rebase, etc.
|
|
Assignee | |
Updated•8 years ago
|
Attachment #8721175 -
Attachment is obsolete: true
|
|
Assignee | |
Comment 18•8 years 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•8 years 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
|
||
Updated•2 years ago
|
Severity: normal → S3
You need to log in
before you can comment on or make changes to this bug.
Description
•