Skip to content

Commit

Permalink
Logging Metadata (#52)
Browse files Browse the repository at this point in the history
* Add metadata

* Change argument order so metadata comes before throwable

* Micro-optimizations around atomics/locking
  • Loading branch information
cedrickcooke authored Apr 16, 2021
1 parent 0e576bf commit 9599f56
Show file tree
Hide file tree
Showing 17 changed files with 303 additions and 126 deletions.
72 changes: 42 additions & 30 deletions logging/api/logging.api
Original file line number Diff line number Diff line change
@@ -1,11 +1,11 @@
public final class com/juul/tuulbox/logging/ConsoleLogger : com/juul/tuulbox/logging/Logger {
public static final field INSTANCE Lcom/juul/tuulbox/logging/ConsoleLogger;
public fun assert (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun debug (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun error (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun info (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun verbose (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun warn (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun assert (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public fun debug (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public fun error (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public fun info (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public fun verbose (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public fun warn (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
}

public final class com/juul/tuulbox/logging/ConstantTagGenerator : com/juul/tuulbox/logging/TagGenerator {
Expand All @@ -15,45 +15,57 @@ public final class com/juul/tuulbox/logging/ConstantTagGenerator : com/juul/tuul

public final class com/juul/tuulbox/logging/DispatchLogger : com/juul/tuulbox/logging/Logger {
public fun <init> ()V
public fun assert (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun assert (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public final fun clear ()V
public fun debug (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun error (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun info (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun debug (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public fun error (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public fun info (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public final fun install (Lcom/juul/tuulbox/logging/Logger;)V
public fun verbose (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun warn (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public fun verbose (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public fun warn (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
}

public abstract interface class com/juul/tuulbox/logging/Key {
}

public final class com/juul/tuulbox/logging/Log {
public static final field INSTANCE Lcom/juul/tuulbox/logging/Log;
public final fun assert (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;)V
public static synthetic fun assert$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;ILjava/lang/Object;)V
public final fun debug (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;)V
public static synthetic fun debug$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;ILjava/lang/Object;)V
public final fun error (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;)V
public static synthetic fun error$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;ILjava/lang/Object;)V
public final fun assert (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;)V
public static synthetic fun assert$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;ILjava/lang/Object;)V
public final fun debug (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;)V
public static synthetic fun debug$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;ILjava/lang/Object;)V
public final fun error (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;)V
public static synthetic fun error$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;ILjava/lang/Object;)V
public final fun getDispatcher ()Lcom/juul/tuulbox/logging/DispatchLogger;
public final fun getTagGenerator ()Lcom/juul/tuulbox/logging/TagGenerator;
public final fun info (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;)V
public static synthetic fun info$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;ILjava/lang/Object;)V
public final fun info (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;)V
public static synthetic fun info$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;ILjava/lang/Object;)V
public final fun setTagGenerator (Lcom/juul/tuulbox/logging/TagGenerator;)V
public final fun verbose (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;)V
public static synthetic fun verbose$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;ILjava/lang/Object;)V
public final fun warn (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;)V
public static synthetic fun warn$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function0;ILjava/lang/Object;)V
public final fun verbose (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;)V
public static synthetic fun verbose$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;ILjava/lang/Object;)V
public final fun warn (Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;)V
public static synthetic fun warn$default (Lcom/juul/tuulbox/logging/Log;Ljava/lang/Throwable;Ljava/lang/String;Lkotlin/jvm/functions/Function1;ILjava/lang/Object;)V
}

public abstract interface class com/juul/tuulbox/logging/Logger {
public abstract fun assert (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public abstract fun debug (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public abstract fun error (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public abstract fun info (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public abstract fun verbose (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public abstract fun warn (Ljava/lang/String;Ljava/lang/String;Ljava/lang/Throwable;)V
public abstract fun assert (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public abstract fun debug (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public abstract fun error (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public abstract fun info (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public abstract fun verbose (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
public abstract fun warn (Ljava/lang/String;Ljava/lang/String;Lcom/juul/tuulbox/logging/ReadMetadata;Ljava/lang/Throwable;)V
}

public abstract interface class com/juul/tuulbox/logging/ReadMetadata {
public abstract fun copy ()Lcom/juul/tuulbox/logging/ReadMetadata;
public abstract fun get (Lcom/juul/tuulbox/logging/Key;)Ljava/lang/Object;
}

public abstract interface class com/juul/tuulbox/logging/TagGenerator {
public abstract fun getTag ()Ljava/lang/String;
}

public abstract interface class com/juul/tuulbox/logging/WriteMetadata {
public abstract fun set (Lcom/juul/tuulbox/logging/Key;Ljava/lang/Object;)V
}

28 changes: 14 additions & 14 deletions logging/src/commonMain/kotlin/DispatchLogger.kt
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
package com.juul.tuulbox.logging

import kotlinx.atomicfu.atomic
import kotlinx.atomicfu.getAndUpdate
import kotlinx.atomicfu.update

/** Implementation of [Logger] which dispatches calls to consumer [Logger]s. */
public class DispatchLogger : Logger {
Expand All @@ -13,35 +13,35 @@ public class DispatchLogger : Logger {

/** Add a consumer to receive future dispatch calls. */
public fun install(consumer: Logger) {
consumers.getAndUpdate { it + consumer }
consumers.update { it + consumer }
}

/** Uninstall all installed consumers. */
public fun clear() {
consumers.value = emptySet()
}

override fun verbose(tag: String, message: String, throwable: Throwable?) {
consumers.value.forEach { it.verbose(tag, message, throwable) }
override fun verbose(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?) {
consumers.value.forEach { it.verbose(tag, message, metadata, throwable) }
}

override fun debug(tag: String, message: String, throwable: Throwable?) {
consumers.value.forEach { it.debug(tag, message, throwable) }
override fun debug(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?) {
consumers.value.forEach { it.debug(tag, message, metadata, throwable) }
}

override fun info(tag: String, message: String, throwable: Throwable?) {
consumers.value.forEach { it.info(tag, message, throwable) }
override fun info(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?) {
consumers.value.forEach { it.info(tag, message, metadata, throwable) }
}

override fun warn(tag: String, message: String, throwable: Throwable?) {
consumers.value.forEach { it.warn(tag, message, throwable) }
override fun warn(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?) {
consumers.value.forEach { it.warn(tag, message, metadata, throwable) }
}

override fun error(tag: String, message: String, throwable: Throwable?) {
consumers.value.forEach { it.error(tag, message, throwable) }
override fun error(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?) {
consumers.value.forEach { it.error(tag, message, metadata, throwable) }
}

override fun assert(tag: String, message: String, throwable: Throwable?) {
consumers.value.forEach { it.assert(tag, message, throwable) }
override fun assert(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?) {
consumers.value.forEach { it.assert(tag, message, metadata, throwable) }
}
}
7 changes: 7 additions & 0 deletions logging/src/commonMain/kotlin/Key.kt
Original file line number Diff line number Diff line change
@@ -0,0 +1,7 @@
package com.juul.tuulbox.logging

/**
* Marker interface to strongly type metadata with its key. Proper usage is
* to create `object`s or `enum class`es when implementing this type.
*/
public interface Key<T : Any>
47 changes: 35 additions & 12 deletions logging/src/commonMain/kotlin/Log.kt
Original file line number Diff line number Diff line change
@@ -1,6 +1,11 @@
package com.juul.tuulbox.logging

import com.juul.tuulbox.logging.Log.dispatcher
import kotlinx.atomicfu.atomic
import kotlin.native.concurrent.ThreadLocal

@ThreadLocal // Thread local pool means that metadata returned from it are safe to mutate on that same thread.
private val metadataPool = Pool(factory = ::Metadata, refurbish = Metadata::clear)

/** Global logging object. To receive logs, call [dispatcher].[install][DispatchLogger.install]. */
public object Log {
Expand All @@ -18,44 +23,62 @@ public object Log {
}

/** Send a verbose-level log message to the global dispatcher. */
public fun verbose(throwable: Throwable? = null, tag: String? = null, message: () -> String) {
public fun verbose(throwable: Throwable? = null, tag: String? = null, message: (WriteMetadata) -> String) {
if (dispatcher.hasConsumers) {
dispatcher.verbose(tag ?: tagGenerator.getTag(), message.invoke(), throwable)
val metadata = metadataPool.borrow()
val body = message(metadata)
dispatcher.verbose(tag ?: tagGenerator.getTag(), body, metadata, throwable)
metadataPool.recycle(metadata)
}
}

/** Send a debug-level log message to the global dispatcher. */
public fun debug(throwable: Throwable? = null, tag: String? = null, message: () -> String) {
public fun debug(throwable: Throwable? = null, tag: String? = null, message: (WriteMetadata) -> String) {
if (dispatcher.hasConsumers) {
dispatcher.debug(tag ?: tagGenerator.getTag(), message.invoke(), throwable)
val metadata = metadataPool.borrow()
val body = message(metadata)
dispatcher.debug(tag ?: tagGenerator.getTag(), body, metadata, throwable)
metadataPool.recycle(metadata)
}
}

/** Send an info-level log message to the global dispatcher. */
public fun info(throwable: Throwable? = null, tag: String? = null, message: () -> String) {
public fun info(throwable: Throwable? = null, tag: String? = null, message: (WriteMetadata) -> String) {
if (dispatcher.hasConsumers) {
dispatcher.info(tag ?: tagGenerator.getTag(), message.invoke(), throwable)
val metadata = metadataPool.borrow()
val body = message(metadata)
dispatcher.info(tag ?: tagGenerator.getTag(), body, metadata, throwable)
metadataPool.recycle(metadata)
}
}

/** Send an warn-level log message to the global dispatcher. */
public fun warn(throwable: Throwable? = null, tag: String? = null, message: () -> String) {
public fun warn(throwable: Throwable? = null, tag: String? = null, message: (WriteMetadata) -> String) {
if (dispatcher.hasConsumers) {
dispatcher.warn(tag ?: tagGenerator.getTag(), message.invoke(), throwable)
val metadata = metadataPool.borrow()
val body = message(metadata)
dispatcher.warn(tag ?: tagGenerator.getTag(), body, metadata, throwable)
metadataPool.recycle(metadata)
}
}

/** Send an error-level log message to the global dispatcher. */
public fun error(throwable: Throwable? = null, tag: String? = null, message: () -> String) {
public fun error(throwable: Throwable? = null, tag: String? = null, message: (WriteMetadata) -> String) {
if (dispatcher.hasConsumers) {
dispatcher.error(tag ?: tagGenerator.getTag(), message.invoke(), throwable)
val metadata = metadataPool.borrow()
val body = message(metadata)
dispatcher.error(tag ?: tagGenerator.getTag(), body, metadata, throwable)
metadataPool.recycle(metadata)
}
}

/** Send an assert-level log message to the global dispatcher. */
public fun assert(throwable: Throwable? = null, tag: String? = null, message: () -> String) {
public fun assert(throwable: Throwable? = null, tag: String? = null, message: (WriteMetadata) -> String) {
if (dispatcher.hasConsumers) {
dispatcher.assert(tag ?: tagGenerator.getTag(), message.invoke(), throwable)
val metadata = metadataPool.borrow()
val body = message(metadata)
dispatcher.assert(tag ?: tagGenerator.getTag(), body, metadata, throwable)
metadataPool.recycle(metadata)
}
}
}
24 changes: 12 additions & 12 deletions logging/src/commonMain/kotlin/Logger.kt
Original file line number Diff line number Diff line change
Expand Up @@ -3,21 +3,21 @@ package com.juul.tuulbox.logging
/** Classes which implement [Logger] can write logs. */
public interface Logger {

/** Log at verbose-level. */
public fun verbose(tag: String, message: String, throwable: Throwable?)
/** Log at verbose-level. Do not store a reference to [metadata], create a [copy][ReadMetadata.copy] if you need to. */
public fun verbose(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?)

/** Log at debug-level. */
public fun debug(tag: String, message: String, throwable: Throwable?)
/** Log at debug-level. Do not store a reference to [metadata], create a [copy][ReadMetadata.copy] if you need to. */
public fun debug(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?)

/** Log at info-level. */
public fun info(tag: String, message: String, throwable: Throwable?)
/** Log at info-level. Do not store a reference to [metadata], create a [copy][ReadMetadata.copy] if you need to. */
public fun info(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?)

/** Log at warn-level. */
public fun warn(tag: String, message: String, throwable: Throwable?)
/** Log at warn-level. Do not store a reference to [metadata], create a [copy][ReadMetadata.copy] if you need to. */
public fun warn(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?)

/** Log at error-level. */
public fun error(tag: String, message: String, throwable: Throwable?)
/** Log at error-level. Do not store a reference to [metadata], create a [copy][ReadMetadata.copy] if you need to. */
public fun error(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?)

/** Log at assert-level. */
public fun assert(tag: String, message: String, throwable: Throwable?)
/** Log at assert-level. Do not store a reference to [metadata], create a [copy][ReadMetadata.copy] if you need to. */
public fun assert(tag: String, message: String, metadata: ReadMetadata, throwable: Throwable?)
}
42 changes: 42 additions & 0 deletions logging/src/commonMain/kotlin/Metadata.kt
Original file line number Diff line number Diff line change
@@ -0,0 +1,42 @@
package com.juul.tuulbox.logging

internal class Metadata : ReadMetadata, WriteMetadata {
private val storedData = mutableMapOf<Key<*>, Any>()

@Suppress("UNCHECKED_CAST")
public override operator fun <T : Any> get(key: Key<T>): T? =
storedData[key] as? T

public override operator fun <T : Any> set(key: Key<T>, value: T) {
storedData[key] = value
}

public override fun copy(): Metadata = Metadata().also { copy ->
copy.storedData += this.storedData
}

internal fun clear() {
storedData.clear()
}

override fun equals(other: Any?): Boolean = other is Metadata && storedData == other.storedData
override fun hashCode(): Int = storedData.hashCode()
}

/**
* Additional data associated with a log. It's important that [Logger] instances do NOT hold onto references
* to [ReadMetadata] arguments after the function returns. If a [ReadMetadata] reference must be kept after
* function return, create a [copy].
*/
public interface ReadMetadata {
public operator fun <T : Any> get(key: Key<T>): T?
public fun copy(): ReadMetadata
}

/**
* Additional data associated with a log. It's important that [Log] calls do NOT hold onto references
* to [WriteMetadata] arguments after the lambda returns.
*/
public interface WriteMetadata {
public operator fun <T : Any> set(key: Key<T>, value: T)
}
19 changes: 19 additions & 0 deletions logging/src/commonMain/kotlin/Pool.kt
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@
package com.juul.tuulbox.logging

import kotlinx.atomicfu.locks.reentrantLock
import kotlinx.atomicfu.locks.withLock

/** While a [Pool] is logically thread safe, Kotlin/Native's memory model requires @ThreadLocal on instances of this. */
internal class Pool<T>(
private val factory: () -> T,
private val refurbish: (T) -> Unit,
) {
private val lock = reentrantLock()
private val cache = ArrayDeque<T>()

fun borrow(): T = lock.withLock { cache.removeLastOrNull() } ?: factory()
fun recycle(value: T) {
refurbish(value)
lock.withLock { cache.addLast(value) }
}
}
3 changes: 2 additions & 1 deletion logging/src/commonTest/kotlin/Call.kt
Original file line number Diff line number Diff line change
Expand Up @@ -3,5 +3,6 @@ package com.juul.tuulbox.logging
data class Call(
val tag: String,
val message: String,
val throwable: Throwable?
val throwable: Throwable?,
val metadata: ReadMetadata
)
Loading

0 comments on commit 9599f56

Please sign in to comment.