Bugzilla

Reporter

Comment 1

•

7 years 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)

Tooru Fujisawa [:arai]

Comment 2

•

7 years ago

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

•

7 years 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

•

7 years 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

•

7 years 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)

Comment 6

•

7 years ago

Do you have some links to the relevant mailnews code?

Flags: needinfo?(bugs)

Comment 7

•

7 years ago

(I wonder what would be the best way to land that kinds of patches to cause less trouble to TB.)

Reporter

Comment 8

•

7 years 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

•

7 years ago

Severity: normal → blocker

Whiteboard: [Thunderbird-testfailure: XZ all]

:aceman

Comment 9

•

7 years ago

Attached patch 1412497.patch (obsolete) — Details — Splinter Review

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)

:aceman

Comment 10

•

7 years 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

•

7 years 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)

Hartmut Figge

Comment 12

•

7 years 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

•

7 years 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

•

7 years 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

•

7 years 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

•

7 years ago

Attached patch 1412497-fix-buffered-test.patch — Details — Splinter Review

How about this then. Seems to work on the test I ran.

Attachment #8923154 - Flags: review?(amarchesini)

Assignee

Comment 17

•

7 years 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

•

7 years ago

Please push it for us.

Flags: needinfo?(amarchesini)

Assignee

Updated

•

7 years ago

Flags: needinfo?(amarchesini)

Pulsebot

Comment 19

•

7 years ago

Pushed by amarchesini@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b65bdac64411
fix test for buffered input stream. r=baku

:aceman

Updated

•

7 years ago

Attachment #8923128 - Attachment is obsolete: true

Reporter

Updated

•

7 years ago

Keywords: leave-open

Reporter

Comment 20

•

7 years 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

•

7 years 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

•

7 years 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.

Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)

Reporter

Comment 23

•

7 years 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)

Comment 24

•

7 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/b65bdac64411

Assignee

Comment 25

•

7 years ago

Can you tell me how to reproduce it locally?

Flags: needinfo?(amarchesini) → needinfo?(jorgk)

Reporter

Comment 26

•

7 years 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

•

7 years ago

Can I do something to help diagnosing this?

Flags: needinfo?(amarchesini)

Assignee

Updated

•

7 years ago

Assignee: nobody → amarchesini

Flags: needinfo?(amarchesini)

Assignee

Comment 28

•

7 years ago

This is a bug in nsBufferedInputStream. I'm going to send a patch to review for today.

Assignee

Comment 29

•

7 years ago

Attached patch buffered.patch — Details — Splinter Review

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)

Comment 30

•

7 years ago

And we don't leak with the patch?
You explicitly added that line in bug 1360887.

Assignee

Comment 31

•

7 years ago

We don't because OnInputStreamReady will be called eventually and we nullify mAsyncWaitCallback there.

Comment 32

•

7 years ago

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

•

7 years 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

•

7 years ago

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

Pulsebot

Comment 35

•

7 years ago

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

Andreea Pavel [:apavel]

Comment 36

•

7 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/725d13675a52

Reporter

Updated

•

7 years ago

Status: NEW → RESOLVED

Closed: 7 years ago

Component: General → DOM

Product: Thunderbird → Core

Resolution: --- → FIXED

Target Milestone: --- → mozilla57