LoggerMetadata values are restricted to Strings

[jordanebelanger]

https://github.com/apple/swift-log/blob/b33865f66bc32553ff5366506f3cad1f704f0a13/Sources/Logging/Logging.swift#L291-L303 Constraining the raw values of the Logger's metadata to strings is fine for syslog style log entries, but some logging platforms support metadata values constrained to more than just strings.

Notably, GCP Stackdriver logging with google-fluentd allows you to record your log entries as JSON, see: https://cloud.google.com/logging/docs/agent/configuration#streaming_logs_from_additional_inputs

A log entry appended to a log file using this type of logging looks like '{"code": 1001, "message": "This is a log from the log file at test-structured-log.log", "isBool": true }'

For this to work as intended for this particular cases, the logger metadata values would need to properly translate to all json raw values, i.e null, bool, number and string.

As of right now, a LogHandler could certainly be created for GCP stackdriver JSON format logging with the raw values being restricted to String only, but that would be a subpar solution that stops the Stackdriver platform from reaching its full potential.

It seems like addressing this, if desired, would incur significant breaking changes to swift-log, but given that some server side framework like Vapor 4 are about to make swift-log defacto, I think it's worth giving a thought :)

[ktoso]

Hello there, firstly: I absolutely share your enthusiasm for structured logging :-)

To put some context before we dive to solutions though, this API had (and still has) as its first and prime objective to get a shared baseline minimum API that libraries and systems can use to log "to the same target (handler)." As such, and in order to gain adoption, it feels quite similar to existing APIs from the Swift ecosystem; What it brings to the table is using the same types and being able to share common log handlers -- which is the main benefit really.

This also implies that it can not be too opinionated, e.g.

• we cannot force everyone to adopt structured logging "only", if they like and are totally happy with normal log statements;
• we can however accommodate such patterns, as really the main benefit of this entire API project is that there is one handler backend installed for a given system, and all your logs can end up in the same place, be it a file or stackdriver.

---

Now back to the question about to carry structured logging in the existing structure:

I believe this is covered already, as this was the one of the reasons we introduced stringConvertible metadata value type (the other one being "delaying rendering of large payloads"), as now you can "smuggle" any kind of value to the underlying log handler, and it MAY inspect and do whichever it wants with those metadata values;

If you implemented a log handler that handles e.g. a "_payload" metadata value, you can go many ways about it; See comments in-line which discuss the implementation tradeoffs.

Example:

struct SomeData: Encodable {
    let code: Int
    let message: String
    let isBool: Bool
}

extension SomeData: CustomStringConvertible {
    // option a) you could have your types do the rendering in the description; their repr is then consistent everywhere, likely okey idea
    var description: String {
        let encoder = JSONEncoder()
        let data = try! encoder.encode(self)
        return String(data: data, encoding: .utf8)!
    }

    // option b) you could do a normal description impl here, but "know" that your log handler actually handles
    // `Encodable` types and would serialize it to e.g. JSON when shipping off to wherever... this implies knowing specifics
    // of the LogHandler -- which is _fine_ for an application, but is _not_ for libraries or this API package.
}

func example(log: Logger) {
    // the core capability exists:
    log.info("", metadata: ["_payload": .stringConvertible(SomeData(code: 1001, message: "This is a log", isBool: false))])

    // a backend library could absolutely ship with a LogHandler that only takes into account the "_payload" (!)
    // it OR end users could also easily provide APIs which are like:

    // or even:
    log.structured(.info, structured)

    // or even:
    log.structured(structured)

    // the main benefit of using the same logging api is that _all libraries_ you are using are using that backend too,
    // so even if those libs are not doing proper nice semantic logging, you can still ingest them along with your own logs.
}

extension Logger {
    func structured<StructuredPayload: CustomStringConvertible & Encodable>(_ level: Logger.Level, _ structured: StructuredPayload) {
        self.log(level: level, "", metadata: ["_payload": .stringConvertible(structured)])
    }

    func structured<StructuredPayload: CustomStringConvertible & Encodable>(_ structured: StructuredPayload) {
        self.log(level: .info, "", metadata: ["_payload": .stringConvertible(structured)])
    }
}

