diff --git a/onfhir-common/src/main/scala/io/onfhir/api/model/FHIRRequest.scala b/onfhir-common/src/main/scala/io/onfhir/api/model/FHIRRequest.scala index 76e8ca8a..d3a13812 100644 --- a/onfhir-common/src/main/scala/io/onfhir/api/model/FHIRRequest.scala +++ b/onfhir-common/src/main/scala/io/onfhir/api/model/FHIRRequest.scala @@ -1,12 +1,12 @@ package io.onfhir.api.model import java.time.Instant - import akka.http.scaladsl.model.{ContentType, HttpMethod, Uri} import akka.http.scaladsl.model.headers.{`If-Match`, `If-Modified-Since`, `If-None-Match`, `X-Forwarded-For`, `X-Forwarded-Host`} import io.onfhir.api.Resource import io.onfhir.api._ import io.onfhir.api.parsers.BundleRequestParser +import io.onfhir.util.JsonFormatter import io.onfhir.util.JsonFormatter.formats /** @@ -284,5 +284,24 @@ case class FHIRRequest( * Get Location of request in transaction (Used for identifiying erroneous requests within transactions/batchs) */ def getRequestLocation():String = s"Request Id: ${id}, Request Url: ${requestUri}" + + /** + * Get a log string summarizing the FHIR request + * @return + */ + def getSummaryString():String = { + val attributes = + Seq( + "Interaction" -> interaction, + "Request Id" -> id, + "Request Url" -> requestUri + ) ++ + resourceType.map(rtype => "ResourceType" -> rtype).toSeq ++ + resourceId.map(rid => "ResourceId" -> rid).toSeq ++ + resource.map(r => s"Resource" -> JsonFormatter.convertToJson(r).toJson) ++ + (if(queryParams.nonEmpty) Some("Query" -> queryParams.flatMap(qp => qp._2.map(v => s"${qp._1}=${v}")).mkString("&")) else None).toSeq + + attributes.map(a => s"${a._1}: ${a._2}").mkString(", ") + } } diff --git a/onfhir-common/src/main/scala/io/onfhir/config/OnfhirConfig.scala b/onfhir-common/src/main/scala/io/onfhir/config/OnfhirConfig.scala index 4d77b8a6..0314c450 100644 --- a/onfhir-common/src/main/scala/io/onfhir/config/OnfhirConfig.scala +++ b/onfhir-common/src/main/scala/io/onfhir/config/OnfhirConfig.scala @@ -178,6 +178,11 @@ object OnfhirConfig { */ lazy val authzConfig:AuthzConfig = new AuthzConfig(OnfhirConfig.config.getConfig("fhir.authorization")) + /** + * Whether to log failed requests and issues related with them + */ + lazy val logFailedRequests:Boolean = Try(config.getBoolean("fhir.failed-request-logging")).toOption.getOrElse(false) + /** * FHIR Subscription related configuration */ diff --git a/onfhir-core/src/main/resources/application.conf b/onfhir-core/src/main/resources/application.conf index 0a6304e4..ff0e5557 100644 --- a/onfhir-core/src/main/resources/application.conf +++ b/onfhir-core/src/main/resources/application.conf @@ -173,6 +173,10 @@ fhir { # This indicates the maximum batch size. If # of audit records passed this amount or batch interval time comes, audits are send to remote server. Default is 50. # batch-size = 50 } + # Whether to log requests that are failed (e.g. invalid FHIR content, search parameter, etc) + # IMPORTANT: Please note that the request content is also logged here so it may be problematic in terms of privacy.Therefore, + # use this for development/test environments + failed-request-logging = false subscription { # Enables sending FHIR subscription events to kafka so onfhir-subscription module can work active = false diff --git a/onfhir-core/src/main/scala/io/onfhir/Onfhir.scala b/onfhir-core/src/main/scala/io/onfhir/Onfhir.scala index d078ff6e..2a3a6c58 100644 --- a/onfhir-core/src/main/scala/io/onfhir/Onfhir.scala +++ b/onfhir-core/src/main/scala/io/onfhir/Onfhir.scala @@ -8,7 +8,7 @@ import akka.http.scaladsl.server.Route import akka.http.scaladsl.settings.ServerSettings import io.onfhir.api.endpoint.{FHIREndpoint, OnFhirInternalEndpoint} import io.onfhir.api.model.FHIRRequest -import io.onfhir.audit.AuditManager +import io.onfhir.audit.{AuditManager, RequestLogManager} import io.onfhir.authz._ import io.onfhir.config.{FhirConfigurationManager, IFhirServerConfigurator, OnfhirConfig, SSLConfig} import io.onfhir.db.{DBConflictManager, EmbeddedMongo} @@ -64,6 +64,10 @@ class Onfhir( Some(Onfhir.actorSystem.actorOf(AuditManager.props(FhirConfigurationManager, customAuditHandler), AuditManager.ACTOR_NAME)) else None + + val requestLogManager = + Onfhir.actorSystem.actorOf(RequestLogManager.props(), "request-response-logger") + //Create db conflict manager actor, if transaction is not enabled val dbConflictManager = if(!OnfhirConfig.mongoUseTransaction) diff --git a/onfhir-core/src/main/scala/io/onfhir/api/endpoint/FHIREndpoint.scala b/onfhir-core/src/main/scala/io/onfhir/api/endpoint/FHIREndpoint.scala index 7ab0a58f..5b864c23 100644 --- a/onfhir-core/src/main/scala/io/onfhir/api/endpoint/FHIREndpoint.scala +++ b/onfhir-core/src/main/scala/io/onfhir/api/endpoint/FHIREndpoint.scala @@ -9,7 +9,7 @@ import io.onfhir.api.model.FHIRRequest import io.onfhir.api.util.{FHIRServerUtil, FHIRUtil} import io.onfhir.server.ErrorHandler.fhirErrorHandler import io.onfhir.server.FHIRRejectionHandler.fhirRejectionHandler -import io.onfhir.audit.AuditManager +import io.onfhir.audit.{AuditManager, RequestLogManager} import io.onfhir.authz.{AuthManager, AuthzConfigurationManager} import io.onfhir.config.{FhirConfigurationManager, OnfhirConfig} import io.onfhir.server.CORSHandler @@ -76,22 +76,24 @@ trait FHIREndpoint ).setId(xRequestId) //Set the identifier of the request //Resolve Token/Auth/Authz context AuthManager.authenticate() { authContext => - //Audit the interaction when result is available - AuditManager.audit(fhirRequest, authContext._1, authContext._2) { - //Handle any exception with our own directive (See details in ErrorHandler) - handleExceptions(fhirErrorHandler(fhirRequest)) { - //Handle any rejection with our own directive (See details in FHIRRejectionHandler) - handleRejections(fhirRejectionHandler(fhirRequest)) { - //Merge all routes, ORDER IS IMPORTANT among same HTTP methods as they are merged as OR !!!! - var routes = - createRoute(fhirRequest, authContext) ~ updateRoute(fhirRequest, authContext) ~ deleteRoute(fhirRequest, authContext) ~ historyRoute(fhirRequest, authContext) ~ readRoute(fhirRequest, authContext) ~ searchRoute(fhirRequest, authContext) ~ compartmentSearchRoute(fhirRequest, authContext) ~ patchRoute(fhirRequest, authContext) ~ batchRoute(fhirRequest, authContext) ~ operationRoute(fhirRequest, authContext) - //Add the external service routes - Onfhir.apply().externalRoutes.foreach(er => routes = routes ~ er(fhirRequest, authContext)) - //Append the security route if our server is secure - if (OnfhirConfig.authzConfig.isSecure()) - routes ~ securityRoute - else - routes + RequestLogManager.logRequest(fhirRequest) { + //Audit the interaction when result is available + AuditManager.audit(fhirRequest, authContext._1, authContext._2) { + //Handle any exception with our own directive (See details in ErrorHandler) + handleExceptions(fhirErrorHandler(fhirRequest)) { + //Handle any rejection with our own directive (See details in FHIRRejectionHandler) + handleRejections(fhirRejectionHandler(fhirRequest)) { + //Merge all routes, ORDER IS IMPORTANT among same HTTP methods as they are merged as OR !!!! + var routes = + createRoute(fhirRequest, authContext) ~ updateRoute(fhirRequest, authContext) ~ deleteRoute(fhirRequest, authContext) ~ historyRoute(fhirRequest, authContext) ~ readRoute(fhirRequest, authContext) ~ searchRoute(fhirRequest, authContext) ~ compartmentSearchRoute(fhirRequest, authContext) ~ patchRoute(fhirRequest, authContext) ~ batchRoute(fhirRequest, authContext) ~ operationRoute(fhirRequest, authContext) + //Add the external service routes + Onfhir.apply().externalRoutes.foreach(er => routes = routes ~ er(fhirRequest, authContext)) + //Append the security route if our server is secure + if (OnfhirConfig.authzConfig.isSecure()) + routes ~ securityRoute + else + routes + } } } } diff --git a/onfhir-core/src/main/scala/io/onfhir/api/validation/FHIRResourceValidator.scala b/onfhir-core/src/main/scala/io/onfhir/api/validation/FHIRResourceValidator.scala index e7efd095..e983dbd0 100644 --- a/onfhir-core/src/main/scala/io/onfhir/api/validation/FHIRResourceValidator.scala +++ b/onfhir-core/src/main/scala/io/onfhir/api/validation/FHIRResourceValidator.scala @@ -5,10 +5,9 @@ import io.onfhir.api._ import io.onfhir.Onfhir import io.onfhir.api.model.{FHIRResponse, OutcomeIssue} import io.onfhir.api.util.FHIRUtil -import io.onfhir.config.{FhirServerConfig, IFhirConfigurationManager, OnfhirConfig} +import io.onfhir.config.{IFhirConfigurationManager, OnfhirConfig} import io.onfhir.exception.BadRequestException import io.onfhir.validation.FhirContentValidator -import org.slf4j.{Logger, LoggerFactory} import scala.concurrent.Future @@ -43,7 +42,6 @@ class FHIRResourceValidator(fhirConfigurationManager: IFhirConfigurationManager) * @return */ def validateResourceAgainstProfile(resource: Resource, rtype:String, profile:Option[String], parentPath:Option[String] =None, bundle:Option[(Option[String],Resource)] = None, silent:Boolean = false): Future[Seq[OutcomeIssue]] = { - OnfhirConfig.fhirValidation match { case FHIR_VALIDATION_ALTERNATIVES.NONE => Future.apply(Nil) // Ignore validation, no issues case _ => @@ -81,8 +79,9 @@ class FHIRResourceValidator(fhirConfigurationManager: IFhirConfigurationManager) .map(issues => { val unknownProfileWarnings = unknownProfiles.map(up => OutcomeIssue(FHIRResponse.SEVERITY_CODES.WARNING, FHIRResponse.OUTCOME_CODES.INFORMATIONAL, None, Some(s"Profile with url '$up' is not known to this server! Therefore, validation is skipped for this profile!"), Seq("meta.profile"))) - if (!silent && issues.exists(_.isError)) + if (!silent && issues.exists(_.isError)) { throw new BadRequestException((issues ++ unknownProfileWarnings).toSeq) + } (issues ++ unknownProfileWarnings).toSeq }) diff --git a/onfhir-core/src/main/scala/io/onfhir/audit/RequestLogManager.scala b/onfhir-core/src/main/scala/io/onfhir/audit/RequestLogManager.scala new file mode 100644 index 00000000..6006eccb --- /dev/null +++ b/onfhir-core/src/main/scala/io/onfhir/audit/RequestLogManager.scala @@ -0,0 +1,92 @@ +package io.onfhir.audit + +import akka.actor.{Actor, ActorSystem, Props} +import akka.http.scaladsl.server.{Directive0, Directives} +import io.onfhir.Onfhir +import io.onfhir.api.model.FHIRRequest +import io.onfhir.audit.RequestLogManager.LogRequest +import io.onfhir.config.OnfhirConfig +import io.onfhir.util.JsonFormatter.formats +import org.json4s.jackson.Serialization +import org.json4s.{Extraction, JArray} +import org.slf4j.{Logger, LoggerFactory} + +import scala.concurrent.ExecutionContextExecutor + +/** + * Actor that logs failed requests + */ +class RequestLogManager() extends Actor { + //Actor system + implicit val actorSystem: ActorSystem = Onfhir.actorSystem + implicit val executionContext: ExecutionContextExecutor = context.dispatcher // actorSystem.dispatchers.lookup("akka.actor.onfhir-blocking-dispatcher") + + //Logger for actor + private val logger: Logger = LoggerFactory.getLogger(this.getClass) + + /** + * Actor commands + * @return + */ + def receive: Receive = { + //Only log errors + case LogRequest(fhirRequest) if fhirRequest.response.exists(_.isError) => + logRequest(fhirRequest) + //For batch requests, log child request errors + case LogRequest(fhirRequest) if fhirRequest.childRequests.nonEmpty && + fhirRequest.childRequests.exists(_.response.exists(_.isError)) => + fhirRequest.childRequests.filter(_.response.exists(_.isError)) + .foreach(childRequest => + logRequest(childRequest) + ) + //We don't log successful requests + case LogRequest(_) => + //Nothing + } + + /** + * Log the request and response status and issues + * @param fhirRequest + */ + def logRequest(fhirRequest: FHIRRequest) = { + logger.warn( + "Problem in FHIR request: " + fhirRequest.getSummaryString() + "\n" + + s"Response status: ${fhirRequest.response.get.httpStatus.intValue()}, Found issues: " + Serialization.write(JArray(fhirRequest.response.get.outcomeIssues.map(i => Extraction.decompose(i)).toList)) + ) + } + +} + +/** + * + */ +object RequestLogManager { + /** + * Log the request-response + * @param fhirRequest FHIR request including the response + */ + case class LogRequest(fhirRequest: FHIRRequest) + + /** + * Log request-response according to configurations + * @param fhirRequest + * @return + */ + def logRequest(fhirRequest: FHIRRequest):Directive0 = { + Directives.mapResponse { httpResponse => + //If configured log failed requests + if(OnfhirConfig.logFailedRequests) + Onfhir.actorSystem.actorSelection(s"/user/request-response-logger") ! LogRequest(fhirRequest) + //Return HttpResponse as it is + httpResponse + } + } + + /** + * Props for Actor + * + * @return + */ + def props() = Props(new RequestLogManager()) + +} diff --git a/onfhir-core/src/main/scala/io/onfhir/server/ErrorHandler.scala b/onfhir-core/src/main/scala/io/onfhir/server/ErrorHandler.scala index 5a27e039..d5a27ef1 100644 --- a/onfhir-core/src/main/scala/io/onfhir/server/ErrorHandler.scala +++ b/onfhir-core/src/main/scala/io/onfhir/server/ErrorHandler.scala @@ -7,22 +7,26 @@ import com.fasterxml.jackson.databind.JsonMappingException import io.onfhir.api.model.{FHIRRequest, FHIRResponse, OutcomeIssue} import io.onfhir.exception._ import io.onfhir.api.model.FHIRMarshallers._ +import io.onfhir.util.JsonFormatter.formats +import org.json4s.{Extraction, JArray} +import org.json4s.jackson.Serialization import scala.language.implicitConversions import org.slf4j.{Logger, LoggerFactory} object ErrorHandler { - val logger: Logger = LoggerFactory.getLogger(this.getClass.getName) + val logger: Logger = LoggerFactory.getLogger(this.getClass) /** * Exception Handler object * @return */ implicit def fhirErrorHandler(fhirRequest:FHIRRequest): ExceptionHandler = ExceptionHandler { - case e:Throwable if fhirErrorHandlerToResponse.isDefinedAt(e) => Directives.complete{ - val response = fhirErrorHandlerToResponse(e) - fhirRequest.setResponse(response) - response - } + case e:Throwable if fhirErrorHandlerToResponse.isDefinedAt(e) => + Directives.complete{ + val response = fhirErrorHandlerToResponse(e) + fhirRequest.setResponse(response) + response + } } /**