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/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 {

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"
+}

backend/src/main/kotlin/org/loculus/backend/controller/SubmissionController.kt

@@ -33,13 +33,17 @@ 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
 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<T>,
     ) = 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)
     }
 }

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)
+        }
+    }
+}

backend/src/main/resources/logback.xml

@@ -1,6 +1,6 @@
 <configuration>
 
-    <property name="PATTERN" value="%date %level [%thread] [%X{organism}] - %class: %message%n"/>
+    <property name="PATTERN" value="%date %level [%thread] [%X{RequestId}] [%X{organism}] - %class: %message%n"/>
 
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
         <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">

backend/src/test/resources/logback-test.xml

@@ -1,7 +1,7 @@
 <configuration>
     <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
         <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
-            <Pattern>%date %level [%thread] [%X{organism}] - %class: %message%n</Pattern>
+            <Pattern>%date %level [%thread] [%X{RequestId}] [%X{organism}] - %class: %message%n</Pattern>
         </encoder>
     </appender>
 

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"
         )

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<typeof backendApi> {
-    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');
     }
 

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<typeof groupManagementApi> {
-    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,

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<typeof seqSetCitationApi> {
-    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,

website/src/services/zodiosWrapperClient.ts

@@ -65,11 +65,18 @@ export class ZodiosWrapperClient<Api extends ZodiosEndpointDefinitions> {
 
         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<Api extends ZodiosEndpointDefinitions> {
                 };
             }
 
-            this.logger.info(`${message}: ${problemDetailResponse.detail}`);
+            this.logger.info(`${requestId}${message}: ${problemDetailResponse.detail}`);
             return problemDetailResponse;
         }
 

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<BaseClient | undefined> {
         if (this._keycloakClient !== undefined) {