Feature Review of meager-log

🠔 Back to Blog Index


id: 7b15be9b-c692-4fb8-9f0a-3223a5834b1c
tags: logging,scala,library

Recently, I have been reworking my logging library and am somewhat happy with the current implementation. I'm taking a moment to review some of the key concepts in play.

♯Table of Contents

♯What is meager-log?

meager-log is the name for the logging library I am currently implementing. It targets Scala 3 and relies on cats-effect and fs2 for the primary engine implementation. At a glance, it offers the following features:

  • All logging operations are expressed as effects.
  • Log messages must be audited.
  • First class support for key/value (audited) data.
  • Opt-in tagging for data entries.
  • Encryption and hashing of log data.
  • Exception message redaction.
  • Structured logs.
  • Application tracing.

The logging API looks like this:

trait Logger[F[_]]:
  def info(log: Log.Builder): F[Unit]

An example of a log call in practice might be:

def example[F[_]: Async: Trace](
  person: Person,
  logger: Logger[F]
): F[Unit] =
  logger.warn(
    log"Person is not eligible".data(
      key"id" -> person.id.safe,
      key"name" -> person.name.PII.hash,
      key"date_of_birth" -> person.dateOfBirth.PII.encrypt,
      key"ssn" -> person.ssn.SPI.hash
    )
  )

The remainder of this post explores the features and how they are expressed from a library user perspective.

♯All Logging Operations are Expressed as Effects

meager-log expresses logging operations as effects, and generally expects the caller to be leveraging some effect system such as cats-effect (the primary option supported) or zio. An Effect is a description of some computation, where that computation will occur only when the effect is evaluated.

As a side bar: if you aren't familiar with effect types and effect systems, the cats-effect documentation does a good job describing the basic concepts.

For the purposes of this post, effect types will be defined as F[_], a type constructor of one argument. We say that F[A] for some A is an effect describing a computation which either produces data of type A, or fails with an exception.

Connecting back to this library, a logging call looks like:

trait Logger[F[_]]:
  def info(log: Log.Builder): F[Unit]

Logging is an effect which does not return anything useful, and just performs some form of side-effecting action. This allows meager-log to fit very naturally into applications with effect systems at their core. This class of applications happens to be exactly what I typically write.

♯Log Messages Must be Audited

meager-log leverages Scala's type system to enforce an audit, by whoever writes the code, of all messages. Let's review the class definition:

opaque type LogMessage

object LogMessage:
  trait Syntax:
    extension (sc: StringContext)
      def log(args: LogData.Safe*): LogMessage = ???

By making the type definition an opaque type, we gain the performance benefit of treating it as a String at runtime without overhead. The only code we write, however, that understands it to be a String is within the companion object. This means that the only way to construct a LogMessage is to use the log String interpolator:

val message: LogMessage =
  log"Defining some ${a} log message ${b}"

In that example, a and b must be of type LogData.Safe, or the code will not compile. Any Loggable data type (Loggable is a type class provided by the library with implementations for all basic types) can be marked as "Safe". The mechanism to do this is to use extension methods for the type class:

val a: String = "foo"
val b: Int = 99

val message: LogMessage =
  log"Defining some ${a.safe} log message ${b.safe}"

Why is this useful?

If you deal with lots of sensitive information like PII, PHI, SPI, etc. you likely have encountered rules and restrictions around what can be logged and where it can be logged. Accidentally logging sensitive information in clear text can result in security incidents which require manual cleanup. Worse, a leak may go undetected and inadvertently broadcast sensitive information.

The implementation provided here forces whoever is writing the code to say "yes, this piece of data is safe to log in clear text." It also provides a way to audit the code in the future -- when paired with meager-log data definitions, every single logged piece of data must describe whether or not it's safe to log, and if not, whether it is hashed or encrypted before being written. Version control allows for another level of depth of analysis.

Note that meager-log has no way to determine if the code writer is wrong or has lied. However, simply refusing to compile until some explicit decision has been made moves the bar in the right direction.

♯First Class Support for Key/Value Data

As a general rule, meager-log discourages the use of complex messages with embedded data, and encourages using key/value data to raise the value of each log. Consider the following example:

logger.warn(
  log"Person with id ${person.id.safe}, name ${person.name.safe}, is not eligible because they were born on ${person.dob.safe}"
)

Compared against:

logger.warn(
  log"Person is not eligible due to an age violation".data(
    key"id" -> person.id.safe,
    key"name" -> person.name.hash,
    key"date_of_birth" -> person.dateOfBirth.encrypt
  )
)

The second example is what meager-log considers to be the superior representation. Rather than a single long string, there is a short, clear message with supporting contextual data. The log explicitly identifies an id, name and date of birth. These will be represented consistently rather than relying on how a given person chooses to call them out within a string. They can also be parsed by any log collector which supports the given structure (JSON).

Additionally, each piece of data must be audited, just like any data used within a message. Additional options such as hash and encrypt are available, and they can be used to safely log sensitive information by either hashing or encrypting it prior to writing the log. The emitted log, in this case, might look like:

{
  "lvl": "warn",
  "ts": "2023-02-21T03:26:52.797Z",
  "msg": "Person is not eligible due to an age violation",
  "data": {
    "id": 100,
    "name": "50d858e0985ecc7f60418aaf0cc5ab587f42c2570a884095a9e8ccacd0f6545c",
    "date_of_birth": "NTNmNGVkNTQ0MTllYmY1N2IxNzcyZjQ0NTQxZTcxNDg="
  }
}

By leveraging a hash for the name, support staff can search the logs by name if they have a tool which will hash candidate names for them. If someone debugging an issue needs the user's date of birth, they can decrypt it (if they have access to do so). Casual browsers of the logs know nothing about this user aside from its numeric identifier.

♯Opt-In Tagging for Data Entries

As part of the audit process, meager-log allows developers to tag their data. This is a code hint (no runtime impact) so that readers can understand categorization of (sensitive) data:

logger.warn(
  log"Person is not eligible".data(
    key"id" -> person.id.safe,
    key"name" -> person.name.PII.hash,
    key"date_of_birth" -> person.dateOfBirth.PII.encrypt,
    key"ssn" -> person.ssn.SPI.hash
  )
)

Casual inspection reveals two pieces of PII and one piece of SPI. While not an essential feature, tagging provides extra information and helps engineers not familiar with a particular domain learn more about their data.

♯Encryption and Hashing of Log Data

When specifying key/value data, that data can be safe, hash, or encrypt. In the first case, the data is safe for emitting in clear text. In the latter two cases, the logging engine will ensure the data is protected before writing it to a log.

Users may define their own hashing and encryption implementations by extending the LogHash and LogEncrypt traits respectively. meager-log also provides some default implementations based on the javax.crypto standard library.

♯Exception Message Redaction

Exceptions which are logged verbatim may inadvertently contain sensitive information. This could be a third party library exposing a password as part of an exception detailing a connection failure, or it could be an in-house exception which happens to dump a user object to string. These cases are usually difficult to detect.

It's worth mentioning that no redaction strategy will really solve this problem, but meager-log provides a mechanism to help identify errant cases. This mechanism (not yet implemented) is a simple regex match on each exception message, replacing it with a redaction string (such as <redacted>) if matched.

This feature should usually not be used! What it provides is (a) a quick fix for known bad cases, and (b) a way to defensively audit suspect code bases. This feature introduces overhead to logging and is a bandaid, at best.

♯Structured Logs

The default output format for meager-log is JSON, and this library assumes that logs have a well-defined structure. While a "plain text" renderer can be defined, meager-log deliberately does not provide one out of the box.

♯Application Tracing

Tracing in the spirit of OpenTelemetry is extremely powerful, and being able to correlate logs to a particular trace is part of that power. meager-log provides flexible support for tracing information which can be specified manually, or automatically determined by the selected implementation. This library will provide support for natchez out of the box. Manual specification is performed while building the log:

logger.info(
  log"Example".data(key"x" -> "y".safe).trace(
    LogTrace.Telemetry(
      traceId = "0e4bcb49825944f5b9c2ab7212e2e595",
      spanId = "1594fd570665"
    )
  )
)

♯Library Status

meager-log is a library with multiple revisions, including one, non-published revision proving the concept with a complete working engine and deployed as part of long-running applications. The public-intended version is currently in my public Git account and close to replacing the main branch with a major revision that establishes the final data model and improves organization overall.

While I would like to provide a concrete timeline for this project, incredibly limited time makes that difficult to do. If all goes well, I expect the end of Q2, 2023 to contain the first public release. The volume of work is not incredibly high, but working for small (30m, etc.) bursts of time tends to heavily reduce my output, so I'm keeping my expectations low.