1545523 - Assertion failure: mConcurrentCacheAccess, at /netwerk/protocol/http/nsHttpChannel.cpp:1723

Status: RESOLVED FIXED

(Core :: Networking, defect, P2)

Description

[Kershaw Chang [:kershaw]]

I hit this assertion when running netwerk/test/unit/test_race_cache_with_network.js.

0:04.43 pid:23491 [(null) 23491: Main Thread]: V/nsHttp HttpTransactionParent::RecvOnStartRequest [this=0x10bab2c00 aStatus=0]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::OnStartRequest [this=0x123c3c000 request=0x10bab2c30 status=0]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::ProcessResponse [this=0x123c3c000 httpStatus=200]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=0x123c3c050 event="http-on-examine-response"]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannelAuthProvider::CheckForSuperfluousAuth? [this=0x123a79c00 channel=0x123c3c618]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp continuation state has been reset
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=0x123c3c050 event="http-on-may-change-process"]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::ContinueProcessResponse3 [this=0x123c3c000, rv=804b0001]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::ProcessNormal [this=0x123c3c000]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::ContinueProcessNormal [this=0x123c3c000]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::CallOnStartRequest [this=0x123c3c000]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp calling mListener->OnStartRequest [this=0x123c3c000, listener=0x123a7d420]
0:04.43 pid:23491 [(null) 23491: Main Thread]: V/nsHttp HttpBaseChannel::DoApplyContentConversions [this=0x123c3c000]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::OnCacheEntryCheck enter [channel=0x123c3c000 entry=0x10bef7760]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpResponseHead::ParseCachedOriginalHeader [this=0x123aee3d0]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpResponseHead::ParseCachedHead [this=0x123aee3d0]
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp nsHttpConnectionMgr::ProcessPendingQForEntry [ci=.......[tlsflags0x00000000]localhost:52459 ent=0x10ec49200 active=0 idle=0 urgent-start-queue=0 queued=0]
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp urgent queue [
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp ] window id = 0 queue [
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp ] active urgent conns [
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp ] active regular conns [
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp ] idle urgent conns [
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp ] idle regular conns [
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp ]
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp Destroying nsHttpConnection @0x10c0bc400
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp nsHttpConnection 0x10c0bc400 performed 1 HTTP/1.x transactions
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp nsHttpConnection 0x10c0bc400 read 0kb on connection spdy=0
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpResponseHead::ParseVersion [version=HTTP/1.1 200 OK
0:04.43 pid:23491 content-type: text/plain
0:04.43 pid:23491 cache-control: Cache-Control: max-age=3600
0:04.43 pid:23491 etag: test-etag1
0:04.43 pid:23491 server: httpd.js
0:04.43 pid:23491 date: Thu, 18 Apr 2019 18:14:06 GMT
0:04.43 pid:23491 content-length: 8
0:04.43 pid:23491 ]
0:04.43 pid:23491 [(null) 23491: Main Thread]: E/nsHttp Have status line [version=11 status=200 statusText=OK]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp ParseContentType [type=text/plain]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpResponseHead::MustValidate ??
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp no mandatory validation requirement
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp NowInSeconds()=1555611248, expiration time=1555614846, freshness lifetime=3600, age=2
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp not validating, expire time not in the past
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp Not validating based on expiration time
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp Opened cache input stream without buffering [channel=0x123c3c000, mCacheEntry=0x10bef7760, stream=0x123aebc80]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHTTPChannel::OnCacheEntryCheck exit [this=0x123c3c000 doValidation=0 result=0]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::OnCacheEntryAvailable [this=0x123c3c000 entry=0x10bef7760 new=0 appcache=0x0 status=0 mAppCache=0x0 mAppCacheForWrite=0x0]
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::ReadFromCache [this=0x123c3c000] Using cached copy of: http://localhost:52459/rcwn_cached
0:04.43 pid:23491 [(null) 23491: Main Thread]: D/nsHttp First response from cache
0:04.43 pid:23491 [Socket 23492: Main Thread]: V/nsHttp HttpTransactionChild::RecvCancel start [this=0x10c0bb400]
0:04.43 pid:23491 [(null) 23491: Main Thread]: V/nsHttp HttpTransactionParent::Cancel [this=0x10bab2c00 status=804b0002]
0:04.43 pid:23491 [Socket 23492: Main Thread]: V/nsHttp nsHttpConnectionMgr::CancelTransaction [trans=0x10c0bb800 reason=804b0002]
0:04.43 pid:23491 [Socket 23492: Main Thread]: V/nsHttp HttpTransactionChild::RecvCancelPump start [this=0x10c0bb400]
0:04.43 pid:23491 [Socket 23492: Socket Thread]: V/nsHttp nsHttpConnectionMgr::OnMsgCancelTransaction [trans=0x10c0bb830]
0:04.44 pid:23491 [Socket 23492: Socket Thread]: D/nsHttp nsHttpTransaction::Close [this=0x10c0bb800 reason=804b0002]
0:04.44 pid:23491 [Socket 23492: Socket Thread]: D/nsHttp already closed
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::OnStopRequest [this=0x123c3c000 request=0x10bab2c30 status=804b0002]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp OnStopRequest 0x123c3c000 requestFromCache: 0 mFirstResponseSource: 1
0:04.44 pid:23491 [Socket 23492: Main Thread]: V/nsHttp HttpTransactionChild::ActorDestroy [this=0x10c0bb400]
0:04.44 pid:23491 [(null) 23491: Main Thread]: V/nsHttp HttpTransactionParent::ActorDestroy [this=0x10bab2c00]
0:04.44 pid:23491 [(null) 23491: Main Thread]: V/nsHttp Destroying HttpTransactionParent @0x10bab2c00
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::TriggerNetwork [this=0x123c3c000]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp network already triggered. Returning.
0:04.44 pid:23491 [Socket 23492: Main Thread]: D/nsHttp nsHttpTransaction::DeleteSelfOnConsumerThread [this=0x10c0bb800]
0:04.44 pid:23491 [Socket 23492: Main Thread]: D/nsHttp Destroying nsHttpTransaction @0x10c0bb800
0:04.44 pid:23491 [Socket 23492: Main Thread]: D/nsHttp nsHttpTransaction::RemoveDispatchedAsBlocking this=0x10c0bb800 not blocking
0:04.44 pid:23491 ###!!! [Parent][DispatchAsyncMessage] Error: PHttpTransaction::Msg_OnDataAvailable Route error: message sent to unknown actor ID
0:04.44 pid:23491 ###!!! [Parent][DispatchAsyncMessage] Error: PHttpTransaction::Msg_OnStopRequest Route error: message sent to unknown actor ID
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::OnCacheEntryCheck enter [channel=0x123a7e000 entry=0x121b48760]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpResponseHead::ParseCachedOriginalHeader [this=0x123aee300]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpResponseHead::ParseCachedHead [this=0x123aee300]
0:04.44 pid:23491 [Socket 23492: Main Thread]: D/nsHttp nsHttpTransaction 0x10c0bb800 request context set to null in ReleaseBlockingTransaction() - was 0x0
0:04.44 pid:23491 [Socket 23492: Main Thread]: D/nsHttp Destroying nsHttpConnectionInfo @0x10c0070e0
0:04.44 pid:23491 [Socket 23492: Main Thread]: V/nsHttp Destroying HttpTransactionChild @0x10c0bb400
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpResponseHead::ParseVersion [version=HTTP/1.1 200 OK
0:04.44 pid:23491 content-type: text/plain
0:04.44 pid:23491 cache-control: Cache-Control: max-age=3600
0:04.44 pid:23491 etag: test-etag1
0:04.44 pid:23491 server: httpd.js
0:04.44 pid:23491 date: Thu, 18 Apr 2019 18:14:06 GMT
0:04.44 pid:23491 content-length: 8
0:04.44 pid:23491 ]
0:04.44 pid:23491 [(null) 23491: Main Thread]: E/nsHttp Have status line [version=11 status=200 statusText=OK]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp ParseContentType [type=text/plain]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpResponseHead::MustValidate ??
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp no mandatory validation requirement
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp NowInSeconds()=1555611248, expiration time=1555614846, freshness lifetime=3600, age=2
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp not validating, expire time not in the past
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp Not validating based on expiration time
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp Opened cache input stream without buffering [channel=0x123a7e000, mCacheEntry=0x121b48760, stream=0x123aebeb0]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHTTPChannel::OnCacheEntryCheck exit [this=0x123a7e000 doValidation=0 result=0]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::OnCacheEntryAvailable [this=0x123a7e000 entry=0x121b48760 new=0 appcache=0x0 status=0 mAppCache=0x0 mAppCacheForWrite=0x0]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp Destroying nsHttpChannel [this=0x123a7e000]
0:04.44 pid:23491 [(null) 23491: Main Thread]: V/nsHttp Destroying HttpBaseChannel @0x123a7e000
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp Destroying nsHttpConnectionInfo @0x10be430e0
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::OnStartRequest [this=0x123c3c000 request=0x123a79800 status=0]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp racingNetAndCache - mFirstResponseSource:1 fromCache:1 fromNet:0
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpHandler::NotifyObservers [chan=0x123c3c050 event="http-on-may-change-process"]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::ContinueOnStartRequest4 [this=0x123c3c000]
0:04.44 pid:23491 [(null) 23491: Main Thread]: D/nsHttp nsHttpChannel::CallOnStartRequest [this=0x123c3c000]
0:04.44 pid:23491 Assertion failure: mConcurrentCacheAccess, at /Users/changkershaw/work/central/netwerk/protocol/http/

