Bug 1133873 - some spdy logs r=hurley
authorPatrick McManus <mcmanus@ducksong.com>
Sun, 29 Nov 2015 16:11:16 -0500
changeset 308725 909a9447985416d963111079241557bf8bce08f9
parent 308724 4d7efb9a8026d7b36eac541f4606157ad073743a
child 308726 50ed3852d0030edda16a5de6abb6d50d52d53a18
push id5513
push userraliiev@mozilla.com
push dateMon, 25 Jan 2016 13:55:34 +0000
treeherdermozilla-beta@5ee97dd05b5c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewershurley
bugs1133873
milestone45.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 1133873 - some spdy logs r=hurley
netwerk/protocol/http/SpdySession31.cpp
netwerk/protocol/http/SpdyStream31.cpp
--- a/netwerk/protocol/http/SpdySession31.cpp
+++ b/netwerk/protocol/http/SpdySession31.cpp
@@ -2052,17 +2052,17 @@ SpdySession31::WriteSegments(nsAHttpSegm
       }
       else if (!mInputFrameDataStream->RecvdData()) {
         LOG3(("SpdySession31 %p First Data Frame Flushes Headers stream 0x%X\n",
               this, streamID));
 
         mInputFrameDataStream->SetRecvdData(true);
         rv = ResponseHeadersComplete();
         if (rv == NS_ERROR_ILLEGAL_VALUE) {
-          LOG3(("SpdySession31 %p PROTOCOL_ERROR detected 0x%X\n",
+          LOG3(("SpdySession31 %p ResponseHeadersComplete PROTOCOL_ERROR detected 0x%X\n",
                 this, streamID));
           CleanupStream(mInputFrameDataStream, rv, RST_PROTOCOL_ERROR);
           ChangeDownstreamState(DISCARDING_DATA_FRAME);
         }
         else {
           mDataPending = true;
         }
       }
--- a/netwerk/protocol/http/SpdyStream31.cpp
+++ b/netwerk/protocol/http/SpdyStream31.cpp
@@ -1174,27 +1174,36 @@ SpdyStream31::FindHeader(nsCString name,
 }
 
 // ConvertHeaders is used to convert the response headers
 // in a syn_reply or in 0..N headers frames that follow it into
 // HTTP/1 format
 nsresult
 SpdyStream31::ConvertHeaders(nsACString &aHeadersOut)
 {
+  LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x\n",
+        mSession, this, mStreamID));
+
   // :status and :version are required.
   nsDependentCSubstring status, version;
   nsresult rv = FindHeader(NS_LITERAL_CSTRING(":status"),
                            status);
-  if (NS_FAILED(rv))
+  if (NS_FAILED(rv)) {
+    LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x missing :status\n",
+          mSession, this, mStreamID));
     return (rv == NS_ERROR_NOT_AVAILABLE) ? NS_ERROR_ILLEGAL_VALUE : rv;
+  }
 
   rv = FindHeader(NS_LITERAL_CSTRING(":version"),
                   version);
-  if (NS_FAILED(rv))
+  if (NS_FAILED(rv)) {
+    LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x missing :version\n",
+          mSession, this, mStreamID));
     return (rv == NS_ERROR_NOT_AVAILABLE) ? NS_ERROR_ILLEGAL_VALUE : rv;
+  }
 
   if (mDecompressedBytes && mDecompressBufferUsed) {
     Telemetry::Accumulate(Telemetry::SPDY_SYN_REPLY_SIZE, mDecompressedBytes);
     uint32_t ratio =
       mDecompressedBytes * 100 / mDecompressBufferUsed;
     Telemetry::Accumulate(Telemetry::SPDY_SYN_REPLY_RATIO, ratio);
   }
 
@@ -1207,41 +1216,61 @@ SpdyStream31::ConvertHeaders(nsACString 
   // Content-Length is 'advisory'.. we will not strip it because it can
   // create UI feedback.
 
   aHeadersOut.Append(version);
   aHeadersOut.Append(' ');
   aHeadersOut.Append(status);
   aHeadersOut.AppendLiteral("\r\n");
 
+  LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x decompressed size %d\n",
+        mSession, this, mStreamID, mDecompressBufferUsed));
+
   const unsigned char *nvpair = reinterpret_cast<unsigned char *>
     (mDecompressBuffer.get()) + 4;
   const unsigned char *lastHeaderByte = reinterpret_cast<unsigned char *>
     (mDecompressBuffer.get()) + mDecompressBufferUsed;
