Skip to content

Commit

Permalink
Merge pull request #5671 from square/jwilson.1230.debug_logging
Browse files Browse the repository at this point in the history
Document debug logging.
  • Loading branch information
swankjesse authored Dec 31, 2019
2 parents b9e0422 + a815093 commit bd675a8
Show file tree
Hide file tree
Showing 9 changed files with 307 additions and 139 deletions.
2 changes: 2 additions & 0 deletions CONTRIBUTING.md
Original file line number Diff line number Diff line change
Expand Up @@ -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/
Original file line number Diff line number Diff line change
@@ -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() {
}
})
}
}
}
57 changes: 57 additions & 0 deletions docs/debug_logging.md
Original file line number Diff line number Diff line change
@@ -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
49 changes: 49 additions & 0 deletions okhttp-testing-support/src/main/java/okhttp3/OkHttpDebugLogging.kt
Original file line number Diff line number Diff line change
@@ -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
}
}
}
20 changes: 12 additions & 8 deletions okhttp/src/main/java/okhttp3/internal/concurrent/TaskLogger.kt
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
11 changes: 7 additions & 4 deletions okhttp/src/main/java/okhttp3/internal/concurrent/TaskQueue.kt
Original file line number Diff line number Diff line change
Expand Up @@ -68,7 +68,7 @@ class TaskQueue internal constructor(
throw RejectedExecutionException()
}

if (scheduleAndDecide(task, delayNanos)) {
if (scheduleAndDecide(task, delayNanos, recurrence = false)) {
taskRunner.kickCoordinator(this)
}
}
Expand Down Expand Up @@ -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
Expand All @@ -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()
Expand All @@ -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 }
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -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()) {
Expand Down
64 changes: 32 additions & 32 deletions okhttp/src/test/java/okhttp3/internal/concurrent/TaskLoggerTest.kt
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
}
}
Loading

0 comments on commit bd675a8

Please sign in to comment.