diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index e0e216ec4..8d7add97f 100644 --- a/CONTRIBUTING.md +++ b/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/ diff --git a/android-test/src/androidTest/java/okhttp/android/test/OkHttpDebugLogcat.kt b/android-test/src/androidTest/java/okhttp/android/test/OkHttpDebugLogcat.kt new file mode 100644 index 000000000..95886bd0f --- /dev/null +++ b/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() + + 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() { + } + }) + } + } +} diff --git a/docs/debug_logging.md b/docs/debug_logging.md new file mode 100644 index 000000000..5e47bb1c1 --- /dev/null +++ b/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 diff --git a/okhttp-testing-support/src/main/java/okhttp3/OkHttpDebugLogging.kt b/okhttp-testing-support/src/main/java/okhttp3/OkHttpDebugLogging.kt new file mode 100644 index 000000000..1a7eaa274 --- /dev/null +++ b/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() + + 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 + } + } +} diff --git a/okhttp/src/main/java/okhttp3/internal/concurrent/TaskLogger.kt b/okhttp/src/main/java/okhttp3/internal/concurrent/TaskLogger.kt index 208143005..09cf9eae3 100644 --- a/okhttp/src/main/java/okhttp3/internal/concurrent/TaskLogger.kt +++ b/okhttp/src/main/java/okhttp3/internal/concurrent/TaskLogger.kt @@ -48,30 +48,34 @@ internal inline fun 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) } diff --git a/okhttp/src/main/java/okhttp3/internal/concurrent/TaskQueue.kt b/okhttp/src/main/java/okhttp3/internal/concurrent/TaskQueue.kt index 4de83b0c8..2f4295ee7 100644 --- a/okhttp/src/main/java/okhttp3/internal/concurrent/TaskQueue.kt +++ b/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 } diff --git a/okhttp/src/main/java/okhttp3/internal/concurrent/TaskRunner.kt b/okhttp/src/main/java/okhttp3/internal/concurrent/TaskRunner.kt index fdec3ab4a..762de1437 100644 --- a/okhttp/src/main/java/okhttp3/internal/concurrent/TaskRunner.kt +++ b/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()) { diff --git a/okhttp/src/test/java/okhttp3/internal/concurrent/TaskLoggerTest.kt b/okhttp/src/test/java/okhttp3/internal/concurrent/TaskLoggerTest.kt index 33d51e523..8d84e3aa6 100644 --- a/okhttp/src/test/java/okhttp3/internal/concurrent/TaskLoggerTest.kt +++ b/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 */ } } diff --git a/okhttp/src/test/java/okhttp3/internal/concurrent/TaskRunnerTest.kt b/okhttp/src/test/java/okhttp3/internal/concurrent/TaskRunnerTest.kt index 898a0531d..36cd743e5 100644 --- a/okhttp/src/test/java/okhttp3/internal/concurrent/TaskRunnerTest.kt +++ b/okhttp/src/test/java/okhttp3/internal/concurrent/TaskRunnerTest.kt @@ -49,9 +49,9 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -80,15 +80,15 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 scheduled after 50 µs: task", - "FINE: Q1 finished in 0 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 scheduled after 150 µs: task", - "FINE: Q1 finished in 0 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 run again after 50 µs: task", + "FINE: Q10000 finished run in 0 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 run again after 150 µs: task", + "FINE: Q10000 finished run in 0 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -119,13 +119,13 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 scheduled after 50 µs: task", - "FINE: Q1 already scheduled: task", - "FINE: Q1 finished in 0 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 scheduled after 50 µs: task", + "FINE: Q10000 already scheduled : task", + "FINE: Q10000 finished run in 0 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -156,13 +156,13 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 scheduled after 200 µs: task", - "FINE: Q1 scheduled after 50 µs: task", - "FINE: Q1 finished in 0 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 scheduled after 200 µs: task", + "FINE: Q10000 run again after 50 µs: task", + "FINE: Q10000 finished run in 0 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -182,8 +182,8 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 canceled: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 canceled : task" ) } @@ -209,9 +209,9 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -231,9 +231,9 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -252,9 +252,9 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -280,12 +280,12 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 scheduled after 50 µs: task", - "FINE: Q1 finished in 0 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 run again after 50 µs: task", + "FINE: Q10000 finished run in 0 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -305,8 +305,8 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 canceled: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 canceled : task" ) } @@ -332,9 +332,9 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -365,15 +365,15 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task one", - "FINE: Q1 scheduled after 100 µs: task two", - "FINE: Q1 scheduled after 100 µs: task three", - "FINE: Q1 starting: task one", - "FINE: Q1 finished in 0 µs: task one", - "FINE: Q1 starting: task two", - "FINE: Q1 finished in 0 µs: task two", - "FINE: Q1 starting: task three", - "FINE: Q1 finished in 0 µs: task three" + "FINE: Q10000 scheduled after 100 µs: task one", + "FINE: Q10000 scheduled after 100 µs: task two", + "FINE: Q10000 scheduled after 100 µs: task three", + "FINE: Q10000 starting : task one", + "FINE: Q10000 finished run in 0 µs: task one", + "FINE: Q10000 starting : task two", + "FINE: Q10000 finished run in 0 µs: task two", + "FINE: Q10000 starting : task three", + "FINE: Q10000 finished run in 0 µs: task three" ) } @@ -404,15 +404,15 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task one", - "FINE: Q2 scheduled after 100 µs: task two", - "FINE: Q3 scheduled after 100 µs: task three", - "FINE: Q1 starting: task one", - "FINE: Q1 finished in 0 µs: task one", - "FINE: Q2 starting: task two", - "FINE: Q2 finished in 0 µs: task two", - "FINE: Q3 starting: task three", - "FINE: Q3 finished in 0 µs: task three" + "FINE: Q10000 scheduled after 100 µs: task one", + "FINE: Q10001 scheduled after 100 µs: task two", + "FINE: Q10002 scheduled after 100 µs: task three", + "FINE: Q10000 starting : task one", + "FINE: Q10000 finished run in 0 µs: task one", + "FINE: Q10001 starting : task two", + "FINE: Q10001 finished run in 0 µs: task two", + "FINE: Q10002 starting : task three", + "FINE: Q10002 finished run in 0 µs: task three" ) } @@ -429,8 +429,8 @@ class TaskRunnerTest { assertThat(redQueue.scheduledTasks.toString()).isEqualTo("[task one, task two]") assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task one", - "FINE: Q1 scheduled after 200 µs: task two" + "FINE: Q10000 scheduled after 100 µs: task one", + "FINE: Q10000 scheduled after 200 µs: task two" ) } @@ -476,15 +476,15 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task one", - "FINE: Q1 scheduled after 200 µs: task two", - "FINE: Q1 starting: task one", - "FINE: Q1 scheduled after 200 µs: task one", - "FINE: Q1 finished in 0 µs: task one", - "FINE: Q1 starting: task two", - "FINE: Q1 finished in 0 µs: task two", - "FINE: Q1 starting: task one", - "FINE: Q1 finished in 0 µs: task one" + "FINE: Q10000 scheduled after 100 µs: task one", + "FINE: Q10000 scheduled after 200 µs: task two", + "FINE: Q10000 starting : task one", + "FINE: Q10000 scheduled after 200 µs: task one", + "FINE: Q10000 finished run in 0 µs: task one", + "FINE: Q10000 starting : task two", + "FINE: Q10000 finished run in 0 µs: task two", + "FINE: Q10000 starting : task one", + "FINE: Q10000 finished run in 0 µs: task one" ) } @@ -514,12 +514,12 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task one", - "FINE: Q2 scheduled after 200 µs: task two", - "FINE: Q1 starting: task one", - "FINE: Q1 finished in 0 µs: task one", - "FINE: Q2 starting: task two", - "FINE: Q2 finished in 0 µs: task two" + "FINE: Q10000 scheduled after 100 µs: task one", + "FINE: Q10001 scheduled after 200 µs: task two", + "FINE: Q10000 starting : task one", + "FINE: Q10000 finished run in 0 µs: task one", + "FINE: Q10001 starting : task two", + "FINE: Q10001 finished run in 0 µs: task two" ) } @@ -534,9 +534,9 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 0 µs: lucky task", - "FINE: Q1 starting: lucky task", - "FINE: Q1 finished in 0 µs: lucky task" + "FINE: Q10000 scheduled after 0 µs: lucky task", + "FINE: Q10000 starting : lucky task", + "FINE: Q10000 finished run in 0 µs: lucky task" ) } @@ -556,8 +556,8 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 canceled: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 canceled : task" ) } @@ -583,9 +583,9 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 scheduled after 100 µs: task", - "FINE: Q1 starting: task", - "FINE: Q1 finished in 0 µs: task" + "FINE: Q10000 scheduled after 100 µs: task", + "FINE: Q10000 starting : task", + "FINE: Q10000 finished run in 0 µs: task" ) } @@ -599,7 +599,7 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 schedule canceled (queue is shutdown): task" + "FINE: Q10000 schedule canceled (queue is shutdown): task" ) } @@ -619,7 +619,7 @@ class TaskRunnerTest { taskFaker.assertNoMoreTasks() assertThat(testLogHandler.takeAll()).containsExactly( - "FINE: Q1 schedule failed (queue is shutdown): task" + "FINE: Q10000 schedule failed (queue is shutdown): task" ) }