From 5db910ca1434a55b7ebe367292c7be81104a6d9c Mon Sep 17 00:00:00 2001 From: zombieb Date: Sat, 19 Jul 2025 18:51:28 -0400 Subject: [PATCH] Added global time format and log timing controls using `LoggingConfiguration` * Bench doc fixes * README fixes * Added test scripts in `tests/` --- BENCH.md | 4 +-- README.md | 43 ++++++++++++++++++++++++++++++++ deno.json | 8 +++--- mod.ts | 12 +++++---- test.ts | 63 ----------------------------------------------- tests/convert.ts | 21 ++++++++++++++++ tests/global.ts | 9 +++++++ tests/shutdown.ts | 16 ++++++++++++ 8 files changed, 102 insertions(+), 74 deletions(-) delete mode 100644 test.ts create mode 100644 tests/convert.ts create mode 100644 tests/global.ts create mode 100644 tests/shutdown.ts diff --git a/BENCH.md b/BENCH.md index 30d1a4a..df206e2 100644 --- a/BENCH.md +++ b/BENCH.md @@ -41,9 +41,9 @@ summary ### TL;DR / What does this mean? -You can, *in theory* and *on average*, construct 650,000 messages per second. +You can, *in theory* and *on average*, construct 643,000 messages per second. I don't know how to benchmark a logger without logging messages to stdout,
so I created a dedicated `bench` function on each source that just *constructs* them. -Deferred is not really much faster, but can be helpful in some scenarios. I think. Maybe. \ No newline at end of file +Deferred is not really much faster, but can be helpful in some scenarios. \ No newline at end of file diff --git a/README.md b/README.md index e20c53c..8ec8a37 100644 --- a/README.md +++ b/README.md @@ -1,6 +1,11 @@ # Undead Logging Logging for stupid idiots like me +* Pluggable event listeners +* Per-source hushing, global log type hushing +* Log timing control +* Time display modes + ```ts import Logging from "@proxnet/undead-logging" @@ -107,6 +112,44 @@ LoggingConfiguration.logTiming = LogTiming.Sync; LoggingConfiguration.logTiming = LogTiming.Deferred; ``` +You might prefer to defer logs in asynchronous situations where order does not matter and
+you'd like to prevent slowing down I/O.
+You might also prefer to reset all sources to synchronous logging during app shutdown.
+This can help debug issues with how your app closes. (see example below) + +## Global resets +Every source is tracked by this module in a `Set`. + +You can reset every source's log timing or time format with `LoggingConfiguration.reset(something)`.
+The corresponding property will be updated on `LoggingConfiguration`: + +```ts +import Logging, { LoggingConfiguration, LogTiming } from "@proxnet/undead-logging"; + +const log = new Logging("Logger"); + +log.logTiming = LogTiming.Sync; // the default +LoggingConfiguration.resetLogTiming = LogTiming.Deferred; + +// both are LogTiming.Deferred +log.d(`My log timing: LogTiming.${LogTiming[log.logTiming]}`); +log.d(`Global: LogTiming.${LogTiming[LoggingConfiguration.logTiming]}`); +``` + +This is useful when you want to use synchronous logging during a shutdown: +```ts +// something is keeping the event loop alive (HTTP server, a database, some I/O?) + +LoggingConfiguration.logTiming = LogTiming.Deferred; +const log = new Logging("Main"); + +Deno.addSignalListener('SIGINT', () => { + LoggingConfiguration.resetLogTiming = LogTiming.Sync; +}); +``` + +See [`tests/shutdown.ts`.](./tests/shutdown.ts) + ## [Benchmarks](./BENCH.md) ## Contributing diff --git a/deno.json b/deno.json index e6f4fe4..b72fca1 100644 --- a/deno.json +++ b/deno.json @@ -1,8 +1,8 @@ { "tasks": { - "debug": "deno run -A test.ts true", - "plain": "deno run -A test.ts", - "dev": "deno run plain", + "test-conversion": "deno run -A tests/convert.ts", + "test-global": "deno run -A tests/global.ts", + "test-shutdown": "deno run -A tests/shutdown.ts", "bench": "deno bench -A" }, "imports": { @@ -10,7 +10,7 @@ "chalk": "npm:chalk@^5.3.0" }, "exports": "./mod.ts", - "version": "1.4.0", + "version": "1.4.1", "name": "@proxnet/undead-logging", "license": "MIT", "bench": { diff --git a/mod.ts b/mod.ts index 559488e..f9c4cfe 100644 --- a/mod.ts +++ b/mod.ts @@ -11,11 +11,8 @@ interface UnknownConversion { converter: (arg: T) => string; } -interface WebLike { - url?: string, - headers?: Headers, - method?: string -} +/** Control all log sources from this module */ +const sources: Set = new Set(); /** The first log message across all sources will not contain carriage return + newline control codes */ let first = true; @@ -54,6 +51,8 @@ class Logging { if (typeof bright == 'boolean') this.bright = bright; if (typeof silent == 'boolean' && !silent) this.info(`Instantiated logging for ${this.source}`); + + sources.add(this); } #conversions(...msgs: PrimitiveItems) { @@ -341,6 +340,9 @@ class LoggingConfigurationBase { get logTiming(): LogTiming { return this.#timing; } set logTiming(data: LogTiming) { this.#timing = data } + set resetTimeFormat(data: TimeFormat) { for (const source of sources.values()) source.timeFormat = data; this.#timeType = data; } + set resetLogTiming(data: LogTiming) { for (const source of sources.values()) source.logTiming = data; this.#timing = data; } + } /** * Configure time display format and log timing here diff --git a/test.ts b/test.ts deleted file mode 100644 index d7f4802..0000000 --- a/test.ts +++ /dev/null @@ -1,63 +0,0 @@ -import Logging, { LoggingListeners, LoggingConfiguration, MessageType, MessageTypeVisibility, TimeFormat, LogTiming } from "./mod.ts"; -import { setImmediate } from "node:timers/promises"; -import process from "node:process"; - -const debug = process.argv[process.argv.length - 1] == 'true'; -console.debug(`Debug mode: ${debug}`); -const changeTimeFormat = process.argv[process.argv.length - 2] == 'true'; -console.debug(`changeTimeFormat: ${changeTimeFormat}`); -if (debug) { - LoggingListeners.onmsg('basic', msg => { - console.debug(`\r\n[d] ${msg}`); - }); - LoggingListeners.onmsg('type', (msg, type, source, time) => { - console.debug(`[D] M:'${msg}' T:${type} S:'${source}' TM:${time.getTime()}`); - }); -} - -LoggingConfiguration.timeFormat = TimeFormat.Utc; - -const log = new Logging("Test1"); - -log.i("Hello World!"); -log.visible = false; -log.e('I should not be visible.'); -log.visible = true; -log.e('Now I should be visible! (above is all UTC time format)'); - -const logg = new Logging("Test2"); - -logg.w(`Uh oh..`); -logg.d(`Here's some info that tells you about that warning:`, new Error('Uh oh..')); - -if (changeTimeFormat) logg.timeFormat = TimeFormat.Unix; -logg.i(`Unix time!`); - -if (changeTimeFormat) logg.timeFormat = TimeFormat.Local; -logg.i(`Process time!`); - -if (changeTimeFormat) logg.timeFormat = TimeFormat.Utc; -logg.logTiming = LogTiming.Deferred; -logg.log(MessageType.Network, "Deferred mode and RoundedLocal time! (shouldn't be UTC)"); - -if (changeTimeFormat) logg.timeFormat = TimeFormat.RoundedLocal; -setImmediate(() => { - // all should NOT be local mode - MessageTypeVisibility.Error = false; - logg.error("I can't be seen!"); - log.error('Same!'); - log.n("I *can* be seen!"); -}); - -// the big red error -const world = null; -if (changeTimeFormat) log.timeFormat = TimeFormat.Utc; -log.log(MessageType.Error, Object, "<-- nasty", 0, undefined, null, JSON.stringify({"hello": world})); - -LoggingConfiguration.logTiming = LogTiming.Sync; -LoggingConfiguration.timeFormat = TimeFormat.Unix; -const webLog = new Logging("Web"); -webLog.d(`Following is a Request`); -webLog.i(new Request('http://example.com?hello=world', { headers: { 'key1': 'value1', 'key2': 'value2' }})); -webLog.d(`Following is a Response`); -webLog.i(await fetch('https://example.com')); \ No newline at end of file diff --git a/tests/convert.ts b/tests/convert.ts new file mode 100644 index 0000000..0ba0bac --- /dev/null +++ b/tests/convert.ts @@ -0,0 +1,21 @@ +import Logging, { LoggingListeners } from "../mod.ts"; +import process from "node:process"; + +const debug = process.argv[process.argv.length - 1] == 'true'; +console.debug(`Debug mode: ${debug}`); +const changeTimeFormat = process.argv[process.argv.length - 2] == 'true'; +console.debug(`changeTimeFormat: ${changeTimeFormat}`); +if (debug) { + LoggingListeners.onmsg('basic', msg => { + console.debug(`\r\n[d] ${msg}`); + }); + LoggingListeners.onmsg('type', (msg, type, source, time) => { + console.debug(`[D] M:'${msg}' T:${type} S:'${source}' TM:${time.getTime()}`); + }); +} + +const webLog = new Logging("Web"); +webLog.d(`Following is a Request`); +webLog.i(new Request('http://example.com?hello=world', { headers: { 'key1': 'value1', 'key2': 'value2' }})); +webLog.d(`Following is a Response`); +webLog.i(await fetch('https://example.com')); \ No newline at end of file diff --git a/tests/global.ts b/tests/global.ts new file mode 100644 index 0000000..13d8213 --- /dev/null +++ b/tests/global.ts @@ -0,0 +1,9 @@ +import Logging, { LoggingConfiguration, LogTiming } from "@proxnet/undead-logging"; + +const log = new Logging("Logger"); + +log.logTiming = LogTiming.Sync; +LoggingConfiguration.resetLogTiming = LogTiming.Deferred; + +log.d(`My log timing: LogTiming.${LogTiming[log.logTiming]} (not sync!)`); +log.d(`Global: LogTiming.${LogTiming[LoggingConfiguration.logTiming]} (not sync!)`); \ No newline at end of file diff --git a/tests/shutdown.ts b/tests/shutdown.ts new file mode 100644 index 0000000..aa53586 --- /dev/null +++ b/tests/shutdown.ts @@ -0,0 +1,16 @@ +import Logging, { LoggingConfiguration, LogTiming } from "@proxnet/undead-logging"; + +//LoggingConfiguration.logTiming = LogTiming.Deferred; + +const log = new Logging("Main"); +log.i(`Deferred! - LogTiming.${LogTiming[log.logTiming]}`); + +const timeout = setTimeout(() => { log.d(`Interval!`) }, 2000); + +Deno.addSignalListener('SIGINT', () => { + clearTimeout(timeout); + + LoggingConfiguration.resetLogTiming = LogTiming.Sync; + + log.i(`Sync! - LogTiming.${LogTiming[LoggingConfiguration.logTiming]}`); +});