🔊 Legger auditlogging inn i PersonQuery

- Audit-teamet vil ikke ha logg på personer vi vet ikke finnes (garbage input, feil i fnr eller aktørId) - WARN på personer vi ikke finner i systemet - WARN og flexString1=deny derom sakbehandler ikke har tilgang til å se på person - INFO på suksess - auditlogTeller som teller antall antall auditlogger Co-authored-by: Jakob Havstein Eriksen <[email protected]> Co-authored-by: Øydis Kind Refsum <[email protected]> Co-authored-by: Trine Linderud <[email protected]>
navikt · Mar 21, 2024 · 5961a01 · 5961a01
1 parent cf95591
commit 5961a01
Show file tree

Hide file tree

Showing 7 changed files with 81 additions and 46 deletions.
diff --git a/spesialist-api/src/main/kotlin/no/nav/helse/spesialist/api/GraphQLMetrikker.kt b/spesialist-api/src/main/kotlin/no/nav/helse/spesialist/api/GraphQLMetrikker.kt
@@ -6,6 +6,7 @@ import io.ktor.server.application.createRouteScopedPlugin
 import io.ktor.server.plugins.callloging.processingTimeMillis
 import io.ktor.server.request.httpMethod
 import io.ktor.server.request.receive
+import io.prometheus.client.Counter
 import io.prometheus.client.Summary
 
 val GraphQLMetrikker = createRouteScopedPlugin("GraphQLMetrikker") {
@@ -23,3 +24,6 @@ private val graphQLResponstider =
     Summary.build("graphql_responstider", "Måler responstider for GraphQL-kall")
         .labelNames("operationName")
         .register()
+
+
+internal val auditLogTeller = Counter.build("auditlog_total", "Teller antall auditlogginnslag").register()
diff --git a/...t-api/src/main/kotlin/no/nav/helse/spesialist/api/graphql/LoggingGraphQLRequestHandler.kt b/...t-api/src/main/kotlin/no/nav/helse/spesialist/api/graphql/LoggingGraphQLRequestHandler.kt
@@ -11,7 +11,6 @@ import org.slf4j.LoggerFactory
 class LoggingGraphQLRequestHandler(graphQL: GraphQL) : GraphQLRequestHandler(graphQL) {
 
     private val sikkerLogg = LoggerFactory.getLogger("tjenestekall")
-    private val auditLog = LoggerFactory.getLogger("auditLogger")
 
     override suspend fun executeRequest(
         graphQLRequest: GraphQLServerRequest,
@@ -21,18 +20,10 @@ class LoggingGraphQLRequestHandler(graphQL: GraphQL) : GraphQLRequestHandler(gra
             graphQLRequest.operationName.also { operationName ->
                 if (operationName != null) {
                     sikkerLogg.trace("GraphQL-kall mottatt, operationName: $operationName")
-                    val personId = graphQLRequest.variables?.get("fnr") ?: graphQLRequest.variables?.get("aktorId")
-                    if (personId != null) auditLog(graphQLContext, operationName, personId as String)
                 } else if (!graphQLRequest.query.contains("query IntrospectionQuery"))
                     sikkerLogg.warn("GraphQL-kall uten navngitt query, bør fikses i kallende kode. Requesten:\n${graphQLRequest.query}")
             }
         }
         return super.executeRequest(graphQLRequest, graphQLContext)
     }
-
-    private fun auditLog(graphQLContext: GraphQLContext, operationName: String, personId: String) {
-        val saksbehandlerIdent = graphQLContext.get<String>(ContextValues.SAKSBEHANDLER_IDENT.key)
-        auditLog.info("end=${System.currentTimeMillis()} suid=$saksbehandlerIdent duid=$personId operation=$operationName")
-        sikkerLogg.debug("audit-logget, operationName: $operationName")
-    }
 }
diff --git a/spesialist-api/src/main/kotlin/no/nav/helse/spesialist/api/graphql/query/PersonQuery.kt b/spesialist-api/src/main/kotlin/no/nav/helse/spesialist/api/graphql/query/PersonQuery.kt
@@ -1,5 +1,6 @@
 package no.nav.helse.spesialist.api.graphql.query
 
+import graphql.GraphQLContext
 import graphql.GraphQLError
 import graphql.GraphqlErrorException
 import graphql.execution.DataFetcherResult
@@ -11,8 +12,10 @@ import kotlinx.coroutines.async
 import net.logstash.logback.argument.StructuredArguments.keyValue
 import no.nav.helse.spesialist.api.Avviksvurderinghenter
 import no.nav.helse.spesialist.api.arbeidsgiver.ArbeidsgiverApiDao
+import no.nav.helse.spesialist.api.auditLogTeller
 import no.nav.helse.spesialist.api.egenAnsatt.EgenAnsattApiDao
 import no.nav.helse.spesialist.api.erDev
+import no.nav.helse.spesialist.api.graphql.ContextValues
 import no.nav.helse.spesialist.api.graphql.schema.Person
 import no.nav.helse.spesialist.api.graphql.schema.Reservasjon
 import no.nav.helse.spesialist.api.notat.NotatDao
@@ -51,13 +54,20 @@ class PersonQuery(
 ) : AbstractPersonQuery(personApiDao, egenAnsattApiDao) {
 
     private val sikkerLogg: Logger = LoggerFactory.getLogger("tjenestekall")
+    private val auditLog = LoggerFactory.getLogger("auditLogger")
 
-    suspend fun person(fnr: String? = null, aktorId: String? = null, env: DataFetchingEnvironment): DataFetcherResult<Person?> {
+    suspend fun person(
+        fnr: String? = null,
+        aktorId: String? = null,
+        env: DataFetchingEnvironment,
+    ): DataFetcherResult<Person?> {
         if (fnr == null) {
             if (aktorId == null)
-                return DataFetcherResult.newResult<Person?>().error(getBadRequestError("Requesten mangler både fødselsnummer og aktørId")).build()
+                return DataFetcherResult.newResult<Person?>()
+                    .error(getBadRequestError("Requesten mangler både fødselsnummer og aktørId")).build()
             if (aktorId.length != 13) {
-                return DataFetcherResult.newResult<Person?>().error(getBadRequestError("Feil lengde på parameter aktorId: ${aktorId.length}")).build()
+                return DataFetcherResult.newResult<Person?>()
+                    .error(getBadRequestError("Feil lengde på parameter aktorId: ${aktorId.length}")).build()
             }
         }
 
@@ -68,24 +78,28 @@ class PersonQuery(
                     personApiDao.finnFødselsnummer(it.toLong())
                 } catch (e: Exception) {
                     val fødselsnumre = personApiDao.finnFødselsnumre(aktorId.toLong()).toSet()
+                    auditLog(env.graphQlContext, aktorId, null, getFlereFødselsnumreError(fødselsnumre).message)
                     return DataFetcherResult.newResult<Person?>().error(getFlereFødselsnumreError(fødselsnumre)).build()
                 }
             }
         if (fødselsnummer == null || (!erDev() && !personApiDao.spesialistHarPersonKlarForVisningISpeil(fødselsnummer))) {
             sikkerLogg.info("Svarer not found for parametere fnr=$fnr, aktorId=$aktorId.")
+            auditLog(env.graphQlContext, fnr ?: aktorId!!, null, getNotFoundError(fnr).message)
             return DataFetcherResult.newResult<Person?>().error(getNotFoundError(fnr)).build()
         }
 
         val reservasjon = finnReservasjonsstatus(fødselsnummer)
 
         if (isForbidden(fødselsnummer, env)) {
+            auditLog(env.graphQlContext, fødselsnummer, false, null)
             return DataFetcherResult.newResult<Person?>().error(getForbiddenError(fødselsnummer)).build()
         }
 
         val snapshot = try {
             snapshotMediator.hentSnapshot(fødselsnummer)
         } catch (e: Exception) {
             sikkerLogg.error("feilet under henting av snapshot for {}", keyValue("fnr", fødselsnummer), e)
+            auditLog(env.graphQlContext, fødselsnummer, null, getSnapshotValidationError().message)
             return DataFetcherResult.newResult<Person?>().error(getSnapshotValidationError()).build()
         }
 
@@ -111,8 +125,10 @@ class PersonQuery(
         }
 
         return if (person == null) {
+            auditLog(env.graphQlContext, fødselsnummer, true, getNotFoundError(fødselsnummer).message)
             DataFetcherResult.newResult<Person?>().error(getNotFoundError(fødselsnummer)).build()
         } else {
+            auditLog(env.graphQlContext, fødselsnummer, true, null)
             DataFetcherResult.newResult<Person?>().data(person).build()
         }
     }
@@ -123,15 +139,16 @@ class PersonQuery(
             reservasjonClient.hentReservasjonsstatus(fødselsnummer)
         }
 
-    private fun getFlereFødselsnumreError(fødselsnumre: Set<String>): GraphQLError = GraphqlErrorException.newErrorException()
-        .message("Mer enn ett fødselsnummer for personen")
-        .extensions(
-            mapOf(
-                "code" to 500,
-                "feilkode" to "HarFlereFodselsnumre",
-                "fodselsnumre" to fødselsnumre,
-            )
-        ).build()
+    private fun getFlereFødselsnumreError(fødselsnumre: Set<String>): GraphQLError =
+        GraphqlErrorException.newErrorException()
+            .message("Mer enn ett fødselsnummer for personen")
+            .extensions(
+                mapOf(
+                    "code" to 500,
+                    "feilkode" to "HarFlereFodselsnumre",
+                    "fodselsnumre" to fødselsnumre,
+                )
+            ).build()
 
     private fun getSnapshotValidationError(): GraphQLError = GraphqlErrorException.newErrorException()
         .message("Lagret snapshot stemmer ikke overens med forventet format. Dette kommer som regel av at noen har gjort endringer på formatet men glemt å bumpe versjonsnummeret.")
@@ -143,4 +160,17 @@ class PersonQuery(
         .extensions(mapOf("code" to 400))
         .build()
 
+    private fun auditLog(graphQLContext: GraphQLContext, personId: String, harTilgang: Boolean?, fantIkkePersonErrorMsg: String?) {
+        val saksbehandlerIdent = graphQLContext.get<String>(ContextValues.SAKSBEHANDLER_IDENT.key)
+        auditLogTeller.inc()
+
+        if (harTilgang == false) {
+            auditLog.warn("end=${System.currentTimeMillis()} suid=$saksbehandlerIdent duid=$personId operation=PersonQuery flexString1=Deny")
+        } else if (fantIkkePersonErrorMsg != null) {
+            auditLog.warn("end=${System.currentTimeMillis()} suid=$saksbehandlerIdent duid=$personId operation=PersonQuery msg=$fantIkkePersonErrorMsg")
+        } else {
+            auditLog.info("end=${System.currentTimeMillis()} suid=$saksbehandlerIdent duid=$personId operation=PersonQuery")
+        }
+        sikkerLogg.debug("audit-logget, operationName: PersonQuery, harTilgang: $harTilgang, fantIkkePersonErrorMsg: $fantIkkePersonErrorMsg")
+    }
 }
diff --git a/spesialist-api/src/test/kotlin/no/nav/helse/spesialist/api/graphql/query/PersonQueryTest.kt b/spesialist-api/src/test/kotlin/no/nav/helse/spesialist/api/graphql/query/PersonQueryTest.kt
@@ -1,5 +1,9 @@
 package no.nav.helse.spesialist.api.graphql.query
 
+import ch.qos.logback.classic.Level
+import ch.qos.logback.classic.Logger
+import ch.qos.logback.classic.spi.ILoggingEvent
+import ch.qos.logback.core.read.ListAppender
 import com.fasterxml.jackson.databind.JsonNode
 import com.fasterxml.jackson.databind.node.ObjectNode
 import com.fasterxml.jackson.module.kotlin.convertValue
@@ -24,10 +28,10 @@ import org.junit.jupiter.api.Assertions.assertNotNull
 import org.junit.jupiter.api.Assertions.assertTrue
 import org.junit.jupiter.api.Test
 import org.junit.jupiter.api.TestInstance
+import org.slf4j.LoggerFactory
 
 @TestInstance(TestInstance.Lifecycle.PER_CLASS)
 internal class PersonQueryTest : AbstractGraphQLApiTest() {
-
     @AfterEach
     fun clean() {
         clearMocks(snapshotClient, egenAnsattApiDao)
@@ -36,11 +40,13 @@ internal class PersonQueryTest : AbstractGraphQLApiTest() {
     @Test
     fun `henter person`() {
         mockSnapshot()
+        val logglytter = opprettLogglytter()
         opprettVedtaksperiode(opprettPerson(), opprettArbeidsgiver())
 
         val body = runQuery("""{ person(fnr: "$FØDSELSNUMMER") { aktorId } }""")
 
         assertEquals(AKTØRID, body["data"]["person"]["aktorId"].asText())
+        assertEquals(1, logglytter.list.filter { it.message.contains("suid=${SAKSBEHANDLER.ident} duid=$FØDSELSNUMMER operation=PersonQuery") && it.level == Level.INFO }.size)
     }
 
     @Test
@@ -61,40 +67,48 @@ internal class PersonQueryTest : AbstractGraphQLApiTest() {
 
     @Test
     fun `får 404-feil når personen man søker etter ikke finnes`() {
+        val logglytter = opprettLogglytter()
         val body = runQuery("""{ person(fnr: "$FØDSELSNUMMER") { aktorId } }""")
 
         assertEquals(404, body["errors"].first()["extensions"]["code"].asInt())
+        assertEquals(1, logglytter.list.filter { it.message.contains("suid=${SAKSBEHANDLER.ident} duid=$FØDSELSNUMMER operation=PersonQuery msg=Finner ikke data for person med fødselsnummer $FØDSELSNUMMER") && it.level == Level.WARN }.size)
     }
 
     @Test
     fun `får personens fødselsnummer-identer når hen har flere`() {
         val dNummer = "41017012345"
         opprettPerson(fødselsnummer = dNummer, aktørId = AKTØRID)
         opprettVedtaksperiode(opprettPerson(fødselsnummer = FØDSELSNUMMER, aktørId = AKTØRID), opprettArbeidsgiver())
+        val logglytter = opprettLogglytter()
         val body = runQuery("""{ person(aktorId: "$AKTØRID") { fodselsnummer } }""")
 
         val extensions = body["errors"].first()["extensions"]
         assertEquals(500, extensions["code"].asInt())
         assertEquals(setOf(dNummer, FØDSELSNUMMER), extensions["fodselsnumre"].map(JsonNode::asText).toSet())
+        assertEquals(1, logglytter.list.filter { it.message.contains("suid=${SAKSBEHANDLER.ident} duid=$AKTØRID operation=PersonQuery msg=Mer enn ett fødselsnummer for personen") && it.level == Level.WARN }.size)
     }
 
     @Test
     fun `kan slå opp kode7-personer med riktige tilganger`() {
         mockSnapshot()
         opprettVedtaksperiode(opprettPerson(adressebeskyttelse = Adressebeskyttelse.Fortrolig), opprettArbeidsgiver())
 
+        val logglytter = opprettLogglytter()
         val body = runQuery("""{ person(fnr: "$FØDSELSNUMMER") { aktorId } }""", kode7Saksbehandlergruppe)
 
         assertEquals(AKTØRID, body["data"]["person"]["aktorId"].asText())
+        assertEquals(1, logglytter.list.filter { it.message.contains("suid=${SAKSBEHANDLER.ident} duid=$FØDSELSNUMMER") && it.level == Level.INFO }.size)
     }
 
     @Test
     fun `får 403-feil ved oppslag av kode7-personer uten riktige tilganger`() {
         opprettVedtaksperiode(opprettPerson(adressebeskyttelse = Adressebeskyttelse.Fortrolig), opprettArbeidsgiver())
 
+        val logglytter = opprettLogglytter()
         val body = runQuery("""{ person(fnr: "$FØDSELSNUMMER") { aktorId } }""")
 
         assertEquals(403, body["errors"].first()["extensions"]["code"].asInt())
+        assertEquals(1, logglytter.list.filter { it.message.contains("suid=${SAKSBEHANDLER.ident} duid=$FØDSELSNUMMER operation=PersonQuery flexString1=Deny") && it.level == Level.WARN }.size)
     }
 
     @Test
@@ -103,29 +117,35 @@ internal class PersonQueryTest : AbstractGraphQLApiTest() {
         every { egenAnsattApiDao.erEgenAnsatt(FØDSELSNUMMER) } returns true
         opprettVedtaksperiode(opprettPerson(), opprettArbeidsgiver())
 
+        val logglytter = opprettLogglytter()
         val body = runQuery("""{ person(fnr: "$FØDSELSNUMMER") { aktorId } }""", skjermedePersonerGruppeId)
 
         assertEquals(AKTØRID, body["data"]["person"]["aktorId"].asText())
+        assertEquals(1, logglytter.list.filter { it.message.contains("suid=${SAKSBEHANDLER.ident} duid=$FØDSELSNUMMER operation=PersonQuery") && it.level == Level.INFO }.size)
     }
 
     @Test
     fun `får 403-feil ved oppslag av skjermede personer`() {
         every { egenAnsattApiDao.erEgenAnsatt(FØDSELSNUMMER) } returns true
         opprettVedtaksperiode(opprettPerson(), opprettArbeidsgiver())
 
+        val logglytter = opprettLogglytter()
         val body = runQuery("""{ person(fnr: "$FØDSELSNUMMER") { aktorId } }""")
 
         assertEquals(403, body["errors"].first()["extensions"]["code"].asInt())
+        assertEquals(1, logglytter.list.filter { it.message.contains("suid=${SAKSBEHANDLER.ident} duid=$FØDSELSNUMMER operation=PersonQuery flexString1=Deny") && it.level == Level.WARN }.size)
     }
 
     @Test
     fun `får 501-feil når oppdatering av snapshot feiler`() {
         every { snapshotClient.hentSnapshot(FØDSELSNUMMER) } throws GraphQLException("Oops")
         opprettVedtaksperiode(opprettPerson(), opprettArbeidsgiver())
 
+        val logglytter = opprettLogglytter()
         val body = runQuery("""{ person(fnr: "$FØDSELSNUMMER") { aktorId } }""")
 
         assertEquals(501, body["errors"].first()["extensions"]["code"].asInt())
+        assertEquals(1, logglytter.list.filter { it.message.contains("suid=${SAKSBEHANDLER.ident} duid=$FØDSELSNUMMER operation=PersonQuery msg=Lagret snapshot stemmer ikke overens med forventet format. Dette kommer som regel av at noen har gjort endringer på formatet men glemt å bumpe versjonsnummeret.") && it.level == Level.WARN }.size)
     }
 
     @Test
@@ -372,4 +392,9 @@ internal class PersonQueryTest : AbstractGraphQLApiTest() {
     )
     private fun Periode.tilBeregnetPeriode(): GraphQLBeregnetPeriode =
         opprettBeregnetPeriode(fom.toString(), tom.toString(), id)
+
+    private fun opprettLogglytter() = ListAppender<ILoggingEvent>().apply {
+        (LoggerFactory.getLogger("auditLogger") as Logger).addAppender(this)
+        start()
+    }
 }
diff --git a/spesialist-selve/src/main/kotlin/no/nav/helse/ApplicationBuilder.kt b/spesialist-selve/src/main/kotlin/no/nav/helse/ApplicationBuilder.kt
@@ -12,19 +12,14 @@ import io.ktor.http.HttpStatusCode
 import io.ktor.serialization.jackson.JacksonConverter
 import io.ktor.server.application.Application
 import io.ktor.server.application.ApplicationCall
-import io.ktor.server.application.ApplicationCallPipeline
-import io.ktor.server.application.call
 import io.ktor.server.application.install
 import io.ktor.server.auth.authenticate
-import io.ktor.server.auth.jwt.JWTPrincipal
-import io.ktor.server.auth.principal
 import io.ktor.server.plugins.callid.CallId
 import io.ktor.server.plugins.callid.callIdMdc
 import io.ktor.server.plugins.callloging.CallLogging
 import io.ktor.server.plugins.cors.routing.CORS
 import io.ktor.server.plugins.doublereceive.DoubleReceive
 import io.ktor.server.plugins.statuspages.StatusPages
-import io.ktor.server.request.header
 import io.ktor.server.request.httpMethod
 import io.ktor.server.request.path
 import io.ktor.server.request.uri
@@ -46,8 +41,8 @@ import no.nav.helse.db.TotrinnsvurderingDao
 import no.nav.helse.mediator.BehandlingsstatistikkMediator
 import no.nav.helse.mediator.GodkjenningMediator
 import no.nav.helse.mediator.GodkjenningService
-import no.nav.helse.mediator.MeldingMediator
 import no.nav.helse.mediator.Kommandofabrikk
+import no.nav.helse.mediator.MeldingMediator
 import no.nav.helse.mediator.SaksbehandlerMediator
 import no.nav.helse.mediator.TilgangskontrollørForReservasjon
 import no.nav.helse.mediator.dokument.DokumentMediator
@@ -104,10 +99,8 @@ import kotlin.random.Random.Default.nextInt
 import io.ktor.server.plugins.contentnegotiation.ContentNegotiation as ContentNegotiationServer
 import no.nav.helse.spesialist.api.tildeling.TildelingDao as TildelingApiDao
 
-private val auditLog = LoggerFactory.getLogger("auditLogger")
 private val logg = LoggerFactory.getLogger("ApplicationBuilder")
 private val sikkerlogg = LoggerFactory.getLogger("tjenestekall")
-private val personIdRegex = "\\d{11,13}".toRegex()
 
 internal class ApplicationBuilder(env: Map<String, String>) : RapidsConnection.StatusListener {
     private val dataSourceBuilder = DataSourceBuilder(env)
@@ -310,22 +303,6 @@ internal class ApplicationBuilder(env: Map<String, String>) : RapidsConnection.S
                 filter { call -> call.request.path().startsWith("/api/") }
             }
             install(DoubleReceive)
-            intercept(ApplicationCallPipeline.Call) {
-                call.principal<JWTPrincipal>()?.let { principal ->
-                    val uri = call.request.uri
-                    val navIdent = principal.payload.getClaim("NAVident").asString()
-                    (personIdRegex.find(uri)?.value ?: call.request.header("fodselsnummer"))?.also { personId ->
-                        auditLog.info(
-                            "end=${System.currentTimeMillis()} suid=$navIdent duid=$personId request=${
-                                uri.substring(
-                                    0,
-                                    uri.length.coerceAtMost(70)
-                                )
-                            }"
-                        )
-                    }
-                }
-            }
             install(ContentNegotiationServer) { register(ContentType.Application.Json, JacksonConverter(objectMapper)) }
             requestResponseTracing(httpTraceLog)
             azureAdAppAuthentication(azureAdAppConfig)

diff --git a/spesialist-selve/src/test/kotlin/no/nav/helse/e2e/OverstyringE2ETest.kt b/spesialist-selve/src/test/kotlin/no/nav/helse/e2e/OverstyringE2ETest.kt
@@ -14,6 +14,7 @@ import no.nav.helse.januar
 import no.nav.helse.spesialist.api.SaksbehandlerTilganger
 import no.nav.helse.spesialist.api.arbeidsgiver.ArbeidsgiverApiDao
 import no.nav.helse.spesialist.api.egenAnsatt.EgenAnsattApiDao
+import no.nav.helse.spesialist.api.graphql.ContextValues
 import no.nav.helse.spesialist.api.graphql.query.PersonQuery
 import no.nav.helse.spesialist.api.graphql.schema.Arbeidsforholdoverstyring
 import no.nav.helse.spesialist.api.graphql.schema.Dagoverstyring
@@ -154,6 +155,7 @@ internal class OverstyringE2ETest : AbstractE2ETest() {
         håndterOverstyrArbeidsforhold()
 
         every { dataFetchingEnvironment.graphQlContext.get<String>("saksbehandlerNavn") } returns "saksbehandler"
+        every { dataFetchingEnvironment.graphQlContext.get<String>(ContextValues.SAKSBEHANDLER_IDENT.key) } returns "A123456"
         every { dataFetchingEnvironment.graphQlContext.get<SaksbehandlerTilganger>("tilganger") } returns SAKSBEHANDLERTILGANGER_UTEN_TILGANGER
 
         val nyUtbetalingId = UUID.randomUUID()