So, as for:

As of right now, a LogHandler could certainly be created for GCP stackdriver JSON format logging with the raw values being restricted to String only, but that would be a subpar solution that stops the Stackdriver platform from reaching its full potential.

I do not think we values are really restricted to just strings, thanks to the above escape hatch. And I'd be really thrilled to see such logging backends to start appearing -- also since myself would like to go towards structured logging with my libraries, and if we could agree e.g. that such payloads should be put into e.g. _payload or some other metadata field, we could start from there and build an ecosystem round it and if (and only if) needed provide more API extensions.

What I would suggest is:

• implement a logging backend library that supports such structured logging,
• adopt the Logging API in a way that it can consume any "normal" libraries logging to it (since you'd still want those logs from libraries, even if they never heard of structured logging),
  • this also makes it generally useful, I'm sure people would love to see a stackdriver logging backend
• well document, and perhaps also try to document the "name" we use to carry the "this is the structured metadata" so other libraries which may want to participate are able to do so

WDYT?

[jordanebelanger]

Thanks for the extensive reply.

I see your point with using StringConvertible, I thought about that before but decided against it since atm Vapor 3's Request's does not have a specific logger property which means the logger has to be explicitly instantiated beforehand which meant you could instantiate something more custom and have that custom logger interface be visible. Vapor 3's also wasn't compatible with swift-log due to name clashes.

Vapor 4's Request now has a swift-log Logger property so things are different.

I wouldn't necessarily go with a custom structured calls in an extension as that might just be too unspecific to the base Logger interface and feel weird were we to somehow switch Logger down the road.

I will give a shot to just creating a log handler that attempts to unmangle the string convertible values upon entering a LogEntry, searching for JSON values and converting them back to a null, bool, number whenever possible before entry.

Keep you posted.

[ktoso]

Cool, looking forward to your findings. This isn’t to say there isn’t anything we could evolve here but I’m wondering if it really is necessary to change the APIs right now.

I will give a shot to just creating a log handler that attempts to unmangle the string convertible values upon entering a LogEntry, searching for JSON values and converting them back to a null, bool, number whenever possible before entry.

Could you clarify this a bit for me? I mean: whatever the values are, they end up as their string representations on the wire as we send the data to the whichever log collector collect stuff them... why would you need to “convert back to bool” anything (on one hand... they already are those raw values so why “back”, and secondly why convert anything this way when entering the log infra — can we not leave them untouched and only to-string them when we need to serialize?)

[jordanebelanger]

Could you clarify this a bit for me?

I was thinking about using JSONEncoder to convert the metadata to JSON which would've required unmangling, but actually if I were to use JSONSerialization the quick test code I made below actually works pretty damn good without having to unmangle.

struct StackDriverLogHandler: LogHandler {

    static private func unpackMetadata(_ value: Logger.MetadataValue) -> Any {
        switch value {
        case .string(let value):
            return value
        case .stringConvertible(let value):
            return value
        case .array(let value):
            return value.map { StackDriverLogHandler.unpackMetadata($0) }
        case .dictionary(let value):
            return value.mapValues { StackDriverLogHandler.unpackMetadata($0) }
        }
    }

    func log(level: Logger.Level, message: Logger.Message, metadata: Logger.Metadata?, file: String, function: String, line: UInt) {
        var entryMetadata: Logger.Metadata?
        if let parameterMetadata = metadata, !parameterMetadata.isEmpty {
            /// Merging both metadata dictionary, giving precendence to the parameter metadata during collisions.
            entryMetadata = self.metadata.merging(parameterMetadata) { $1 }
        } else if !self.metadata.isEmpty {
            entryMetadata = self.metadata
        }

        var json: [String: Any] = [
            "message": message.description,
        ]
        if let entryMetadata = entryMetadata {
            json["metadata"] = StackDriverLogHandler.unpackMetadata(.dictionary(entryMetadata))
        }

        let data = try! JSONSerialization.data(withJSONObject: json, options: [])
        // Append the data to the end of a structured json log file
        // Profit
    }

[jordanebelanger]

@ktoso https://github.com/Brainfinance/StackdriverLogging 👌 😉