-  if (lastHeaderByte < nvpair)
+  if (lastHeaderByte < nvpair) {
+    LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x format err 1\n",
+          mSession, this, mStreamID));
     return NS_ERROR_ILLEGAL_VALUE;
+  }
 
   do {
     uint32_t numPairs = PR_ntohl(reinterpret_cast<const uint32_t *>(nvpair)[-1]);
+    LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x numPairs %d\n",
+          mSession, this, mStreamID, numPairs));
 
     for (uint32_t index = 0; index < numPairs; ++index) {
-      if (lastHeaderByte < nvpair + 4)
+      LOG5(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x index=%u remaining=%u\n",
+            mSession, this, mStreamID, index, lastHeaderByte - nvpair));
+      if (lastHeaderByte < nvpair + 4) {
+        LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x format err 2\n",
+              mSession, this, mStreamID));
         return NS_ERROR_ILLEGAL_VALUE;
-
+      }
       uint32_t nameLen = (nvpair[0] << 24) + (nvpair[1] << 16) +
         (nvpair[2] << 8) + nvpair[3];
-      if (lastHeaderByte < nvpair + 4 + nameLen)
+      LOG5(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x namelen=%u\n",
+            mSession, this, mStreamID, nameLen));
+      if (lastHeaderByte < nvpair + 4 + nameLen) {
+        LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x format err 3\n",
+              mSession, this, mStreamID));
         return NS_ERROR_ILLEGAL_VALUE;
+      }
 
       nsDependentCSubstring nameString =
         Substring(reinterpret_cast<const char *>(nvpair) + 4,
                   reinterpret_cast<const char *>(nvpair) + 4 + nameLen);
 
-      if (lastHeaderByte < nvpair + 8 + nameLen)
+      if (lastHeaderByte < nvpair + 8 + nameLen) {
+        LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x format err 4\n",
+              mSession, this, mStreamID));
         return NS_ERROR_ILLEGAL_VALUE;
+      }
 
       // Look for illegal characters in the nameString.
       // This includes upper case characters and nulls (as they will
       // break the fixup-nulls-in-value-string algorithm)
       // Look for upper case characters in the name. They are illegal.
       for (char *cPtr = nameString.BeginWriting();
            cPtr && cPtr < nameString.EndWriting();
            ++cPtr) {
@@ -1251,18 +1280,21 @@ SpdyStream31::ConvertHeaders(nsACString 
           LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p "
                 "upper case response header found. [%s]\n",
                 mSession, this, toLog.get()));
 
           return NS_ERROR_ILLEGAL_VALUE;
         }
 
         // check for null characters
-        if (*cPtr == '\0')
+        if (*cPtr == '\0') {
+          LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x unexpected null\n",
+                mSession, this, mStreamID));
           return NS_ERROR_ILLEGAL_VALUE;
+        }
       }
 
       // HTTP Chunked responses are not legal over spdy. We do not need
       // to look for chunked specifically because it is the only HTTP
       // allowed default encoding and we did not negotiate further encodings
       // via TE
       if (nameString.EqualsLiteral("transfer-encoding")) {
         LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p "
@@ -1270,19 +1302,23 @@ SpdyStream31::ConvertHeaders(nsACString 
               mSession, this));
 
         return NS_ERROR_ILLEGAL_VALUE;
       }
 
       uint32_t valueLen =
         (nvpair[4 + nameLen] << 24) + (nvpair[5 + nameLen] << 16) +
         (nvpair[6 + nameLen] << 8)  +   nvpair[7 + nameLen];
-
-      if (lastHeaderByte < nvpair + 8 + nameLen + valueLen)
+      LOG5(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x valueLen=%u\n",
+            mSession, this, mStreamID, valueLen));
+      if (lastHeaderByte < nvpair + 8 + nameLen + valueLen) {
+        LOG3(("SpdyStream31::ConvertHeaders session=%p stream=%p id=0x%x format err 5\n",
+              mSession, this, mStreamID));
         return NS_ERROR_ILLEGAL_VALUE;
+      }
 
       // spdy transport level headers shouldn't be gatewayed into http/1
       if (!nameString.IsEmpty() && nameString[0] != ':' &&
           !nameString.EqualsLiteral("connection") &&
           !nameString.EqualsLiteral("keep-alive")) {
         nsDependentCSubstring valueString =
           Substring(reinterpret_cast<const char *>(nvpair) + 8 + nameLen,
                     reinterpret_cast<const char *>(nvpair) + 8 + nameLen +