diff --git a/CHANGELOG.md b/CHANGELOG.md index 9f09135..6a0fddc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,16 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Fixed + +- **`quickUtils.logLevel` now does something.** It was declared, described in + both language files, documented and offered in the settings editor — and no + code read it, so setting it changed nothing. It is a *floor*: VS Code owns a + `LogOutputChannel`'s level, per channel, in the Output panel, so this can make + the log quieter but cannot turn on output VS Code is already dropping. Use + **Developer: Set Log Level** for that. The level is read per entry, so a + change applies immediately rather than after a reload. + ## [0.3.0] - 2026-08-08 Three new features, and a rebuild on `@kkdev92/vscode-ext-kit` 3.x underneath diff --git a/src/core/logging.ts b/src/core/logging.ts new file mode 100644 index 0000000..79952c9 --- /dev/null +++ b/src/core/logging.ts @@ -0,0 +1,75 @@ +/** + * `quickUtils.logLevel`, applied. + * + * The framework logs into a `LogOutputChannel`, and VS Code filters that by the + * level chosen in the Output panel — per channel, persisted, and not something + * an extension can raise for itself. So this setting is a *floor* on top of + * that: it can make the log quieter, never louder. `Developer: Set Log Level` + * is what turns `debug` back on. + * + * The level is read per call rather than captured, because the services that + * hold a logger are singletons built once at activation — capturing would mean + * the setting only took effect after a reload, which is not what a settings + * change looks like anywhere else in this extension. + */ + +import { serviceToken, type Logger, type ServiceToken } from '@kkdev92/vscode-ext-kit'; + +/** The values `quickUtils.logLevel` accepts, in severity order. */ +export type LogLevel = 'trace' | 'debug' | 'info' | 'warn' | 'error'; + +const SEVERITY: Record = { + trace: 0, + debug: 1, + info: 2, + warn: 3, + error: 4, +}; + +/** + * Wraps `logger` so entries below `level()` are dropped. + * + * `withFields` returns a filtered child rather than the bare one, so a scoped + * logger handed to a feature keeps the floor. + */ +export function filtered(logger: Logger, level: () => LogLevel): Logger { + const passes = (of: LogLevel): boolean => SEVERITY[of] >= SEVERITY[level()]; + return { + trace: (message, fields): void => { + if (passes('trace')) { + logger.trace(message, fields); + } + }, + debug: (message, fields): void => { + if (passes('debug')) { + logger.debug(message, fields); + } + }, + info: (message, fields): void => { + if (passes('info')) { + logger.info(message, fields); + } + }, + warn: (message, fields): void => { + if (passes('warn')) { + logger.warn(message, fields); + } + }, + error: (message, error, fields): void => { + if (passes('error')) { + logger.error(message, error, fields); + } + }, + withFields: (fields): Logger => filtered(logger.withFields(fields), level), + }; +} + +/** + * The logger everything in this extension is given. + * + * A token rather than the framework's `Log` directly, because the ambient set + * in `./services` names one logger for the whole module — swapping it here is + * what makes the setting apply to every feature at once, instead of each one + * remembering to wrap. + */ +export const AppLog: ServiceToken = serviceToken('quickUtils.log'); diff --git a/src/core/services.ts b/src/core/services.ts index d101d83..d8923bc 100644 --- a/src/core/services.ts +++ b/src/core/services.ts @@ -14,7 +14,6 @@ import { Editors, Localization, - Log, Notifications, QuickInput, type CommandsService, @@ -26,6 +25,7 @@ import { } from '@kkdev92/vscode-ext-kit'; import { EditorSettings, Settings } from './config'; +import { AppLog } from './logging'; import type { RegexClient } from '../regex/client'; /** @@ -36,8 +36,12 @@ import type { RegexClient } from '../regex/client'; * exactly the drift nobody notices until a member is silently `unknown`. */ export const uses = { - /** Scoped per feature, so an entry says where it came from. */ - logger: Log, + /** + * Scoped per feature, so an entry says where it came from — and filtered by + * `quickUtils.logLevel`, which is why it is {@link AppLog} rather than the + * framework's `Log`. + */ + logger: AppLog, /** This extension's settings. */ config: Settings.token, /** `editor.*`, for the settings VS Code owns. */ diff --git a/src/extension.ts b/src/extension.ts index 1caee50..da2753b 100644 --- a/src/extension.ts +++ b/src/extension.ts @@ -35,7 +35,8 @@ import * as vscode from 'vscode'; import { KIT_VERSION } from './core/build'; import * as Cmd from './core/commands'; import { EditorSettings, Settings, resolveJsonIndent } from './core/config'; -import { EXTENSION_ID, EXTENSION_NAME, PUBLISHER, REGEX_TESTER_VIEW_TYPE, VIEWS } from './core/constants'; +import { CONFIG, EXTENSION_ID, EXTENSION_NAME, PUBLISHER, REGEX_TESTER_VIEW_TYPE, VIEWS } from './core/constants'; +import { AppLog, filtered } from './core/logging'; import { uses, type TesterServices } from './core/services'; import { DefaultSecret, @@ -150,6 +151,14 @@ const quickUtils = defineModule('quickUtils', { uses }, (module): undefined => { // ---- Services ---------------------------------------------------------- + // Registered first because everything below asks for it. The ambient set in + // `core/services` names this token rather than the framework's `Log`, so a + // feature gets the filtered logger without knowing there is a filter. + module.services.singleton(AppLog, { + inject: { logger: Log, config: Settings.token }, + create: ({ logger, config }) => filtered(logger, () => config.read().get(CONFIG.LOG_LEVEL)), + }); + module.services.singleton(Registry, { inject: { config: Settings.token, editorConfig: EditorSettings.token, l10n: Localization }, create: ({ config, editorConfig, l10n }) => @@ -160,7 +169,7 @@ const quickUtils = defineModule('quickUtils', { uses }, (module): undefined => { }); module.services.singleton(History, { - inject: { storage: HistoryStorage.token, config: Settings.token, log: Log }, + inject: { storage: HistoryStorage.token, config: Settings.token, log: AppLog }, create: ({ storage, config, log }) => new HistoryStore(storage, config, log.withFields({ feature: 'history' })), }); @@ -171,7 +180,7 @@ const quickUtils = defineModule('quickUtils', { uses }, (module): undefined => { }); module.services.singleton(Regex, { - inject: { log: Log }, + inject: { log: AppLog }, create: ({ log }) => new RegexClient(defaultWorkerPath(), log.withFields({ feature: 'regex' })), }); @@ -189,7 +198,7 @@ const quickUtils = defineModule('quickUtils', { uses }, (module): undefined => { // the store and logger once here is what stops the three of them from // drifting into three slightly different loads. module.services.singleton(PresetReload, { - inject: { store: Presets, log: Log }, + inject: { store: Presets, log: AppLog }, create: ({ store, log }) => (): Promise => @@ -199,7 +208,7 @@ const quickUtils = defineModule('quickUtils', { uses }, (module): undefined => { // A service rather than a tree-view local: the checkbox handler and the // reset command both drive the same provider. module.services.singleton(Tools, { - inject: { registry: Registry, favorites: Favorites, l10n: Localization, log: Log }, + inject: { registry: Registry, favorites: Favorites, l10n: Localization, log: AppLog }, create: ({ registry, favorites, l10n, log }) => new ToolsTreeProvider(registry, favorites, l10n, log.withFields({ feature: 'tools' })), }); @@ -345,7 +354,7 @@ const quickUtils = defineModule('quickUtils', { uses }, (module): undefined => { module.hostedServices.add({ id: 'quickUtils.favoritesCheckbox', - inject: { tools: Tools, log: Log }, + inject: { tools: Tools, log: AppLog }, start: (context, { tools, log }) => { const subscription = tools.onDidChangeCheckboxState((changes) => { void (async (): Promise => { diff --git a/test/integration/testHost.test.ts b/test/integration/testHost.test.ts index 89a1144..daa9656 100644 --- a/test/integration/testHost.test.ts +++ b/test/integration/testHost.test.ts @@ -158,4 +158,27 @@ describe('the application, run on fakes', () => { expect(host.logs.at('error')).toEqual([]); }); + + // `quickUtils.logLevel` was declared, documented and localised for a while + // with nothing reading it, so this pair is about the wiring rather than the + // comparison — `HistoryStore` takes its logger from the injected token, and + // that is the seam where a filter is easy to forget. + it('logs at info by default', async () => { + await host.start(); + host.notifications._respondWith(0); // confirm the clear, which is what logs + await host.commands.execute(COMMANDS.HISTORY_CLEAR); + + expect(host.logs.at('info').map((entry) => entry.message)).toContain('History cleared'); + await host.stop(); + }); + + it('drops an info entry once logLevel is raised to warn', async () => { + host.settings._set('quickUtils', 'logLevel', 'globalValue', 'warn'); + await host.start(); + host.notifications._respondWith(0); + await host.commands.execute(COMMANDS.HISTORY_CLEAR); + + expect(host.logs.at('info').map((entry) => entry.message)).not.toContain('History cleared'); + await host.stop(); + }); }); diff --git a/test/unit/logging.test.ts b/test/unit/logging.test.ts new file mode 100644 index 0000000..d00b4ce --- /dev/null +++ b/test/unit/logging.test.ts @@ -0,0 +1,120 @@ +/** + * The `quickUtils.logLevel` floor. + * + * Two things are worth pinning here rather than trusting by inspection: that + * every level is compared against the floor (an off-by-one in the table shows + * up as one level leaking), and that the level is read *per call*. The second + * is the reason this wrapper takes a thunk — the services that hold a logger + * are singletons built once at activation, so capturing the level would make + * the setting take effect only after a reload. + */ + +import { describe, expect, it } from 'vitest'; + +import type { LogFields, Logger } from '@kkdev92/vscode-ext-kit'; + +import { filtered, type LogLevel } from '../../src/core/logging'; + +interface Recorded { + readonly level: string; + readonly message: string; + readonly fields?: LogFields | undefined; +} + +/** A logger that records instead of writing, with `withFields` kept faithful. */ +function recorder(entries: Recorded[], inherited?: LogFields): Logger { + const merged = (fields?: LogFields): LogFields | undefined => + inherited === undefined && fields === undefined ? undefined : { ...inherited, ...fields }; + return { + trace: (message, fields): void => { + entries.push({ level: 'trace', message, fields: merged(fields) }); + }, + debug: (message, fields): void => { + entries.push({ level: 'debug', message, fields: merged(fields) }); + }, + info: (message, fields): void => { + entries.push({ level: 'info', message, fields: merged(fields) }); + }, + warn: (message, fields): void => { + entries.push({ level: 'warn', message, fields: merged(fields) }); + }, + error: (message, _error, fields): void => { + entries.push({ level: 'error', message, fields: merged(fields) }); + }, + withFields: (fields): Logger => recorder(entries, { ...inherited, ...fields }), + }; +} + +/** Logs one entry at every level and returns the levels that got through. */ +function levelsThatPass(level: LogLevel): string[] { + const entries: Recorded[] = []; + const log = filtered(recorder(entries), () => level); + log.trace('t'); + log.debug('d'); + log.info('i'); + log.warn('w'); + log.error('e'); + return entries.map((entry) => entry.level); +} + +describe('the logLevel floor', () => { + it('lets everything through at trace', () => { + expect(levelsThatPass('trace')).toEqual(['trace', 'debug', 'info', 'warn', 'error']); + }); + + it('drops only what is below the floor', () => { + expect(levelsThatPass('debug')).toEqual(['debug', 'info', 'warn', 'error']); + expect(levelsThatPass('info')).toEqual(['info', 'warn', 'error']); + expect(levelsThatPass('warn')).toEqual(['warn', 'error']); + }); + + it('keeps errors at the highest floor', () => { + expect(levelsThatPass('error')).toEqual(['error']); + }); + + it('re-reads the level on every call, so a settings change applies at once', () => { + const entries: Recorded[] = []; + let level: LogLevel = 'info'; + const log = filtered(recorder(entries), () => level); + + log.debug('before'); + level = 'debug'; + log.debug('after'); + + expect(entries.map((entry) => entry.message)).toEqual(['after']); + }); + + it('keeps the floor on a scoped child, and its fields', () => { + const entries: Recorded[] = []; + const log = filtered(recorder(entries), () => 'warn').withFields({ feature: 'history' }); + + log.info('dropped'); + log.warn('kept'); + + expect(entries).toEqual([{ level: 'warn', message: 'kept', fields: { feature: 'history' } }]); + }); + + it('passes the error argument through', () => { + const seen: unknown[] = []; + const log = filtered( + { + trace: (): void => {}, + debug: (): void => {}, + info: (): void => {}, + warn: (): void => {}, + error: (_message, error): void => { + seen.push(error); + }, + withFields: function (this: Logger): Logger { + return this; + }, + }, + () => 'trace' + ); + const boom = new Error('boom'); + + log.error('failed', boom); + + expect(seen).toEqual([boom]); + }); +});