Logging.kt

src/jvmMain/kotlin/afield/ai/diagnostics/Logging.kt · 429 lines · cited by Logging: channels, sinks and the console

package afield.ai.diagnostics

import afield.ai.conversation.AiToastPolicy
import afield.app.notifications.notify
import java.nio.charset.StandardCharsets
import java.nio.file.Files
import java.nio.file.Path
import java.nio.file.Paths
import java.nio.file.StandardOpenOption
import java.time.Instant
import java.util.concurrent.CopyOnWriteArrayList
import java.util.UUID
import kotlin.contracts.ExperimentalContracts
import kotlin.contracts.InvocationKind
import kotlin.contracts.contract

The channel-tagged log events the AI tooling writes, and the sinks that receive them.

A LogEvent carries a channel (a comma-separated set of tags such as info,ai.toolio), a message, and optional block indent and boundary markers. LogDispatcher fans each event out to every installed LogSink; LogDispatcher.withSink attaches one for the length of a block.

Sinks

• StdoutLog — prints to the terminal, skipping channels muted by ConsoleMute.
• NotifyLog — prints like StdoutLog and also raises a clipped, de-duplicated toast.
• SilentLog — drops everything.

ChannelMatch is the rule all channel selectors share: a selector matches when each of its tags is among the channel's.

File traces

TraceLogger appends sectioned, truncated text to a trace file when afield.ai4.trace (or AFIELD_AI4_TRACE) is set; 1/true selects ~/.afield/logs/ai4_trace.log. AiToolIoLogger writes one JSONL file per tool session under ~/.afield/logs/ai4_tool_io, on unless afield.ai4.toolIoLog (or AFIELD_AI4_TOOL_IO_LOG) is 0, false or off.

data class LogEvent

One log line: its channel tags, message, time, and the block indent and boundary it sits in.

data class LogEvent(
    val channel: String,
    val message: String,
    val timestamp: Instant = Instant.now(),
    val indent: String = "",
    val blockId: String? = null,
    val boundary: BlockBoundary? = null
)

enum class BlockBoundary { BEGIN, END }

fun interface LogSink

fun log(event: LogEvent)

fun LogSink.log

fun LogSink.log(
    channel: String,
    message: String,
    indent: String = "",
    blockId: String? = null,
    boundary: BlockBoundary? = null
) = log(LogEvent(channel = channel, message = message, indent = indent, blockId = blockId, boundary = boundary))

object LogDispatcher

object LogDispatcher {
    private val sinks = CopyOnWriteArrayList<LogSink>().apply { add(StdoutLog) }

fun setSinks(newSinks: List<LogSink>)

    fun setSinks(newSinks: List<LogSink>) {
        sinks.clear()
        sinks.addAll(newSinks)
    }

fun addSink(sink: LogSink)

    fun addSink(sink: LogSink) {
        sinks.add(sink)
    }

fun removeSink(sink: LogSink)

    fun removeSink(sink: LogSink) {
        sinks.remove(sink)
    }

fun log(event: LogEvent)

    fun log(event: LogEvent) {
        sinks.forEach { sink ->
            runCatching { sink.log(event) }
        }
    }

fun log

    fun log(
        channel: String,
        message: String,
        indent: String = "",
        blockId: String? = null,
        boundary: BlockBoundary? = null
    ) = log(LogEvent(channel = channel, message = message, indent = indent, blockId = blockId, boundary = boundary))
}

