From 6eb836612d04070930e7e8bb0df10db401bd8c58 Mon Sep 17 00:00:00 2001 From: Fabian Engelniederhammer <92720311+fengelniederhammer@users.noreply.github.com> Date: Mon, 28 Oct 2024 10:02:29 +0100 Subject: [PATCH] 1072 implement request ids to trace errors (#3005) * feat(backend): add x-request-id header to trace requests across artifacts in logs resolves #1072 * fix(website): use singleton instance of logger and with correct names * chore(website,preprocessing): also log request ids when calling the backend --- .../backend/config/BackendSpringConfig.kt | 36 ++++++++++++++ .../controller/LoculusCustomHeaders.kt | 6 +++ .../controller/SubmissionController.kt | 16 +++++-- .../org/loculus/backend/log/RequestId.kt | 47 +++++++++++++++++++ backend/src/main/resources/logback.xml | 2 +- backend/src/test/resources/logback-test.xml | 2 +- .../src/loculus_preprocessing/backend.py | 5 +- website/src/services/backendClient.ts | 7 ++- website/src/services/groupManagementClient.ts | 7 ++- website/src/services/seqSetCitationClient.ts | 9 ++-- website/src/services/zodiosWrapperClient.ts | 11 ++++- website/src/utils/KeycloakClientManager.ts | 6 ++- 12 files changed, 130 insertions(+), 24 deletions(-) create mode 100644 backend/src/main/kotlin/org/loculus/backend/controller/LoculusCustomHeaders.kt create mode 100644 backend/src/main/kotlin/org/loculus/backend/log/RequestId.kt diff --git a/backend/src/main/kotlin/org/loculus/backend/config/BackendSpringConfig.kt b/backend/src/main/kotlin/org/loculus/backend/config/BackendSpringConfig.kt index 0071c904c..11cc2b0d5 100644 --- a/backend/src/main/kotlin/org/loculus/backend/config/BackendSpringConfig.kt +++ b/backend/src/main/kotlin/org/loculus/backend/config/BackendSpringConfig.kt @@ -2,10 +2,16 @@ package org.loculus.backend.config import com.fasterxml.jackson.databind.ObjectMapper import com.fasterxml.jackson.module.kotlin.readValue +import io.swagger.v3.oas.models.headers.Header +import io.swagger.v3.oas.models.media.StringSchema +import io.swagger.v3.oas.models.parameters.HeaderParameter import org.flywaydb.core.Flyway import org.jetbrains.exposed.spring.autoconfigure.ExposedAutoConfiguration import org.jetbrains.exposed.sql.DatabaseConfig import org.jetbrains.exposed.sql.Slf4jSqlDebugLogger +import org.loculus.backend.controller.LoculusCustomHeaders +import org.loculus.backend.log.REQUEST_ID_HEADER_DESCRIPTION +import org.springdoc.core.customizers.OperationCustomizer import org.springframework.beans.factory.annotation.Value import org.springframework.boot.autoconfigure.ImportAutoConfiguration import org.springframework.boot.autoconfigure.jdbc.DataSourceTransactionManagerAutoConfiguration @@ -76,6 +82,36 @@ class BackendSpringConfig { @Bean fun openApi(backendConfig: BackendConfig) = buildOpenApiSchema(backendConfig) + + @Bean + fun headerCustomizer() = OperationCustomizer { operation, _ -> + val foundRequestIdHeaderParameter = operation.parameters?.any { it.name == LoculusCustomHeaders.REQUEST_ID } + if (foundRequestIdHeaderParameter == false || foundRequestIdHeaderParameter == null) { + operation.addParametersItem( + HeaderParameter().apply { + name = LoculusCustomHeaders.REQUEST_ID + required = false + example = "1747481c-816c-4b60-af20-a61717a35067" + description = REQUEST_ID_HEADER_DESCRIPTION + schema = StringSchema() + }, + ) + } + for ((_, response) in operation.responses) { + if (response.headers == null || !response.headers.containsKey(LoculusCustomHeaders.REQUEST_ID)) { + response.addHeaderObject( + LoculusCustomHeaders.REQUEST_ID, + Header().apply { + description = REQUEST_ID_HEADER_DESCRIPTION + required = false + example = "1747481c-816c-4b60-af20-a61717a35067" + schema = StringSchema() + }, + ) + } + } + operation + } } fun readBackendConfig(objectMapper: ObjectMapper, configPath: String): BackendConfig { diff --git a/backend/src/main/kotlin/org/loculus/backend/controller/LoculusCustomHeaders.kt b/backend/src/main/kotlin/org/loculus/backend/controller/LoculusCustomHeaders.kt new file mode 100644 index 000000000..daa714508 --- /dev/null +++ b/backend/src/main/kotlin/org/loculus/backend/controller/LoculusCustomHeaders.kt @@ -0,0 +1,6 @@ +package org.loculus.backend.controller + +object LoculusCustomHeaders { + const val REQUEST_ID = "x-request-id" + const val X_TOTAL_RECORDS = "x-total-records" +} diff --git a/backend/src/main/kotlin/org/loculus/backend/controller/SubmissionController.kt b/backend/src/main/kotlin/org/loculus/backend/controller/SubmissionController.kt index 6a7dab09c..46546faa2 100644 --- a/backend/src/main/kotlin/org/loculus/backend/controller/SubmissionController.kt +++ b/backend/src/main/kotlin/org/loculus/backend/controller/SubmissionController.kt @@ -33,6 +33,9 @@ import org.loculus.backend.api.UnprocessedData import org.loculus.backend.api.WarningsFilter import org.loculus.backend.auth.AuthenticatedUser import org.loculus.backend.auth.HiddenParam +import org.loculus.backend.controller.LoculusCustomHeaders.X_TOTAL_RECORDS +import org.loculus.backend.log.REQUEST_ID_MDC_KEY +import org.loculus.backend.log.RequestIdContext import org.loculus.backend.model.RELEASED_DATA_RELATED_TABLES import org.loculus.backend.model.ReleasedDataModel import org.loculus.backend.model.SubmissionParams @@ -40,6 +43,7 @@ import org.loculus.backend.model.SubmitModel import org.loculus.backend.service.submission.SubmissionDatabaseService import org.loculus.backend.utils.Accession import org.loculus.backend.utils.IteratorStreamer +import org.slf4j.MDC import org.springframework.http.HttpHeaders import org.springframework.http.HttpStatus import org.springframework.http.MediaType @@ -71,6 +75,7 @@ open class SubmissionController( private val releasedDataModel: ReleasedDataModel, private val submissionDatabaseService: SubmissionDatabaseService, private val iteratorStreamer: IteratorStreamer, + private val requestIdContext: RequestIdContext, ) { @Operation(description = SUBMIT_DESCRIPTION) @@ -259,7 +264,7 @@ open class SubmissionController( ], headers = [ Header( - name = "x-total-records", + name = X_TOTAL_RECORDS, description = "The total number of records sent in responseBody", schema = Schema(type = "integer"), ), @@ -297,7 +302,7 @@ open class SubmissionController( compression?.let { headers.add(HttpHeaders.CONTENT_ENCODING, it.compressionName) } val totalRecords = submissionDatabaseService.countReleasedSubmissions(organism) - headers.add("x-total-records", totalRecords.toString()) + headers.add(X_TOTAL_RECORDS, totalRecords.toString()) // TODO(https://github.com/loculus-project/loculus/issues/2778) // There's a possibility that the totalRecords change between the count and the actual query // this is not too bad, if the client ends up with a few more records than expected @@ -369,7 +374,7 @@ open class SubmissionController( description = GET_ORIGINAL_METADATA_RESPONSE_DESCRIPTION, headers = [ Header( - name = "x-total-records", + name = X_TOTAL_RECORDS, description = "The total number of records sent in responseBody", schema = Schema(type = "integer"), ), @@ -411,7 +416,7 @@ open class SubmissionController( groupIdsFilter?.takeIf { it.isNotEmpty() }, statusesFilter?.takeIf { it.isNotEmpty() }, ) - headers.add("x-total-records", totalRecords.toString()) + headers.add(X_TOTAL_RECORDS, totalRecords.toString()) // TODO(https://github.com/loculus-project/loculus/issues/2778) // There's a possibility that the totalRecords change between the count and the actual query // this is not too bad, if the client ends up with a few more records than expected @@ -476,6 +481,8 @@ open class SubmissionController( compressionFormat: CompressionFormat? = null, sequenceProvider: () -> Sequence, ) = StreamingResponseBody { responseBodyStream -> + MDC.put(REQUEST_ID_MDC_KEY, requestIdContext.requestId) + val outputStream = when (compressionFormat) { CompressionFormat.ZSTD -> ZstdCompressorOutputStream(responseBodyStream) null -> responseBodyStream @@ -493,5 +500,6 @@ open class SubmissionController( } } } + MDC.remove(REQUEST_ID_MDC_KEY) } } diff --git a/backend/src/main/kotlin/org/loculus/backend/log/RequestId.kt b/backend/src/main/kotlin/org/loculus/backend/log/RequestId.kt new file mode 100644 index 000000000..9fd2229bc --- /dev/null +++ b/backend/src/main/kotlin/org/loculus/backend/log/RequestId.kt @@ -0,0 +1,47 @@ +package org.loculus.backend.log + +import jakarta.servlet.FilterChain +import jakarta.servlet.http.HttpServletRequest +import jakarta.servlet.http.HttpServletResponse +import org.loculus.backend.controller.LoculusCustomHeaders.REQUEST_ID +import org.slf4j.MDC +import org.springframework.core.annotation.Order +import org.springframework.stereotype.Component +import org.springframework.web.context.annotation.RequestScope +import org.springframework.web.filter.OncePerRequestFilter +import java.util.UUID + +@Component +@RequestScope +class RequestIdContext { + var requestId: String? = null +} + +const val REQUEST_ID_MDC_KEY = "RequestId" +private const val HIGH_PRECEDENCE_BUT_LOW_ENOUGH_TO_HAVE_REQUEST_SCOPE_AVAILABLE = -100 +const val REQUEST_ID_HEADER_DESCRIPTION = """ +A UUID that uniquely identifies the request for tracing purposes. +If none is provided in the request, the backend will generate one. +""" + +@Component +@Order(HIGH_PRECEDENCE_BUT_LOW_ENOUGH_TO_HAVE_REQUEST_SCOPE_AVAILABLE) +class RequestIdFilter(private val requestIdContext: RequestIdContext) : OncePerRequestFilter() { + override fun doFilterInternal( + request: HttpServletRequest, + response: HttpServletResponse, + filterChain: FilterChain, + ) { + val requestId = request.getHeader(REQUEST_ID) ?: UUID.randomUUID().toString() + + MDC.put(REQUEST_ID_MDC_KEY, requestId) + requestIdContext.requestId = requestId + response.addHeader(REQUEST_ID, requestId) + + try { + filterChain.doFilter(request, response) + } finally { + MDC.remove(REQUEST_ID_MDC_KEY) + } + } +} diff --git a/backend/src/main/resources/logback.xml b/backend/src/main/resources/logback.xml index 95e727928..752185d68 100644 --- a/backend/src/main/resources/logback.xml +++ b/backend/src/main/resources/logback.xml @@ -1,6 +1,6 @@ - + diff --git a/backend/src/test/resources/logback-test.xml b/backend/src/test/resources/logback-test.xml index 51979572c..5b60a899a 100644 --- a/backend/src/test/resources/logback-test.xml +++ b/backend/src/test/resources/logback-test.xml @@ -1,7 +1,7 @@ - %date %level [%thread] [%X{organism}] - %class: %message%n + %date %level [%thread] [%X{RequestId}] [%X{organism}] - %class: %message%n diff --git a/preprocessing/nextclade/src/loculus_preprocessing/backend.py b/preprocessing/nextclade/src/loculus_preprocessing/backend.py index a407a9eb5..1811db78b 100644 --- a/preprocessing/nextclade/src/loculus_preprocessing/backend.py +++ b/preprocessing/nextclade/src/loculus_preprocessing/backend.py @@ -103,6 +103,8 @@ def fetch_unprocessed_sequences( } logging.debug(f"Requesting data with ETag: {etag}") response = requests.post(url, data=params, headers=headers, timeout=10) + logging.info( + f"Unprocessed data from backend: status code {response.status_code}, request id: {response.headers.get('x-request-id')}") match response.status_code: case HTTPStatus.NOT_MODIFIED: return etag, None @@ -140,7 +142,8 @@ def submit_processed_sequences( if not response.ok: Path("failed_submission.json").write_text(ndjson_string, encoding="utf-8") msg = ( - f"Submitting processed data failed. Status code: {response.status_code}\n" + f"Submitting processed data failed. Status code: {response.status_code}, " + f"request id: {response.headers.get('x-request-id')}\n" f"Response: {response.text}\n" f"Data sent: {ndjson_string[:1000]}...\n" ) diff --git a/website/src/services/backendClient.ts b/website/src/services/backendClient.ts index 56306d428..2658525a1 100644 --- a/website/src/services/backendClient.ts +++ b/website/src/services/backendClient.ts @@ -4,11 +4,10 @@ import { getRuntimeConfig } from '../config.ts'; import { getInstanceLogger } from '../logger.ts'; import { createAuthorizationHeader } from '../utils/createAuthorizationHeader.ts'; +const myLogger = getInstanceLogger('BackendClient'); + export class BackendClient extends ZodiosWrapperClient { - public static create( - backendUrl: string = getRuntimeConfig().serverSide.backendUrl, - logger = getInstanceLogger('serverSideBackendClient'), - ) { + public static create(backendUrl: string = getRuntimeConfig().serverSide.backendUrl, logger = myLogger) { return new BackendClient(backendUrl, backendApi, (axiosError) => axiosError.data, logger, 'backend'); } diff --git a/website/src/services/groupManagementClient.ts b/website/src/services/groupManagementClient.ts index 4fdc2cc29..2679aa4a6 100644 --- a/website/src/services/groupManagementClient.ts +++ b/website/src/services/groupManagementClient.ts @@ -5,11 +5,10 @@ import { getInstanceLogger } from '../logger.ts'; import type { NewGroup } from '../types/backend.ts'; import { createAuthorizationHeader } from '../utils/createAuthorizationHeader.ts'; +const instanceLogger = getInstanceLogger('GroupManagementClient'); + export class GroupManagementClient extends ZodiosWrapperClient { - public static create( - backendUrl: string = getRuntimeConfig().serverSide.backendUrl, - logger = getInstanceLogger('serverSideBackendClient'), - ) { + public static create(backendUrl: string = getRuntimeConfig().serverSide.backendUrl, logger = instanceLogger) { return new GroupManagementClient( backendUrl, groupManagementApi, diff --git a/website/src/services/seqSetCitationClient.ts b/website/src/services/seqSetCitationClient.ts index ab3865670..58c3562cf 100644 --- a/website/src/services/seqSetCitationClient.ts +++ b/website/src/services/seqSetCitationClient.ts @@ -1,14 +1,13 @@ import { seqSetCitationApi } from './seqSetCitationApi.ts'; import { ZodiosWrapperClient } from './zodiosWrapperClient.ts'; import { getRuntimeConfig } from '../config.ts'; -import { getInstanceLogger } from '../logger.ts'; +import { getInstanceLogger, type InstanceLogger } from '../logger.ts'; import { createAuthorizationHeader } from '../utils/createAuthorizationHeader.ts'; +const myLogger: InstanceLogger = getInstanceLogger('SeqSetCitationClient'); + export class SeqSetCitationClient extends ZodiosWrapperClient { - public static create( - backendUrl: string = getRuntimeConfig().serverSide.backendUrl, - logger = getInstanceLogger('serverSideBackendClient'), - ) { + public static create(backendUrl: string = getRuntimeConfig().serverSide.backendUrl, logger = myLogger) { return new SeqSetCitationClient( backendUrl, seqSetCitationApi, diff --git a/website/src/services/zodiosWrapperClient.ts b/website/src/services/zodiosWrapperClient.ts index e83213399..dee2bbc22 100644 --- a/website/src/services/zodiosWrapperClient.ts +++ b/website/src/services/zodiosWrapperClient.ts @@ -65,11 +65,18 @@ export class ZodiosWrapperClient { const message = error.message; if (error.response !== undefined) { + const requestId = + error.response.headers['x-request-id'] !== undefined + ? `(request id ${error.response.headers['x-request-id']}) ` + : ''; + let problemDetailResponse; try { problemDetailResponse = problemDetail.parse(this.tryToExtractProblemDetail(error.response)); } catch (e) { - this.logger.error(`Unknown error from ${this.serviceName}: ${JSON.stringify(error.response.data)}`); + this.logger.error( + `Unknown error from ${this.serviceName} ${requestId}: ${JSON.stringify(error.response.data)}`, + ); return { type: 'about:blank', title: error.message, @@ -79,7 +86,7 @@ export class ZodiosWrapperClient { }; } - this.logger.info(`${message}: ${problemDetailResponse.detail}`); + this.logger.info(`${requestId}${message}: ${problemDetailResponse.detail}`); return problemDetailResponse; } diff --git a/website/src/utils/KeycloakClientManager.ts b/website/src/utils/KeycloakClientManager.ts index b36358251..ffdd6d59d 100644 --- a/website/src/utils/KeycloakClientManager.ts +++ b/website/src/utils/KeycloakClientManager.ts @@ -1,13 +1,15 @@ import { type BaseClient, Issuer } from 'openid-client'; +import { getClientMetadata } from './clientMetadata.ts'; import { realmPath } from './realmPath.ts'; import { getRuntimeConfig } from '../config.ts'; import { getInstanceLogger } from '../logger.ts'; -import { getClientMetadata } from '../utils/clientMetadata.ts'; + +const instanceLogger = getInstanceLogger('KeycloakClientManager'); export class KeycloakClientManager { private static _keycloakClient: BaseClient | undefined; - private static readonly logger = getInstanceLogger('LoginMiddleware'); // Assuming getInstanceLogger is available + private static readonly logger = instanceLogger; public static async getClient(): Promise { if (this._keycloakClient !== undefined) {