Removes the multiple redundant logs on exceptions in favor of including

the log level and exception in the RequestLoggingInterceptor logs. If
the RequestLoggingInterceptor does not log for the current request the
existing ExceptionHandlingInterceptor log is preserved. Removes the log
in RequestBodyLoggingInterceptor as it is always redundant.

GitOrigin-RevId: 27ad4bbac3862fa4096d7fde36ff8c79abf1c749

Author: ericloe-cash

misk-grpc-tests/src/test/kotlin/misk/grpc/MiskClientMiskServerTest.kt

@@ -1,9 +1,15 @@
 package misk.grpc
 
+import ch.qos.logback.classic.Level
 import com.google.inject.Guice
 import com.google.inject.util.Modules
 import com.squareup.wire.GrpcException
 import com.squareup.wire.GrpcStatus
+import jakarta.inject.Inject
+import jakarta.inject.Named
+import java.net.HttpURLConnection.HTTP_BAD_REQUEST
+import kotlin.test.assertEquals
+import kotlin.test.assertFailsWith
 import kotlinx.coroutines.GlobalScope
 import kotlinx.coroutines.channels.ReceiveChannel
 import kotlinx.coroutines.runBlocking
@@ -16,6 +22,7 @@ import misk.logging.LogCollectorModule
 import misk.metrics.FakeMetrics
 import misk.testing.MiskTest
 import misk.testing.MiskTestModule
+import misk.web.exceptions.ExceptionHandlingInterceptor
 import misk.web.interceptors.RequestLoggingInterceptor
 import okhttp3.HttpUrl
 import org.assertj.core.api.Assertions.assertThat
@@ -33,11 +40,6 @@ import routeguide.Point
 import routeguide.RouteGuideClient
 import routeguide.RouteNote
 import wisp.logging.LogCollector
-import java.net.HttpURLConnection.HTTP_BAD_REQUEST
-import jakarta.inject.Inject
-import jakarta.inject.Named
-import kotlin.test.assertEquals
-import kotlin.test.assertFailsWith
 
 @MiskTest(startService = true)
 class MiskClientMiskServerTest {
@@ -148,6 +150,15 @@ class MiskClientMiskServerTest {
       // is only thrown if a properly constructed gRPC error is received.
       assertResponseCount(200, 0)
       assertResponseCount(500, 1)
+
+      // Confirm only RequestLoggingInterceptor logs exceptions
+      val requestLoggingInterceptorLogs = logCollector.takeMessages(RequestLoggingInterceptor::class, Level.ERROR)
+      assertEquals(1, requestLoggingInterceptorLogs.size)
+      assertThat(requestLoggingInterceptorLogs[0])
+        .contains("GetFeatureGrpcAction principal=unknown time=0.000 ns failed request=Point{latitude=-1, longitude=500}")
+
+      val exceptionLoggingInterceptorLogs = logCollector.takeMessages(ExceptionHandlingInterceptor::class)
+      assertThat(exceptionLoggingInterceptorLogs).isEmpty()
     }
   }
 
@@ -171,6 +182,15 @@ class MiskClientMiskServerTest {
       // is only thrown if a properly constructed gRPC error is received.
       assertResponseCount(200, 0)
       assertResponseCount(404, 1)
+
+      // Confirm only RequestLoggingInterceptor logs exceptions
+      val requestLoggingInterceptorLogs = logCollector.takeMessages(RequestLoggingInterceptor::class, Level.WARN)
+      assertEquals(1, requestLoggingInterceptorLogs.size)
+      assertThat(requestLoggingInterceptorLogs[0])
+        .contains("GetFeatureGrpcAction principal=unknown time=0.000 ns failed request=Point{latitude=-1, longitude=404}")
+
+      val exceptionLoggingInterceptorLogs = logCollector.takeMessages(ExceptionHandlingInterceptor::class)
+      assertThat(exceptionLoggingInterceptorLogs).isEmpty()
     }
   }
 

misk/api/misk.api

@@ -1768,7 +1768,7 @@ public final class misk/web/exceptions/ActionExceptionLogLevelConfig : wisp/conf
 }
 
 public final class misk/web/exceptions/ExceptionHandlingInterceptor : misk/web/NetworkInterceptor {
-	public fun <init> (Ljava/lang/String;Lmisk/web/exceptions/ExceptionMapperResolver;)V
+	public synthetic fun <init> (Ljava/lang/String;Lmisk/web/exceptions/ExceptionMapperResolver;Lmisk/web/interceptors/hooks/RequestResponseLoggedCapture;Lkotlin/jvm/internal/DefaultConstructorMarker;)V
 	public fun intercept (Lmisk/web/NetworkChain;)V
 }
 