inline fun <R> LogDispatcher.withSink(sink: LogSink, block: () -> R): R {

Runs block with sink attached, and detaches it again however block ends — normally, by an early return, or on a throw.

Prefer this to a bare LogDispatcher.addSink/LogDispatcher.removeSink pair. The sink list is process-wide and outlives any one box, so a sink leaked by a path that skipped its own cleanup does not go quiet: it keeps receiving every event on every channel for the life of the JVM, and the box that installed it is long gone. Worse, LogDispatcher.log wraps every sink in runCatching, so a leaked sink that throws fails silently and forever. Making the removal part of the call is the difference between a rule the caller has to remember and one they cannot get wrong.

The same bracketing shape, and the same reason for it, as afield.app.diagnostics.logging.lblock.

Top-level rather than a member of LogDispatcher because Kotlin permits contract only on top-level functions, and the callsInPlace contract is what lets a caller assign a val inside the block. The call reads identically either way.

The example writes the channel as a variable on purpose: a literal here would be counted as a production lprintln call site by ProseNumeralContractTest's channel census, which reads source and does not exclude KDoc — so a doc snippet would silently move a statistic about real logging.

val seen = LogDispatcher.withSink(probe) {
    lprintln(channel, "a plain line")
    probe.count
}

@OptIn(ExperimentalContracts::class)
inline fun <R> LogDispatcher.withSink(sink: LogSink, block: () -> R): R {
    contract { callsInPlace(block, InvocationKind.EXACTLY_ONCE) }
    addSink(sink)
    try {
        return block()
    } finally {
        removeSink(sink)
    }
}

object ChannelMatch

The one rule every channel selector follows — the console mute set, the pinned console and the LogStream filter: a channel is a comma-separated set of tags, and a selector matches when every one of its tags is among the channel's. So boxes matches info,boxes and boxes,debug; info,boxes matches boxes,info and info,boxes,slow; kotlin does not match kotlinjs. Tags compare exactly, case included, as written at the call site.

fun tags(channel: String): Set<String>

    fun tags(channel: String): Set<String> =
        channel.split(',').mapNotNullTo(HashSet()) { it.trim().takeIf(String::isNotEmpty) }

fun matches(channel: String, selector: String): Boolean

    fun matches(channel: String, selector: String): Boolean {
        val wanted = tags(selector)
        return wanted.isNotEmpty() && tags(channel).containsAll(wanted)
    }
}

object ConsoleMute

Channels suppressed from the console — both the plain StdoutLog and the interactive PinnedConsole honor this. Muted events still reach every other sink (e.g. the LogStream web widget), so nothing is lost; they're just too chatty for the terminal. Default mutes the chatty background channels (info,boxes, info,persist, info,ai.boxnames, debug,boxes). Override with -Dafield.log.mute=... or AFIELD_LOG_MUTE=... (semicolon-separated selectors, matched by ChannelMatch: boxes mutes every channel tagged boxes); set to a blank/empty value to mute nothing.

val channels: Set<String>

    val channels: Set<String> = run {
        val raw = System.getProperty("afield.log.mute") ?: System.getenv("AFIELD_LOG_MUTE")
        if (raw != null) {
            raw.split(';').map { it.trim() }.filter { it.isNotEmpty() }.toSet()
        } else {
            setOf("info,boxes", "info,persist", "info,ai.boxnames", "debug,boxes")
        }
    }

fun isMuted(channel: String): Boolean = channels.any { ChannelMatch.matches(channel, it) }

object StdoutLog : LogSink

object StdoutLog : LogSink {
    private const val ANSI_RESET = "\u001B[0m"
    private const val ANSI_DARK_GRAY = "\u001B[90m"
    private const val ANSI_ITALIC = "\u001B[3m"

override fun log(event: LogEvent)

    override fun log(event: LogEvent) {
        if (ConsoleMute.isMuted(event.channel)) return
        val prefix = ""
        val channelPart = if (event.channel.isNotBlank()) {
            // Render channel tags as dark gray + italic for easier skimming in stdout
            "$ANSI_DARK_GRAY$ANSI_ITALIC[${event.channel}]$ANSI_RESET "
        } else ""
        val boundaryMarker = when (event.boundary) {
            BlockBoundary.BEGIN -> ">|> "
            BlockBoundary.END -> "<|< "
            null -> ""
        }
        val full = prefix + channelPart + depthIndent(event.indent) + boundaryMarker + event.message
        println(full)
    }

internal fun depthIndent(indent: String): String

An lblock indent is one "<block uuid>\t" token per open block — the structured sinks use the ids. A terminal wants the depth: two spaces per level, not 36 characters of UUID.

    internal fun depthIndent(indent: String): String =
        if (indent.isEmpty()) "" else "  ".repeat(indent.count { it == '\t' }.coerceAtLeast(1))
}

class NotifyLog

