feat(cli): add debug logging via CHKIT_DEBUG env variable

.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.

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<string, string> = {
   codegen: 'Codegen',
@@ -74,6 +75,7 @@ function collectPluginCommands(runtime: Awaited<ReturnType<typeof loadPluginRunt
 async function main(): Promise<void> {
   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<void> {
   })
 
   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)
   })

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<void> {
   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)
 }

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<void> {
   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<void> {
         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({

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<typeof item> => 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 ||

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: '<name>' },
@@ -60,6 +61,8 @@ async function cmdGenerate(ctx: CommandRunContext): Promise<void> {
   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<void> {
     activeTableMappings
   )
 
+  debug('generate', `previous snapshot: ${previousDefinitions.length} definitions, current: ${definitions.length} definitions`)
+
   let plan: ReturnType<typeof planDiff>
   try {
     plan = planDiff(remappedPreviousDefinitions, definitions)
@@ -173,6 +178,8 @@ async function cmdGenerate(ctx: CommandRunContext): Promise<void> {
       })
     : definitions
 
+  debug('generate', `plan: ${plan.operations.length} operations — writing artifacts`)
+
   const result = await generateArtifacts({
     definitions: artifactDefinitions,
     migrationsDir,

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<void> {
   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<void> {
     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<void> {
     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,

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<void> {
   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,

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<void> {

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
+}

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<MigrationJournal>
@@ -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<void> {
     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<MigrationJournal> {
+      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<MigrationRow>(
         `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<void> {
+      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))
         }
       }