Alert: Legacy Services calls & request tracing

When viewing requests that require authenticating through Legacy Services, as is the case with Launchpad tokens, request tracing will appear to be broken. This is because CMR calls Legacy Services very early in the request flow, but Legacy Services does not accept the "Request Id" header, so the assigned request ID is lost.

This code is found at cmr.transmit.echo.tokens/get-user-id and is slated to be replaced by a call to the URS API instead, in PI 23.1.


Current Request Tracing in Common Metadata Repository

Ingest Request Flow Sequence Diagram

Note: we use structured logging for request tracing. Do not confuse with OpenTelemetry-style request tracing.

"Structured logging" means that all logs generated from the same initial request will be prepended by the same request ID. The request ID is set at the initial request, either taken from the "X-Request-Id" header, "Cmr-Request-Id" header, or autogenerated (as an alphanumeric string taking this form: 6d27cb3f-f95d-41ba-ba29-642ef923cbd9). Services external to CMR typically will have already set a request ID so that it is possible to link request flow between CMR and other services.

Note that in those cases where the request flow is not initiated by an HTTP request but rather as a result of a queue message or other asynchronous event processing, the request ID will take the form async-thread-<#>. One example can be seen in the diagram above: ingesting a new concept is initiated via HTTP request, assigned an autogenerated request ID which remains the same in the logs for common-lib and metadata-db as well as ingest's final logs, but metadata-db also publishes a message which asynchronously triggers indexing the new concept into Elasticsearch, causing indexer's logs (as well as the metadata-db logs that result from indexing) to carry a different request ID.

There are preliminary plans to change this design in the particular case of indexing a newly ingested concept, so that the resulting indexer and metadata-db logs match the same request ID originally assigned at initial ingest.

In order to see a list of all CMR request IDs by log group in splunk, you can use this splunk search query: log_group=cmr* request_guid=*-*-*-* | stats list(request_guid), list(log_group) by log_group

CMR code mechanics

The way that the CMR code accomplishes assigning, tracking, and logging request ID is as follows:

  • For the microservices ingest, search, metadata-db, indexer, bootstrap, access-control, virtual-product, and common-lib, one of the ring handlers used is build-request-context-handler.
  • This handler cmr.common.api.context/build-request-context-handler accomplishes two things: it builds a request-context by parsing header information (or generates one) and makes that available, and it attaches log/with-request-id.
  • cmr.common.log/with-request-id is a macro which simply adds a binding for the dynamic var *request-id*
  • In cmr.common.log you can also see that the logger is configured to use thread name if *request-id* is not defined. (thus the async-thread-<#> results)
  • No labels