class NotifyLog(
    private val label: String = "AI4",
    private val prefix: String = "AI4",
    private val maxLen: Int = 200,
    private val dedupeWindowMs: Long = 1000
) : LogSink {
    private val policy = AiToastPolicy(dedupeWindowMs = dedupeWindowMs)

override fun log(event: LogEvent)

    override fun log(event: LogEvent) {
        // Keep the complete diagnostic event in the log, even when it has no toast.
        StdoutLog.log(event)
        val text = policy.message(event, System.currentTimeMillis()) ?: return
        val clipped = text.take(maxLen.coerceAtLeast(1))
        notify(clipped, label.ifBlank { prefix.ifBlank { "AI4" } })
    }
}

object SilentLog : LogSink

override fun log(event: LogEvent)

    override fun log(event: LogEvent) {
        // intentionally quiet
    }
}

class TraceLogger private constructor

class TraceLogger private constructor(
    private val path: Path,
    private val maxChars: Int
) {
    private val lock = Any()

fun log(section: String, payload: String)

    fun log(section: String, payload: String) {
        val clipped = if (payload.length > maxChars) {
            payload.take(maxChars) + "\n... [truncated ${payload.length - maxChars} chars]"
        } else {
            payload
        }
        val entry = buildString {
            append("---- ")
            append(section)
            append(" ")
            append(Instant.now().toString())
            append("\n")
            append(clipped)
            append("\n\n")
        }
        LogDispatcher.log(CHANNEL, "$section: ${payload.length} chars -> $path")
        synchronized(lock) {
            Files.createDirectories(path.parent)
            Files.newBufferedWriter(
                path,
                StandardCharsets.UTF_8,
                StandardOpenOption.CREATE,
                StandardOpenOption.APPEND
            ).use { it.write(entry) }
        }
    }

companion object

    companion object {

const val CHANNEL = "info,ai.trace"

The channel each trace entry is announced on (one line; the payload stays in the file).

fun fromEnv(): TraceLogger?

        fun fromEnv(): TraceLogger? {
            val raw = System.getProperty("afield.ai4.trace")
                ?: System.getProperty("afield.ai4.trace.path")
                ?: System.getenv("AFIELD_AI4_TRACE")
                ?: System.getenv("AFIELD_AI4_TRACE_PATH")
                ?: return null
            val normalized = raw.trim()
            if (normalized.isEmpty()) return null
            if (normalized.equals("0", ignoreCase = true) ||
                normalized.equals("false", ignoreCase = true) ||
                normalized.equals("off", ignoreCase = true)
            ) {
                return null
            }
            val defaultPath = Paths.get(System.getProperty("user.home"), ".afield", "logs", "ai4_trace.log")
            val path = if (
                normalized.equals("1", ignoreCase = true) ||
                normalized.equals("true", ignoreCase = true) ||
                normalized.equals("yes", ignoreCase = true) ||
                normalized.equals("on", ignoreCase = true)
            ) {
                defaultPath
            } else {
                val p = Paths.get(normalized)
                if (p.isAbsolute) p else Paths.get(System.getProperty("user.dir")).resolve(p)
            }
            val max = (
                System.getProperty("afield.ai4.trace.max")
                    ?: System.getenv("AFIELD_AI4_TRACE_MAX")
            )?.toIntOrNull()?.coerceAtLeast(1000) ?: 20000
            return TraceLogger(path, max).also {
                it.log(
                    "TRACE_INIT",
                    buildString {
                        appendLine("path=$path")
                        appendLine("maxChars=$max")
                    }
                )
            }
        }
    }
}

class AiToolIoLogger private constructor

