Merge pull request #123 from TrueNine/dev

Update release CLI workflow to publish SDK native bindings

Author: TrueNine

cli/src/commands/CleanCommand.ts

@@ -5,13 +5,35 @@ export class CleanCommand implements Command {
   readonly name = 'clean'
 
   async execute(ctx: CommandContext): Promise<CommandResult> {
-    const {logger, outputPlugins, createCleanContext} = ctx
-    logger.info('running clean pipeline', {command: 'clean'})
+    const {logger, outputPlugins, createCleanContext, collectedOutputContext} = ctx
+    logger.info('started', {
+      command: 'clean',
+      pluginCount: outputPlugins.length,
+      projectCount: collectedOutputContext.workspace.projects.length,
+      workspaceDir: collectedOutputContext.workspace.directory.path
+    })
+    logger.info('clean phase started', {phase: 'cleanup'})
     const result = await performCleanup(outputPlugins, createCleanContext(false), logger)
     if (result.violations.length > 0 || result.conflicts.length > 0) {
+      logger.info('clean halted', {
+        phase: 'cleanup',
+        conflicts: result.conflicts.length,
+        violations: result.violations.length,
+        ...result.message != null ? {message: result.message} : {}
+      })
       return {success: false, filesAffected: 0, dirsAffected: 0, ...result.message != null ? {message: result.message} : {}}
     }
-    logger.info('clean complete', {deletedFiles: result.deletedFiles, deletedDirs: result.deletedDirs})
+    logger.info('clean phase complete', {
+      phase: 'cleanup',
+      deletedFiles: result.deletedFiles,
+      deletedDirs: result.deletedDirs,
+      errors: result.errors.length
+    })
+    logger.info('complete', {
+      command: 'clean',
+      filesAffected: result.deletedFiles,
+      dirsAffected: result.deletedDirs
+    })
     return {success: true, filesAffected: result.deletedFiles, dirsAffected: result.deletedDirs}
   }
 }

cli/src/commands/ExecuteCommand.ts

@@ -5,17 +5,47 @@ export class ExecuteCommand implements Command {
   readonly name = 'execute'
 
   async execute(ctx: CommandContext): Promise<CommandResult> {
-    const {logger, outputPlugins, createCleanContext, createWriteContext} = ctx
-    logger.info('started', {command: 'execute'})
+    const {logger, outputPlugins, createCleanContext, createWriteContext, collectedOutputContext} = ctx
+    logger.info('started', {
+      command: 'execute',
+      pluginCount: outputPlugins.length,
+      projectCount: collectedOutputContext.workspace.projects.length,
+      workspaceDir: collectedOutputContext.workspace.directory.path
+    })
 
     const writeCtx = createWriteContext(false)
+    logger.info('execute phase started', {phase: 'collect-output-declarations'})
     const predeclaredOutputs = await collectOutputDeclarations(outputPlugins, writeCtx)
+    const declarationCount = [...predeclaredOutputs.values()]
+      .reduce((total, declarations) => total + declarations.length, 0)
+    logger.info('execute phase complete', {
+      phase: 'collect-output-declarations',
+      pluginCount: predeclaredOutputs.size,
+      declarationCount
+    })
+
+    logger.info('execute phase started', {phase: 'cleanup-before-write'})
     const cleanupResult = await performCleanup(outputPlugins, createCleanContext(false), logger, predeclaredOutputs)
     if (cleanupResult.violations.length > 0 || cleanupResult.conflicts.length > 0) {
+      logger.info('execute halted', {
+        phase: 'cleanup-before-write',
+        conflicts: cleanupResult.conflicts.length,
+        violations: cleanupResult.violations.length,
+        ...cleanupResult.message != null ? {message: cleanupResult.message} : {}
+      })
       return {success: false, filesAffected: 0, dirsAffected: 0, ...cleanupResult.message != null ? {message: cleanupResult.message} : {}}
     }
 
-    logger.info('cleanup complete', {deletedFiles: cleanupResult.deletedFiles, deletedDirs: cleanupResult.deletedDirs})
+    logger.info('execute phase complete', {
+      phase: 'cleanup-before-write',
+      deletedFiles: cleanupResult.deletedFiles,
+      deletedDirs: cleanupResult.deletedDirs
+    })
+
+    logger.info('execute phase started', {
+      phase: 'write-output-files',
+      declarationCount
+    })
     const results = await executeDeclarativeWriteOutputs(outputPlugins, writeCtx, predeclaredOutputs)
 
     let totalFiles = 0
@@ -29,17 +59,46 @@ export class ExecuteCommand implements Command {
       }
     }
 
+    logger.info('execute phase complete', {
+      phase: 'write-output-files',
+      pluginCount: results.size,
+      filesAffected: totalFiles,
+      dirsAffected: totalDirs,
+      writeErrors: writeErrors.length
+    })
+
     if (writeErrors.length > 0) {
+      logger.info('execute halted', {
+        phase: 'write-output-files',
+        writeErrors: writeErrors.length
+      })
       return {success: false, filesAffected: totalFiles, dirsAffected: totalDirs, message: writeErrors.join('\n')}
     }
 
+    logger.info('execute phase started', {phase: 'sync-wsl-mirrors'})
     const wslMirrorResult = await syncWindowsConfigIntoWsl(outputPlugins, writeCtx, void 0, predeclaredOutputs)
     if (wslMirrorResult.errors.length > 0) {
+      logger.info('execute halted', {
+        phase: 'sync-wsl-mirrors',
+        mirroredFiles: wslMirrorResult.mirroredFiles,
+        errors: wslMirrorResult.errors.length
+      })
       return {success: false, filesAffected: totalFiles, dirsAffected: totalDirs, message: wslMirrorResult.errors.join('\n')}
     }
 
     totalFiles += wslMirrorResult.mirroredFiles
-    logger.info('complete', {command: 'execute', pluginCount: results.size})
+    logger.info('execute phase complete', {
+      phase: 'sync-wsl-mirrors',
+      mirroredFiles: wslMirrorResult.mirroredFiles,
+      warnings: wslMirrorResult.warnings.length,
+      errors: wslMirrorResult.errors.length
+    })
+    logger.info('complete', {
+      command: 'execute',
+      pluginCount: results.size,
+      filesAffected: totalFiles,
+      dirsAffected: totalDirs
+    })
     return {success: true, filesAffected: totalFiles, dirsAffected: totalDirs}
   }
 }

