138754 - http pipelining related assertions

Status: VERIFIED FIXED

(Core :: Networking: HTTP, defect, P2)

Description

[Harshal Pradhan]

With http pipelining turned on, I have been seeing a lot of assertions with a 
truck cvs debug build from earlier today. (I am assuming this is directly 
related to bug #93054). I see two types of asserts:

Type 1:

nsDebug::NotReached(const char * 0x014226bc `string', const char * 0x014226c8 
`string', int 98) line 452 + 22 bytes
nsHttpConnection::PushBack(const char * 0x034fb34c, unsigned int 7) line 98 + 
25 bytes
nsHttpTransaction::Read(nsHttpTransaction * const 0x034c2e70, char * 
0x034fae40, unsigned int 1299, unsigned int * 0x017ffdc4) line 907
nsReadFromInputStream(nsIOutputStream * 0x034e42b8, void * 0x034c2e70, char * 
0x034fae40, unsigned int 0, unsigned int 4096, unsigned int * 0x017ffdc4) line 
838
nsPipe::nsPipeOutputStream::WriteSegments(nsPipe::nsPipeOutputStream * const 
0x034e42b8, unsigned int (nsIOutputStream *, void *, char *, unsigned int, 
unsigned int, unsigned int *)* 0x10062d40 nsReadFromInputStream(nsIOutputStream 
*, void *, char *, unsigned int, unsigned int, unsigned int *), void * 
0x034c2e70, unsigned int 16384, unsigned int * 0x017ffe58) line 711 + 29 bytes
nsPipe::nsPipeOutputStream::WriteFrom(nsPipe::nsPipeOutputStream * const 
0x034e42b8, nsIInputStream * 0x034c2e70, unsigned int 16384, unsigned int * 
0x017ffe58) line 846
nsStreamListenerProxy::OnDataAvailable(nsStreamListenerProxy * const 
0x034e45f0, nsIRequest * 0x034c2e6c, nsISupports * 0x00000000, nsIInputStream * 
0x034c2e70, unsigned int 0, unsigned int 16384) line 306 + 38 bytes
nsHttpTransaction::OnDataReadable(nsIInputStream * 0x034fc290) line 252 + 96 
bytes
nsHttpConnection::OnDataAvailable(nsHttpConnection * const 0x034e7f7c, 
nsIRequest * 0x034e8198, nsISupports * 0x00000000, nsIInputStream * 0x034fc290, 
unsigned int 263, unsigned int 8192) line 701 + 21 bytes
nsSocketReadRequest::OnRead() line 2852 + 57 bytes
nsSocketTransport::doReadWrite(short 1) line 1123 + 14 bytes
nsSocketTransport::Process(short 1) line 547 + 13 bytes
nsSocketTransportService::Run(nsSocketTransportService * const 0x00fc70bc) line 
516 + 13 bytes

Type 2:

###!!! ASSERTION: potential deadlock between Lock@33a0e68 and Lock@33fddb8: 'Err
or', file M:\lat\mozilla\xpcom\threads\nsAutoLock.cpp, line 265

nsDebug::Assertion(const char * 0x019efd70, const char * 0x10128830, const char 
* 0x101201a0, int 265) line 291 + 13 bytes
nsDebug::Error(const char * 0x019efd70, const char * 0x101201a0, int 265) line 
458 + 22 bytes
nsAutoLockBase::nsAutoLockBase(void * 0x033fddb8, 
nsAutoLockBase::nsAutoLockType eAutoLock) line 265 + 22 bytes
nsAutoLock::nsAutoLock(PRLock * 0x033fddb8) line 176 + 23 bytes
nsHttpConnection::OnTransactionComplete(nsAHttpTransaction * 0x033a0db4, 
unsigned int 0) line 266
nsHttpPipeline::OnDataReadable(nsIInputStream * 0x033edd60) line 527
nsHttpConnection::OnDataAvailable(nsHttpConnection * const 0x033fe43c, 
nsIRequest * 0x033f5d20, nsISupports * 0x00000000, nsIInputStream * 0x033edd60, 
unsigned int 2488, unsigned int 8192) line 701 + 21 bytes
nsSocketReadRequest::OnRead() line 2852 + 57 bytes
nsSocketTransport::doReadWrite(short 1) line 1123 + 14 bytes
nsSocketTransport::Process(short 1) line 547 + 13 bytes
nsSocketTransportService::Run(nsSocketTransportService * const 0x00fb1dcc) line 
516 + 13 bytes


Happens 100% reproducibly browsing around at www.cnn.com. But it doesn't seems 
to be site specific. I see these happen almost every time requests get 
pipelined (looking at nsHttp:5). (I'm in India, and behind a dialup 
connection... latency to sites such as cnn is very high.)

Everything seems to work fine if I just ignore the assertions, so maybe these 
are harmless. But I thought I should report it anyway.

Comment 1

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Confirming.  I'm seeing lots of the first assertions, all over the place, on
Linux.  Makes it hard to know if there are any other assertions in the code I'm
working on...

Comment 2

[Harshal Pradhan]

Should have clarified earlier that Type 1 happens even with pipelining turned 
off. Type 2 happens only with pipelining. So maybe these should be two separate 
bugs.

Comment 3

[Darin Fisher]

ok, so the PushBack assertion actually occurs whenever we process a document
served up with a chunked encoding.  it turns out that bytesWritten returned from
nsHttpTransaction::HandleContent is the number of bytes of the document body
read from the socket minus the chunk delimiters.  this results in bytesWritten
being slightly less than count and hence we call PushBack.  when not pipelining,
PushBack does nothing other than assertion not reached.  there are no negative
side-effects.

however, when pipelining is enabled, this problem can cause trouble.  in many
cases it doesn't because of the fact that our header parser is tolerant of a
little garbage before the status line.  if the document is chunked too finely,
this bug could foul up the header parser completely.

the solution is to make HandleContent also return the actual/real number of
bytes consumed, taking into account chunk delimiters.  patch in hand.

Comment 4

[Darin Fisher]

Attachment: v1 patch - fixes both assertions

- fixes PushBack assertion (changes to nsHttpTransaction::HandleContent)
- fixes potential deadlock assertion (changes to
nsHttpPipeling::OnDataReadable)

Comment 5

[Darin Fisher]

Attachment: v1 patch w/ -u10w for readability

Comment 6

[rpotts (gone)]

Comment on attachment 80518 [details] [diff] [review]
v1 patch w/ -u10w for readability

sr=[e-mail].

Looks like there are some tabbing inconsistancies in nsHttpPipeline.cpp
-- rick

Comment 7

[Darin Fisher]

*** Bug 139207 has been marked as a duplicate of this bug. ***

Comment 8

[Gagan]

Comment on attachment 80518 [details] [diff] [review]
v1 patch w/ -u10w for readability

r=gagan

Comment 9

[Darin Fisher]

fixed-on-trunk

Comment 10

[Tom Everingham]

verified - confirmed patch checked in on trunk