Comment 1

[Kershaw Chang [:kershaw]]

Attachment: another http log

Comment 2

[Kershaw Chang [:kershaw]]

Here is my analysis.
I think this assertion should only happen on running test_race_cache_with_network.js, because:

1. RCWN is turned off at [1], so mRaceCacheWithNetwork is also false at [2].
2. According to the log, OnStartRequest is called from HttpTransactionParent. mFirstResponseSource cannot be set to RESPONSE_FROM_NETWORK since mRaceCacheWithNetwork is false.
3. Cache entry is opened at [3] and mRaceCacheWithNetwork is set to true.
4. OnStartRequest is called again from cache and we hit this assertion.

I am not sure what is the correct way to fix this. Maybe we should check if mOnStartRequestCalled is true in nsHttpChannel::ReadFromCache. If so, we should not use the response from cache.
Valentin, what do you think?

[1] https://searchfox.org/mozilla-central/rev/ddb81c7a43ffada1f6cb4200c4f625e50e44dcf3/netwerk/test/unit/test_race_cache_with_network.js#73
[2] https://searchfox.org/mozilla-central/rev/ddb81c7a43ffada1f6cb4200c4f625e50e44dcf3/netwerk/protocol/http/nsHttpChannel.cpp#9971
[3] https://searchfox.org/mozilla-central/rev/ddb81c7a43ffada1f6cb4200c4f625e50e44dcf3/netwerk/protocol/http/nsHttpChannel.cpp#4098

Comment 3

[Valentin Gosu [:valentin] (he/him)]

I haven't looked too closely, but I think we should set mRaceCacheWithNetwork = true; before assigning mCacheOpenFunc.
As you describe the issue, that means the test isn't emulating how the request behaves in the real world anyway.
I think we may also have to change the condition at [2] to be something like this, so we don't overwrite mRaceCacheWithNetwork:

  if (AwaitingCacheCallbacks() && !mCacheOpenFunc) {
    mRaceCacheWithNetwork = sRCWNEnabled;
  }

Comment 4

[Kershaw Chang [:kershaw]]

Attachment: Bug 1545523 - Set mRaceCacheWithNetwork to true if mCacheOpenFunc is assigned

Comment 5

[Honza Bambas (:mayhemer)]

Note that with my upcoming patch for bug 1463729 - which apparently has scheduling influence - I can (100%) reproduce this bug (likely with same cause) on otherwise vanilla m-c. Applying the patch here fixes the intermittent for me.

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/35bf2fd7dc3b
Set mRaceCacheWithNetwork to true if mCacheOpenFunc is assigned r=michal

Comment 7

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/35bf2fd7dc3b