cli/src/plugin-runtime.ts

@@ -71,14 +71,27 @@ function flushAndExit(code: number): never {
 async function main(): Promise<void> {
   const {subcommand, json, dryRun} = parseRuntimeArgs(process.argv)
   if (json) setGlobalLogLevel('silent')
+  const logger = createLogger('PluginRuntime')
+
+  logger.info('runtime bootstrap started', {subcommand, json, dryRun})
 
   const userPluginConfig = await createDefaultPluginConfig(process.argv, subcommand)
   let command = resolveRuntimeCommand(subcommand, dryRun)
   if (json && !new Set(['plugins']).has(command.name)) command = new JsonOutputCommand(command)
 
   const {context, outputPlugins, userConfigOptions} = userPluginConfig
-  const logger = createLogger('PluginRuntime')
+  logger.info('runtime configuration resolved', {
+    command: command.name,
+    pluginCount: outputPlugins.length,
+    projectCount: context.workspace.projects.length,
+    workspaceDir: context.workspace.directory.path,
+    ...context.aindexDir != null ? {aindexDir: context.aindexDir} : {}
+  })
   const runtimeTargets = discoverOutputRuntimeTargets(logger)
+  logger.info('runtime targets discovered', {
+    command: command.name,
+    jetbrainsCodexDirs: runtimeTargets.jetbrainsCodexDirs.length
+  })
   const createCleanContext = (dry: boolean): OutputCleanContext => ({
     logger,
     collectedOutputContext: context,
@@ -102,7 +115,15 @@ async function main(): Promise<void> {
     createCleanContext,
     createWriteContext
   }
+  logger.info('command dispatch started', {command: command.name})
   const result = await command.execute(commandCtx)
+  logger.info('command dispatch complete', {
+    command: command.name,
+    success: result.success,
+    filesAffected: result.filesAffected,
+    dirsAffected: result.dirsAffected,
+    ...result.message != null ? {message: result.message} : {}
+  })
   if (!result.success) flushAndExit(1)
   flushOutput()
 }

libraries/logger/src/index.test.ts

@@ -83,10 +83,28 @@ describe('logger bindings', () => {
 
     logger.info('hello', {count: 1})
 
-    expect(nativeLogger.log).toHaveBeenCalledWith('info', 'hello', '{"count":1}')
+    expect(nativeLogger.log).toHaveBeenCalledTimes(1)
+    expect(nativeLogger.log).toHaveBeenCalledWith(
+      'info',
+      'hello',
+      expect.any(String)
+    )
+    const payload = JSON.parse(String(nativeLogger.log.mock.calls[0]?.[2])) as Record<string, unknown>
+    expect(payload['count']).toBe(1)
+    expect(payload['loggerTiming']).toEqual(expect.any(String))
     expect(nativeLogger.logDiagnostic).not.toHaveBeenCalled()
   })
 
+  it('adds logger timing even when no metadata is provided', async () => {
+    const {createLogger} = await import('./index')
+    const logger = createLogger('logger-test')
+
+    logger.info('hello')
+
+    const payload = JSON.parse(String(nativeLogger.log.mock.calls[0]?.[2])) as Record<string, unknown>
+    expect(payload['loggerTiming']).toEqual(expect.any(String))
+  })
+
   it('skips serializing filtered plain logs on the JS side', async () => {
     const {createLogger} = await import('./index')
     const logger = createLogger('logger-test', 'info')

libraries/logger/src/index.ts

@@ -74,6 +74,11 @@ const LOG_LEVEL_PRIORITY: Readonly<Record<LogLevel, number>> = {
 let napiBinding: NapiLoggerModule | undefined,
   napiBindingError: Error | undefined
 
+const LOGGER_TIMING_STATE = {
+  processStartNs: process.hrtime.bigint(),
+  lastLogNs: void 0 as bigint | undefined
+}
+
 function isNapiLoggerModule(value: unknown): value is NapiLoggerModule {
   if (value == null || typeof value !== 'object') return false
 
@@ -267,12 +272,55 @@ function normalizeLogArguments(message: string | object, meta: unknown[]): {mess
   }
 }
 
+function formatElapsedMilliseconds(milliseconds: number): string {
+  if (!Number.isFinite(milliseconds) || milliseconds <= 0) return '0ms'
+  if (milliseconds >= 1000) return `${(milliseconds / 1000).toFixed(2)}s`
+  if (milliseconds >= 100) return `${Math.round(milliseconds)}ms`
+  return `${milliseconds.toFixed(1)}ms`
+}
+
+function createLoggerTimingLabel(): string {
+  const nowNs = process.hrtime.bigint()
+  const sinceStartMs = Number(nowNs - LOGGER_TIMING_STATE.processStartNs) / 1_000_000
+  const sincePreviousMs = LOGGER_TIMING_STATE.lastLogNs == null
+    ? sinceStartMs
+    : Number(nowNs - LOGGER_TIMING_STATE.lastLogNs) / 1_000_000
+
+  LOGGER_TIMING_STATE.lastLogNs = nowNs
+  return `+${formatElapsedMilliseconds(sincePreviousMs)} since previous log, ${formatElapsedMilliseconds(sinceStartMs)} since process start`
+}
+
+function injectLoggerTiming(metaJson: string | undefined): string {
+  const loggerTiming = createLoggerTimingLabel()
+  if (metaJson == null) return serializePayload({loggerTiming})
+
+  try {
+    const parsed = JSON.parse(metaJson) as unknown
+    if (parsed != null && typeof parsed === 'object' && !Array.isArray(parsed)) {
+      return serializePayload({
+        ...(parsed as Record<string, unknown>),
+        loggerTiming
+      })
+    }
+
+    return serializePayload({
+      loggerTiming,
+      meta: parsed
+    })
+  } catch {
+    return serializePayload({
+      loggerTiming,
+      meta: metaJson
+    })
+  }
+}
+
 function createLogMethod(instance: NapiLoggerInstance, loggerLevel: LogLevel, level: PlainLogLevel): LoggerMethod {
   return (message: string | object, ...meta: unknown[]): void => {
     if (!shouldEmitLog(level, loggerLevel)) return
 
     const {message: normalizedMessage, metaJson} = normalizeLogArguments(message, meta)
-    instance.log(level, normalizedMessage, metaJson)
+    instance.log(level, normalizedMessage, injectLoggerTiming(metaJson))
   }
 }