diff --git a/.changeset/add-debug-logging.md b/.changeset/add-debug-logging.md new file mode 100644 index 0000000..a4058fb --- /dev/null +++ b/.changeset/add-debug-logging.md @@ -0,0 +1,5 @@ +--- +"chkit": patch +--- + +Add debug logging via `CHKIT_DEBUG=1` environment variable. Logs config loading, command dispatch, plugin lifecycle hooks, ClickHouse queries with timing, journal operations, and per-command details to stderr. diff --git a/packages/cli/src/bin/chkit.ts b/packages/cli/src/bin/chkit.ts index cc3ec5b..49e300c 100644 --- a/packages/cli/src/bin/chkit.ts +++ b/packages/cli/src/bin/chkit.ts @@ -16,6 +16,7 @@ import { formatGlobalHelp, formatCommandHelp } from './help.js' import { loadPluginRuntime } from './plugin-runtime.js' import { getInternalPlugins } from './internal-plugins/index.js' import { CLI_VERSION } from './version.js' +import { debug } from './debug.js' const WELL_KNOWN_PLUGIN_COMMANDS: Record = { codegen: 'Codegen', @@ -74,6 +75,7 @@ function collectPluginCommands(runtime: Awaited { const argv = process.argv.slice(2) const commandName = argv[0] + debug('cli', `chkit ${CLI_VERSION} — argv: [${argv.join(', ')}]`) if (!commandName || commandName === '-h' || commandName === '--help') { const configPathArg = extractConfigPath(argv) @@ -135,6 +137,7 @@ async function main(): Promise { }) const resolved = registry.get(commandName) + debug('cli', `command "${commandName}" resolved: ${resolved ? (resolved.isPlugin ? 'plugin' : 'core') : 'not found'}`) if (!resolved) { const wellKnown = WELL_KNOWN_PLUGIN_COMMANDS[commandName] @@ -188,6 +191,7 @@ main() } catch { // onComplete errors must not mask the original error } + debug('cli', 'fatal error', error instanceof Error ? { message: error.message, stack: error.stack, ...(('code' in error) ? { code: (error as NodeJS.ErrnoException).code } : {}) } : error) console.error(formatFatalError(error)) process.exit(1) }) diff --git a/packages/cli/src/bin/command-dispatch.ts b/packages/cli/src/bin/command-dispatch.ts index 73d9831..757ae8d 100644 --- a/packages/cli/src/bin/command-dispatch.ts +++ b/packages/cli/src/bin/command-dispatch.ts @@ -3,6 +3,7 @@ import { parseFlags, UnknownFlagError, MissingFlagValueError, type ParsedFlags } import { typedFlags } from '../plugins.js' import type { CommandRegistry, RegisteredCommand } from './command-registry.js' import { resolveDirs } from './config.js' +import { debug } from './debug.js' import { GLOBAL_FLAGS } from './global-flags.js' import { printOutput } from './json-output.js' import type { PluginRuntime } from './plugin-runtime.js' @@ -214,8 +215,10 @@ export async function runResolvedCommand(input: { onAmbiguousPluginSubcommand?: () => void }): Promise { if (input.resolved.isPlugin && !input.resolved.run) { + debug('dispatch', `routing to plugin command "${input.commandName}"`) await runPluginCommand(input) return } + debug('dispatch', `routing to core command "${input.commandName}"`) await runCoreOrBuiltinCommand(input) } diff --git a/packages/cli/src/bin/commands/check.ts b/packages/cli/src/bin/commands/check.ts index 5e0e94d..20a7e3a 100644 --- a/packages/cli/src/bin/commands/check.ts +++ b/packages/cli/src/bin/commands/check.ts @@ -2,6 +2,7 @@ import { mkdir } from 'node:fs/promises' import { summarizeDriftReasons } from '../../drift.js' import { typedFlags, type CommandDef, type CommandRunContext } from '../../plugins.js' +import { debug } from '../debug.js' import { GLOBAL_FLAGS } from '../global-flags.js' import { emitJson } from '../json-output.js' import { createJournalStore } from '../journal-store.js' @@ -25,6 +26,7 @@ async function cmdCheck(runCtx: CommandRunContext): Promise { const jsonMode = f['--json'] === true const tableSelector = f['--table'] const { migrationsDir, metaDir } = dirs + debug('check', `flags: strict=${strict}, json=${jsonMode}`) await mkdir(migrationsDir, { recursive: true }) if (!ctx.hasExecutor) { @@ -100,6 +102,7 @@ async function cmdCheck(runCtx: CommandRunContext): Promise { failedChecks.push(`plugin:${result.plugin}`) } } + debug('check', `results: pending=${pending.length}, checksumMismatches=${checksumMismatches.length}, drift=${drift?.drifted ?? 'n/a'}, pluginChecks=${pluginResults.length}, failedChecks=[${failedChecks.join(', ')}]`) const ok = failedChecks.length === 0 const driftReasonSummary = drift ? summarizeDriftReasons({ diff --git a/packages/cli/src/bin/commands/drift.ts b/packages/cli/src/bin/commands/drift.ts index f1cad00..81392c9 100644 --- a/packages/cli/src/bin/commands/drift.ts +++ b/packages/cli/src/bin/commands/drift.ts @@ -11,6 +11,7 @@ import { type ObjectDriftDetail, type TableDriftDetail, } from '../../drift.js' +import { debug } from '../debug.js' import { emitJson } from '../json-output.js' import { readSnapshot } from '../migration-store.js' import { resolveTableScope, tableKeysFromDefinitions, type TableScope } from '../table-scope.js' @@ -49,6 +50,7 @@ export async function buildDriftPayload( if (!executor) throw new Error('clickhouse config is required for drift checks') const db = executor + debug('drift', `building drift payload — expected: ${snapshot.definitions.length} definitions`) let actualObjects: SchemaObjectRef[] try { actualObjects = await db.listSchemaObjects() @@ -115,6 +117,8 @@ export async function buildDriftPayload( .filter((item): item is NonNullable => item !== null) .sort((a, b) => a.table.localeCompare(b.table)) + debug('drift', `comparison: missing=${missing.length}, extra=${extra.length}, kindMismatches=${kindMismatches.length}, objectDrift=${objectDrift.length}, tableDrift=${tableDrift.length}`) + const drifted = missing.length > 0 || extra.length > 0 || diff --git a/packages/cli/src/bin/commands/generate.ts b/packages/cli/src/bin/commands/generate.ts index ad1c5cf..50484ec 100644 --- a/packages/cli/src/bin/commands/generate.ts +++ b/packages/cli/src/bin/commands/generate.ts @@ -35,6 +35,7 @@ import { resolveActiveTableMappings, } from './generate/rename-mappings.js' import { emitGenerateApplyOutput, emitGeneratePlanOutput } from './generate/output.js' +import { debug } from '../debug.js' const GENERATE_FLAGS = defineFlags([ { name: '--name', type: 'string', description: 'Migration name', placeholder: '' }, @@ -60,6 +61,8 @@ async function cmdGenerate(ctx: CommandRunContext): Promise { const planMode = f['--dryrun'] === true const jsonMode = f['--json'] === true + debug('generate', `flags: name=${migrationName ?? '(auto)'}, dryrun=${planMode}, json=${jsonMode}`) + await pluginRuntime.runOnConfigLoaded({ command: 'generate', config, @@ -119,6 +122,8 @@ async function cmdGenerate(ctx: CommandRunContext): Promise { activeTableMappings ) + debug('generate', `previous snapshot: ${previousDefinitions.length} definitions, current: ${definitions.length} definitions`) + let plan: ReturnType try { plan = planDiff(remappedPreviousDefinitions, definitions) @@ -173,6 +178,8 @@ async function cmdGenerate(ctx: CommandRunContext): Promise { }) : definitions + debug('generate', `plan: ${plan.operations.length} operations — writing artifacts`) + const result = await generateArtifacts({ definitions: artifactDefinitions, migrationsDir, diff --git a/packages/cli/src/bin/commands/migrate.ts b/packages/cli/src/bin/commands/migrate.ts index 4aba62b..0444aa4 100644 --- a/packages/cli/src/bin/commands/migrate.ts +++ b/packages/cli/src/bin/commands/migrate.ts @@ -23,6 +23,7 @@ import { type DestructiveOperationMarker, } from '../safety-markers.js' import { databaseKeyFromOperationKey, resolveTableScope, tableKeyFromOperationKey, tableKeysFromDefinitions } from '../table-scope.js' +import { debug } from '../debug.js' const MIGRATE_FLAGS = defineFlags([ { name: '--apply', type: 'boolean', description: 'Apply pending migrations on ClickHouse (no prompt)' }, @@ -103,6 +104,7 @@ async function cmdMigrate(runCtx: CommandRunContext): Promise { const jsonMode = f['--json'] === true const { migrationsDir, metaDir } = dirs + debug('migrate', `flags: execute=${executeRequested}, allowDestructive=${allowDestructive}, json=${jsonMode}`) if (!ctx.hasExecutor) { throw new Error('clickhouse config is required for migrate (journal is stored in ClickHouse)') @@ -127,7 +129,11 @@ async function cmdMigrate(runCtx: CommandRunContext): Promise { const journal = await journalStore.readJournal() const appliedNames = new Set(journal.applied.map((entry) => entry.name)) const pendingAll = files.filter((f) => !appliedNames.has(f)) + debug('migrate', `migrations: total=${files.length}, applied=${journal.applied.length}, pending=${pendingAll.length}`) const checksumMismatches = await findChecksumMismatches(migrationsDir, journal) + if (checksumMismatches.length > 0) { + debug('migrate', `checksum mismatches: ${checksumMismatches.map((m) => m.name).join(', ')}`) + } if (checksumMismatches.length > 0) { if (jsonMode) { @@ -275,10 +281,12 @@ async function cmdMigrate(runCtx: CommandRunContext): Promise { const appliedNow: MigrationJournalEntry[] = [] for (const file of pending) { + debug('migrate', `applying ${file}`) const fullPath = join(migrationsDir, file) const sql = await readFile(fullPath, 'utf8') const parsedStatements = extractExecutableStatements(sql) const operationSummaries = extractMigrationOperationSummaries(sql) + debug('migrate', `${file}: ${parsedStatements.length} statements, ${operationSummaries.length} operations`) const statements = await pluginRuntime.runOnBeforeApply({ command: 'migrate', config, diff --git a/packages/cli/src/bin/commands/status.ts b/packages/cli/src/bin/commands/status.ts index c258299..826a190 100644 --- a/packages/cli/src/bin/commands/status.ts +++ b/packages/cli/src/bin/commands/status.ts @@ -1,6 +1,7 @@ import { mkdir } from 'node:fs/promises' import type { CommandDef, CommandRunContext } from '../../plugins.js' +import { debug } from '../debug.js' import { emitJson } from '../json-output.js' import { createJournalStore } from '../journal-store.js' import { findChecksumMismatches, listMigrations } from '../migration-store.js' @@ -31,6 +32,8 @@ async function cmdStatus(runCtx: CommandRunContext): Promise { const pending = files.filter((f) => !appliedNames.has(f)) const checksumMismatches = await findChecksumMismatches(migrationsDir, journal) + debug('status', `files=${files.length}, applied=${journal.applied.length}, pending=${pending.length}, checksumMismatches=${checksumMismatches.length}`) + const databaseMissing = journalStore.databaseMissing const payload = { migrationsDir, diff --git a/packages/cli/src/bin/config.ts b/packages/cli/src/bin/config.ts index 3ebec57..c3e1b86 100644 --- a/packages/cli/src/bin/config.ts +++ b/packages/cli/src/bin/config.ts @@ -12,6 +12,7 @@ import { type ChxConfigInput, type ResolvedChxConfig, } from '@chkit/core' +import { debug } from './debug.js' export const DEFAULT_CONFIG_FILE = 'clickhouse.config.ts' @@ -24,6 +25,7 @@ export async function loadConfig( env: ChxConfigEnv = {} ): Promise<{ config: ResolvedChxConfig; path: string }> { const configPath = resolve(process.cwd(), configPathArg ?? DEFAULT_CONFIG_FILE) + debug('config', `resolving config at ${configPath}`) if (!existsSync(configPath)) { throw new Error(`Config not found at ${configPath}. Run 'chkit init' first.`) } @@ -36,12 +38,20 @@ export async function loadConfig( ) } - const userConfig = isConfigFunction(candidate) ? await candidate(env) : (candidate as ChxConfig) + const isFn = isConfigFunction(candidate) + debug('config', `config export is ${isFn ? 'function' : 'object'}`) + const userConfig = isFn ? await candidate(env) : (candidate as ChxConfig) + const config = resolveConfig(userConfig) - return { - config: resolveConfig(userConfig), - path: configPath, - } + debug('config', `loaded`, { + schema: config.schema, + outDir: config.outDir, + migrationsDir: config.migrationsDir, + clickhouse: config.clickhouse ? `${config.clickhouse.url} (db: ${config.clickhouse.database ?? 'default'})` : 'not configured', + plugins: (config.plugins ?? []).length, + }) + + return { config, path: configPath } } export async function writeIfMissing(filePath: string, content: string): Promise { diff --git a/packages/cli/src/bin/debug.ts b/packages/cli/src/bin/debug.ts new file mode 100644 index 0000000..5893a18 --- /dev/null +++ b/packages/cli/src/bin/debug.ts @@ -0,0 +1,22 @@ +import process from 'node:process' + +const enabled = process.env.CHKIT_DEBUG === '1' || process.env.CHKIT_DEBUG === 'true' + +function timestamp(): string { + const now = new Date() + return now.toISOString().slice(11, 23) // HH:mm:ss.SSS +} + +export function debug(category: string, message: string, detail?: unknown): void { + if (!enabled) return + const prefix = `[chkit:${category}]` + if (detail !== undefined) { + console.error(`${timestamp()} ${prefix} ${message}`, detail) + } else { + console.error(`${timestamp()} ${prefix} ${message}`) + } +} + +export function isDebugEnabled(): boolean { + return enabled +} diff --git a/packages/cli/src/bin/journal-store.ts b/packages/cli/src/bin/journal-store.ts index acca90d..204c8ee 100644 --- a/packages/cli/src/bin/journal-store.ts +++ b/packages/cli/src/bin/journal-store.ts @@ -3,6 +3,7 @@ import type { ChxConfig } from '@chkit/core' import type { MigrationJournal, MigrationJournalEntry } from './migration-store.js' import { CLI_VERSION } from './version.js' +import { debug } from './debug.js' export interface JournalStore { readJournal(): Promise @@ -38,6 +39,7 @@ function isRetryableInsertRace(error: unknown): boolean { export function createJournalStore(db: ClickHouseExecutor): JournalStore { const journalTable = resolveJournalTableName() + debug('journal', `journal table: ${journalTable}${process.env.CHKIT_JOURNAL_TABLE ? ' (from CHKIT_JOURNAL_TABLE)' : ''}`) const createTableSql = `CREATE TABLE IF NOT EXISTS ${journalTable} ( name String, applied_at DateTime64(3, 'UTC'), @@ -51,38 +53,36 @@ SETTINGS index_granularity = 1` async function ensureTable(): Promise { if (bootstrapped) return - // Probe whether the table already exists before issuing CREATE TABLE. - // On ClickHouse Cloud, repeated CREATE TABLE IF NOT EXISTS can fail with - // "already exists in metadata backend with different schema" because the - // engine normalisation (SharedMergeTree vs SharedMergeTree()) differs - // between the stored metadata and the new DDL statement. + debug('journal', `probing journal table "${journalTable}"`) try { await db.query(`SELECT name FROM ${journalTable} LIMIT 0`) + debug('journal', 'journal table exists') bootstrapped = true return } catch (error) { if (isUnknownDatabaseError(error)) { + debug('journal', 'database does not exist') _databaseMissing = true bootstrapped = true return } - // Table does not exist yet – create it below. } + debug('journal', 'creating journal table') try { await db.command(createTableSql) } catch (error) { if (isUnknownDatabaseError(error)) { + debug('journal', 'database missing on CREATE — deferring') _databaseMissing = true bootstrapped = true return } throw error } - // On ClickHouse Cloud, DDL propagation across nodes may lag behind the - // CREATE TABLE acknowledgment. Wait until the table is queryable. for (let attempt = 0; attempt < 10; attempt++) { try { await db.query(`SELECT name FROM ${journalTable} LIMIT 0`) + debug('journal', `DDL propagation confirmed (attempt ${attempt + 1})`) break } catch { await new Promise((r) => setTimeout(r, 250)) @@ -96,8 +96,10 @@ SETTINGS index_granularity = 1` return _databaseMissing }, async readJournal(): Promise { + debug('journal', 'reading journal') await ensureTable() if (_databaseMissing) { + debug('journal', 'database missing — returning empty journal') return { version: 1, applied: [] } } try { @@ -108,6 +110,7 @@ SETTINGS index_granularity = 1` const rows = await db.query( `SELECT name, applied_at, checksum, chkit_version FROM ${journalTable} ORDER BY name SETTINGS select_sequential_consistency = 1` ) + debug('journal', `journal has ${rows.length} applied entries`) return { version: 1, applied: rows.map((row) => ({ @@ -119,8 +122,9 @@ SETTINGS index_granularity = 1` }, async appendEntry(entry: MigrationJournalEntry): Promise { + debug('journal', `appending entry: ${entry.name} (checksum: ${entry.checksum})`) if (_databaseMissing) { - // A migration may have created the database — reset and retry. + debug('journal', 'resetting databaseMissing flag — migration may have created the database') _databaseMissing = false bootstrapped = false } @@ -136,6 +140,7 @@ SETTINGS index_granularity = 1` if (!isRetryableInsertRace(error) || attempt === maxAttempts) { throw error } + debug('journal', `insert race detected — retrying (attempt ${attempt}/${maxAttempts})`) await new Promise((r) => setTimeout(r, attempt * 150)) } } diff --git a/packages/cli/src/bin/plugin-runtime.ts b/packages/cli/src/bin/plugin-runtime.ts index 275df4e..d0c5386 100644 --- a/packages/cli/src/bin/plugin-runtime.ts +++ b/packages/cli/src/bin/plugin-runtime.ts @@ -31,6 +31,7 @@ import type { } from '../plugins.js' import { isInlinePluginRegistration } from '../plugins.js' import type { TableScope } from './table-scope.js' +import { debug, isDebugEnabled } from './debug.js' interface LoadedPlugin { options: Record @@ -126,6 +127,99 @@ function normalizePluginRegistration( } } +function wrapExecutorWithDebug(executor: ClickHouseExecutor): ClickHouseExecutor { + if (!isDebugEnabled()) return executor + + return { + async command(sql: string): Promise { + debug('clickhouse', `command: ${sql.slice(0, 200)}${sql.length > 200 ? '...' : ''}`) + const start = performance.now() + try { + await executor.command(sql) + debug('clickhouse', `command OK (${Math.round(performance.now() - start)}ms)`) + } catch (error) { + debug('clickhouse', `command FAILED (${Math.round(performance.now() - start)}ms)`, error instanceof Error ? error.message : error) + throw error + } + }, + async query(sql: string): Promise { + debug('clickhouse', `query: ${sql.slice(0, 200)}${sql.length > 200 ? '...' : ''}`) + const start = performance.now() + try { + const rows = await executor.query(sql) + debug('clickhouse', `query OK — ${rows.length} rows (${Math.round(performance.now() - start)}ms)`) + return rows + } catch (error) { + debug('clickhouse', `query FAILED (${Math.round(performance.now() - start)}ms)`, error instanceof Error ? error.message : error) + throw error + } + }, + async insert>(params: { table: string; values: T[] }): Promise { + debug('clickhouse', `insert into ${params.table} — ${params.values.length} rows`) + const start = performance.now() + try { + await executor.insert(params) + debug('clickhouse', `insert OK (${Math.round(performance.now() - start)}ms)`) + } catch (error) { + debug('clickhouse', `insert FAILED (${Math.round(performance.now() - start)}ms)`, error instanceof Error ? error.message : error) + throw error + } + }, + async submit(sql: string, queryId?: string): Promise { + debug('clickhouse', `submit${queryId ? ` (id: ${queryId})` : ''}: ${sql.slice(0, 200)}${sql.length > 200 ? '...' : ''}`) + const start = performance.now() + try { + const id = await executor.submit(sql, queryId) + debug('clickhouse', `submit OK — id: ${id} (${Math.round(performance.now() - start)}ms)`) + return id + } catch (error) { + debug('clickhouse', `submit FAILED (${Math.round(performance.now() - start)}ms)`, error instanceof Error ? error.message : error) + throw error + } + }, + async queryStatus(queryId: string, options?: { afterTime?: string }) { + debug('clickhouse', `queryStatus for ${queryId}`) + const start = performance.now() + try { + const status = await executor.queryStatus(queryId, options) + debug('clickhouse', `queryStatus: ${status.status} (${Math.round(performance.now() - start)}ms)`) + return status + } catch (error) { + debug('clickhouse', `queryStatus FAILED (${Math.round(performance.now() - start)}ms)`, error instanceof Error ? error.message : error) + throw error + } + }, + async listSchemaObjects() { + debug('clickhouse', 'listSchemaObjects') + const start = performance.now() + try { + const objects = await executor.listSchemaObjects() + debug('clickhouse', `listSchemaObjects OK — ${objects.length} objects (${Math.round(performance.now() - start)}ms)`) + return objects + } catch (error) { + debug('clickhouse', `listSchemaObjects FAILED (${Math.round(performance.now() - start)}ms)`, error instanceof Error ? error.message : error) + throw error + } + }, + async listTableDetails(databases: string[]) { + debug('clickhouse', `listTableDetails for databases: [${databases.join(', ')}]`) + const start = performance.now() + try { + const tables = await executor.listTableDetails(databases) + debug('clickhouse', `listTableDetails OK — ${tables.length} tables (${Math.round(performance.now() - start)}ms)`) + return tables + } catch (error) { + debug('clickhouse', `listTableDetails FAILED (${Math.round(performance.now() - start)}ms)`, error instanceof Error ? error.message : error) + throw error + } + }, + async close(): Promise { + debug('clickhouse', 'closing connections') + await executor.close() + }, + } +} + function formatPluginError(pluginName: string, hook: string, error: unknown): Error { const message = error instanceof Error ? error.message : String(error) return new Error(`Plugin "${pluginName}" failed in ${hook}: ${message}`) @@ -207,6 +301,11 @@ export async function loadPluginRuntime(input: { throw new Error(`Duplicate plugin name "${plugin.manifest.name}" in config.plugins.`) } + debug('plugin', `loaded "${plugin.manifest.name}" v${plugin.manifest.version ?? '?'}`, { + hooks: Object.keys(plugin.hooks ?? {}), + commands: (plugin.commands ?? []).map((c) => c.name), + }) + const item: LoadedPlugin = { plugin, options: normalized.options, @@ -231,6 +330,7 @@ export async function loadPluginRuntime(input: { if (item.plugin.manifest.name === pluginName) continue const hook = item.plugin.hooks?.onBeforePluginCommand if (!hook) continue + debug('hook', `onBeforePluginCommand → ${item.plugin.manifest.name} (target: ${pluginName}:${commandName})`) try { const result = await hook({ ...context, @@ -238,7 +338,10 @@ export async function loadPluginRuntime(input: { command: commandName, options: item.options, }) - if (result.handled) return result + if (result.handled) { + debug('hook', `onBeforePluginCommand ← ${item.plugin.manifest.name} handled command (exitCode: ${result.exitCode})`) + return result + } } catch (error) { throw formatPluginError(item.plugin.manifest.name, 'onBeforePluginCommand', error) } @@ -266,10 +369,12 @@ export async function loadPluginRuntime(input: { plugins: loaded, async resolveContext(input) { const hasClickhouseConfig = !!input.config.clickhouse + debug('context', `resolving executor — clickhouse config: ${hasClickhouseConfig ? 'yes' : 'no'}`) + const rawExecutor = hasClickhouseConfig + ? createClickHouseExecutor(input.config.clickhouse!) + : NULL_EXECUTOR const defaults: PluginContext = { - executor: hasClickhouseConfig - ? createClickHouseExecutor(input.config.clickhouse!) - : NULL_EXECUTOR, + executor: wrapExecutorWithDebug(rawExecutor), hasExecutor: hasClickhouseConfig, } let ctx = defaults @@ -279,6 +384,7 @@ export async function loadPluginRuntime(input: { try { const result = await hook({ ...input, defaults }) if (result && typeof result === 'object' && 'executor' in result && result.executor) { + debug('context', `plugin "${item.plugin.manifest.name}" provided executor override`) // Plugin returned an executor override — close the default one if (ctx.executor !== defaults.executor) { // A previous plugin already overrode — close that one @@ -310,6 +416,7 @@ export async function loadPluginRuntime(input: { for (const item of loaded) { const hook = item.plugin.hooks?.onInit if (!hook) continue + debug('hook', `onInit → ${item.plugin.manifest.name}`) try { await hook({ ...context, options: item.options }) } catch (error) { @@ -322,6 +429,7 @@ export async function loadPluginRuntime(input: { for (const item of loaded) { const hook = item.plugin.hooks?.onComplete if (!hook) continue + debug('hook', `onComplete → ${item.plugin.manifest.name} (exitCode: ${exitCode})`) try { await hook({ ...context, exitCode, options: item.options }) } catch (error) { @@ -334,6 +442,7 @@ export async function loadPluginRuntime(input: { for (const item of loaded) { const hook = item.plugin.hooks?.onConfigLoaded if (!hook) continue + debug('hook', `onConfigLoaded → ${item.plugin.manifest.name}`) try { await hook({ ...context, options: item.options, tableScope }) } catch (error) { @@ -346,9 +455,11 @@ export async function loadPluginRuntime(input: { for (const item of loaded) { const hook = item.plugin.hooks?.onSchemaLoaded if (!hook) continue + debug('hook', `onSchemaLoaded → ${item.plugin.manifest.name} (${definitions.length} definitions)`) try { const next = await hook({ ...context, definitions }) if (Array.isArray(next)) { + debug('hook', `onSchemaLoaded ← ${item.plugin.manifest.name} returned ${next.length} definitions`) definitions = canonicalizeDefinitions(next) } } catch (error) { @@ -363,9 +474,13 @@ export async function loadPluginRuntime(input: { for (const item of loaded) { const hook = item.plugin.hooks?.onPlanCreated if (!hook) continue + debug('hook', `onPlanCreated → ${item.plugin.manifest.name} (${plan.operations.length} operations)`) try { const next = await hook({ ...context, tableScope, plan }) - if (next) plan = next + if (next) { + debug('hook', `onPlanCreated ← ${item.plugin.manifest.name} modified plan (${next.operations.length} operations)`) + plan = next + } } catch (error) { throw formatPluginError(item.plugin.manifest.name, 'onPlanCreated', error) } @@ -377,9 +492,13 @@ export async function loadPluginRuntime(input: { for (const item of loaded) { const hook = item.plugin.hooks?.onBeforeApply if (!hook) continue + debug('hook', `onBeforeApply → ${item.plugin.manifest.name} (${context.migration}, ${statements.length} statements)`) try { const result = await hook({ ...context, statements }) - if (result?.statements) statements = result.statements + if (result?.statements) { + debug('hook', `onBeforeApply ← ${item.plugin.manifest.name} modified statements (${result.statements.length})`) + statements = result.statements + } } catch (error) { throw formatPluginError(item.plugin.manifest.name, 'onBeforeApply', error) } @@ -390,6 +509,7 @@ export async function loadPluginRuntime(input: { for (const item of loaded) { const hook = item.plugin.hooks?.onAfterApply if (!hook) continue + debug('hook', `onAfterApply → ${item.plugin.manifest.name} (${context.migration})`) try { await hook(context) } catch (error) { @@ -403,9 +523,11 @@ export async function loadPluginRuntime(input: { for (const item of loaded) { const hook = item.plugin.hooks?.onCheck if (!hook) continue + debug('hook', `onCheck → ${item.plugin.manifest.name}`) try { const result = await hook({ ...context, options: item.options, tableScope }) if (!result) continue + debug('hook', `onCheck ← ${item.plugin.manifest.name}: ok=${result.ok}, findings=${result.findings.length}`) results.push({ plugin: result.plugin || item.plugin.manifest.name, evaluated: result.evaluated, @@ -434,6 +556,7 @@ export async function loadPluginRuntime(input: { }, runOnBeforePluginCommand: runBeforePluginCommandHooks, async runPluginCommand(pluginName, commandName, context) { + debug('command', `running plugin command "${pluginName}:${commandName}"`) const item = byName.get(pluginName) if (!item) return 1 const command = (item.plugin.commands ?? []).find((entry) => entry.name === commandName) diff --git a/packages/cli/src/bin/schema-loader.ts b/packages/cli/src/bin/schema-loader.ts index ad7e5ef..76b73c6 100644 --- a/packages/cli/src/bin/schema-loader.ts +++ b/packages/cli/src/bin/schema-loader.ts @@ -2,7 +2,12 @@ import process from 'node:process' import { loadSchemaDefinitions as loadSchemaDefinitionsFromCore } from '@chkit/core/schema-loader' import type { SchemaDefinition } from '@chkit/core' +import { debug } from './debug.js' export async function loadSchemaDefinitions(schemaGlobs: string | string[]): Promise { - return loadSchemaDefinitionsFromCore(schemaGlobs, { cwd: process.cwd() }) + const globs = Array.isArray(schemaGlobs) ? schemaGlobs : [schemaGlobs] + debug('schema', `loading definitions from globs: [${globs.join(', ')}] (cwd: ${process.cwd()})`) + const definitions = await loadSchemaDefinitionsFromCore(schemaGlobs, { cwd: process.cwd() }) + debug('schema', `loaded ${definitions.length} schema definitions`) + return definitions }