API Logging and Instrumentation

sequenceDiagram
    participant Client
    participant OpenTelemetryMiddleware
    participant WiskErrorMiddleware
    participant JWTMiddleware
    participant ExecutionTimeMiddleware
    participant BusinessLogic

    Client->>+OpenTelemetryMiddleware: Add trace_id to request
    OpenTelemetryMiddleware->>+WiskErrorMiddleware: Wrap for error handling
    WiskErrorMiddleware->>+JWTMiddleware: Check JWT Auth
    JWTMiddleware->>+ExecutionTimeMiddleware: Log execution time
    ExecutionTimeMiddleware->>+BusinessLogic: Process Request
    BusinessLogic->>+ExecutionTimeMiddleware: Response
    ExecutionTimeMiddleware->>+JWTMiddleware: 
    JWTMiddleware->>+WiskErrorMiddleware: 
    WiskErrorMiddleware->>+OpenTelemetryMiddleware: Response

    Note over OpenTelemetryMiddleware: Adds the OpenTelemetry Span Id
    Note over WiskErrorMiddleware: Puts the error in the response
    Note over JWTMiddleware: JWT authentication middleware<br/>Verifies client identity using JWT
    Note over ExecutionTimeMiddleware: Execution time middleware<br/>Measures request and response processing time

OpenTelemetry Middleware

Example of the payload

{
  "type": "api_incoming",
  "request_method": "GET/POST/PUT/DELETE",
  "url": "/authenticate",
  "body": {
    "email": "..."
  }
}

It will also add the trace_id and trace_url to the response headers

response.headers.add(name: "trace_id", value: WiskTracer.currentTraceId)
response.headers.add(name: "trace_url", value: "https://console.cloud.google.com/traces/list?project=\(Configuration.googleCloudProjectName.name)&tid=\(WiskTracer.currentTraceId)")

WiskErrorMiddleware

It’s the middleware that handles the errors specific to Wisk
It does 2 things:

• It logs the error and sends it to the Google Cloud Logs Here is an example

  req.logger.report(error: error,
  metadata: [
      "@type": "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent",
      "trace_id": .stringConvertible(WiskTracer.currentTraceId),
      "type": "error",
      "error": .stringConvertible(wiskErrorMessage),
      "instance_uuid": .stringConvertible(Configuration.instanceUuid),
      "request_url": .stringConvertible(req.url.string),
      "request_method": .stringConvertible(req.method.string),
      "venue_id": .stringConvertible(venueId ?? 0),
      "body": .dictionary(req.postBodyJSONValue.dictionaryObjectValue.mapValues { value -> Logger.MetadataValue in
          .stringConvertible(String(describing: value))
      }),
  ])
  

• it also sends the error in the response to the client ```swift let errorResponse = ErrorResponse( code: code, errorCode: errorCode, status: “error”, reason: reason, message: localizedReason, info: info, isBusinessError: isBusinessError )

# JWTMiddleware
It validates the JWT token and logs the user id in the request metadata.  
Also makes sure that the `user_id` and `venue_id` are added to the request metadata

# ExecutionTimeMiddleware

Before the API is executed, it logs the request and the start time
```swift
request.logger.info("wisk_api: received a request at \(startTime.iso8601) for \(requestUrl)",
    metadata: [
        "trace_id": .stringConvertible(WiskTracer.currentTraceId),
        "request_uuid": .stringConvertible(request.requestId),
        "instance_uuid": .stringConvertible(Configuration.instanceUuid),
        "request_url": .stringConvertible(requestUrl),
        "request_method": .stringConvertible(request.method.string),
        "venue_id": .stringConvertible(request.venueIdValue),
        "user_id": .stringConvertible(request.userIdValue),
        "start_time": .stringConvertible(startTime)
    ])

then it passes the request to the API

let response = try await next.respond(to: request).get()

next it logs the response and the end time

request.logger.info("wisk_api_performance: at \(Date().iso8601) prepared a response \(requestUrl) in \(duration) seconds for request started at \(startTime.iso8601)",
    metadata: [
        "request_uuid": .stringConvertible(requestUuid),
        "instance_uuid": .stringConvertible(Configuration.instanceUuid),
        "type": "performance",
        "request_url": .stringConvertible(requestUrl),
        "request_method": .stringConvertible(requestMethod),
        "venue_id": .stringConvertible(venueId),
        "duration": .stringConvertible(duration),
        "start_time": .stringConvertible(startTime),
        "end_time": .stringConvertible(endTime),
        "trace_id": .stringConvertible(WiskTracer.currentTraceId),
    ])

This is also the middleware that logs the Wisk Errors:

WiskLogger.logger.error("wisk_error: at \(Date().iso8601) prepared a response \(requestUrl) in \(duration) seconds for request started at \(startTime.iso8601)",
    metadata: [
        "@type": "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent",
        "trace_id": .stringConvertible(WiskTracer.currentTraceId),
        "type": "error",
        "error": .stringConvertible(wiskErrorMessage),
        "instance_uuid": .stringConvertible(Configuration.instanceUuid),
        "request_url": .stringConvertible(requestUrl),
        "request_method": .stringConvertible(request.method.rawValue),
        "venue_id": .stringConvertible(venueId),
        "user_id": .stringConvertible(userId),
        "duration": .stringConvertible(duration),
        "start_time": .stringConvertible(startTime),
        "end_time": .stringConvertible(endTime),
        "body": .dictionary(request.postBodyJSON?.dictionaryObjectValue.mapValues { value -> Logger.MetadataValue in
            let stringConvertible: Logger.MetadataValue = .stringConvertible(String(describing: value))
            return stringConvertible
        } ?? [:]),
    ])