Document debug logging.

CONTRIBUTING.md

@@ -36,10 +36,12 @@ Committer's Guides
 ------------------
 
  * [Concurrency][concurrency]
+ * [Debug Logging][debug_logging]
  * [Releasing][releasing]
 
  [cla]: https://spreadsheets.google.com/spreadsheet/viewform?formkey=dDViT2xzUHAwRkI3X3k5Z0lQM091OGc6MQ&ndplr=1
  [concurrency]: http://square.github.io/okhttp/concurrency/
+ [debug_logging]: http://square.github.io/okhttp/debug_logging/
  [releasing]: http://square.github.io/okhttp/releasing/
  [security]: http://square.github.io/okhttp/security/
  [works_with_okhttp]: http://square.github.io/okhttp/works_with_okhttp/

android-test/src/androidTest/java/okhttp/android/test/OkHttpDebugLogcat.kt

@@ -0,0 +1,53 @@
+/*
+ * Copyright (C) 2019 Square, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package okhttp.android.test
+
+import android.util.Log
+import okhttp3.internal.concurrent.TaskRunner
+import okhttp3.internal.http2.Http2
+import java.util.concurrent.CopyOnWriteArraySet
+import java.util.logging.Handler
+import java.util.logging.Level
+import java.util.logging.LogRecord
+import java.util.logging.Logger
+import kotlin.reflect.KClass
+
+object OkHttpDebugLogcat {
+  // Keep references to loggers to prevent their configuration from being GC'd.
+  private val configuredLoggers = CopyOnWriteArraySet<Logger>()
+
+  fun enableHttp2() = enable(Http2::class)
+
+  fun enableTaskRunner() = enable(TaskRunner::class)
+
+  private fun enable(loggerClass: KClass<*>) {
+    val logger = Logger.getLogger(loggerClass.java.name)
+    if (configuredLoggers.add(logger)) {
+      logger.level = Level.FINE
+      logger.addHandler(object : Handler() {
+        override fun publish(record: LogRecord) {
+          Log.i(loggerClass.simpleName, record.message, record.thrown)
+        }
+
+        override fun flush() {
+        }
+
+        override fun close() {
+        }
+      })
+    }
+  }
+}

docs/debug_logging.md

@@ -0,0 +1,57 @@
+Debug Logging
+=============
+
+OkHttp has internal APIs to enable debug logging. It uses the `java.util.logging` API which can be
+tricky to configure. As a shortcut, you can paste [OkHttpDebugLogging.kt]. Then enable debug logging
+for whichever features you need:
+
+```
+OkHttpDebugLogging.enableHttp2()
+OkHttpDebugLogging.enableTaskRunner()
+```
+
+On Android, use [OkHttpDebugLogcat.kt] instead. It connects OkHttp logs to Logcat in Android Studio.
+
+### HTTP/2 Frame Logging
+
+This logs inbound (`<<`) and outbound (`>>`) frames for HTTP/2 connections.
+
+```
+[2020-01-01 00:00:00] >> CONNECTION 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
+[2020-01-01 00:00:00] >> 0x00000000     6 SETTINGS
+[2020-01-01 00:00:00] >> 0x00000000     4 WINDOW_UPDATE
+[2020-01-01 00:00:00] >> 0x00000003    47 HEADERS       END_STREAM|END_HEADERS
+[2020-01-01 00:00:00] << 0x00000000     6 SETTINGS
+[2020-01-01 00:00:00] << 0x00000000     0 SETTINGS      ACK
+[2020-01-01 00:00:00] << 0x00000000     4 WINDOW_UPDATE
+[2020-01-01 00:00:00] >> 0x00000000     0 SETTINGS      ACK
+[2020-01-01 00:00:00] << 0x00000003   322 HEADERS       END_HEADERS
+[2020-01-01 00:00:00] << 0x00000003   288 DATA
+[2020-01-01 00:00:00] << 0x00000003     0 DATA          END_STREAM
+[2020-01-01 00:00:00] << 0x00000000     8 GOAWAY
+[2020-01-01 00:00:05] << 0x00000000     8 GOAWAY
+```
+
+### Task Runner Logging 
+
+This logs task enqueues, starts, and finishes.
+
+```
+[2020-01-01 00:00:00] Q10000 scheduled after   0 µs: OkHttp ConnectionPool
+[2020-01-01 00:00:00] Q10000 starting              : OkHttp ConnectionPool
+[2020-01-01 00:00:00] Q10000 run again after 300 s : OkHttp ConnectionPool
+[2020-01-01 00:00:00] Q10000 finished run in   1 ms: OkHttp ConnectionPool
+[2020-01-01 00:00:00] Q10001 scheduled after   0 µs: OkHttp squareup.com applyAndAckSettings
+[2020-01-01 00:00:00] Q10001 starting              : OkHttp squareup.com applyAndAckSettings
+[2020-01-01 00:00:00] Q10003 scheduled after   0 µs: OkHttp squareup.com onSettings
+[2020-01-01 00:00:00] Q10003 starting              : OkHttp squareup.com onSettings
+[2020-01-01 00:00:00] Q10001 finished run in   3 ms: OkHttp squareup.com applyAndAckSettings
+[2020-01-01 00:00:00] Q10003 finished run in 528 µs: OkHttp squareup.com onSettings
+[2020-01-01 00:00:00] Q10000 scheduled after   0 µs: OkHttp ConnectionPool
+[2020-01-01 00:00:00] Q10000 starting              : OkHttp ConnectionPool
+[2020-01-01 00:00:00] Q10000 run again after 300 s : OkHttp ConnectionPool
+[2020-01-01 00:00:00] Q10000 finished run in 739 µs: OkHttp ConnectionPool
+```
+
+[OkHttpDebugLogging.kt]: https://github.com/square/okhttp/blob/master/okhttp-testing-support/src/main/java/okhttp3/OkHttpDebugLogging.kt
+[OkHttpDebugLogcat.kt]: https://github.com/square/okhttp/blob/master/android-test/src/androidTest/java/okhttp/android/test/OkHttpDebugLogcat.kt

okhttp-testing-support/src/main/java/okhttp3/OkHttpDebugLogging.kt

@@ -0,0 +1,49 @@
+/*
+ * Copyright (C) 2019 Square, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package okhttp3
+
+import okhttp3.internal.concurrent.TaskRunner
+import okhttp3.internal.http2.Http2
+import java.util.concurrent.CopyOnWriteArraySet
+import java.util.logging.ConsoleHandler
+import java.util.logging.Level
+import java.util.logging.LogRecord
+import java.util.logging.Logger
+import java.util.logging.SimpleFormatter
+import kotlin.reflect.KClass
+
+object OkHttpDebugLogging {
+  // Keep references to loggers to prevent their configuration from being GC'd.
+  private val configuredLoggers = CopyOnWriteArraySet<Logger>()
+
+  fun enableHttp2() = enable(Http2::class)
+
+  fun enableTaskRunner() = enable(TaskRunner::class)
+
+  private fun enable(loggerClass: KClass<*>) {
+    val logger = Logger.getLogger(loggerClass.java.name)
+    if (configuredLoggers.add(logger)) {
+      logger.addHandler(ConsoleHandler().apply {
+        level = Level.FINE
+        formatter = object : SimpleFormatter() {
+          override fun format(record: LogRecord) =
+              String.format("[%1\$tF %1\$tT] %2\$s %n", record.millis, record.message)
+        }
+      })
+      logger.level = Level.FINE
+    }
+  }
+}

okhttp/src/main/java/okhttp3/internal/concurrent/TaskLogger.kt

@@ -48,30 +48,34 @@ internal inline fun <T> logElapsed(
     if (loggingEnabled) {
       val elapsedNs = queue.taskRunner.backend.nanoTime() - startNs
       if (completedNormally) {
-        log(task, queue, "finished in ${formatDuration(elapsedNs)}")
+        log(task, queue, "finished run in ${formatDuration(elapsedNs)}")
       } else {
-        log(task, queue, "failed in ${formatDuration(elapsedNs)}")
+        log(task, queue, "failed a run in ${formatDuration(elapsedNs)}")
       }
     }
   }
 }
 
 private fun log(task: Task, queue: TaskQueue, message: String) {
-  TaskRunner.logger.fine("${queue.name} $message: ${task.name}")
+  TaskRunner.logger.fine("${queue.name} ${String.format("%-22s", message)}: ${task.name}")
 }
 
 /**
- * Returns a duration in the nearest whole-number units like "999 µs" or "1 ms". This rounds 0.5
+ * Returns a duration in the nearest whole-number units like "999 µs" or "  1 s ". This rounds 0.5
  * units away from 0 and 0.499 towards 0. The smallest unit this returns is "µs"; the largest unit
- * it returns is "s". For values in [-499..499] this returns "0 µs".
+ * it returns is "s". For values in [-499..499] this returns "  0 µs".
+ *
+ * The returned string attempts to be column-aligned to 6 characters. For negative and large values
+ * the returned string may be longer.
  */
 fun formatDuration(ns: Long): String {
-  return when {
-    ns <= -999_500_000 -> "${(ns - 500_000_000) / 1_000_000_000} s"
+  val s = when {
+    ns <= -999_500_000 -> "${(ns - 500_000_000) / 1_000_000_000} s "
     ns <= -999_500 -> "${(ns - 500_000) / 1_000_000} ms"
     ns <= 0 -> "${(ns - 500) / 1_000} µs"
     ns < 999_500 -> "${(ns + 500) / 1_000} µs"
     ns < 999_500_000 -> "${(ns + 500_000) / 1_000_000} ms"
-    else -> "${(ns + 500_000_000) / 1_000_000_000} s"
+    else -> "${(ns + 500_000_000) / 1_000_000_000} s "
   }
+  return String.format("%6s", s)
 }

okhttp/src/main/java/okhttp3/internal/concurrent/TaskQueue.kt

@@ -68,7 +68,7 @@ class TaskQueue internal constructor(
         throw RejectedExecutionException()
       }
 
-      if (scheduleAndDecide(task, delayNanos)) {
+      if (scheduleAndDecide(task, delayNanos, recurrence = false)) {
         taskRunner.kickCoordinator(this)
       }
     }
@@ -122,7 +122,7 @@ class TaskQueue internal constructor(
 
       // Don't delegate to schedule() because that enforces shutdown rules.
       val newTask = AwaitIdleTask()
-      if (scheduleAndDecide(newTask, 0L)) {
+      if (scheduleAndDecide(newTask, 0L, recurrence = false)) {
         taskRunner.kickCoordinator(this)
       }
       return newTask.latch
@@ -139,7 +139,7 @@ class TaskQueue internal constructor(
   }
 
   /** Adds [task] to run in [delayNanos]. Returns true if the coordinator is impacted. */
-  internal fun scheduleAndDecide(task: Task, delayNanos: Long): Boolean {
+  internal fun scheduleAndDecide(task: Task, delayNanos: Long, recurrence: Boolean): Boolean {
     task.initQueue(this)
 
     val now = taskRunner.backend.nanoTime()
@@ -155,7 +155,10 @@ class TaskQueue internal constructor(
       futureTasks.removeAt(existingIndex) // Already scheduled later: reschedule below!
     }
     task.nextExecuteNanoTime = executeNanoTime
-    taskLog(task, this) { "scheduled after ${formatDuration(executeNanoTime - now)}" }
+    taskLog(task, this) {
+      if (recurrence) "run again after ${formatDuration(executeNanoTime - now)}"
+      else "scheduled after ${formatDuration(executeNanoTime - now)}"
+    }
 
     // Insert in chronological order. Always compare deltas because nanoTime() is permitted to wrap.
     var insertAt = futureTasks.indexOfFirst { it.nextExecuteNanoTime - now > delayNanos }

okhttp/src/main/java/okhttp3/internal/concurrent/TaskRunner.kt

@@ -41,7 +41,7 @@ import java.util.logging.Logger
 class TaskRunner(
   val backend: Backend
 ) {
-  private var nextQueueName = 1
+  private var nextQueueName = 10000
   private var coordinatorWaiting = false
   private var coordinatorWakeUpAt = 0L
 
@@ -133,7 +133,7 @@ class TaskRunner(
     busyQueues.remove(queue)
 
     if (delayNanos != -1L && !cancelActiveTask && !queue.shutdown) {
-      queue.scheduleAndDecide(task, delayNanos)
+      queue.scheduleAndDecide(task, delayNanos, recurrence = true)
     }
 
     if (queue.futureTasks.isNotEmpty()) {

okhttp/src/test/java/okhttp3/internal/concurrent/TaskLoggerTest.kt

@@ -21,49 +21,49 @@ import org.junit.Test
 class TaskLoggerTest {
   @Test fun formatTime() {
     /* ktlint-disable */
-    assertThat(formatDuration(-3_499_999_999L)).isEqualTo("-3 s")
-    assertThat(formatDuration(-3_000_000_000L)).isEqualTo("-3 s")
-    assertThat(formatDuration(-2_500_000_000L)).isEqualTo("-3 s")
-    assertThat(formatDuration(-2_499_999_999L)).isEqualTo("-2 s")
-    assertThat(formatDuration(-1_500_000_000L)).isEqualTo("-2 s")
-    assertThat(formatDuration(-1_499_999_999L)).isEqualTo("-1 s")
-    assertThat(formatDuration(-1_000_000_000L)).isEqualTo("-1 s")
-    assertThat(formatDuration(  -999_500_000L)).isEqualTo("-1 s")
+    assertThat(formatDuration(-3_499_999_999L)).isEqualTo(" -3 s ")
+    assertThat(formatDuration(-3_000_000_000L)).isEqualTo(" -3 s ")
+    assertThat(formatDuration(-2_500_000_000L)).isEqualTo(" -3 s ")
+    assertThat(formatDuration(-2_499_999_999L)).isEqualTo(" -2 s ")
+    assertThat(formatDuration(-1_500_000_000L)).isEqualTo(" -2 s ")
+    assertThat(formatDuration(-1_499_999_999L)).isEqualTo(" -1 s ")
+    assertThat(formatDuration(-1_000_000_000L)).isEqualTo(" -1 s ")
+    assertThat(formatDuration(  -999_500_000L)).isEqualTo(" -1 s ")
     assertThat(formatDuration(  -999_499_999L)).isEqualTo("-999 ms")
     assertThat(formatDuration(  -998_500_000L)).isEqualTo("-999 ms")
     assertThat(formatDuration(  -998_499_999L)).isEqualTo("-998 ms")
-    assertThat(formatDuration(    -1_499_999L)).isEqualTo("-1 ms")
-    assertThat(formatDuration(      -999_500L)).isEqualTo("-1 ms")
+    assertThat(formatDuration(    -1_499_999L)).isEqualTo(" -1 ms")
+    assertThat(formatDuration(      -999_500L)).isEqualTo(" -1 ms")
     assertThat(formatDuration(      -999_499L)).isEqualTo("-999 µs")
     assertThat(formatDuration(      -998_500L)).isEqualTo("-999 µs")
-    assertThat(formatDuration(        -1_500L)).isEqualTo("-2 µs")
-    assertThat(formatDuration(        -1_499L)).isEqualTo("-1 µs")
-    assertThat(formatDuration(        -1_000L)).isEqualTo("-1 µs")
-    assertThat(formatDuration(          -999L)).isEqualTo("-1 µs")
-    assertThat(formatDuration(          -500L)).isEqualTo("-1 µs")
-    assertThat(formatDuration(          -499L)).isEqualTo("0 µs")
+    assertThat(formatDuration(        -1_500L)).isEqualTo(" -2 µs")
+    assertThat(formatDuration(        -1_499L)).isEqualTo(" -1 µs")
+    assertThat(formatDuration(        -1_000L)).isEqualTo(" -1 µs")
+    assertThat(formatDuration(          -999L)).isEqualTo(" -1 µs")
+    assertThat(formatDuration(          -500L)).isEqualTo(" -1 µs")
+    assertThat(formatDuration(          -499L)).isEqualTo("  0 µs")
 
-    assertThat(formatDuration( 3_499_999_999L)).isEqualTo("3 s")
-    assertThat(formatDuration( 3_000_000_000L)).isEqualTo("3 s")
-    assertThat(formatDuration( 2_500_000_000L)).isEqualTo("3 s")
-    assertThat(formatDuration( 2_499_999_999L)).isEqualTo("2 s")
-    assertThat(formatDuration( 1_500_000_000L)).isEqualTo("2 s")
-    assertThat(formatDuration( 1_499_999_999L)).isEqualTo("1 s")
-    assertThat(formatDuration( 1_000_000_000L)).isEqualTo("1 s")
-    assertThat(formatDuration(   999_500_000L)).isEqualTo("1 s")
+    assertThat(formatDuration( 3_499_999_999L)).isEqualTo("  3 s ")
+    assertThat(formatDuration( 3_000_000_000L)).isEqualTo("  3 s ")
+    assertThat(formatDuration( 2_500_000_000L)).isEqualTo("  3 s ")
+    assertThat(formatDuration( 2_499_999_999L)).isEqualTo("  2 s ")
+    assertThat(formatDuration( 1_500_000_000L)).isEqualTo("  2 s ")
+    assertThat(formatDuration( 1_499_999_999L)).isEqualTo("  1 s ")
+    assertThat(formatDuration( 1_000_000_000L)).isEqualTo("  1 s ")
+    assertThat(formatDuration(   999_500_000L)).isEqualTo("  1 s ")
     assertThat(formatDuration(   999_499_999L)).isEqualTo("999 ms")
     assertThat(formatDuration(   998_500_000L)).isEqualTo("999 ms")
     assertThat(formatDuration(   998_499_999L)).isEqualTo("998 ms")
-    assertThat(formatDuration(     1_499_999L)).isEqualTo("1 ms")
-    assertThat(formatDuration(       999_500L)).isEqualTo("1 ms")
+    assertThat(formatDuration(     1_499_999L)).isEqualTo("  1 ms")
+    assertThat(formatDuration(       999_500L)).isEqualTo("  1 ms")
     assertThat(formatDuration(       999_499L)).isEqualTo("999 µs")
     assertThat(formatDuration(       998_500L)).isEqualTo("999 µs")
-    assertThat(formatDuration(         1_500L)).isEqualTo("2 µs")
-    assertThat(formatDuration(         1_499L)).isEqualTo("1 µs")
-    assertThat(formatDuration(         1_000L)).isEqualTo("1 µs")
-    assertThat(formatDuration(           999L)).isEqualTo("1 µs")
-    assertThat(formatDuration(           500L)).isEqualTo("1 µs")
-    assertThat(formatDuration(           499L)).isEqualTo("0 µs")
+    assertThat(formatDuration(         1_500L)).isEqualTo("  2 µs")
+    assertThat(formatDuration(         1_499L)).isEqualTo("  1 µs")
+    assertThat(formatDuration(         1_000L)).isEqualTo("  1 µs")
+    assertThat(formatDuration(           999L)).isEqualTo("  1 µs")
+    assertThat(formatDuration(           500L)).isEqualTo("  1 µs")
+    assertThat(formatDuration(           499L)).isEqualTo("  0 µs")
     /* ktlint-enable */
   }
 }