Include more information in WINDOW_UPDATE frame logs (#7325)

* Include more information in WINDOW_UPDATE frame logs As a part of investigating this issue: #7248 * Log a WINDOW_UPDATE frame even if it is malformed
square · Jun 12, 2022 · da6c06d · da6c06d
1 parent 0658b67
commit da6c06d
Show file tree

Hide file tree

Showing 5 changed files with 224 additions and 170 deletions.
diff --git a/okhttp/src/jvmMain/kotlin/okhttp3/internal/http2/Http2.kt b/okhttp/src/jvmMain/kotlin/okhttp3/internal/http2/Http2.kt
@@ -90,7 +90,7 @@ object Http2 {
   }
 
   /**
-   * Returns human-readable representation of HTTP/2 frame headers.
+   * Returns a human-readable representation of HTTP/2 frame headers.
    *
    * The format is:
    *
@@ -119,6 +119,22 @@ object Http2 {
         direction, streamId, length, formattedType, formattedFlags)
   }
 
+  /**
+   * Returns a human-readable representation of a `WINDOW_UPDATE` frame. This frame includes the
+   * window size increment instead of flags.
+   */
+  fun frameLogWindowUpdate(
+    inbound: Boolean,
+    streamId: Int,
+    length: Int,
+    windowSizeIncrement: Long,
+  ): String {
+    val formattedType = formattedType(TYPE_WINDOW_UPDATE)
+    val direction = if (inbound) "<<" else ">>"
+    return format("%s 0x%08x %5d %-13s %d",
+        direction, streamId, length, formattedType, windowSizeIncrement)
+  }
+
   internal fun formattedType(type: Int): String =
     if (type < FRAME_NAMES.size) FRAME_NAMES[type] else format("0x%02x", type)
 

diff --git a/okhttp/src/jvmMain/kotlin/okhttp3/internal/http2/Http2Reader.kt b/okhttp/src/jvmMain/kotlin/okhttp3/internal/http2/Http2Reader.kt
@@ -42,6 +42,7 @@ import okhttp3.internal.http2.Http2.TYPE_SETTINGS
 import okhttp3.internal.http2.Http2.TYPE_WINDOW_UPDATE
 import okhttp3.internal.http2.Http2.formattedType
 import okhttp3.internal.http2.Http2.frameLog
+import okhttp3.internal.http2.Http2.frameLogWindowUpdate
 import okhttp3.internal.readMedium
 import okio.Buffer
 import okio.BufferedSource
@@ -109,7 +110,9 @@ class Http2Reader(
     val type = source.readByte() and 0xff
     val flags = source.readByte() and 0xff
     val streamId = source.readInt() and 0x7fffffff // Ignore reserved bit.
-    if (logger.isLoggable(FINE)) logger.fine(frameLog(true, streamId, length, type, flags))
+    if (type != TYPE_WINDOW_UPDATE && logger.isLoggable(FINE)) {
+      logger.fine(frameLog(true, streamId, length, type, flags))
+    }
 
     if (requireSettings && type != TYPE_SETTINGS) {
       throw IOException("Expected a SETTINGS frame but was ${formattedType(type)}")
@@ -303,11 +306,26 @@ class Http2Reader(
     handler.goAway(lastStreamId, errorCode, debugData)
   }
 
+  /** Unlike other `readXxx()` functions, this one must log the frame before returning. */
   @Throws(IOException::class)
   private fun readWindowUpdate(handler: Handler, length: Int, flags: Int, streamId: Int) {
-    if (length != 4) throw IOException("TYPE_WINDOW_UPDATE length !=4: $length")
-    val increment = source.readInt() and 0x7fffffffL
-    if (increment == 0L) throw IOException("windowSizeIncrement was 0")
+    val increment: Long
+    try {
+      if (length != 4) throw IOException("TYPE_WINDOW_UPDATE length !=4: $length")
+      increment = source.readInt() and 0x7fffffffL
+      if (increment == 0L) throw IOException("windowSizeIncrement was 0")
+    } catch (e: Exception) {
+      logger.fine(frameLog(true, streamId, length, TYPE_WINDOW_UPDATE, flags))
+      throw e
+    }
+    if (logger.isLoggable(FINE)) {
+      logger.fine(frameLogWindowUpdate(
+        inbound = true,
+        streamId = streamId,
+        length = length,
+        windowSizeIncrement = increment,
+      ))
+    }
     handler.windowUpdate(streamId, increment)
   }
 

diff --git a/okhttp/src/jvmMain/kotlin/okhttp3/internal/http2/Http2Writer.kt b/okhttp/src/jvmMain/kotlin/okhttp3/internal/http2/Http2Writer.kt
@@ -36,6 +36,7 @@ import okhttp3.internal.http2.Http2.TYPE_RST_STREAM
 import okhttp3.internal.http2.Http2.TYPE_SETTINGS
 import okhttp3.internal.http2.Http2.TYPE_WINDOW_UPDATE
 import okhttp3.internal.http2.Http2.frameLog
+import okhttp3.internal.http2.Http2.frameLogWindowUpdate
 import okhttp3.internal.writeMedium
 import okio.Buffer
 import okio.BufferedSink
@@ -243,6 +244,14 @@ class Http2Writer(
     require(windowSizeIncrement != 0L && windowSizeIncrement <= 0x7fffffffL) {
       "windowSizeIncrement == 0 || windowSizeIncrement > 0x7fffffffL: $windowSizeIncrement"
     }
+    if (logger.isLoggable(FINE)) {
+      logger.fine(frameLogWindowUpdate(
+        inbound = false,
+        streamId = streamId,
+        length = 4,
+        windowSizeIncrement = windowSizeIncrement,
+      ))
+    }
     frameHeader(
         streamId = streamId,
         length = 4,
@@ -255,7 +264,9 @@ class Http2Writer(
 
   @Throws(IOException::class)
   fun frameHeader(streamId: Int, length: Int, type: Int, flags: Int) {
-    if (logger.isLoggable(FINE)) logger.fine(frameLog(false, streamId, length, type, flags))
+    if (type != TYPE_WINDOW_UPDATE && logger.isLoggable(FINE)) {
+      logger.fine(frameLog(false, streamId, length, type, flags))
+    }
     require(length <= maxFrameSize) { "FRAME_SIZE_ERROR length > $maxFrameSize: $length" }
     require(streamId and 0x80000000.toInt() == 0) { "reserved bit set: $streamId" }
     sink.writeMedium(length)

diff --git a/okhttp/src/jvmTest/java/okhttp3/internal/http2/FrameLogTest.java b/okhttp/src/jvmTest/java/okhttp3/internal/http2/FrameLogTest.java