Massive Xpcshell test failure on 2017-10-28: 100 failing Xpcshell tests, 1 failing Mozmill test (Friday bustage)

RESOLVED FIXED in mozilla57

Status

()

--
blocker
RESOLVED FIXED
a year ago
a year ago

People

(Reporter: jorgk, Assigned: baku)

Tracking

Trunk
mozilla57
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [Thunderbird-testfailure: XZ all])

Attachments

(2 attachments, 1 obsolete attachment)

(Reporter)

Description

a year ago
TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_bug695309.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_bug695309.js | test_newMsgs - [test_newMsgs : 48] 0 == 3
TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_server.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_server.js | do_check_transaction - [do_check_transaction : 201] "MODE READER" == "MODE READER,LIST"
TEST-UNEXPECTED-FAIL | mailnews/base/test/unit/test_copyThenMoveManual.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/base/test/unit/test_copyThenMoveManual.js | getLocalMessages1 - [getLocalMessages1 : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/base/test/unit/test_junkWhitelisting.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/base/test/unit/test_junkWhitelisting.js | OnStopRunningUrl - [OnStopRunningUrl : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/base/test/unit/test_quarantineFilterMove.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/base/test/unit/test_quarantineFilterMove.js | getLocalMessages1 - [getLocalMessages1 : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/base/test/unit/test_postPluginFilters.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/base/test/unit/test_postPluginFilters.js | OnStopRunningUrl - [OnStopRunningUrl : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_bug474774.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_bug474774.js | onStopSending - [onStopSending : 52] 0 == 1
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_bug155172.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_bug155172.js | - "" == "EHLO test,AUTH PLAIN AHRlc3Quc210cEBmYWtlc2VydmVyAHNtdHB0ZXN0,AUTH LOGIN,AUTH PLAIN AHRlc3Quc210cEBmYWtlc2VydmVyAHdyb25n,MAIL F
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMailMessage.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMailMessage.js | do_check_transaction - [do_check_transaction : 71] "" == "EHLO test,MAIL FROM:<from@foo.invalid> BODY=8BITMIME SIZE=155,RCPT TO:<to@foo.invalid>,DATA"
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMessageFile.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMessageFile.js | onStopSending - [onStopSending : 38] 2153066801 == 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMailAddressIDN.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMailAddressIDN.js | alert - [alert : 33] "to@foo.invalid" == "børken.to@invalid.foo.invalid"
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMailAddressIDN.js | onStopSending - [onStopSending : 54] 2153066801 == 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMailAddressIDN.js | alert - [alert : 33] "to@välid.foo.invalid" == "børken.to@invalid.foo.invalid"
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMailAddressIDN.js | onStopSending - [onStopSending : 54] 2153066801 == 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMessageLater.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMessageLater.js | onStopSending - [onStopSending : 64] 2153066801 == 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMessageLater2.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendMessageLater2.js | onStopSending - [onStopSending : 89] 2153066801 == 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtp8bitMime.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtp8bitMime.js | do_check_transaction - [do_check_transaction : 71] "" == "EHLO test,MAIL FROM:<from@foo.invalid> SIZE=155,RCPT TO:<to@foo.invalid>,DATA"
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendBackground.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_sendBackground.js | onStopSending - [onStopSending : 51] 2153066801 == 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpAuthMethods.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpAuthMethods.js | do_check_transaction - [do_check_transaction : 71] "" == "EHLO test,AUTH PLAIN AGZyZWQAd2lsbWE=,MAIL FROM:<from@foo.invalid> BODY=8BITMIME SIZE=155,RCPT TO:<to@foo.invalid>,DATA"
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_messageHeaders.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpPassword.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpPassword.js | - "" == "EHLO test,AUTH PLAIN AHRlc3RzbXRwAHNtdHB0ZXN0,MAIL FROM:<from@foo.invalid> BODY=8BITMIME SIZE=155,RCPT TO:<to@foo.invalid>,DATA
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpPasswordFailure2.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpPasswordFailure2.js | - 0 == 2
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpPasswordFailure1.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpPasswordFailure1.js | - 0 == 2
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpPasswordFailure3.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpPasswordFailure3.js | - 2147549183 == 0
TEST-UNEXPECTED-FAIL | mailnews/compose/test/unit/test_smtpProxy.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_localToImapFilterQuarantine.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_localToImapFilterQuarantine.js | OnStopRunningUrl - [OnStopRunningUrl : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_localToImapFilterQuarantine.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/imap/test/unit/test_localToImapFilterQuarantine.js | OnStopRunningUrl - [OnStopRunningUrl : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_bug457168.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_bug457168.js | do_check_transaction - [do_check_transaction : 121] "" == "AUTH,CAPA,AUTH PLAIN,STAT,LIST,UIDL,RETR 1,DELE 1,RETR 2,DELE 2,RETR 3,DELE 3"
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_duplicateKey.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_duplicateKey.js | runPump - [runPump : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3AuthMethods.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3AuthMethods.js | OnStopRunningUrl - [OnStopRunningUrl : 68] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Download.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Download.js | OnStopRunningUrl - [OnStopRunningUrl : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3DownloadTempFileHandling.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3DownloadTempFileHandling.js | OnStopRunningUrl - [OnStopRunningUrl : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Duplicates.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Duplicates.js | OnStopRunningUrl - [OnStopRunningUrl : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3FilterActions.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3FilterActions.js | getLocalMessages1 - [getLocalMessages1 : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3GSSAPIFail.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3GSSAPIFail.js | do_check_transaction - [do_check_transaction : 121] "" == "AUTH,CAPA"
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3MoveFilter.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3MoveFilter.js | getLocalMessages1 - [getLocalMessages1 : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3GetNewMail.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3GetNewMail.js | do_check_transaction - [do_check_transaction : 121] "" == "AUTH,CAPA,AUTH PLAIN,STAT"
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3MoveFilter2.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3MoveFilter2.js | getLocalMessages1 - [getLocalMessages1 : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3MultiCopy2.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3MultiCopy2.js | setupFolders - [setupFolders : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3MultiCopy.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3MultiCopy.js | runPump - [runPump : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Password.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Password.js | - "" == "AUTH,CAPA,AUTH PLAIN,STAT,LIST,UIDL,RETR 1,DELE 1"
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Proxy.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Pump.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Pump.js | runPump - [runPump : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Password2.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3Password2.js | - "" == "AUTH,CAPA,AUTH PLAIN,STAT,LIST,UIDL,RETR 1,DELE 1"
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3ServerBrokenCRAMFail.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3ServerBrokenCRAMFail.js | OnStopRunningUrl - [OnStopRunningUrl : 20] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3PasswordFailure.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3PasswordFailure.js | - 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3ServerBrokenCRAMDisconnect.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3ServerBrokenCRAMDisconnect.js | do_check_transaction - [do_check_transaction : 121] "" == "AUTH,CAPA,AUTH CRAM-MD5"
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3PasswordFailure3.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3PasswordFailure3.js | OnStopRunningUrl - [OnStopRunningUrl : 98] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3PasswordFailure2.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3PasswordFailure2.js | OnStopRunningUrl - [OnStopRunningUrl : 96] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_streamHeaders.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_streamHeaders.js | OnStopRunningUrl - [OnStopRunningUrl : 70] 2147500037 == 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_verifyLogon.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_verifyLogon.js | OnStopRunningUrl - [OnStopRunningUrl : 41] false == true
TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_bug37465.js | xpcshell return code: 0
TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_bug37465.js | onStopRequest - [onStopRequest : 234] 2147549183 == 0
TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_bug37465.js | run_test - [run_test : 35] "" == "Path: border1.nntp.dca.giganews.com!nntp.giganews.com!local02.nntp.dca.giganews.com!nntp.mozilla.org!news.mozilla.org.POSTED!no
TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_biff.js | xpcshell return code: 0

=== Xpcshell ===
Log:
One example:
WARNING -  TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_bug695309.js | test_newMsgs - [test_newMsgs : 48] 0 == 3
INFO -  C:/slave/test/build/tests/xpcshell/tests/mailnews/news/test/unit/test_bug695309.js:test_newMsgs:48
INFO -  ../../../resources/asyncTestUtils.js:_async_driver:158
INFO -  C:\slave\test\build\tests\xpcshell\head.js:run:701
INFO -  C:\slave\test\build\tests\xpcshell\head.js:_do_main:221
INFO -  C:\slave\test\build\tests\xpcshell\head.js:_execute_test:544
INFO -  -e:null:1
INFO -  exiting test
INFO -  PID 9408 | *******************************************
INFO -  PID 9408 | Generator explosion!
INFO -  PID 9408 | Unhappiness at: undefined:undefined
INFO -  PID 9408 | Because: 2147500036
INFO -  PID 9408 | **** Async Generator Stack source functions:
INFO -  PID 9408 |   test_newMsgs
INFO -  PID 9408 |   _async_test_runner
INFO -  PID 9408 | *********
INFO -  PID 9408 | 2147500036
INFO -  PID 9408 | -- Exception object --
INFO -  PID 9408 | +  (number) 2147500036
INFO -  PID 9408 | *
INFO -  Generator explosion. ex: 2147500036 async stack [test_newMsgs,_async_test_runner]
INFO -  ../../../resources/asyncTestUtils.js:_async_driver:187

Another example:
INFO -  TEST-START | mailnews/news/test/unit/test_server.js
WARNING -  TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_server.js | xpcshell return code: 0
INFO -  TEST-INFO took 831ms
INFO -  >>>>>>>
INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
WARNING -  TEST-UNEXPECTED-FAIL | mailnews/news/test/unit/test_server.js | do_check_transaction - [do_check_transaction : 201] "MODE READER" == "MODE READER,LIST"

=== Mozmill ===
TEST-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\subscribe\test-subscribe-news-filter.js | test-subscribe-news-filter.js::test_subscribe_newsgroup_filter

Log:
INFO -  SUMMARY-PASS | test-subscribe-news-filter.js::setupModule
INFO -  SUMMARY-UNEXPECTED-FAIL | C:\slave\test\build\tests\mozmill\subscribe\test-subscribe-news-filter.js | test-subscribe-news-filter.js::test_subscribe_newsgroup_filter
INFO -    EXCEPTION: test.subscribe.empty not in the list
INFO -      at: utils.js line 409
INFO -         TimeoutError utils.js:409 13
INFO -         waitFor utils.js:447 11
INFO -         filter_test_helper test-subscribe-news-filter.js:39 3

M-C last good: ae49d4a57622 (try run)
M-C first bad: d58424c244c3
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=ae49d4a57622&tochange=d58424c244c3
Flags: needinfo?(acelists)
(Reporter)

Comment 1

a year ago
Oh, I forgot to say: Aceman, could you lend a hand here please. This looks pretty busted.

Tooru and FRG: You're my Oracles ;-) Can you see the bug that cause this?
Flags: needinfo?(frgrahl)
Flags: needinfo?(arai.unmht)
maybe Bug 1411939?
the condition around the following assertion is touched by it, and the assertion didn't failed before that.

https://hg.mozilla.org/mozilla-central/rev/560296786c0c

> 17:46:14     INFO -  PID 21688 | [21688, Main Thread] ###!!! ASSERTION: OnDataAvailable implementation consumed no data:
> 'Error', file /builds/slave/tb-c-cen-lx-d-0000000000000000/build/mozilla/netwerk/base/nsInputStreamPump.cpp, line 614

I'm not sure if there's any other related changes, but the change around stream could cause so much errors like that.
Flags: needinfo?(arai.unmht)
(Reporter)

Comment 3

a year ago
Thanks. Hmm, yes, I spotted that bug, too. So more Necko bustage and no Mailnews reviewers, great :-((
I'll do a local backout and see.
(Reporter)

Comment 4

a year ago
Running
  mozilla/mach xpcshell-test mailnews/news/test/unit/test_bug695309.js
manually in a debug build I crash at 
PROCESS_OUTPUT: Thread-1 (pid:3444) "[3444, Main Thread] ###!!! ASSERTION: OnDataAvailable implementation consumed no data: 'Error', file c:/mozilla-source/comm-central/mozilla/netwerk/base/nsInputStreamPump.cpp, line 614"

That code reads:
                else if (mSuspendCount == 0) {
                    //
                    // possible infinite loop if we continue pumping data!
                    //
                    // NOTE: although not allowed by nsIStreamListener, we
                    // will allow the ODA impl to Suspend the pump.  IMAP
                    // does this :-(
                    //
614                 NS_ERROR("OnDataAvailable implementation consumed no data");
                    mStatus = NS_ERROR_UNEXPECTED;

Jolly good, so the internals of Netwerk know about IMAP ;-)

With https://hg.mozilla.org/mozilla-central/rev/01998e227015 from bug 1411939 backed out, the test passes.

Since it's Mailnews bustage, I'll have to fix it myself.
Blocks: 1411939
Flags: needinfo?(frgrahl)
Flags: needinfo?(acelists)
(Reporter)

Comment 5

a year ago
Andrea and Olli, https://hg.mozilla.org/mozilla-central/rev/01998e227015 seems like a small change, but it caused a lot of bustage. Any hints what to look for?

For example the first failing test is in mailnews/news, so I'm looking at the use of nsIInputStreamPump in nsNNTPProtocol.cpp. I'm not sure what to look for. Is there a pattern?
Flags: needinfo?(bugs)
Flags: needinfo?(amarchesini)
Do you have some links to the relevant mailnews code?
Flags: needinfo?(bugs)
(I wonder what would be the best way to land that kinds of patches to cause less trouble to TB.)
(Reporter)

Comment 8

a year ago
> (I wonder what would be the best way to land that kinds of patches to cause less trouble to TB.)
Me too.

> Do you have some links to the relevant mailnews code?
Links, well, there is DXR.
https://dxr.mozilla.org/comm-central/source/mailnews

One could start by looking at the first test and see why it fails. Maybe there is a pattern.

News code is here:
https://dxr.mozilla.org/comm-central/source/mailnews/news/src

Pump usage is here:
https://dxr.mozilla.org/comm-central/source/mailnews/news/src/nsNNTPProtocol.cpp

Looks like there are a lot of POP tests failing, so the POP stuff is here:
https://dxr.mozilla.org/comm-central/source/mailnews/local/src

What is the thing we're looking for?
(Reporter)

Updated

a year ago
Severity: normal → blocker
Whiteboard: [Thunderbird-testfailure: XZ all]

Comment 9

a year ago
Created attachment 8923128 [details] [diff] [review]
1412497.patch

Looking at https://hg.mozilla.org/mozilla-central/rev/01998e227015 I found this change suspicious:
 nsresult
 nsInputStreamPump::CreateBufferedStreamIfNeeded()
 {
-  if (mBufferedStream) {
+  if (mAsyncStream) {
     return NS_OK;
   }

If you see later on in the function, when the stream is made buffered, it is assigned back to the same mAsyncStream function.
So I think just checking if mAsyncStream is non-null does not mean it is already a buffered stream (may still be only asyncStream).

This patch removes this superfluous check. The check may have been useful before as mBufferedStream indicated the stream was already buffered.

Or should it be changed to check and fail if mAsyncStream is NOT initialized?

It fixes some of the c-c test for me that I tried locally.
Jorg, please push to try.
Attachment #8923128 - Flags: feedback?(jorgk)

Comment 10

a year ago
(In reply to :aceman from comment #9)
> If you see later on in the function, when the stream is made buffered, it is
> assigned back to the same mAsyncStream function.
... mAsyncStream variable.
(Reporter)

Comment 11

a year ago
Comment on attachment 8923128 [details] [diff] [review]
1412497.patch

https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=6a09eb5839d705159fac869f53a708076d35253e

That code looks reasonable. If left in, the following code will never run:

 nsresult
 nsInputStreamPump::CreateBufferedStreamIfNeeded()
 {
-  if (mAsyncStream) {
-    return NS_OK;
-  }
-
   // ReadSegments is not available for any nsIAsyncInputStream. In order to use
   // it, we wrap a nsIBufferedInputStream around it, if needed.
 
   if (NS_InputStreamIsBuffered(mAsyncStream)) {
     return NS_OK;
   }
Attachment #8923128 - Flags: feedback?(bugs)
Attachment #8923128 - Flags: feedback?(amarchesini)

Comment 12

a year ago
Ah, this patches solves a serious problem with SM/TB-Trunk. One of the many aspects were the impossibility to read posts on a NG.
(Reporter)

Comment 13

a year ago
Comment on attachment 8923128 [details] [diff] [review]
1412497.patch

This patch is a blasting SUCCESS!! It reduces the test failures from 100 down to one, only failure left is:
TEST-UNEXPECTED-FAIL | mailnews/local/test/unit/test_pop3PasswordFailure.js | xpcshell return code: 0
I haven't looked into it, but that might be our problem.

As for:
> (I wonder what would be the best way to land that kinds of patches to
> cause less trouble to TB.)
There are a few answers: 
- Give some heads-up: In bug 1402888 you changed the interface to
  a few functions we use (which DXR would have shown) which predictably caused
  (a lot of) bustage.
- Don't land it on Friday and then be unavailable during the weekend.
  TB is mainly carried by volunteers who work on on the weekend and can't
  work of our tree is busted.
- Get it right ;-)
  I believe what you landed was wrong to start with and although not tested in FF
  the problem was detected by FF's secondary testing brigade.
- Increase test coverage so the former doesn't happen.

I'd appreciate a quick review and since neither I nor Aceman push to inbound or autoland, please push it for us, it you think it's right.

Aceman: Maybe you have time to investigate the last failure. Anyway, with one failure instead of 100 sheriffing is possible again and I can reopen our tree.
Flags: needinfo?(amarchesini)
Attachment #8923128 - Flags: review?(bugs)
Attachment #8923128 - Flags: review?(amarchesini)
Attachment #8923128 - Flags: feedback?(jorgk)
Attachment #8923128 - Flags: feedback?(bugs)
Attachment #8923128 - Flags: feedback?(amarchesini)
Attachment #8923128 - Flags: feedback+
(Reporter)

Comment 14

a year ago
I ran
  mozilla/mach xpcshell-test mailnews/local/test/unit/test_pop3PasswordFailure.js
and it hung. So some sort of async problem. Needs further analysis.
(Assignee)

Comment 15

a year ago
Comment on attachment 8923128 [details] [diff] [review]
1412497.patch

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

Maybe would be nice to have a boolean, otherwise we constantly execute ReadSegments() via NS_InputStreamIsBuffered().
Attachment #8923128 - Flags: review?(bugs)
Attachment #8923128 - Flags: review?(amarchesini)
Attachment #8923128 - Flags: review-
(Reporter)

Comment 16

a year ago
Created attachment 8923154 [details] [diff] [review]
1412497-fix-buffered-test.patch

How about this then. Seems to work on the test I ran.
Attachment #8923154 - Flags: review?(amarchesini)
(Assignee)

Comment 17

a year ago
Comment on attachment 8923154 [details] [diff] [review]
1412497-fix-buffered-test.patch

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

Thanks!
Attachment #8923154 - Flags: review?(amarchesini) → review+
(Reporter)

Comment 18

a year ago
Please push it for us.
Flags: needinfo?(amarchesini)
(Assignee)

Updated

a year ago
Flags: needinfo?(amarchesini)

Updated

a year ago
Attachment #8923128 - Attachment is obsolete: true
(Reporter)

Updated

a year ago
Keywords: leave-open
(Reporter)

Comment 20

a year ago
Confirmed via local backout of M-C rev 01998e227015 that the failure of test_pop3PasswordFailure.js is also caused by that change.
(Reporter)

Comment 21

a year ago
Further looking into test_pop3PasswordFailure.js.

Working run looks like this:
0:02.80 PROCESS_OUTPUT: Thread-1 (pid:5276) "Get Mail 1"
...
 0:02.93 PROCESS_OUTPUT: Thread-1 (pid:5276) "Cancelling login attempt"
 0:02.94 TEST_STATUS: Thread-1  PASS 0 == 0
 0:02.94 TEST_STATUS: Thread-1  PASS 2152398850 == 2152398850

Where the last two tests come from OnStopRunningUrl().
Value	0x804B0002 (2152398850)
Name	NS_BINDING_ABORTED

When the test fails, the debug looks like this:
 0:02.94 PROCESS_OUTPUT: Thread-1 (pid:968) "Get Mail 1"
 0:02.95 PROCESS_OUTPUT: Thread-1 (pid:968) "GetDiskSpaceAvailable returned: 7693582336
 0:02.96 PROCESS_OUTPUT: Thread-1 (pid:968) "[968, Main Thread] WARNING: NS_ENSURE_SUCC
 0:02.96 PROCESS_OUTPUT: Thread-1 (pid:968) "=== urlListener OnStartRunningUrl"
...
 0:03.08 PROCESS_OUTPUT: Thread-1 (pid:968) "Cancelling login attempt"
 0:03.09 LOG: Thread-1 INFO (xpcshell/head.js) | test _async_driver finished (3)
 4:02.95 LOG: Thread-1 ERROR Timeout running test, and we want you to have the log.

So OnStopRunningUrl() isn't called any more. Currently investigating from where it should be called and then hopefully why it's not called any more.
(Reporter)

Comment 22

a year ago
On an older build where this is still working, Joshua did some debugging for me, here's a working stack:

#27 0x00007fffead86704 in nsMsgMailNewsUrl::SetUrlState(bool, nsresult) (this=0x7fffd3c0ec88, aRunningUrl=false, aExitCode=-2142568446) at /src/trunk/comm-central/mailnews/base/util/nsMsgMailNewsUrl.cpp:168
#28 0x00007fffead8e2d0 in nsMsgProtocol::OnStopRequest(nsIRequest*, nsISupports*, nsresult) (this=0x7fffd85c9ac0, request=0x7fffd3b66100, ctxt=0x7fffd3c0ec88, aStatus=-2142568446)
    at /src/trunk/comm-central/mailnews/base/util/nsMsgProtocol.cpp:393
#29 0x00007fffeb01b6cc in nsPop3Protocol::OnStopRequest(nsIRequest*, nsISupports*, nsresult) (this=0x7fffd85c9ac0, aRequest=0x7fffd3b66100, aContext=0x7fffd3c0ec88, aStatus=-2142568446)
    at /src/trunk/comm-central/mailnews/local/src/nsPop3Protocol.cpp:990
#30 0x00007fffeb3539dd in nsInputStreamPump::OnStateStop() (this=0x7fffd3b66100) at /src/trunk/comm-central/mozilla/netwerk/base/nsInputStreamPump.cpp:704
#31 0x00007fffeb35293d in nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) (this=0x7fffd3b66100, stream=0x7fffd3de1550) at /src/trunk/comm-central/mozilla/netwerk/base/nsInputStreamPump.cpp:427
#32 0x00007fffeb1fcdeb in nsInputStreamReadyEvent::Run() (this=0x7fffd3b89e70) at /src/trunk/comm-central/mozilla/xpcom/io/nsStreamUtils.cpp:97

Note that nsMsgMailNewsUrl.cpp:168 is NOTIFY_URL_LISTENERS(OnStopRunningUrl, (this, aExitCode));

So let's see why nsInputStreamPump::OnStateStop() doesn't appear to be calling mListener->OnStopRequest() any more.
(Reporter)

Comment 23

a year ago
(In reply to Jorg K (GMT+2) from comment #22)
> So let's see why nsInputStreamPump::OnStateStop() doesn't appear to be
> calling mListener->OnStopRequest() any more.
Oh, ignore comment #22, it always calls mListener->OnStopRequest(), but it looks like nsInputStreamPump::OnStateStop() isn't called.

Joshua suggested a nsStreamPump log.

So that gives:
 0:03.35 PROCESS_OUTPUT: Thread-1 (pid:6356) "Alert Title: Error with account testpop3 on localhost"
 0:03.35 PROCESS_OUTPUT: Thread-1 (pid:6356) "Alert Text: Sending of password for user testpop3 did not succeed. Mail server localhost responded: invalid password"
 0:03.35 PROCESS_OUTPUT: Thread-1 (pid:6356) "Cancelling login attempt"
 0:03.35 PROCESS_OUTPUT: Thread-1 (pid:6356) "[Main Thread]: D/nsStreamPump nsInputStreamPump::Cancel [this=0C5C6FC0 status=804b0002]"
 0:03.33 LOG: Thread-1 INFO (xpcshell/head.js) | test _async_driver finished (3)

Going back to a working version to compare, I see:
 0:03.67 PROCESS_OUTPUT: Thread-1 (pid:6300) "Alert Title: Error with account testpop3 on localhost"
 0:03.67 PROCESS_OUTPUT: Thread-1 (pid:6300) "Alert Text: Sending of password for user testpop3 did not succeed. Mail server localhost responded: invalid password"
 0:03.67 PROCESS_OUTPUT: Thread-1 (pid:6300) "Cancelling login attempt"
 0:03.67 PROCESS_OUTPUT: Thread-1 (pid:6300) "[Main Thread]: D/nsStreamPump nsInputStreamPump::Cancel [this=0BDE7FC0 status=804b0002]"
 0:03.67 PROCESS_OUTPUT: Thread-1 (pid:6300) "[Main Thread]: D/nsStreamPump nsInputStreamPump::OnInputStreamReady [this=0BDE7FC0]"
 0:03.68 PROCESS_OUTPUT: Thread-1 (pid:6300) "[Main Thread]: D/nsStreamPump   OnStateTransfer [this=0BDE7FC0]"
 0:03.68 PROCESS_OUTPUT: Thread-1 (pid:6300) "[Main Thread]: D/nsStreamPump   OnStateStop [this=0BDE7FC0 status=804b0002]"
 0:03.68 PROCESS_OUTPUT: Thread-1 (pid:6300) "=== urlListener OnStopRunningUrl 1"
 0:03.68 PROCESS_OUTPUT: Thread-1 (pid:6300) "=== urlListener OnStopRunningUrl 2"
 0:03.65 TEST_STATUS: Thread-1  PASS 0 == 0
 0:03.65 TEST_STATUS: Thread-1  PASS 2152398850 == 2152398850

So I think we need to go back to Olli and Andrea and ask: Why has the behaviour of the pump changed here?

Before I got
 0:03.67 PROCESS_OUTPUT: Thread-1 (pid:6300) "[Main Thread]: D/nsStreamPump nsInputStreamPump::Cancel [this=0BDE7FC0 status=804b0002]"
 0:03.67 PROCESS_OUTPUT: Thread-1 (pid:6300) "[Main Thread]: D/nsStreamPump nsInputStreamPump::OnInputStreamReady [this=0BDE7FC0]"
 0:03.68 PROCESS_OUTPUT: Thread-1 (pid:6300) "[Main Thread]: D/nsStreamPump   OnStateTransfer [this=0BDE7FC0]"
 0:03.68 PROCESS_OUTPUT: Thread-1 (pid:6300) "[Main Thread]: D/nsStreamPump   OnStateStop [this=0BDE7FC0 status=804b0002]"

Now I get:
 0:03.35 PROCESS_OUTPUT: Thread-1 (pid:6356) "[Main Thread]: D/nsStreamPump nsInputStreamPump::Cancel [this=0C5C6FC0 status=804b0002]"

Is this intentional? In OnStateStop our listener gets called and now it doesn't get called any more.
Flags: needinfo?(bugs)
Flags: needinfo?(amarchesini)
(Assignee)

Comment 25

a year ago
Can you tell me how to reproduce it locally?
Flags: needinfo?(amarchesini) → needinfo?(jorgk)
(Reporter)

Comment 26

a year ago
We reproduce it by building Thunderbird [1], then we run
  mozilla/mach xpcshell-test mailnews/local/test/unit/test_pop3PasswordFailure.js
from the command line.

Sorry, I have no better answer. I was going to say that I'll upload you a debug Windows build or you can download a Treeherder debug build but that won't allow you to run the test.

[1] https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Build_Instructions/Simple_Thunderbird_build
Flags: needinfo?(jorgk)
(Reporter)

Comment 27

a year ago
Can I do something to help diagnosing this?
Flags: needinfo?(amarchesini)
(Assignee)

Updated

a year ago
Assignee: nobody → amarchesini
Flags: needinfo?(amarchesini)
(Assignee)

Comment 28

a year ago
This is a bug in nsBufferedInputStream. I'm going to send a patch to review for today.
(Assignee)

Comment 29

a year ago
Created attachment 8924457 [details] [diff] [review]
buffered.patch

nsBufferedInputStream::Close() should not nullify mAsyncWaitCallback, because, if we have a callback, this has to be triggered when the stream is closed. If the callback is dispatched asynchronously, when  nsBufferedInputStream::OnInputStreamReady is called, mAsyncWaitCallback doesn't have to be null, in order to continue calling the nsIInputStreamCallback callback.

I want to create a template to cleanup some code here, in SlicedInputStream and in other wrapper inputStreams.
Attachment #8924457 - Flags: review?(bugs)
And we don't leak with the patch?
You explicitly added that line in bug 1360887.
(Assignee)

Comment 31

a year ago
We don't because OnInputStreamReady will be called eventually and we nullify mAsyncWaitCallback there.
Comment on attachment 8924457 [details] [diff] [review]
buffered.patch

Crossing fingers this doesn't cause leaks then :)
Flags: needinfo?(bugs)
Attachment #8924457 - Flags: review?(bugs) → review+
(Reporter)

Comment 33

a year ago
No one has asked for my feedback and I also don't know whether Andrea in fact built TB (which can be a hassle on Windows with MAPI headers, etc.) and ran the test. Here it comes anyway:
  mozilla/mach xpcshell-test mailnews/local/test/unit/test_pop3PasswordFailure.js
now passes \o/

Thanks!
(Assignee)

Comment 34

a year ago
Oh yes, I used comm-central to check if my patch was able to pass that test.

Comment 35

a year ago
Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/725d13675a52
nsBufferedInputStream should call the nsIInputStreamCallback when closed, r=smaug
(Reporter)

Updated

a year ago
Status: NEW → RESOLVED
Last Resolved: a year ago
Component: General → DOM
Product: Thunderbird → Core
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
(Reporter)

Updated

a year ago
Keywords: leave-open
You need to log in before you can comment on or make changes to this bug.