|
| 1 | +options gen2 |
| 2 | +options indenting = 4 |
| 3 | +options no_global_variables = false |
| 4 | +options no_unused_block_arguments = false |
| 5 | +options no_unused_function_arguments = false |
| 6 | + |
| 7 | +module logger shared public |
| 8 | + |
| 9 | +//! Structured logging for daslang tools. |
| 10 | +//! |
| 11 | +//! Writes one JSON object per line ("JSON Lines" / ``ndjson``) to |
| 12 | +//! ``{get_das_root()}/logs/<name>.log``. Reuses the runtime ``LOG_TRACE`` / |
| 13 | +//! ``LOG_DEBUG`` / ``LOG_INFO`` / ``LOG_WARNING`` / ``LOG_ERROR`` / |
| 14 | +//! ``LOG_CRITICAL`` levels. Each record carries an ISO 8601 UTC timestamp |
| 15 | +//! (millisecond precision), level name, category, message, and optional |
| 16 | +//! ``fields`` object. |
| 17 | +//! |
| 18 | +//! All public names carry the ``logger_`` prefix — short verbs like |
| 19 | +//! ``flush`` / ``close`` / ``info`` / ``debug`` would collide with user |
| 20 | +//! code when called unqualified. The intended call shape is |
| 21 | +//! ``logger_info("mcp.tool", "...")``, not ``logger::info(...)``. |
| 22 | +//! |
| 23 | +//! **Categories** are free-form strings; the convention is dotted |
| 24 | +//! hierarchy from tool name down to subsystem: |
| 25 | +//! |
| 26 | +//! - ``"mcp"`` — top-level events for the MCP server |
| 27 | +//! - ``"mcp.req"`` / ``"mcp.res"`` — JSON-RPC request / response framing |
| 28 | +//! - ``"mcp.tool"`` — tool dispatch (start / complete / error) |
| 29 | +//! - ``"mcp.live"``, ``"mcp.live.launch"`` — live-reload subsystem |
| 30 | +//! - ``"mcp.heap"`` — heap-collection ticks |
| 31 | +//! |
| 32 | +//! Filters apply at the most-specific dotted prefix: |
| 33 | +//! :func:`logger_set_category_level` ``("mcp.live", LOG_DEBUG)`` enables |
| 34 | +//! debug for ``"mcp.live"``, ``"mcp.live.launch"``, etc. — anything else |
| 35 | +//! stays at the global :func:`logger_set_min_level`. |
| 36 | +//! |
| 37 | +//! :func:`logger_install_hook` plugs a GLOBAL debug agent into the runtime |
| 38 | +//! so accidental ``print()`` / ``to_log()`` calls are diverted into the |
| 39 | +//! log file instead of stdout/stderr — important for stdio-transport |
| 40 | +//! processes (MCP server, language servers) where any stdout write |
| 41 | +//! corrupts the wire format. One install covers every Context including |
| 42 | +//! future ``new_thread`` workers. |
| 43 | + |
| 44 | +require daslib/json public |
| 45 | +require daslib/fio public |
| 46 | +require strings |
| 47 | +require daslib/jsonrpc |
| 48 | +require daslib/debugger |
| 49 | +require daslib/rtti |
| 50 | + |
| 51 | +// ── State (per-Context) ────────────────────────────────────────────── |
| 52 | + |
| 53 | +var private log_file : FILE const? = null |
| 54 | +var private log_path : string |
| 55 | +var private log_name : string |
| 56 | +var private log_open_attempted = false |
| 57 | +var private log_open_failed = false |
| 58 | +var private log_min_level = LOG_INFO |
| 59 | +var private log_category_overrides : table<string; int> |
| 60 | +var private log_fallback_to_stderr = true |
| 61 | + |
| 62 | +// ── Internal helpers ───────────────────────────────────────────────── |
| 63 | + |
| 64 | +def private level_name(level : int) : string { |
| 65 | + return "critical" if (level >= LOG_CRITICAL) |
| 66 | + return "error" if (level >= LOG_ERROR) |
| 67 | + return "warning" if (level >= LOG_WARNING) |
| 68 | + return "info" if (level >= LOG_INFO) |
| 69 | + return "debug" if (level >= LOG_DEBUG) |
| 70 | + return "trace" |
| 71 | +} |
| 72 | + |
| 73 | +// Resolve filter level for a category. Most-specific dotted prefix wins — |
| 74 | +// "mcp.live.foo" first looks up the full path, then "mcp.live", then "mcp", |
| 75 | +// before falling back to the global min level. |
| 76 | +def private resolve_level(category : string) : int { |
| 77 | + var probe = category |
| 78 | + while (true) { |
| 79 | + if (key_exists(log_category_overrides, probe)) return log_category_overrides[probe] |
| 80 | + let dot = probe |> rfind(".") |
| 81 | + break if (dot < 0) |
| 82 | + probe = probe |> slice(0, dot) |
| 83 | + } |
| 84 | + return log_min_level |
| 85 | +} |
| 86 | + |
| 87 | +def private should_log(level : int; category : string) : bool { |
| 88 | + return level >= resolve_level(category) |
| 89 | +} |
| 90 | + |
| 91 | +def private ensure_dir(path : string) { |
| 92 | + let dir = dir_name(path) |
| 93 | + return if (empty(dir)) |
| 94 | + let st = stat(dir) |
| 95 | + return if (st.is_valid && st.is_dir) |
| 96 | + mkdir(dir) |
| 97 | +} |
| 98 | + |
| 99 | +def private ensure_open() { |
| 100 | + return if (log_file != null || log_open_failed || empty(log_path)) |
| 101 | + log_open_attempted = true |
| 102 | + ensure_dir(log_path) |
| 103 | + log_file = fopen(log_path, "ab") |
| 104 | + if (log_file == null) { |
| 105 | + log_open_failed = true |
| 106 | + } |
| 107 | +} |
| 108 | + |
| 109 | +// JSON-encode the four fixed fields directly into the writer, then append |
| 110 | +// the optional `fields` object via daslib/json's public `write_json` (no |
| 111 | +// json_boost reflection — fast path). |
| 112 | +def private write_record(var w : StringBuilderWriter; ts, lvl, cat, msg : string; fields : JsonValue?) { |
| 113 | + w |> write("\{\"ts\":\"") |
| 114 | + write_escape_string(w, ts) |
| 115 | + w |> write("\",\"level\":\"") |
| 116 | + write_escape_string(w, lvl) |
| 117 | + w |> write("\",\"cat\":\"") |
| 118 | + write_escape_string(w, cat) |
| 119 | + w |> write("\",\"msg\":\"") |
| 120 | + write_escape_string(w, msg) |
| 121 | + if (fields != null) { |
| 122 | + w |> write("\",\"fields\":") |
| 123 | + // write_json always pretty-prints (depth=0 still inserts \n/\t between |
| 124 | + // elements). One JSON object per line is load-bearing for JSON Lines, |
| 125 | + // so flatten via the jsonrpc framing helper (preserves whitespace |
| 126 | + // inside string literals). |
| 127 | + w |> write(compact_json_whitespace(write_json(fields))) |
| 128 | + w |> write("}\n") |
| 129 | + } else { |
| 130 | + w |> write("\"}\n") |
| 131 | + } |
| 132 | +} |
| 133 | + |
| 134 | +def private emit(level : int; category, message : string; fields : JsonValue?) { |
| 135 | + return if (!should_log(level, category)) |
| 136 | + ensure_open() |
| 137 | + let line = build_string() $(var w) { |
| 138 | + write_record(w, iso8601_now(), level_name(level), category, message, fields) |
| 139 | + } |
| 140 | + if (log_file != null) { |
| 141 | + fwrite(log_file, line) |
| 142 | + fflush(log_file) |
| 143 | + return |
| 144 | + } |
| 145 | + // Open failed (or path never set). stderr is always safe — it isn't the |
| 146 | + // JSON-RPC channel for stdio-transport servers, so a tail fallback can't |
| 147 | + // corrupt protocol framing. |
| 148 | + if (log_fallback_to_stderr) { |
| 149 | + fwrite(fstderr(), line) |
| 150 | + } |
| 151 | +} |
| 152 | + |
| 153 | +// ── Public configuration ───────────────────────────────────────────── |
| 154 | +// |
| 155 | +// All public names carry the ``logger_`` prefix on purpose. Short verbs |
| 156 | +// like ``flush`` / ``close`` / ``info`` / ``debug`` collide with user |
| 157 | +// code when callers ``require daslib/logger`` and reach for the |
| 158 | +// unqualified form. The prefix keeps the call sites readable |
| 159 | +// (``logger_info("foo", "bar")``) without forcing ``logger::`` everywhere. |
| 160 | + |
| 161 | +def logger_set_name(name : string) { |
| 162 | + //! Configure the log file as ``{get_das_root()}/logs/<name>.log``. |
| 163 | + //! Re-opens if the path changes; closes the previous handle. Each |
| 164 | + //! Context tracks its own state — call once per context. |
| 165 | + let new_path = path_join(get_das_root(), "logs/{name}.log") |
| 166 | + logger_set_path(new_path) |
| 167 | + log_name = name |
| 168 | +} |
| 169 | + |
| 170 | +def logger_set_path(path : string) { |
| 171 | + //! Override the log file path explicitly. Pass an absolute path or a |
| 172 | + //! path relative to the current working directory. |
| 173 | + if (path == log_path) return |
| 174 | + if (log_file != null) { |
| 175 | + fclose(log_file) |
| 176 | + log_file = null |
| 177 | + } |
| 178 | + log_path = path |
| 179 | + log_open_attempted = false |
| 180 | + log_open_failed = false |
| 181 | +} |
| 182 | + |
| 183 | +def logger_get_path() : string { |
| 184 | + //! Returns the currently configured log file path (empty if unset). |
| 185 | + return log_path |
| 186 | +} |
| 187 | + |
| 188 | +def logger_get_name() : string { |
| 189 | + //! Returns the logical name passed to :func:`logger_set_name` |
| 190 | + //! (empty if the path was set directly via :func:`logger_set_path`). |
| 191 | + return log_name |
| 192 | +} |
| 193 | + |
| 194 | +def logger_set_min_level(level : int) { |
| 195 | + //! Global minimum level. Records below this are dropped before |
| 196 | + //! formatting. Default ``LOG_INFO``. |
| 197 | + log_min_level = level |
| 198 | +} |
| 199 | + |
| 200 | +def logger_get_min_level() : int { |
| 201 | + //! Returns the currently configured global minimum level. |
| 202 | + return log_min_level |
| 203 | +} |
| 204 | + |
| 205 | +def logger_set_category_level(category : string; level : int) { |
| 206 | + //! Override the level filter for one category. Dotted prefix |
| 207 | + //! matching: an override on ``"mcp.live"`` applies to ``"mcp.live"``, |
| 208 | + //! ``"mcp.live.foo"``, ``"mcp.live.bar"`` (unless they have their own |
| 209 | + //! more specific override). |
| 210 | + log_category_overrides[category] = level |
| 211 | +} |
| 212 | + |
| 213 | +def logger_clear_category_levels() { |
| 214 | + //! Remove all per-category overrides. |
| 215 | + log_category_overrides |> clear |
| 216 | +} |
| 217 | + |
| 218 | +def logger_set_stderr_fallback(enabled : bool) { |
| 219 | + //! Enable / disable writing to stderr when the log file can't be |
| 220 | + //! opened. Defaults to true; set to false for strict stdio-transport |
| 221 | + //! servers that must NEVER write to either stream on file failure. |
| 222 | + log_fallback_to_stderr = enabled |
| 223 | +} |
| 224 | + |
| 225 | +// ── Log calls ──────────────────────────────────────────────────────── |
| 226 | + |
| 227 | +def logger_log(level : int; category, message : string; fields : JsonValue? = null) { |
| 228 | + //! Generic log entry. Prefer the named-level helpers below. |
| 229 | + emit(level, category, message, fields) |
| 230 | +} |
| 231 | + |
| 232 | +def logger_trace(category, message : string; fields : JsonValue? = null) { |
| 233 | + //! Verbose trace-level record. ``LOG_TRACE``. |
| 234 | + emit(LOG_TRACE, category, message, fields) |
| 235 | +} |
| 236 | + |
| 237 | +def logger_debug(category, message : string; fields : JsonValue? = null) { |
| 238 | + //! Debug-level record. ``LOG_DEBUG``. |
| 239 | + emit(LOG_DEBUG, category, message, fields) |
| 240 | +} |
| 241 | + |
| 242 | +def logger_info(category, message : string; fields : JsonValue? = null) { |
| 243 | + //! Informational record. ``LOG_INFO`` — the default level. |
| 244 | + emit(LOG_INFO, category, message, fields) |
| 245 | +} |
| 246 | + |
| 247 | +def logger_warning(category, message : string; fields : JsonValue? = null) { |
| 248 | + //! Warning record. ``LOG_WARNING``. |
| 249 | + emit(LOG_WARNING, category, message, fields) |
| 250 | +} |
| 251 | + |
| 252 | +def logger_error(category, message : string; fields : JsonValue? = null) { |
| 253 | + //! Error record. ``LOG_ERROR``. |
| 254 | + emit(LOG_ERROR, category, message, fields) |
| 255 | +} |
| 256 | + |
| 257 | +def logger_critical(category, message : string; fields : JsonValue? = null) { |
| 258 | + //! Critical / fatal record. ``LOG_CRITICAL``. |
| 259 | + emit(LOG_CRITICAL, category, message, fields) |
| 260 | +} |
| 261 | + |
| 262 | +// ── Lifecycle ──────────────────────────────────────────────────────── |
| 263 | + |
| 264 | +def logger_flush() { |
| 265 | + //! Explicit flush. Each write already flushes; only useful if you |
| 266 | + //! disable auto-flush in a fork. |
| 267 | + if (log_file != null) { |
| 268 | + fflush(log_file) |
| 269 | + } |
| 270 | +} |
| 271 | + |
| 272 | +def logger_close() { |
| 273 | + //! Close the log file. Subsequent writes will lazy-reopen. |
| 274 | + if (log_file != null) { |
| 275 | + fclose(log_file) |
| 276 | + log_file = null |
| 277 | + } |
| 278 | + log_open_attempted = false |
| 279 | + log_open_failed = false |
| 280 | +} |
| 281 | + |
| 282 | +// ── Debug-agent hook ───────────────────────────────────────────────── |
| 283 | +// |
| 284 | +// Intercepts ``Context::to_out`` (the underlying mechanism behind ``print`` |
| 285 | +// and ``to_log``) and routes every message into the configured log file |
| 286 | +// instead of stdout/stderr. Critical for stdio-transport processes — MCP |
| 287 | +// servers, language servers, anything where stdout is the wire format. |
| 288 | +// |
| 289 | +// Registered as a GLOBAL debug agent (not thread-local) under the |
| 290 | +// ``"daslib_logger"`` category. One install covers every Context that |
| 291 | +// later spawns; ``new_thread`` workers don't need to re-install. The |
| 292 | +// agent's ``onLog`` is dispatched into its installing Context, which |
| 293 | +// owns the log file handle — cross-context invocations route writes |
| 294 | +// through that single handle. |
| 295 | + |
| 296 | +let private LOGGER_AGENT_CATEGORY = "daslib_logger" |
| 297 | + |
| 298 | +class private LogHookAgent : DapiDebugAgent { |
| 299 | + def override onLog(context : Context?; at : LineInfo const?; level : int; text : string#) : bool { |
| 300 | + // Fail-open when logging isn't configured — let the default |
| 301 | + // stdout/stderr path through instead of swallowing silently. |
| 302 | + // Makes accidental "hook before logger_set_name" calls harmless |
| 303 | + // rather than blackholing every print(). |
| 304 | + if (empty(log_path) && !log_fallback_to_stderr) return false |
| 305 | + var fields : JsonValue? = null |
| 306 | + if (at != null && at.fileInfo != null) { |
| 307 | + fields = JV({"at" => JV("{at.fileInfo.name}:{at.line}")}) |
| 308 | + } |
| 309 | + emit(level, "runtime", string(text), fields) |
| 310 | + return true |
| 311 | + } |
| 312 | +} |
| 313 | + |
| 314 | +def logger_install_hook() { |
| 315 | + //! Install a global debug agent that diverts ``print`` and |
| 316 | + //! ``to_log`` (from any Context, current or future) into the |
| 317 | + //! configured log file. Idempotent — safe to call from every |
| 318 | + //! module's [init], from MCP main, etc. Worker threads spawned via |
| 319 | + //! ``new_thread`` inherit the hook automatically; no per-context |
| 320 | + //! re-install needed. |
| 321 | + return if (has_debug_agent_context(LOGGER_AGENT_CATEGORY)) |
| 322 | + install_new_debug_agent(new LogHookAgent(), LOGGER_AGENT_CATEGORY) |
| 323 | +} |
| 324 | + |
| 325 | +def logger_init(name : string) { |
| 326 | + //! Convenience: ``logger_set_name(name)`` + ``logger_install_hook()``. |
| 327 | + //! The common-case one-liner for tools that want both behaviors. |
| 328 | + logger_set_name(name) |
| 329 | + logger_install_hook() |
| 330 | +} |
0 commit comments