class AiToolIoLogger private constructor(
    private val root: Path,
    private val maxChars: Int,
    private val log: LogSink
) {

data class Session

    data class Session(
        val id: String,
        val path: Path
    )

    private val lock = Any()

fun begin(fields: Map<String, Any?>): Session

    fun begin(fields: Map<String, Any?>): Session {
        val now = Instant.now()
        val id = UUID.randomUUID().toString()
        val fileStamp = now.toString()
            .replace(":", "")
            .replace(".", "-")
        val path = root.resolve("$fileStamp-${id.take(8)}.jsonl")
        val session = Session(id = id, path = path)
        event(session, "session_start", fields + ("logPath" to path.toString()))
        log.log("info,ai.toolio", "log=${path.toAbsolutePath()}")
        return session
    }

fun event(session: Session, event: String, fields: Map<String, Any?> = emptyMap())

    fun event(session: Session, event: String, fields: Map<String, Any?> = emptyMap()) {
        val record = linkedMapOf<String, Any?>(
            "timestamp" to Instant.now().toString(),
            "sessionId" to session.id,
            "event" to event
        )
        record.putAll(fields)
        append(session.path, jsonValue(record) + "\n")
    }

    private fun append(path: Path, text: String) {
        synchronized(lock) {
            Files.createDirectories(path.parent)
            Files.newBufferedWriter(
                path,
                StandardCharsets.UTF_8,
                StandardOpenOption.CREATE,
                StandardOpenOption.APPEND
            ).use { it.write(text) }
        }
    }

    private fun clipped(text: String): String =
        if (text.length <= maxChars) text else text.take(maxChars) + "\n... [truncated ${text.length - maxChars} chars]"

    private fun jsonValue(value: Any?): String = when (value) {
        null -> "null"
        is Boolean -> value.toString()
        is Byte, is Short, is Int, is Long -> value.toString()
        is Float -> if (value.isFinite()) value.toString() else jsonString(value.toString())
        is Double -> if (value.isFinite()) value.toString() else jsonString(value.toString())
        is String -> jsonString(clipped(value))
        is Map<*, *> -> value.entries.joinToString(prefix = "{", postfix = "}") { (k, v) ->
            "${jsonString(k?.toString() ?: "null")}:${jsonValue(v)}"
        }
        is Iterable<*> -> value.joinToString(prefix = "[", postfix = "]") { jsonValue(it) }
        is Array<*> -> value.joinToString(prefix = "[", postfix = "]") { jsonValue(it) }
        else -> jsonString(clipped(value.toString()))
    }

    private fun jsonString(value: String): String = buildString {
        append('"')
        value.forEach { ch ->
            when (ch) {
                '\\' -> append("\\\\")
                '"' -> append("\\\"")
                '\b' -> append("\\b")
                '\u000C' -> append("\\f")
                '\n' -> append("\\n")
                '\r' -> append("\\r")
                '\t' -> append("\\t")
                else -> {
                    if (ch.code < 0x20) {
                        append("\\u")
                        append(ch.code.toString(16).padStart(4, '0'))
                    } else {
                        append(ch)
                    }
                }
            }
        }
        append('"')
    }

companion object

fun fromEnvOrDefault(log: LogSink): AiToolIoLogger?

        fun fromEnvOrDefault(log: LogSink): AiToolIoLogger? {
            val enabledRaw = System.getProperty("afield.ai4.toolIoLog")
                ?: System.getenv("AFIELD_AI4_TOOL_IO_LOG")
            if (enabledRaw != null) {
                val normalized = enabledRaw.trim()
                if (normalized.equals("0", ignoreCase = true) ||
                    normalized.equals("false", ignoreCase = true) ||
                    normalized.equals("off", ignoreCase = true)
                ) {
                    return null
                }
            }

            val rootRaw = System.getProperty("afield.ai4.toolIoLog.path")
                ?: System.getenv("AFIELD_AI4_TOOL_IO_LOG_PATH")
            val defaultRoot = Paths.get(System.getProperty("user.home"), ".afield", "logs", "ai4_tool_io")
            val root = rootRaw
                ?.trim()
                ?.takeIf { it.isNotBlank() }
                ?.let {
                    val path = Paths.get(it)
                    if (path.isAbsolute) path else Paths.get(System.getProperty("user.dir")).resolve(path)
                }
                ?: defaultRoot
            val max = (
                System.getProperty("afield.ai4.toolIoLog.max")
                    ?: System.getenv("AFIELD_AI4_TOOL_IO_LOG_MAX")
            )?.toIntOrNull()?.coerceAtLeast(1000) ?: 200_000
            return AiToolIoLogger(root, max, log)
        }
    }
}