Log ledger api validation failures at info level (#10080)

* CHANGELOG_BEGIN
Log ledger api validation failures at info level
CHANGELOG_END

* log validation failures in Api*Service family of classes

* address review comments

ledger/ledger-api-common/BUILD.bazel

@@ -39,6 +39,7 @@ da_scala_library(
         "//ledger/ledger-resources",
         "//ledger/metrics",
         "//libs-scala/concurrent",
+        "//libs-scala/contextualized-logging",
         "//libs-scala/resources",
         "//libs-scala/resources-akka",
         "//libs-scala/resources-grpc",

ledger/ledger-api-common/src/main/scala/com/digitalasset/platform/server/api/ValidationLogger.scala

@@ -0,0 +1,24 @@
+// Copyright (c) 2021 Digital Asset (Switzerland) GmbH and/or its affiliates. All rights reserved.
+// SPDX-License-Identifier: Apache-2.0
+
+package com.daml.platform.server.api
+
+import com.daml.logging.{ContextualizedLogger, LoggingContext}
+import org.slf4j.Logger
+
+object ValidationLogger {
+  def logFailure[Request](request: Request, t: Throwable)(implicit logger: Logger): Throwable = {
+    logger.debug(s"Request validation failed for $request. Message: ${t.getMessage}")
+    logger.info(t.getMessage)
+    t
+  }
+
+  def logFailureWithContext[Request](request: Request, t: Throwable)(implicit
+      logger: ContextualizedLogger,
+      loggingContext: LoggingContext,
+  ): Throwable = {
+    logger.debug(s"Request validation failed for $request. Message: ${t.getMessage}")
+    logger.info(t.getMessage)
+    t
+  }
+}

ledger/ledger-api-common/src/main/scala/com/digitalasset/platform/server/api/services/grpc/GrpcCommandCompletionService.scala

@@ -14,7 +14,9 @@ import com.daml.ledger.api.messages.command.completion.{
 import com.daml.ledger.api.v1.command_completion_service._
 import com.daml.ledger.api.v1.ledger_offset.LedgerOffset
 import com.daml.ledger.api.validation.{CompletionServiceRequestValidator, PartyNameChecker}
+import com.daml.platform.server.api.ValidationLogger
 import com.daml.platform.server.api.services.domain.CommandCompletionService
+import org.slf4j.{Logger, LoggerFactory}
 
 import scala.concurrent.{ExecutionContext, Future}
 
@@ -44,6 +46,7 @@ class GrpcCommandCompletionService(
 ) extends CommandCompletionServiceAkkaGrpc {
 
   private val validator = new CompletionServiceRequestValidator(ledgerId, partyNameChecker)
+  protected implicit val logger: Logger = LoggerFactory.getLogger(service.getClass)
 
   override def completionStreamSource(
       request: CompletionStreamRequest
@@ -52,7 +55,7 @@ class GrpcCommandCompletionService(
       validator
         .validateCompletionStreamRequest(request, ledgerEnd, service.offsetOrdering)
         .fold(
-          Source.failed[CompletionStreamResponse],
+          t => Source.failed[CompletionStreamResponse](ValidationLogger.logFailure(request, t)),
           GrpcCommandCompletionService.fillInWithDefaults _ andThen service.completionStreamSource,
         )
     }
@@ -62,7 +65,7 @@ class GrpcCommandCompletionService(
     validator
       .validateCompletionEndRequest(request)
       .fold(
-        Future.failed[CompletionEndResponse],
+        t => Future.failed[CompletionEndResponse](ValidationLogger.logFailure(request, t)),
         req =>
           service
             .getLedgerEnd(req.ledgerId)

ledger/ledger-api-common/src/main/scala/com/digitalasset/platform/server/api/services/grpc/GrpcCommandService.scala

@@ -10,7 +10,7 @@ import com.daml.ledger.api.v1.command_service.CommandServiceGrpc.CommandService
 import com.daml.ledger.api.v1.command_service._
 import com.daml.ledger.api.validation.{CommandsValidator, SubmitAndWaitRequestValidator}
 import com.daml.platform.api.grpc.GrpcApiService
-import com.daml.platform.server.api.ProxyCloseable
+import com.daml.platform.server.api.{ProxyCloseable, ValidationLogger}
 import com.google.protobuf.empty.Empty
 import io.grpc.ServerServiceDefinition
 import org.slf4j.{Logger, LoggerFactory}
@@ -28,36 +28,48 @@ class GrpcCommandService(
     with GrpcApiService
     with ProxyCloseable {
 
-  protected val logger: Logger = LoggerFactory.getLogger(CommandService.getClass)
+  protected implicit val logger: Logger = LoggerFactory.getLogger(service.getClass)
 
   private[this] val validator =
     new SubmitAndWaitRequestValidator(new CommandsValidator(ledgerId))
 
   override def submitAndWait(request: SubmitAndWaitRequest): Future[Empty] =
     validator
       .validate(request, currentLedgerTime(), currentUtcTime(), maxDeduplicationTime())
-      .fold(Future.failed, _ => service.submitAndWait(request))
+      .fold(
+        t => Future.failed(ValidationLogger.logFailure(request, t)),
+        _ => service.submitAndWait(request),
+      )
 
   override def submitAndWaitForTransactionId(
       request: SubmitAndWaitRequest
   ): Future[SubmitAndWaitForTransactionIdResponse] =
     validator
       .validate(request, currentLedgerTime(), currentUtcTime(), maxDeduplicationTime())
-      .fold(Future.failed, _ => service.submitAndWaitForTransactionId(request))
+      .fold(
+        t => Future.failed(ValidationLogger.logFailure(request, t)),
+        _ => service.submitAndWaitForTransactionId(request),
+      )
 
   override def submitAndWaitForTransaction(
       request: SubmitAndWaitRequest
   ): Future[SubmitAndWaitForTransactionResponse] =
     validator
       .validate(request, currentLedgerTime(), currentUtcTime(), maxDeduplicationTime())
-      .fold(Future.failed, _ => service.submitAndWaitForTransaction(request))
+      .fold(
+        t => Future.failed(ValidationLogger.logFailure(request, t)),
+        _ => service.submitAndWaitForTransaction(request),
+      )
 
   override def submitAndWaitForTransactionTree(
       request: SubmitAndWaitRequest
   ): Future[SubmitAndWaitForTransactionTreeResponse] =
     validator
       .validate(request, currentLedgerTime(), currentUtcTime(), maxDeduplicationTime())
-      .fold(Future.failed, _ => service.submitAndWaitForTransactionTree(request))
+      .fold(
+        t => Future.failed(ValidationLogger.logFailure(request, t)),
+        _ => service.submitAndWaitForTransactionTree(request),
+      )
 
   override def bindService(): ServerServiceDefinition =
     CommandServiceGrpc.bindService(this, executionContext)

ledger/ledger-api-common/src/main/scala/com/digitalasset/platform/server/api/services/grpc/GrpcCommandSubmissionService.scala

@@ -16,7 +16,7 @@ import com.daml.ledger.api.v1.command_submission_service.{
 import com.daml.ledger.api.validation.{CommandsValidator, SubmitRequestValidator}
 import com.daml.metrics.{Metrics, Timed}
 import com.daml.platform.api.grpc.GrpcApiService
-import com.daml.platform.server.api.ProxyCloseable
+import com.daml.platform.server.api.{ProxyCloseable, ValidationLogger}
 import com.daml.platform.server.api.services.domain.CommandSubmissionService
 import com.daml.telemetry.{DefaultTelemetry, SpanAttribute, TelemetryContext}
 import com.google.protobuf.empty.Empty
@@ -37,7 +37,7 @@ class GrpcCommandSubmissionService(
     with ProxyCloseable
     with GrpcApiService {
 
-  protected val logger: Logger = LoggerFactory.getLogger(ApiCommandSubmissionService.getClass)
+  protected implicit val logger: Logger = LoggerFactory.getLogger(service.getClass)
 
   private val validator = new SubmitRequestValidator(new CommandsValidator(ledgerId))
 
@@ -59,7 +59,10 @@ class GrpcCommandSubmissionService(
           validator
             .validate(request, currentLedgerTime(), currentUtcTime(), maxDeduplicationTime()),
         )
-        .fold(Future.failed, service.submit(_).map(_ => Empty.defaultInstance)),
+        .fold(
+          t => Future.failed(ValidationLogger.logFailure(request, t)),
+          service.submit(_).map(_ => Empty.defaultInstance),
+        ),
     )
   }
 

ledger/ledger-api-common/src/main/scala/com/digitalasset/platform/server/api/services/grpc/GrpcTransactionService.scala

@@ -9,13 +9,11 @@ import akka.stream.scaladsl.Source
 import com.daml.grpc.adapter.ExecutionSequencerFactory
 import com.daml.ledger.api.domain.LedgerId
 import com.daml.ledger.api.v1.ledger_offset.LedgerOffset
-import com.daml.ledger.api.v1.transaction_service.TransactionServiceGrpc.{
-  TransactionService => ApiTransactionService
-}
 import com.daml.ledger.api.v1.transaction_service._
 import com.daml.ledger.api.validation.TransactionServiceRequestValidator.Result
 import com.daml.ledger.api.validation.{PartyNameChecker, TransactionServiceRequestValidator}
 import com.daml.platform.api.grpc.GrpcApiService
+import com.daml.platform.server.api.ValidationLogger
 import com.daml.platform.server.api.services.domain.TransactionService
 import com.daml.platform.server.api.validation.{ErrorFactories, FieldValidations}
 import io.grpc.ServerServiceDefinition
@@ -36,7 +34,7 @@ final class GrpcTransactionService(
     with ErrorFactories
     with FieldValidations {
 
-  protected val logger: Logger = LoggerFactory.getLogger(ApiTransactionService.getClass)
+  protected implicit val logger: Logger = LoggerFactory.getLogger(service.getClass)
 
   private val validator =
     new TransactionServiceRequestValidator(ledgerId, partyNameChecker)
@@ -49,10 +47,7 @@ final class GrpcTransactionService(
       val validation = validator.validate(request, ledgerEnd, service.offsetOrdering)
 
       validation.fold(
-        { t =>
-          logger.debug("Request validation failed for {}. Message: {}", request: Any, t.getMessage)
-          Source.failed(t)
-        },
+        t => Source.failed(ValidationLogger.logFailure(request, t)),
         req =>
           if (req.filter.filtersByParty.isEmpty) Source.empty
           else service.getTransactions(req),
@@ -68,10 +63,7 @@ final class GrpcTransactionService(
       val validation = validator.validateTree(request, ledgerEnd, service.offsetOrdering)
 
       validation.fold(
-        { t =>
-          logger.debug("Request validation failed for {}. Message: {}", request: Any, t.getMessage)
-          Source.failed(t)
-        },
+        t => Source.failed(ValidationLogger.logFailure(request, t)),
         req => {
           if (req.parties.isEmpty) Source.empty
           else service.getTransactionTrees(req)
@@ -81,11 +73,11 @@ final class GrpcTransactionService(
   }
 
   private def getSingleTransaction[Request, DomainRequest, DomainTx, Response](
-      req: Request,
+      request: Request,
       validate: Request => Result[DomainRequest],
       fetch: DomainRequest => Future[Response],
   ): Future[Response] =
-    validate(req).fold(Future.failed, fetch(_))
+    validate(request).fold(t => Future.failed(ValidationLogger.logFailure(request, t)), fetch(_))
 
   override def getTransactionByEventId(
       request: GetTransactionByEventIdRequest
@@ -131,7 +123,7 @@ final class GrpcTransactionService(
     val validation = validator.validateLedgerEnd(request)
 
     validation.fold(
-      Future.failed,
+      t => Future.failed(ValidationLogger.logFailure(request, t)),
       _ =>
         service
           .getLedgerEnd(request.ledgerId)

ledger/ledger-api-common/src/main/scala/com/digitalasset/platform/server/api/validation/ActiveContractsServiceValidation.scala

@@ -11,7 +11,7 @@ import com.daml.ledger.api.v1.active_contracts_service.{
   GetActiveContractsResponse,
 }
 import com.daml.platform.api.grpc.GrpcApiService
-import com.daml.platform.server.api.ProxyCloseable
+import com.daml.platform.server.api.{ProxyCloseable, ValidationLogger}
 import io.grpc.ServerServiceDefinition
 import io.grpc.stub.StreamObserver
 import org.slf4j.{Logger, LoggerFactory}
@@ -27,14 +27,17 @@ class ActiveContractsServiceValidation(
     with GrpcApiService
     with FieldValidations {
 
-  protected val logger: Logger = LoggerFactory.getLogger(ActiveContractsService.getClass)
+  protected implicit val logger: Logger = LoggerFactory.getLogger(service.getClass)
 
   override def getActiveContracts(
       request: GetActiveContractsRequest,
       responseObserver: StreamObserver[GetActiveContractsResponse],
   ): Unit = {
     matchLedgerId(ledgerId)(LedgerId(request.ledgerId))
-      .fold(responseObserver.onError, _ => service.getActiveContracts(request, responseObserver))
+      .fold(
+        t => responseObserver.onError(ValidationLogger.logFailure(request, t)),
+        _ => service.getActiveContracts(request, responseObserver),
+      )
   }
   override def bindService(): ServerServiceDefinition =
     ActiveContractsServiceGrpc.bindService(this, executionContext)

ledger/ledger-api-common/src/main/scala/com/digitalasset/platform/server/api/validation/LedgerConfigurationServiceValidation.scala

@@ -11,7 +11,7 @@ import com.daml.ledger.api.v1.ledger_configuration_service.{
   LedgerConfigurationServiceGrpc,
 }
 import com.daml.platform.api.grpc.GrpcApiService
-import com.daml.platform.server.api.ProxyCloseable
+import com.daml.platform.server.api.{ProxyCloseable, ValidationLogger}
 import io.grpc.ServerServiceDefinition
 import io.grpc.stub.StreamObserver
 import org.slf4j.{Logger, LoggerFactory}
@@ -27,14 +27,14 @@ class LedgerConfigurationServiceValidation(
     with GrpcApiService
     with FieldValidations {
 
-  protected val logger: Logger = LoggerFactory.getLogger(LedgerConfigurationService.getClass)
+  protected implicit val logger: Logger = LoggerFactory.getLogger(service.getClass)
 
   override def getLedgerConfiguration(
       request: GetLedgerConfigurationRequest,
       responseObserver: StreamObserver[GetLedgerConfigurationResponse],
   ): Unit =
     matchLedgerId(ledgerId)(LedgerId(request.ledgerId)).fold(
-      t => responseObserver.onError(t),
+      t => responseObserver.onError(ValidationLogger.logFailure(request, t)),
       _ => service.getLedgerConfiguration(request, responseObserver),
     )
 

ledger/ledger-api-common/src/main/scala/com/digitalasset/platform/server/api/validation/PackageServiceValidation.scala

@@ -7,7 +7,7 @@ import com.daml.ledger.api.domain.LedgerId
 import com.daml.ledger.api.v1.package_service.PackageServiceGrpc.PackageService
 import com.daml.ledger.api.v1.package_service._
 import com.daml.platform.api.grpc.GrpcApiService
-import com.daml.platform.server.api.ProxyCloseable
+import com.daml.platform.server.api.{ProxyCloseable, ValidationLogger}
 import io.grpc.ServerServiceDefinition
 import org.slf4j.{Logger, LoggerFactory}
 
@@ -23,21 +23,21 @@ class PackageServiceValidation(
     with GrpcApiService
     with FieldValidations {
 
-  protected val logger: Logger = LoggerFactory.getLogger(PackageService.getClass)
+  protected implicit val logger: Logger = LoggerFactory.getLogger(service.getClass)
 
   override def listPackages(request: ListPackagesRequest): Future[ListPackagesResponse] =
     matchLedgerId(ledgerId)(LedgerId(request.ledgerId))
       .map(const(request))
       .fold(
-        Future.failed,
+        t => Future.failed(ValidationLogger.logFailure(request, t)),
         service.listPackages,
       )
 
   override def getPackage(request: GetPackageRequest): Future[GetPackageResponse] =
     matchLedgerId(ledgerId)(LedgerId(request.ledgerId))
       .map(const(request))
       .fold(
-        Future.failed,
+        t => Future.failed(ValidationLogger.logFailure(request, t)),
         service.getPackage,
       )
 
@@ -47,7 +47,7 @@ class PackageServiceValidation(
     matchLedgerId(ledgerId)(LedgerId(request.ledgerId))
       .map(const(request))
       .fold(
-        Future.failed,
+        t => Future.failed(ValidationLogger.logFailure(request, t)),
         service.getPackageStatus,
       )
   override def bindService(): ServerServiceDefinition =