There are a few things we rely on services to do to make debugging and other contextual information of our services by ourselves and other teams (including non-development teams) easier. They fall into two buckets: tracing & authorization HTTP request headers propagation, and logging with contextual information.

Tracing HTTP request headers

In order to provide tracing information across services, which is then sent by services to a system like Jaeger, when any of the following HTTP headers are present on any request into a service, those header names and values should also sent on any outgoing HTTP requests from that service. See banno-propagation for Scala services and go-microservice/propagation for Go.

Authorization HTTP Request Headers

The node-api-gateway service at the edge populates authenticated user client information in the following headers. See node-api-gateway Upstream Headers documentation for more information on the content of the header values. They should be propagated so that further upstream services can use the contextual information as well. There are tools to help consume the X-BannoConsumer0 and X-BannoEnterprise0 headers and propagate the headers onto upstreams. For Scala see banno-propagation and for Go see go-microservice/propagation.

The headers below should no longer be in use for internal services auth, services should have switched to using the Authorization provided by the node-api-gateway. There are exceptions for services in support of the node-api-gateway authorization, that should be handled on a case by case basis. The following SHOULD NOT BE FORWARDED

Log Context Standards

In order to provide reliable information across services, when available the following information should be provided in standardized fields when logging.

Standards

Request Information

The below headers should be logged in the context values below if available when logging any message. See banno-propagation for Scala services and go-microservice/propagation for Go.

Institution Information

Consumer User Information

Organization Information

Enterprise User Information

Account Information

Notification / Alert Information

Conversations / Support Information

Logging with Context - Approaches

The logging aggregation picks up the logs as a Json object for each log. Nested objects are annotated by . in between the logs. So a minimal log would look like.

{
    "message": "My Message"
}

However generally more information is desired, as such utilizing a sane set of defaults such as exposed in the Static section below is recommended.

Static - Team Information using Logback

In addition to the dynamic fields described above, it can also be useful to log the team owning the service. For Scala services utilizing Logback, this can be statically added to the logback.xml for the application. Here is an example with team aviato. These are now added to every log made by the application automatically.

<configuration>
    <appender name="stdoutLogstash" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <customFields>
                {
                "app_name":"alerts-settings",
                "team": "aviato"
                }
            </customFields>
        </encoder>
    </appender>
</configuration>

Log4cats (Recommended for Scala services)

Log4cats for Scala has built-in utilities for this structured logging that is supported by backends. This can be achieve by either logging explicitly with the StructuredLogger or modifying the logger with additional information and then passing that along to log messages. This also allows referentially transparent logging to be the default.

import io.chrisdavenport.log4cats._

// Explicit Logging
def getUserInformation(logger: StructuredLogger[F], userId: String): F[Unit] = {
  logger.info(Map("banno.user.id" -> userId))("Starting to Get User Information") >>
    ??? // Whatever your operation is
}

// May not need to know about context information added to logs within
def getUserInformation2(logger: Logger[F]): F[Unit]

// Builds A Context and Passes a Logger which does not know about the Context Information
def getUserInformationWithContextModification(
  logger: StructuredLogger[F],
  userId: String): F[Unit] = getUserInformation2(
      StructuredLogger.withContext(iLogger)(Map("banno.user.id" -> userId))
  )

Log4s for Scala services

Log4s allows manual MDC manipulation via thread-locals and continuations on a scala.mutable.Map. Both are susceptible to issues with throwing, and assume you are the only caller with control over that thread which is not true in the case of concurrency.

import log4s._

private[this] val logger = getLogger
def doSomething(userId: String, requestId: String): Unit = {
    // Empty out the MDC for this thread
    MDC.clear

    /* *************************** */
    /* Set some context in the MDC */
    /* *************************** */

    // Set a single value
    MDC("banno.request.x_request_id") = requestId
    // Set multiple values
    MDC += ("banno.user.id" -> userId, "request-time" -> System.currentTimeMilli)

    // No need to put the request ID in the message: it's in the context
    logger.debug("Processing request")

    // Don't forget to defensively clear it for the next caller.
    MDC.clear

}

def doSomethingElse(userId: String, requestId: String): Unit = {
    // This context operates only for the block, then cleans itself up
    MDC.withCtx ("banno.request.x_request_id" -> requestId, "banno.user.id" -> userId) {
      logger.debug("Processing request")
    }
}

SLF4J for Scala services - CAUTION: This is very easy to get wrong by accident

Slf4j gives very little safety by default, it knows whether the logger is enabled/disabled and has the ability to log strings. The rest is in your hands.

import org.slf4j.{LoggerFactory, Logger, MDC}

// Clazz Reflection Named Access
val logger = LoggerFactory.getLogger(this)

def doSomething(userId: String, requestId: String): Unit = {
    if (logger.isEnabled){
        val backup = MDC.getCopyOfContextMap
        try {
            MDC.put("banno.request.x_request_id", userId)
            MDC.put("banno.user.id", userId)
            logger.debug("Doing Something")
        } finally {
            if (backup eq null) MDC.clear()
            else MDC.setContextMap(backup)
        }
    } else ()
}