Bug 1388448 - Logs for better network requests and context tracking. r=mcmanus
authorHonza Bambas <honzab.moz@firemni.cz>
Thu, 17 Aug 2017 12:16:00 -0400
changeset 376203 464568af8eb17b3eaeb143f4a7f9e233800e2612
parent 376202 3c3ec9970a727197dbfd717b6dceefb25d4efaaf
child 376204 e240d265b038729647f31a1b887f7c3e33187bca
push id32376
push userkwierso@gmail.com
push dateWed, 23 Aug 2017 00:07:40 +0000
treeherdermozilla-central@64a45ee1731c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmcmanus
bugs1388448
milestone57.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1388448 - Logs for better network requests and context tracking. r=mcmanus
dom/base/nsDocument.cpp
layout/base/PresShell.cpp
netwerk/base/nsChannelClassifier.cpp
netwerk/base/nsChannelClassifier.h
netwerk/base/nsLoadGroup.cpp
netwerk/dns/nsHostResolver.cpp
netwerk/protocol/http/HttpBaseChannel.cpp
netwerk/protocol/http/HttpBaseChannel.h
netwerk/protocol/http/HttpChannelChild.cpp
netwerk/protocol/http/HttpChannelParent.cpp
netwerk/protocol/http/nsHttpChannel.cpp
netwerk/protocol/http/nsHttpConnection.cpp
netwerk/protocol/http/nsHttpTransaction.cpp
--- a/dom/base/nsDocument.cpp
+++ b/dom/base/nsDocument.cpp
@@ -3919,16 +3919,19 @@ nsDocument::CreateShell(nsPresContext* a
   // Note: we don't hold a ref to the shell (it holds a ref to us)
   mPresShell = shell;
 
   // Make sure to never paint if we belong to an invisible DocShell.
   nsCOMPtr<nsIDocShell> docShell(mDocumentContainer);
   if (docShell && docShell->IsInvisible())
     shell->SetNeverPainting(true);
 
+  MOZ_LOG(gDocumentLeakPRLog, LogLevel::Debug, ("DOCUMENT %p with PressShell %p and DocShell %p",
+                                                this, shell.get(), docShell.get()));
+
   mExternalResourceMap.ShowViewers();
 
   UpdateFrameRequestCallbackSchedulingState();
 
   // Now that we have a shell, we might have @font-face rules.
   RebuildUserFontSet();
 
   return shell.forget();
@@ -5455,16 +5458,19 @@ nsDocument::EndLoad()
 
 void
 nsDocument::UnblockDOMContentLoaded()
 {
   MOZ_ASSERT(mBlockDOMContentLoaded);
   if (--mBlockDOMContentLoaded != 0 || mDidFireDOMContentLoaded) {
     return;
   }
+
+  MOZ_LOG(gDocumentLeakPRLog, LogLevel::Debug, ("DOCUMENT %p UnblockDOMContentLoaded", this));
+
   mDidFireDOMContentLoaded = true;
 
   MOZ_ASSERT(mReadyState == READYSTATE_INTERACTIVE);
   if (!mSynchronousDOMContentLoaded) {
     MOZ_RELEASE_ASSERT(NS_IsMainThread());
     nsCOMPtr<nsIRunnable> ev =
       NewRunnableMethod("nsDocument::DispatchContentLoadedEvents",
                         this,
--- a/layout/base/PresShell.cpp
+++ b/layout/base/PresShell.cpp
@@ -832,16 +832,18 @@ PresShell::PresShell()
   , mInResize(false)
   , mApproximateFrameVisibilityVisited(false)
   , mNextPaintCompressed(false)
   , mHasCSSBackgroundColor(false)
   , mScaleToResolution(false)
   , mIsLastChromeOnlyEscapeKeyConsumed(false)
   , mHasReceivedPaintMessage(false)
 {
+  MOZ_LOG(gLog, LogLevel::Debug, ("PresShell::PresShell this=%p", this));
+
 #ifdef MOZ_REFLOW_PERF
   mReflowCountMgr = new ReflowCountMgr();
   mReflowCountMgr->SetPresContext(mPresContext);
   mReflowCountMgr->SetPresShell(this);
 #endif
   mLastOSWake = mLoadBegin = TimeStamp::Now();
 
   mSelectionFlags = nsISelectionDisplay::DISPLAY_TEXT | nsISelectionDisplay::DISPLAY_IMAGES;
@@ -881,16 +883,18 @@ PresShell::PresShell()
 
 NS_IMPL_ISUPPORTS(PresShell, nsIPresShell, nsIDocumentObserver,
                   nsISelectionController,
                   nsISelectionDisplay, nsIObserver, nsISupportsWeakReference,
                   nsIMutationObserver)
 
 PresShell::~PresShell()
 {
+  MOZ_LOG(gLog, LogLevel::Debug, ("PresShell::~PresShell this=%p", this));
+
   if (!mHaveShutDown) {
     NS_NOTREACHED("Someone did not call nsIPresShell::destroy");
     Destroy();
   }
 
   NS_ASSERTION(mCurrentEventContentStack.Count() == 0,
                "Huh, event content left on the stack in pres shell dtor!");
   NS_ASSERTION(mFirstCallbackEventRequest == nullptr &&
@@ -1721,16 +1725,18 @@ PresShell::Initialize(nscoord aWidth, ns
     return NS_OK;
   }
 
   if (!mDocument) {
     // Nothing to do
     return NS_OK;
   }
 
+  MOZ_LOG(gLog, LogLevel::Debug, ("PresShell::Initialize this=%p", this));
+
   NS_ASSERTION(!mDidInitialize, "Why are we being called?");
 
   nsCOMPtr<nsIPresShell> kungFuDeathGrip(this);
   mDidInitialize = true;
 
 #ifdef DEBUG
   if (VERIFY_REFLOW_NOISY_RC & gVerifyReflowFlags) {
     if (mDocument) {
@@ -3875,16 +3881,19 @@ PresShell::CaptureHistoryState(nsILayout
 
 void
 PresShell::ScheduleBeforeFirstPaint()
 {
   if (!mDocument->IsResourceDoc()) {
     // Notify observers that a new page is about to be drawn. Execute this
     // as soon as it is safe to run JS, which is guaranteed to be before we
     // go back to the event loop and actually draw the page.
+    MOZ_LOG(gLog, LogLevel::Debug,
+           ("PresShell::ScheduleBeforeFirstPaint this=%p", this));
+
     nsContentUtils::AddScriptRunner(new nsBeforeFirstPaintDispatcher(mDocument));
   }
 }
 
 void
 PresShell::UnsuppressAndInvalidate()
 {
   // Note: We ignore the EnsureVisible check for resource documents, because
--- a/netwerk/base/nsChannelClassifier.cpp
+++ b/netwerk/base/nsChannelClassifier.cpp
@@ -229,19 +229,25 @@ NS_IMPL_ISUPPORTS(nsChannelClassifier,
 
 nsChannelClassifier::nsChannelClassifier(nsIChannel *aChannel)
   : mIsAllowListed(false),
     mSuspendedChannel(false),
     mChannel(aChannel),
     mTrackingProtectionEnabled(Nothing()),
     mTrackingAnnotationEnabled(Nothing())
 {
+  LOG(("nsChannelClassifier::nsChannelClassifier %p", this));
   MOZ_ASSERT(mChannel);
 }
 
+nsChannelClassifier::~nsChannelClassifier()
+{
+  LOG(("nsChannelClassifier::~nsChannelClassifier %p", this));
+}
+
 bool
 nsChannelClassifier::ShouldEnableTrackingProtection()
 {
   if (mTrackingProtectionEnabled) {
     return mTrackingProtectionEnabled.value();
   }
 
   mTrackingProtectionEnabled = Some(false);
--- a/netwerk/base/nsChannelClassifier.h
+++ b/netwerk/base/nsChannelClassifier.h
@@ -61,17 +61,17 @@ private:
     // True if the channel is on the allow list.
     bool mIsAllowListed;
     // True if the channel has been suspended.
     bool mSuspendedChannel;
     nsCOMPtr<nsIChannel> mChannel;
     Maybe<bool> mTrackingProtectionEnabled;
     Maybe<bool> mTrackingAnnotationEnabled;
 
-    ~nsChannelClassifier() {}
+    ~nsChannelClassifier();
     // Caches good classifications for the channel principal.
     void MarkEntryClassified(nsresult status);
     bool HasBeenClassified(nsIChannel *aChannel);
     // Helper function so that we ensure we call ContinueBeginConnect once
     // Start is called. Returns NS_OK if and only if we will get a callback
     // from the classifier service.
     nsresult StartInternal();
     // Helper function to check a URI against the hostname whitelist
--- a/netwerk/base/nsLoadGroup.cpp
+++ b/netwerk/base/nsLoadGroup.cpp
@@ -413,16 +413,19 @@ nsLoadGroup::GetDefaultLoadRequest(nsIRe
     *aRequest = mDefaultLoadRequest;
     NS_IF_ADDREF(*aRequest);
     return NS_OK;
 }
 
 NS_IMETHODIMP
 nsLoadGroup::SetDefaultLoadRequest(nsIRequest *aRequest)
 {
+    LOG(("nsLoadGroup::SetDefaultLoadRequest this=%p default-request=%p",
+         this, aRequest));
+
     mDefaultLoadRequest = aRequest;
     // Inherit the group load flags from the default load request
     if (mDefaultLoadRequest) {
         mDefaultLoadRequest->GetLoadFlags(&mLoadFlags);
         //
         // Mask off any bits that are not part of the nsIRequest flags.
         // in particular, nsIChannel::LOAD_DOCUMENT_URI...
         //
@@ -752,16 +755,19 @@ nsLoadGroup::GetRootLoadGroup(nsILoadGro
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 // nsPILoadGroupInternal methods:
 
 NS_IMETHODIMP
 nsLoadGroup::OnEndPageLoad(nsIChannel *aDefaultChannel)
 {
+    LOG(("nsLoadGroup::OnEndPageLoad this=%p default-request=%p",
+         this, aDefaultChannel));
+
     // for the moment, nothing to do here.
     return NS_OK;
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 // nsISupportsPriority methods:
 
 NS_IMETHODIMP
--- a/netwerk/dns/nsHostResolver.cpp
+++ b/netwerk/dns/nsHostResolver.cpp
@@ -554,16 +554,18 @@ nsHostResolver::~nsHostResolver() = defa
 
 nsresult
 nsHostResolver::Init()
 {
     if (NS_FAILED(GetAddrInfoInit())) {
         return NS_ERROR_FAILURE;
     }
 
+    LOG(("nsHostResolver::Init this=%p", this));
+
     mShutdown = false;
 
 #if TTL_AVAILABLE
     // The preferences probably haven't been loaded from the disk yet, so we
     // need to register a callback that will set up the experiment once they
     // are. We also need to explicitly set a value for the props otherwise the
     // callback won't be called.
     {
--- a/netwerk/protocol/http/HttpBaseChannel.cpp
+++ b/netwerk/protocol/http/HttpBaseChannel.cpp
@@ -260,16 +260,23 @@ HttpBaseChannel::ReleaseMainThreadOnlyRe
   arrayToRelease.AppendElement(mTopWindowURI.forget());
   arrayToRelease.AppendElement(mListener.forget());
   arrayToRelease.AppendElement(mListenerContext.forget());
   arrayToRelease.AppendElement(mCompressListener.forget());
 
   NS_DispatchToMainThread(new ProxyReleaseRunnable(Move(arrayToRelease)));
 }
 
+void
+HttpBaseChannel::SetIsTrackingResource()
+{
+  LOG(("HttpBaseChannel::SetIsTrackingResource %p", this));
+  mIsTrackingResource = true;
+}
+
 nsresult
 HttpBaseChannel::Init(nsIURI *aURI,
                       uint32_t aCaps,
                       nsProxyInfo *aProxyInfo,
                       uint32_t aProxyResolveFlags,
                       nsIURI *aProxyURI,
                       uint64_t aChannelId)
 {
@@ -4063,16 +4070,18 @@ HttpBaseChannel::GetThrottleQueue(nsIInp
 
 //------------------------------------------------------------------------------
 
 bool
 HttpBaseChannel::EnsureRequestContextID()
 {
     if (mRequestContextID) {
         // Already have a request context ID, no need to do the rest of this work
+        LOG(("HttpBaseChannel::EnsureRequestContextID this=%p id=%" PRIx64,
+             this, mRequestContextID));
         return true;
     }
 
     // Find the loadgroup at the end of the chain in order
     // to make sure all channels derived from the load group
     // use the same connection scope.
     nsCOMPtr<nsILoadGroupChild> childLoadGroup = do_QueryInterface(mLoadGroup);
     if (!childLoadGroup) {
@@ -4082,16 +4091,20 @@ HttpBaseChannel::EnsureRequestContextID(
     nsCOMPtr<nsILoadGroup> rootLoadGroup;
     childLoadGroup->GetRootLoadGroup(getter_AddRefs(rootLoadGroup));
     if (!rootLoadGroup) {
         return false;
     }
 
     // Set the load group connection scope on the transaction
     rootLoadGroup->GetRequestContextID(&mRequestContextID);
+
+    LOG(("HttpBaseChannel::EnsureRequestContextID this=%p id=%" PRIx64,
+         this, mRequestContextID));
+
     return true;
 }
 
 void
 HttpBaseChannel::EnsureTopLevelOuterContentWindowId()
 {
   if (mTopLevelOuterContentWindowId) {
     return;
--- a/netwerk/protocol/http/HttpBaseChannel.h
+++ b/netwerk/protocol/http/HttpBaseChannel.h
@@ -359,20 +359,17 @@ public: /* Necko internal use only... */
     DoApplyContentConversions(nsIStreamListener *aNextListener,
                               nsIStreamListener **aNewNextListener);
 
     // Callback on STS thread called by CopyComplete when NS_AsyncCopy()
     // is finished. This function works as a proxy function to dispatch
     // |EnsureUploadStreamIsCloneableComplete| to main thread.
     virtual void OnCopyComplete(nsresult aStatus);
 
-    void SetIsTrackingResource()
-    {
-      mIsTrackingResource = true;
-    }
+    void SetIsTrackingResource();
 
     const uint64_t& ChannelId() const
     {
       return mChannelId;
     }
 
 protected:
   // Handle notifying listener, removing from loadgroup if request failed.
--- a/netwerk/protocol/http/HttpChannelChild.cpp
+++ b/netwerk/protocol/http/HttpChannelChild.cpp
@@ -1918,17 +1918,17 @@ HttpChannelChild::CleanupRedirectingChan
 
 //-----------------------------------------------------------------------------
 // HttpChannelChild::nsIChildChannel
 //-----------------------------------------------------------------------------
 
 NS_IMETHODIMP
 HttpChannelChild::ConnectParent(uint32_t registrarId)
 {
-  LOG(("HttpChannelChild::ConnectParent [this=%p]\n", this));
+  LOG(("HttpChannelChild::ConnectParent [this=%p, id=%" PRIu32 "]\n", this, registrarId));
   mozilla::dom::TabChild* tabChild = nullptr;
   nsCOMPtr<nsITabChild> iTabChild;
   GetCallback(iTabChild);
   if (iTabChild) {
     tabChild = static_cast<mozilla::dom::TabChild*>(iTabChild.get());
   }
   if (MissingRequiredTabChild(tabChild, "http")) {
     return NS_ERROR_ILLEGAL_VALUE;
@@ -2592,16 +2592,19 @@ HttpChannelChild::ContinueAsyncOpen()
   EnsureRequestContextID();
   openArgs.requestContextID() = mRequestContextID;
 
   openArgs.channelId() = mChannelId;
 
   openArgs.contentWindowId() = contentWindowId;
   openArgs.topLevelOuterContentWindowId() = mTopLevelOuterContentWindowId;
 
+  LOG(("HttpChannelChild::ContinueAsyncOpen this=%p gid=%" PRIu64 " topwinid=%" PRIx64,
+       this, mChannelId, mTopLevelOuterContentWindowId));
+
   if (tabChild && !tabChild->IPCOpen()) {
     return NS_ERROR_FAILURE;
   }
 
   ContentChild* cc = static_cast<ContentChild*>(gNeckoChild->Manager());
   if (cc->IsShuttingDown()) {
     return NS_ERROR_FAILURE;
   }
@@ -2923,16 +2926,18 @@ HttpChannelChild::ResumeAt(uint64_t star
 
 //-----------------------------------------------------------------------------
 // HttpChannelChild::nsISupportsPriority
 //-----------------------------------------------------------------------------
 
 NS_IMETHODIMP
 HttpChannelChild::SetPriority(int32_t aPriority)
 {
+  LOG(("HttpChannelChild::SetPriority %p p=%d", this, aPriority));
+
   int16_t newValue = clamped<int32_t>(aPriority, INT16_MIN, INT16_MAX);
   if (mPriority == newValue)
     return NS_OK;
   mPriority = newValue;
   if (RemoteChannelExists())
     SendSetPriority(mPriority);
   return NS_OK;
 }
@@ -2943,36 +2948,45 @@ HttpChannelChild::SetPriority(int32_t aP
 NS_IMETHODIMP
 HttpChannelChild::SetClassFlags(uint32_t inFlags)
 {
   if (mClassOfService == inFlags) {
     return NS_OK;
   }
 
   mClassOfService = inFlags;
+
+  LOG(("HttpChannelChild %p ClassOfService=%u", this, mClassOfService));
+
   if (RemoteChannelExists()) {
     SendSetClassOfService(mClassOfService);
   }
   return NS_OK;
 }
 
 NS_IMETHODIMP
 HttpChannelChild::AddClassFlags(uint32_t inFlags)
 {
   mClassOfService |= inFlags;
+
+  LOG(("HttpChannelChild %p ClassOfService=%u", this, mClassOfService));
+
   if (RemoteChannelExists()) {
     SendSetClassOfService(mClassOfService);
   }
   return NS_OK;
 }
 
 NS_IMETHODIMP
 HttpChannelChild::ClearClassFlags(uint32_t inFlags)
 {
   mClassOfService &= ~inFlags;
+
+  LOG(("HttpChannelChild %p ClassOfService=%u", this, mClassOfService));
+
   if (RemoteChannelExists()) {
     SendSetClassOfService(mClassOfService);
   }
   return NS_OK;
 }
 
 //-----------------------------------------------------------------------------
 // HttpChannelChild::nsIProxiedChannel
--- a/netwerk/protocol/http/HttpChannelParent.cpp
+++ b/netwerk/protocol/http/HttpChannelParent.cpp
@@ -489,18 +489,18 @@ HttpChannelParent::DoAsyncOpen(  const U
     return false;
   }
   nsCOMPtr<nsIURI> originalUri = DeserializeURI(aOriginalURI);
   nsCOMPtr<nsIURI> docUri = DeserializeURI(aDocURI);
   nsCOMPtr<nsIURI> referrerUri = DeserializeURI(aReferrerURI);
   nsCOMPtr<nsIURI> apiRedirectToUri = DeserializeURI(aAPIRedirectToURI);
   nsCOMPtr<nsIURI> topWindowUri = DeserializeURI(aTopWindowURI);
 
-  LOG(("HttpChannelParent RecvAsyncOpen [this=%p uri=%s]\n",
-       this, uri->GetSpecOrDefault().get()));
+  LOG(("HttpChannelParent RecvAsyncOpen [this=%p uri=%s, gid=%" PRIu64 " topwinid=%" PRIx64 "]\n",
+       this, uri->GetSpecOrDefault().get(), aChannelId, aTopLevelOuterContentWindowId));
 
   nsresult rv;
 
   nsCOMPtr<nsIIOService> ios(do_GetIOService(&rv));
   if (NS_FAILED(rv))
     return SendFailedAsyncOpen(rv);
 
   nsCOMPtr<nsILoadInfo> loadInfo;
@@ -814,16 +814,18 @@ HttpChannelParent::ConnectChannel(const 
   LOG(("  found channel %p, rv=%08" PRIx32, channel.get(), static_cast<uint32_t>(rv)));
   mChannel = do_QueryObject(channel);
   if (!mChannel) {
     LOG(("  but it's not nsHttpChannel"));
     Delete();
     return true;
   }
 
+  LOG(("  and it is nsHttpChannel %p", mChannel.get()));
+
   mChannel->SetWarningReporter(this);
 
   nsCOMPtr<nsINetworkInterceptController> controller;
   NS_QueryNotificationCallbacks(channel, controller);
   RefPtr<HttpChannelParentListener> parentListener = do_QueryObject(controller);
   MOZ_ASSERT(parentListener);
   parentListener->SetupInterceptionAfterRedirect(shouldIntercept);
 
--- a/netwerk/protocol/http/nsHttpChannel.cpp
+++ b/netwerk/protocol/http/nsHttpChannel.cpp
@@ -1091,17 +1091,18 @@ nsHttpChannel::SetupTransactionRequestCo
     }
 
     mTransaction->SetRequestContext(rc);
 }
 
 nsresult
 nsHttpChannel::SetupTransaction()
 {
-    LOG(("nsHttpChannel::SetupTransaction [this=%p]\n", this));
+    LOG(("nsHttpChannel::SetupTransaction [this=%p, cos=%u, prio=%d]\n",
+         this, mClassOfService, mPriority));
 
     NS_ENSURE_TRUE(!mTransaction, NS_ERROR_ALREADY_INITIALIZED);
 
     nsresult rv;
 
     mozilla::MutexAutoLock lock(mRCWNLock);
 
     // If we're racing cache with network, conditional or byte range header
@@ -6265,16 +6266,18 @@ bool
 nsHttpChannel::InitLocalBlockList(const InitLocalBlockListCallback& aCallback)
 {
     mLocalBlocklist = false;
 
     if (!(mLoadFlags & LOAD_CLASSIFY_URI)) {
         return false;
     }
 
+    LOG(("nsHttpChannel::InitLocalBlockList this=%p", this));
+
     // Check to see if this principal exists on local blocklists.
     RefPtr<nsChannelClassifier> channelClassifier =
         GetOrCreateChannelClassifier();
 
     // We skip speculative connections by setting mLocalBlocklist only
     // when tracking protection is enabled. Though we could do this for
     // both phishing and malware, it is not necessary for correctness,
     // since no network events will be received while the
@@ -6696,16 +6699,19 @@ nsHttpChannel::SetChannelIsForDownload(b
 //-----------------------------------------------------------------------------
 
 NS_IMETHODIMP
 nsHttpChannel::SetPriority(int32_t value)
 {
     int16_t newValue = clamped<int32_t>(value, INT16_MIN, INT16_MAX);
     if (mPriority == newValue)
         return NS_OK;
+
+    LOG(("nsHttpChannel::SetPriority %p p=%d", this, newValue));
+
     mPriority = newValue;
     if (mTransaction) {
         nsresult rv = gHttpHandler->RescheduleTransaction(mTransaction, mPriority);
         if (NS_FAILED(rv)) {
             LOG(("nsHttpChannel::SetPriority [this=%p] "
                  "RescheduleTransaction failed (%08x)", this,
                  static_cast<uint32_t>(rv)));
         }
@@ -7388,16 +7394,18 @@ nsHttpChannel::OnStopRequest(nsIRequest 
         }
 
         // If DoAuthRetry failed, or if we have been cancelled since showing
         // the auth. dialog, then we need to send OnStartRequest now
         if (authRetry || (mAuthRetryPending && NS_FAILED(status))) {
             MOZ_ASSERT(NS_FAILED(status), "should have a failure code here");
             // NOTE: since we have a failure status, we can ignore the return
             // value from onStartRequest.
+            LOG(("  calling mListener->OnStartRequest [this=%p, listener=%p]\n",
+                 this, mListener.get()));
             if (mListener) {
                 MOZ_ASSERT(!mOnStartRequestCalled,
                            "We should not call OnStartRequest twice.");
                 mListener->OnStartRequest(this, mListenerContext);
                 mOnStartRequestCalled = true;
             } else {
                 NS_WARNING("OnStartRequest skipped because of null listener");
             }
@@ -7526,17 +7534,17 @@ nsHttpChannel::OnStopRequest(nsIRequest 
 
     // Register entry to the Performance resource timing
     mozilla::dom::Performance* documentPerformance = GetPerformance();
     if (documentPerformance) {
         documentPerformance->AddEntry(this, this);
     }
 
     if (mListener) {
-        LOG(("  calling OnStopRequest\n"));
+        LOG(("nsHttpChannel %p calling OnStopRequest\n", this));
         MOZ_ASSERT(mOnStartRequestCalled,
                    "OnStartRequest should be called before OnStopRequest");
         MOZ_ASSERT(!mOnStopRequestCalled,
                    "We should not call OnStopRequest twice");
         mListener->OnStopRequest(this, mListenerContext, status);
         mOnStopRequestCalled = true;
     }
 
--- a/netwerk/protocol/http/nsHttpConnection.cpp
+++ b/netwerk/protocol/http/nsHttpConnection.cpp
@@ -146,17 +146,17 @@ nsHttpConnection::Init(nsHttpConnectionI
                        uint16_t maxHangTime,
                        nsISocketTransport *transport,
                        nsIAsyncInputStream *instream,
                        nsIAsyncOutputStream *outstream,
                        bool connectedTransport,
                        nsIInterfaceRequestor *callbacks,
                        PRIntervalTime rtt)
 {
-    LOG(("nsHttpConnection::Init this=%p", this));
+    LOG(("nsHttpConnection::Init this=%p sockettransport=%p", this, transport));
     NS_ENSURE_ARG_POINTER(info);
     NS_ENSURE_TRUE(!mConnInfo, NS_ERROR_ALREADY_INITIALIZED);
 
     mConnectedTransport = connectedTransport;
     mConnInfo = info;
     MOZ_ASSERT(mConnInfo);
     mLastWriteTime = mLastReadTime = PR_IntervalNow();
     mRtt = rtt;
--- a/netwerk/protocol/http/nsHttpTransaction.cpp
+++ b/netwerk/protocol/http/nsHttpTransaction.cpp
@@ -714,24 +714,28 @@ nsHttpTransaction::ReadRequestSegment(ns
 {
     // For the tracking of sent bytes that we used to do for the networkstats
     // API, please see bug 1318883 where it was removed.
 
     nsHttpTransaction *trans = (nsHttpTransaction *) closure;
     nsresult rv = trans->mReader->OnReadSegment(buf, count, countRead);
     if (NS_FAILED(rv)) return rv;
 
+    LOG(("nsHttpTransaction::ReadRequestSegment %p read=%u", trans, *countRead));
+
     trans->mSentData = true;
     return NS_OK;
 }
 
 nsresult
 nsHttpTransaction::ReadSegments(nsAHttpSegmentReader *reader,
                                 uint32_t count, uint32_t *countRead)
 {
+    LOG(("nsHttpTransaction::ReadSegments %p", this));
+
     MOZ_ASSERT(OnSocketThread(), "not on socket thread");
 
     if (mTransactionDone) {
         *countRead = 0;
         return mStatus;
     }
 
     if (!mConnected && !m0RTTInProgress) {
@@ -813,16 +817,18 @@ nsHttpTransaction::WritePipeSegment(nsIO
 
     nsresult rv;
     //
     // OK, now let the caller fill this segment with data.
     //
     rv = trans->mWriter->OnWriteSegment(buf, count, countWritten);
     if (NS_FAILED(rv)) return rv; // caller didn't want to write anything
 
+    LOG(("nsHttpTransaction::WritePipeSegment %p written=%u", trans, *countWritten));
+
     MOZ_ASSERT(*countWritten > 0, "bad writer");
     trans->mReceivedData = true;
     trans->mTransferSize += *countWritten;
 
     // Let the transaction "play" with the buffer.  It is free to modify
     // the contents of the buffer and/or modify countWritten.
     // - Bytes in HTTP headers don't count towards countWritten, so the input
     // side of pipe (aka nsHttpChannel's mTransactionPump) won't hit