Skip to content
Permalink
Browse files

RequestLoggingInterceptor logs response time and code (#1206)

  • Loading branch information...
mightyguava committed Sep 24, 2019
1 parent a2d3459 commit 3040c683f45e8d75dec01137651c2eb3ebebd821
@@ -10,7 +10,7 @@ import misk.logging.LogCollector
import misk.logging.LogCollectorModule
import misk.testing.MiskTest
import misk.testing.MiskTestModule
import misk.web.interceptors.RequestLoggingInterceptor
import misk.web.interceptors.RequestBodyLoggingInterceptor
import org.assertj.core.api.Assertions.assertThat
import org.junit.jupiter.api.Test
import routeguide.Feature
@@ -51,10 +51,10 @@ class MiskClientMiskServerTest {
}

// Confirm interceptors were invoked.
assertThat(logCollector.takeMessage(RequestLoggingInterceptor::class)).isEqualTo(
assertThat(logCollector.takeMessage(RequestBodyLoggingInterceptor::class)).isEqualTo(
"GetFeatureGrpcAction principal=unknown request=[$point]")
assertThat(logCollector.takeMessage(RequestLoggingInterceptor::class)).isEqualTo(
"GetFeatureGrpcAction principal=unknown time=0.000 ns response=$feature")
assertThat(logCollector.takeMessage(RequestBodyLoggingInterceptor::class)).isEqualTo(
"GetFeatureGrpcAction principal=unknown response=$feature")
}

@Test
@@ -71,10 +71,10 @@ class MiskClientMiskServerTest {
}

// Confirm interceptors were invoked.
assertThat(logCollector.takeMessage(RequestLoggingInterceptor::class)).isEqualTo(
assertThat(logCollector.takeMessage(RequestBodyLoggingInterceptor::class)).isEqualTo(
"RouteChatGrpcAction principal=unknown request=[GrpcMessageSource, GrpcMessageSink]")
assertThat(logCollector.takeMessage(RequestLoggingInterceptor::class)).isEqualTo(
"RouteChatGrpcAction principal=unknown time=0.000 ns response=kotlin.Unit")
assertThat(logCollector.takeMessage(RequestBodyLoggingInterceptor::class)).isEqualTo(
"RouteChatGrpcAction principal=unknown response=kotlin.Unit")
}

@Test
@@ -43,6 +43,7 @@ internal class RealLogCollector @Inject constructor() :
minLevel: Level,
pattern: Regex?
): List<ILoggingEvent> {
Thread.sleep(100) // Give the logger some time to flush events.
val result = mutableListOf<ILoggingEvent>()
while (queue.isNotEmpty()) {
val event = takeOrNull(loggerClass, minLevel, pattern)
@@ -35,6 +35,7 @@ import misk.web.interceptors.InternalErrorInterceptorFactory
import misk.web.interceptors.MetricsInterceptor
import misk.web.interceptors.RebalancingInterceptor
import misk.web.interceptors.RequestLogContextInterceptor
import misk.web.interceptors.RequestBodyLoggingInterceptor
import misk.web.interceptors.RequestLoggingInterceptor
import misk.web.interceptors.TracingInterceptor
import misk.web.jetty.JettyConnectionMetricsCollector
@@ -114,9 +115,13 @@ class MiskWebModule(private val config: WebConfig) : KAbstractModule() {
.to<ExceptionHandlingInterceptor.Factory>()

// Optionally log request and response details
multibind<ApplicationInterceptor.Factory>(MiskDefault::class)
multibind<NetworkInterceptor.Factory>(MiskDefault::class)
.to<RequestLoggingInterceptor.Factory>()

// Optionally log request and response body
multibind<ApplicationInterceptor.Factory>(MiskDefault::class)
.to<RequestBodyLoggingInterceptor.Factory>()

install(ExceptionMapperModule.create<ActionException, ActionExceptionMapper>())

// Register built-in feature bindings.
@@ -0,0 +1,84 @@
package misk.web.interceptors

import misk.Action
import misk.ApplicationInterceptor
import misk.Chain
import misk.MiskCaller
import misk.logging.getLogger
import misk.random.ThreadLocalRandom
import misk.scope.ActionScoped
import javax.inject.Inject
import javax.inject.Singleton
import kotlin.reflect.full.findAnnotation

private val logger = getLogger<RequestBodyLoggingInterceptor>()

/**
* Logs request and response information for an action.
* Timing information doesn't count time writing the response to the remote client.
*/
class RequestBodyLoggingInterceptor internal constructor(
private val action: Action,
private val sampling: Double,
private val caller: ActionScoped<MiskCaller?>,
private val random: ThreadLocalRandom
) : ApplicationInterceptor {

@Singleton
class Factory @Inject internal constructor(
private val caller: @JvmSuppressWildcards ActionScoped<MiskCaller?>,
private val random: ThreadLocalRandom
) : ApplicationInterceptor.Factory {
override fun create(action: Action): ApplicationInterceptor? {
val logRequestResponse = action.function.findAnnotation<LogRequestResponse>() ?: return null
require(0.0 < logRequestResponse.sampling && logRequestResponse.sampling <= 1.0) {
"${action.name} @LogRequestResponse sampling must be in the range (0.0, 1.0]"
}
if (!logRequestResponse.includeBody) {
return null
}

return RequestBodyLoggingInterceptor(
action,
logRequestResponse.sampling,
caller,
random
)
}
}

override fun intercept(chain: Chain): Any {
val randomDouble = random.current().nextDouble()
if (randomDouble >= sampling) {
return chain.proceed(chain.args)
}

val principal = caller.get()?.principal ?: "unknown"

logger.info { "${action.name} principal=$principal request=${chain.args}" }

try {
val result = chain.proceed(chain.args)
logger.info { "${action.name} principal=$principal response=$result" }
return result
} catch (t: Throwable) {
logger.info { "${action.name} principal=$principal failed" }
throw t
}
}
}

/**
* Annotation indicating that request and response information should be logged.
*
* sampling is used to sample the number of requests logged with 0.0 for none and 1.0 for all.
* Valid values are in the range (0.0, 1.0].
*
* If includeBody is true both the action arguments and the response will be logged.
*
* If arguments and responses may include sensitive information, it is expected that the toString()
* methods of these objects will redact it.
*/
@Retention(AnnotationRetention.RUNTIME)
@Target(AnnotationTarget.FUNCTION)
annotation class LogRequestResponse(val sampling: Double, val includeBody: Boolean)
@@ -3,12 +3,14 @@ package misk.web.interceptors
import com.google.common.base.Stopwatch
import com.google.common.base.Ticker
import misk.Action
import misk.ApplicationInterceptor
import misk.Chain
import misk.MiskCaller
import misk.logging.getLogger
import misk.logging.info
import misk.random.ThreadLocalRandom
import misk.scope.ActionScoped
import misk.web.NetworkChain
import misk.web.NetworkInterceptor
import java.util.concurrent.TimeUnit
import javax.inject.Inject
import javax.inject.Singleton
import kotlin.reflect.full.findAnnotation
@@ -22,19 +24,17 @@ private val logger = getLogger<RequestLoggingInterceptor>()
class RequestLoggingInterceptor internal constructor(
private val action: Action,
private val sampling: Double,
private val includeBody: Boolean,
private val caller: ActionScoped<MiskCaller?>,
private val ticker: Ticker,
private val random: ThreadLocalRandom
) : ApplicationInterceptor {

) : NetworkInterceptor {
@Singleton
class Factory @Inject internal constructor(
private val caller: @JvmSuppressWildcards ActionScoped<MiskCaller?>,
private val ticker: Ticker,
private val random: ThreadLocalRandom
) : ApplicationInterceptor.Factory {
override fun create(action: Action): ApplicationInterceptor? {
) : NetworkInterceptor.Factory {
override fun create(action: Action): NetworkInterceptor? {
val logRequestResponse = action.function.findAnnotation<LogRequestResponse>() ?: return null
require(0.0 < logRequestResponse.sampling && logRequestResponse.sampling <= 1.0) {
"${action.name} @LogRequestResponse sampling must be in the range (0.0, 1.0]"
@@ -43,49 +43,35 @@ class RequestLoggingInterceptor internal constructor(
return RequestLoggingInterceptor(
action,
logRequestResponse.sampling,
logRequestResponse.includeBody,
caller,
ticker,
random
)
}
}

override fun intercept(chain: Chain): Any {
override fun intercept(chain: NetworkChain) {
val randomDouble = random.current().nextDouble()
if (randomDouble >= sampling) {
return chain.proceed(chain.args)
return chain.proceed(chain.httpCall)
}

val principal = caller.get()?.principal ?: "unknown"
val requestString = if (includeBody) chain.args.toString() else ""

logger.info { "${action.name} principal=$principal request=$requestString" }
logger.info { "${action.name} principal=$principal" }

val stopwatch = Stopwatch.createStarted(ticker)
try {
val result = chain.proceed(chain.args)
val resultString = if (includeBody) result.toString() else ""
logger.info { "${action.name} principal=$principal time=$stopwatch response=$resultString" }
val result = chain.proceed(chain.httpCall)
stopwatch.stop()
logger.info(
"response_code" to chain.httpCall.statusCode,
"response_time_millis" to stopwatch.elapsed(TimeUnit.MILLISECONDS)
) { "${action.name} principal=$principal time=$stopwatch code=${chain.httpCall.statusCode}" }
return result
} catch (t: Throwable) {
logger.info { "${action.name} principal=$principal time=$stopwatch failed" }
throw t
}
}
}

/**
* Annotation indicating that request and response information should be logged.
*
* sampling is used to sample the number of requests logged with 0.0 for none and 1.0 for all.
* Valid values are in the range (0.0, 1.0].
*
* If includeBody is true both the action arguments and the response will be logged.
*
* If arguments and responses may include sensitive information, it is expected that the toString()
* methods of these objects will redact it.
*/
@Retention(AnnotationRetention.RUNTIME)
@Target(AnnotationTarget.FUNCTION)
annotation class LogRequestResponse(val sampling: Double, val includeBody: Boolean)
@@ -9,7 +9,7 @@ import misk.web.actions.WebAction
import misk.web.actions.WebSocket
import misk.web.actions.WebSocketListener
import misk.web.interceptors.LogRequestResponse
import misk.web.interceptors.RequestLoggingInterceptor
import misk.web.interceptors.RequestBodyLoggingInterceptor
import misk.web.jetty.JettyService
import okhttp3.OkHttpClient
import okhttp3.Request
@@ -43,11 +43,11 @@ internal class WebSocketsTest {
assertEquals("ACK hello", listener.takeMessage())

// Confirm interceptors were invoked.
val (m0, m1) = logCollector.takeMessages(RequestLoggingInterceptor::class)
val (m0, m1) = logCollector.takeMessages(RequestBodyLoggingInterceptor::class)
assertThat(m0)
.matches("EchoWebSocket principal=unknown request=\\[JettyWebSocket\\[.* to /echo]]")
assertThat(m1)
.isEqualTo("EchoWebSocket principal=unknown time=0.000 ns response=EchoListener")
.isEqualTo("EchoWebSocket principal=unknown response=EchoListener")
}

@Singleton
@@ -27,7 +27,7 @@ import java.util.concurrent.TimeUnit
import javax.inject.Inject

@MiskTest(startService = true)
internal class RequestLoggingInterceptorTest {
internal class RequestBodyLoggingInterceptorTest {

@MiskTestModule
val module = TestModule()
@@ -46,10 +46,10 @@ internal class RequestLoggingInterceptorTest {
@Test
fun includesBody() {
assertThat(invoke("/call/includeBodyRequestLogging/hello", "caller").isSuccessful).isTrue()
val messages = logCollector.takeMessages(RequestLoggingInterceptor::class)
val messages = logCollector.takeMessages(RequestBodyLoggingInterceptor::class)
assertThat(messages).containsExactly(
"IncludeBodyRequestLoggingAction principal=caller request=[hello]",
"IncludeBodyRequestLoggingAction principal=caller time=100.0 ms response=echo: hello"
"IncludeBodyRequestLoggingAction principal=caller response=echo: hello"
)
}

@@ -58,18 +58,19 @@ internal class RequestLoggingInterceptorTest {
assertThat(invoke("/call/excludeBodyRequestLogging/hello", "caller").isSuccessful).isTrue()
val messages = logCollector.takeMessages(RequestLoggingInterceptor::class)
assertThat(messages).containsExactly(
"ExcludeBodyRequestLoggingAction principal=caller request=",
"ExcludeBodyRequestLoggingAction principal=caller time=100.0 ms response="
"ExcludeBodyRequestLoggingAction principal=caller",
"ExcludeBodyRequestLoggingAction principal=caller time=100.0 ms code=200"
)
assertThat(logCollector.takeMessages(RequestBodyLoggingInterceptor::class)).isEmpty()
}

@Test
fun exceptionThrown() {
assertThat(invoke("/call/exceptionThrowingRequestLogging/fail", "caller").code).isEqualTo(500)
val messages = logCollector.takeMessages(RequestLoggingInterceptor::class)
val messages = logCollector.takeMessages(RequestBodyLoggingInterceptor::class)
assertThat(messages).containsExactly(
"ExceptionThrowingRequestLoggingAction principal=caller request=[fail]",
"ExceptionThrowingRequestLoggingAction principal=caller time=100.0 ms failed"
"ExceptionThrowingRequestLoggingAction principal=caller failed"
)
}

@@ -78,6 +79,7 @@ internal class RequestLoggingInterceptorTest {
fakeRandom.nextDouble = 0.7
assertThat(invoke("/call/sampledRequestLogging/hello", "caller").isSuccessful).isTrue()
assertThat(logCollector.takeMessages(RequestLoggingInterceptor::class)).isEmpty()
assertThat(logCollector.takeMessages(RequestBodyLoggingInterceptor::class)).isEmpty()
}

@Test
@@ -91,6 +93,7 @@ internal class RequestLoggingInterceptorTest {
fun noRequestLoggingIfMissingAnnotation() {
assertThat(invoke("/call/noRequestLogging/hello", "caller").isSuccessful).isTrue()
assertThat(logCollector.takeMessages(RequestLoggingInterceptor::class)).isEmpty()
assertThat(logCollector.takeMessages(RequestBodyLoggingInterceptor::class)).isEmpty()
}

fun invoke(path: String, asService: String? = null): okhttp3.Response {

0 comments on commit 3040c68

Please sign in to comment.
You can’t perform that action at this time.