47263 - fix pipe refcounting bug [@ nsFileTransport::Process]

Status: VERIFIED FIXED

(Core :: Networking, defect, P1)

Description

[Warren Harris]

Some intermittent problem was introduced with the file transport and how it 
refcounts pipes. This shows up in bug 46267 and bug 45358. Danm checked in a 
work-around, but I'm afraid the real problem lurks elsewhere. I need to 
investigate.

Comment 1

[Dan M]

  I've run into this problem again. It's difficult to reproduce under a debugger 
-- it happens only intermittently and dallying at breakpoints seems to make it 
happen less often, though not to kill it completely.
  So I was encouraged to put printfs into the END_READ case of 
nsFileTransport::Process(), like this:

--- ./netwerk/base/src/nsFileTransport.cpp.1.84	Mon Aug 14 16:10:38 2000
+++ ./netwerk/base/src/nsFileTransport.cpp	Mon Aug 14 16:02:10 2000
@@ -481,7 +481,15 @@
       }
 
       case END_READ: {
-        
+
+        printf("END_READ nsFileTransport %8lX own thread %8lX curr thread 
%8lX\n",
+          (long)this,(long)_mOwningThread,(long)NS_CurrentThread());
+        if (!mBufferOutputStream) {
+          mXferState = CLOSING;
+          printf("***************** bad END_READ ****************\n");
+          break;
+        }
+
         PR_AtomicDecrement(&mService->mInUseTransports);
 
         PR_LOG(gFileTransportLog, PR_LOG_DEBUG,

I get output like this, occasionally including the *** bad END_READ *** part:

Error loading URL file:///d|/download/800Kfile.exe
WEBSHELL+ = 5
END_READ nsFileTransport  38847A0 own thread   944CC0 curr thread  2499A18
END_READ nsFileTransport  335F028 own thread   944CC0 curr thread  2499A18
END_READ nsFileTransport  38C7B20 own thread   944CC0 curr thread  2499A18

result native path = D:\download\test

WEBSHELL+ = 6
************************************************************
** NOTE: This report will only be printed in DEBUG builds.**
* Call to xpconnect wrapped JSObject produced this error:  *
[Exception... "[Exception... "Illegal value"  code: "-2147024809" nsresult: "0x8
0070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "chrome://global/content/downloadPr
ogress.js Line: 70"] [nsIObserver::Observe]"  nsresult: "0x8057001c (NS_ERROR_XP
C_JS_THREW_JS_OBJECT)"  location: "<unknown>"  data: no]
************************************************************
D:\builds\moz\mozilla\xpfe\components\xfer\src\nsStreamXferOp.cpp 389: Observe f
ailed, rv=0x8057001C
END_READ nsFileTransport  32A74C8 own thread   944CC0 curr thread   DE3FF8
WEBSHELL- = 5
END_READ nsFileTransport  38D27A8 own thread   944CC0 curr thread   D0FF08
WEBSHELL- = 4
END_READ nsFileTransport  338A028 own thread   944CC0 curr thread   D0FF08
END_READ nsFileTransport  338A028 own thread   944CC0 curr thread  2499A18
***************** bad END_READ ****************
END_READ nsFileTransport  338A028 own thread   944CC0 curr thread   DE3FF8
END_READ nsFileTransport  338A028 own thread   944CC0 curr thread  248EC18

  I'd swear I did the owning thread / current thread comparison correctly. If 
so, there are a couple of things to notice here. First, the current executing 
thread seems *never* to be the object's owning thread. Second, in this example, 
the same nsFileTransport object is sent through the END_READ case twice, once 
each from different threads.
  This causes at least an assertion on debug builds because 
mBufferOutputStream->Flush() is called when mBufferOutputStream is null. It was 
the crux of the problem with bug 46267.

  I don't know where to go from here. It seems that a bunch of threads jump in 
and cause the END_READ case at the end of a file transport. Is this expected? It 
seems wrong. My ignorance of the code is making me not want to try to figure out 
where the threads are coming from (though a breakpoint in the thread constructor 
tells me no new threads were created during the file download).
  Does this ring any bells?
  Another perhaps related thing: if you launch Mozilla and get a directory 
listing by typing into the url bar something like file:///d|/builds, all looks 
normal. If however you launch Mozilla with that -url, all directories in the 
d|/builds directory are listed twice. I mention this here because it seems like 
there may be competing read threads executing. Maybe it's unrelated.

Comment 2

[Jay Patel [:jay]]

Adding topcrash keyword (this crash [@ nsFileTransport::Process] shows up in the 
latest talkback data).  The latest stack traces are the same as the one given in 
bug 46267.

Comment 3

[Jay Patel [:jay]]

Adding chofmann to cc list.  I didn't want to log another tracking bug for this
crash since warren already seems to be on it.  Just for future reference, this
crash is #4 on the topcrash list (8/23) from talkback for PR2 build 2000080712

Comment 4

[Jay Patel [:jay]]

Here are some newer entries from talkback, this crash is still in the top20 for 
the latest builds!

nsFileTransport::Process 029656bf
        
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/netwerk/base/src/nsFileTrans
port.cpp line 511
        Build: 2000092213 CrashDate: 2000-09-25 UptimeMinutes: 1  Total: 21 
        OS: Windows NT  5.0 build 2195
        URL: http://securityportal.com/topnews/weekly/linux20000925.html 
ftp://ftp.porcupine.org/mirrors/postfix-release/experimental/
        Comment: it crashed with no back and forth between the two sites:
         Detailed : http://climate/reports/incidenttemplate.cfm?bbid=18011083
         StackTrace: 
http://climate/reports/stackcommentemail.cfm?dynamicBBID=18011083

    nsFileTransport::Process 029656bf
        
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/netwerk/base/src/nsFileTrans
port.cpp line 511
        Build: 2000092213 CrashDate: 2000-09-25 UptimeMinutes: 8  Total: 8 
        OS: Windows NT  5.0 build 2195
        URL: http://securityportal.com/topnews/weekly/linux20000925.html 
ftp://ftp.porcupine.org/mirrors/postfix-release/experimental/
        Comment: after browsing to the ftp site (I started at 
http://linuxtoday.com
         Detailed : http://climate/reports/incidenttemplate.cfm?bbid=18009663
         StackTrace: 
http://climate/reports/stackcommentemail.cfm?dynamicBBID=18009663

nsFileTransport::Process c7e73879
        
http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/netwerk/base/src/nsFileTrans
port.cpp line 511
        Build: 2000092112 CrashDate: 2000-09-21 UptimeMinutes: 106  Total: 106 
        OS: Windows NT  5.0 build 2195
        URL: view-source: 
chrome://messenger/content/mail3PaneWindowVertLayout.xul
        Comment: 
         Detailed : http://climate/reports/incidenttemplate.cfm?bbid=17831338
         StackTrace: 
http://climate/reports/stackcommentemail.cfm?dynamicBBID=17831338

Comment 5

[Phil Peterson]

Not holding PR3 for this; marking nsbeta3-. Adding rtm keyword since it's a
topcrash.

Comment 6

[Michael La Guardia]

Marking "needinfo." Will reconsider for inclusion once there is a reviewed and
super reviewed patch.

Comment 7

[John Morrison]

So, I hit this crash today, and later noticed that this was on the list
of top crashers in n.p.m.crash-data (somewhere around #15 on average).

Current talkback stack traces say the crash is happening here:
http://lxr.mozilla.org/seamonkey/source/netwerk/base/src/nsFileTransport.cpp#51
6

511   if (mTransferAmount > 0 && NS_SUCCEEDED(mStatus)) {
512       // This happens when the requested read amount is more than the amo
513       // of the data in the stream/file.
514       mStatus = NS_BASE_STREAM_CLOSED;
515   }
516   mOutputStream->Flush();                    <----- Boom!!
517   mOutputStream = null_nsCOMPtr();
518   mInputStream = null_nsCOMPtr();
519 

As a bandaid, would a kungFuDeathGrip and/or a null pointer check be the
way to skip the crash for RTM? (Especially since the next thing we are
about to do is to null the pointer).

Comment 8

[Warren Harris]

This is interesting -- since line 517 is the only place we set this to null, it 
would imply that we're coming through END_READ twice. That could screw up the 
mInUseTransports count, among other things. 

I don't think a kungFuDeathGrip will help the situation here since it's an 
instance variable, not something on the stack, but I do think being defensive 
about calling Flush is a good thing. 

Cc'ing jband who might take an interest in taking a look at this hard to spot 
problem.

Comment 9

[Warren Harris]

Index: nsFileTransport.cpp
===================================================================
RCS file: /cvsroot/mozilla/netwerk/base/src/nsFileTransport.cpp,v
retrieving revision 1.87
diff -u -r1.87 nsFileTransport.cpp
--- nsFileTransport.cpp	2000/09/26 05:03:30	1.87
+++ nsFileTransport.cpp	2000/10/12 10:45:25
@@ -513,8 +513,10 @@
             // of the data in the stream/file.
             mStatus = NS_BASE_STREAM_CLOSED;
         }
-        mOutputStream->Flush();
-        mOutputStream = null_nsCOMPtr();
+        if (mOutputStream) {
+            mOutputStream->Flush();
+            mOutputStream = null_nsCOMPtr();
+        }
         mInputStream = null_nsCOMPtr();
 
         mSource = null_nsCOMPtr();

Comment 10

[John Morrison]

I just checked, and this crash still occurs on occasion in candidate builds of 
the 19th and 20th. It was a big source of crashes in PR3. 

(By the way, some of the comments refer to dealing with large files or large 
mail folders).

Comment 11

[John Morrison]

I realize that there is a larger bug at question here (why does this routine
get entered twice). However, this crash is still occuring in candidate builds
with enough regularity that I think the simple bulletproof null pointer check
would be worthwhile to check into the branch. 

(That is unless it is the case that the user is doomed no matter what, and 
doing the null-pointer check will just transfer the crash or data-loss to 
some other point in the code).  

Comment 12

[Chris Waterson]

sure, this bulletproofing looks good. add an assertion somewhere so that we
don't completely forget about the "enter END_READ twice" problem, and sr=waterson

Comment 13

[Warren Harris]

Removing 'need info'. Let's rtm++ this.

Comment 14

[selmer (gone)]

This bug is in candidate limbo.  We will reconsider this fix once we have a 
candidate in hand, but we can't take this fix before then.  Please check into 
the trunk ASAP.

Comment 15

[Warren Harris]

Checked into trunk. (Note that this is a work-around.)

Comment 16

[selmer (gone)]

rtm++, please checkin ASAP so we can build today.

Comment 17

[Warren Harris]

Checked into branch too.

Comment 18

[John Morrison]

Filed bug 59215 to track the original refcounting bug. 

Marking verified fixed, based on the checkin  (no easy steps to reproduce).