misk/src/main/kotlin/misk/web/exceptions/ExceptionHandlingInterceptor.kt

@@ -16,6 +16,7 @@ import misk.web.NetworkChain
 import misk.web.NetworkInterceptor
 import misk.web.Response
 import misk.web.ResponseBody
+import misk.web.interceptors.hooks.RequestResponseLoggedCapture
 import misk.web.mediatype.MediaTypes
 import misk.web.toResponseBody
 import okhttp3.Headers.Companion.toHeaders
@@ -41,9 +42,10 @@ import java.util.Base64
  *
  * TODO(isabel): Set the response body in a ThreadLocal to log in [RequestLoggingInterceptor]
  */
-class ExceptionHandlingInterceptor(
+class ExceptionHandlingInterceptor private constructor(
   private val actionName: String,
-  private val mapperResolver: ExceptionMapperResolver
+  private val mapperResolver: ExceptionMapperResolver,
+  private val requestResponseLoggedCapture: RequestResponseLoggedCapture,
 ) : NetworkInterceptor {
 
   @OptIn(ExperimentalMiskApi::class)
@@ -60,7 +62,7 @@ class ExceptionHandlingInterceptor(
           val response = toResponse(th, suppressLog = true, mdcTags)
           sendGrpcFailure(chain.httpCall, response.statusCode, toGrpcResponse(th, mdcTags))
         } else {
-          val response = toResponse(th, suppressLog = false, mdcTags)
+          val response = toResponse(th, suppressLog = requestResponseLoggedCapture.isLogged(), mdcTags)
           chain.httpCall.statusCode = response.statusCode
           sendHttpFailure(chain.httpCall, response)
         }
@@ -117,41 +119,40 @@ class ExceptionHandlingInterceptor(
     return buffer.readUtf8()
   }
 
-  private fun toResponse(th: Throwable, suppressLog: Boolean, mdcTags: Set<Tag>): Response<*> {
-    // If the exception is a reflection wrapper, unwrap first.
-    when (th) {
-      is InvocationTargetException -> return toResponse(th.targetException, suppressLog, mdcTags)
-      is UncheckedExecutionException -> return toResponse(th.cause!!, suppressLog, mdcTags)
-    }
+  private fun toResponse(th: Throwable, suppressLog: Boolean, mdcTags: Set<Tag>): Response<*> =
+    unwrappedToResponse(th.unwrap(), suppressLog, mdcTags)
 
+  private fun unwrappedToResponse(th: Throwable, suppressLog: Boolean, mdcTags: Set<Tag>): Response<*> =
     // Prefer the mapper's response, if one exists.
-    val mapper = mapperResolver.mapperFor(th)
-    if (mapper != null) {
+    mapperResolver.mapperFor(th)?.let {
       if (!suppressLog) {
         log.log(
-          level = mapper.loggingLevel(th),
+          level = it.loggingLevel(th),
           th = th,
-          tags = *mdcTags.toTypedArray(),
+          tags = mdcTags.toTypedArray(),
         ) { "exception dispatching to $actionName" }
       }
-      return mapper.toResponse(th)
-    }
 
+      it.toResponse(th)
+    }
     // Fall back to a default mapping.
-    return toInternalServerError(th, mdcTags)
-  }
+      ?: toInternalServerError(th, suppressLog, mdcTags)
+
 
-  private fun toGrpcResponse(th: Throwable, mdcTags: Set<Tag>): GrpcErrorResponse = when (th) {
+  private fun toGrpcResponse(th: Throwable, mdcTags: Set<Tag>): GrpcErrorResponse =
+    unwrappedToGrpcResponse(th.unwrap(), mdcTags)
+
+  private fun unwrappedToGrpcResponse(th: Throwable, mdcTags: Set<Tag>): GrpcErrorResponse = when (th) {
     is UnauthenticatedException -> GrpcErrorResponse(GrpcStatus.UNAUTHENTICATED, th.message)
     is UnauthorizedException -> GrpcErrorResponse(GrpcStatus.PERMISSION_DENIED, th.message)
-    is InvocationTargetException -> toGrpcResponse(th.targetException, mdcTags)
-    is UncheckedExecutionException -> toGrpcResponse(th.cause!!, mdcTags)
     else -> mapperResolver.mapperFor(th)?.let {
-      log.log(
-        level = it.loggingLevel(th),
-        th = th,
-        tags = *mdcTags.toTypedArray(),
-      ) { "exception dispatching to $actionName" }
+      if (!requestResponseLoggedCapture.isLogged()) {
+        log.log(
+          level = it.loggingLevel(th),
+          th = th,
+          tags = mdcTags.toTypedArray(),
+        ) { "exception dispatching to $actionName" }
+      }
       val grpcResponse = it.toGrpcResponse(th)
       if (grpcResponse == null) {
         val httpResponse = toResponse(th, suppressLog = true, mdcTags)
@@ -162,15 +163,19 @@ class ExceptionHandlingInterceptor(
     } ?: GrpcErrorResponse.INTERNAL_SERVER_ERROR
   }
 
-  private fun toInternalServerError(th: Throwable, mdcTags: Set<Tag>): Response<*> {
-    log.error(th, *mdcTags.toTypedArray()) { "unexpected error dispatching to $actionName" }
+  private fun toInternalServerError(th: Throwable, suppressLog: Boolean, mdcTags: Set<Tag>): Response<*> {
+    if (!suppressLog) {
+      log.error(th = th, tags = mdcTags.toTypedArray()) { "unexpected error dispatching to $actionName" }
+    }
     return INTERNAL_SERVER_ERROR_RESPONSE
   }
 
   class Factory @Inject internal constructor(
-    private val mapperResolver: ExceptionMapperResolver
+    private val mapperResolver: ExceptionMapperResolver,
+    private val requestResponseLoggedCapture: RequestResponseLoggedCapture,
   ) : NetworkInterceptor.Factory {
-    override fun create(action: Action) = ExceptionHandlingInterceptor(action.name, mapperResolver)
+    override fun create(action: Action) =
+      ExceptionHandlingInterceptor(action.name, mapperResolver, requestResponseLoggedCapture)
   }
 
   private companion object {
@@ -200,6 +205,20 @@ fun toGrpcStatus(statusCode: Int): GrpcStatus {
   }
 }
 
+/**
+ * Unwrap [InvocationTargetException] and [UncheckedExecutionException] to find the root cause.
+ */
+internal fun Throwable.unwrap(): Throwable {
+  var th = this
+  while (true) {
+    th = when (th) {
+      is InvocationTargetException -> th.targetException
+      is UncheckedExecutionException -> th.cause!!
+      else -> return th
+    }
+  }
+}
+
 /** Convert to a compatible base64-proto-encoded google.rpc.Status-compatible value. */
 private val GrpcErrorResponse.toEncodedStatusProto
   get() : String {

misk/src/main/kotlin/misk/web/interceptors/RequestBodyLoggingInterceptor.kt

@@ -83,25 +83,20 @@ class RequestBodyLoggingInterceptor @Inject internal constructor(
         response = null,
         requestHeaders = redactedRequestHeaders.headers,
         responseHeaders = null,
-      )
+      ),
     )
 
-    try {
-      val result = chain.proceed(chain.args)
-      val redactedResponseHeaders = HeadersCapture(chain.httpCall.responseHeaders)
-      bodyCapture.set(
-        RequestResponseBody(
-          request = args,
-          response = result,
-          requestHeaders = redactedRequestHeaders.headers,
-          responseHeaders = redactedResponseHeaders.headers,
-        )
-      )
-      return result
-    } catch (t: Throwable) {
-      logger.info { "${action.name} principal=$principal failed" }
-      throw t
-    }
+    val result = chain.proceed(chain.args)
+    val redactedResponseHeaders = HeadersCapture(chain.httpCall.responseHeaders)
+    bodyCapture.set(
+      RequestResponseBody(
+        request = args,
+        response = result,
+        requestHeaders = redactedRequestHeaders.headers,
+        responseHeaders = redactedResponseHeaders.headers,
+      ),
+    )
+    return result
   }
 }
 

misk/src/main/kotlin/misk/web/interceptors/hooks/RequestResponseLoggingHook.kt

@@ -4,8 +4,11 @@ import jakarta.inject.Inject
 import jakarta.inject.Singleton
 import misk.Action
 import misk.MiskCaller
+import misk.annotation.ExperimentalMiskApi
 import misk.random.ThreadLocalRandom
 import misk.web.HttpCall
+import misk.web.exceptions.ExceptionMapperResolver
+import misk.web.exceptions.unwrap
 import misk.web.interceptors.ActionLoggingConfig
 import misk.web.interceptors.LogRateLimiter
 import misk.web.interceptors.LogRateLimiter.LogBucketId
@@ -14,26 +17,34 @@ import misk.web.interceptors.RequestLoggingConfig
 import misk.web.interceptors.RequestLoggingInterceptor
 import misk.web.interceptors.RequestLoggingMode
 import misk.web.interceptors.RequestResponseBody
+import org.slf4j.event.Level
 import wisp.deployment.Deployment
+import wisp.logging.SmartTagsThreadLocalHandler
+import wisp.logging.Tag
 import wisp.logging.getLogger
-import wisp.logging.info
+import wisp.logging.log
 import java.time.Duration
 import kotlin.reflect.full.findAnnotation
 
 /** For backwards compatibility, the interceptor logger is used since that is where the functionality used to live. */
 private val logger = getLogger<RequestLoggingInterceptor>()
 
+@OptIn(ExperimentalMiskApi::class)
 internal class RequestResponseLoggingHook private constructor(
   private val action: Action,
   private val random: ThreadLocalRandom,
   private val logRateLimiter: LogRateLimiter,
+  private val mapperResolver: ExceptionMapperResolver,
+  private val requestResponseLoggedCapture: RequestResponseLoggedCapture,
   val config: ActionLoggingConfig,
 ) : RequestResponseHook {
   @Singleton
   class Factory @Inject constructor(
     private val random: ThreadLocalRandom,
     private val logRateLimiter: LogRateLimiter,
     private val deployment: Deployment,
+    private val mapperResolver: ExceptionMapperResolver,
+    private val requestResponseLoggedCapture: RequestResponseLoggedCapture,
     private val configs: Set<RequestLoggingConfig>,
   ) : RequestResponseHook.Factory {
     override fun create(action: Action): RequestResponseHook? {
@@ -58,7 +69,14 @@ internal class RequestResponseLoggingHook private constructor(
         "${action.name} @LogRequestResponse errorBodySampling must be in the range (0.0, 1.0]"
       }
 
-      return RequestResponseLoggingHook(action, random, logRateLimiter, config)
+      return RequestResponseLoggingHook(
+        action,
+        random,
+        logRateLimiter,
+        mapperResolver,
+        requestResponseLoggedCapture,
+        config,
+      )
     }
   }
 
@@ -70,6 +88,8 @@ internal class RequestResponseLoggingHook private constructor(
     elapsedToString: String,
     error: Throwable?
   ) {
+    requestResponseLoggedCapture.reset()
+
     val statusCode = httpCall.statusCode
     val isError = statusCode > 299 || error != null
     if (!isError && config.requestLoggingMode == RequestLoggingMode.ERROR_ONLY) {
@@ -86,11 +106,16 @@ internal class RequestResponseLoggingHook private constructor(
     val randomDouble = random.current().nextDouble()
     val includeBody = randomDouble < sampling
 
-    logger.info(
+    val additionalTags: MutableSet<Tag> = mutableSetOf(
       "response_code" to statusCode,
       "response_time_millis" to elapsed.toMillis(),
-    ) {
-      buildDescription(
+    )
+
+    requestResponseLoggedCapture.onLogged()
+
+    val error = error?.unwrap()
+    fun buildDescriptionImpl(): Any? {
+      return buildDescription(
         caller = caller,
         httpCall = httpCall,
         elapsedToString = elapsedToString,
@@ -99,6 +124,24 @@ internal class RequestResponseLoggingHook private constructor(
         includeBody = includeBody,
       )
     }
+
+    if (error != null) {
+      // Log with the exception and smart tags applied on error.
+      val level = mapperResolver.mapperFor(error)?.loggingLevel(error) ?: Level.ERROR
+
+      logger.log(
+        level = level,
+        th = error,
+        tags = (SmartTagsThreadLocalHandler.peekThreadLocalSmartTags() + additionalTags).toTypedArray(),
+        message = ::buildDescriptionImpl,
+      )
+    } else {
+      logger.log(
+        level = Level.INFO,
+        tags = additionalTags.toTypedArray(),
+        message = ::buildDescriptionImpl,
+      )
+    }
   }
 
   private fun buildDescription(
@@ -137,3 +180,24 @@ internal class RequestResponseLoggingHook private constructor(
     }
   }
 }
+
+/**
+ * Captures whether the RequestResponseLogger has already logged the response to avoid double logging.
+ */
+internal class RequestResponseLoggedCapture @Inject constructor() {
+  companion object {
+    private val capture = object : ThreadLocal<Boolean>() {
+      override fun initialValue() = false
+    }
+  }
+
+  fun isLogged(): Boolean = capture.get()
+
+  fun onLogged() {
+    capture.set(true)
+  }
+
+  fun reset() {
+    return capture.set(false)
+  }
+}