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.