feat: Introduce a logging context which holds logs and source lines w…

…hich allows for log messages to include a summary of the source code which resulted in the log message
algorandfoundation · Oct 16, 2024 · eb48a3a · eb48a3a
1 parent 88b9a10
commit eb48a3a
Show file tree

Hide file tree

Showing 9 changed files with 151 additions and 86 deletions.
diff --git a/src/cli.ts b/src/cli.ts
@@ -2,7 +2,8 @@ import { Command, Option } from 'commander'
 import { z } from 'zod'
 import { buildCompileOptions } from './compile-options'
 import { compile } from './index'
-import { logger, LogLevel } from './logger'
+import { logger, LoggingContext, LogLevel } from './logger'
+import { ConsoleLogSink } from './logger/sinks/console-log-sink'
 import type { PuyaPassThroughOptions } from './puya/options'
 import { defaultPuyaOptions, LocalsCoalescingStrategy } from './puya/options'
 
@@ -105,20 +106,21 @@ function cli() {
     )
 
     .action((a, o) => {
+      using logCtx = LoggingContext.create()
       try {
         const paths = cliArgumentsSchema.parse(a)
         const cliOptions = cliOptionsSchema.parse(o)
-        logger.configure({
-          minLogLevel: cliOptions.logLevel,
-        })
+        logger.configure([new ConsoleLogSink(cliOptions.logLevel)])
         const compileOptions = buildCompileOptions({
           paths,
           ...cliOptions,
         })
         const passThroughOptions: PuyaPassThroughOptions = cliOptions
 
         if (cliOptions.isolatedFiles) {
+          let anyHasErrors = false
           for (const file of compileOptions.filePaths) {
+            using logCtx = LoggingContext.create()
             try {
               compile(
                 {
@@ -130,15 +132,14 @@ function cli() {
             } catch (e) {
               logger.critical(undefined, `Compilation failure: ${e}`)
             }
+            anyHasErrors ||= logCtx.hasErrors()
           }
-          if (logger.export().some((l) => l.level === LogLevel.Error || l.level === LogLevel.Critical)) {
+          if (anyHasErrors) {
             process.exit(-1)
           }
         } else {
-          const result = compile(compileOptions, passThroughOptions)
-          if (result.logs.some((l) => l.level === LogLevel.Error || l.level === LogLevel.Critical)) {
-            process.exit(-1)
-          }
+          compile(compileOptions, passThroughOptions)
+          logCtx.exitIfErrors()
         }
       } catch (e) {
         if (e instanceof Error) {

diff --git a/src/index.ts b/src/index.ts
@@ -5,9 +5,7 @@ import { buildAwst } from './awst_build'
 import { registerPTypes } from './awst_build/ptypes/register'
 import { typeRegistry } from './awst_build/type-registry'
 import type { CompileOptions } from './compile-options'
-import { AwstBuildFailureError } from './errors'
-import type { LogEvent } from './logger'
-import { logger } from './logger'
+import { logger, LoggingContext } from './logger'
 import type { CreateProgramResult } from './parser'
 import { createTsProgram } from './parser'
 import { invokePuya } from './puya'
@@ -46,11 +44,10 @@ export const encodingUtil = {
 }
 
 export type CompileResult = {
-  logs: LogEvent[]
   programDirectory: string
   awst?: AWST[]
   ast?: Record<string, ts.SourceFile>
-  compilationSet: CompilationSet
+  compilationSet?: CompilationSet
 }
 
 type Hooks = {
@@ -72,25 +69,28 @@ type Hooks = {
 }
 
 export function compile(options: CompileOptions, passThroughOptions: PuyaPassThroughOptions, hooks?: Partial<Hooks>): CompileResult {
+  const loggerCtx = LoggingContext.current
   registerPTypes(typeRegistry)
   const programResult = createTsProgram(options)
+  if (loggerCtx.hasErrors()) {
+    logger.critical(undefined, 'TypeScript parse failure')
+    return {
+      programDirectory: programResult.programDirectory,
+      ast: programResult.sourceFiles,
+    }
+  }
   if (hooks?.onProgramCreated?.(programResult) === false) {
     throw new Error('Compilation halted by onProgramCreated hook')
   }
-  let moduleAwst: AWST[] = []
-  let compilationSet: CompilationSet = []
-  try {
-    ;[moduleAwst, compilationSet] = buildAwst(programResult, options)
-  } catch (e) {
-    if (e instanceof AwstBuildFailureError) {
-      return {
-        programDirectory: programResult.programDirectory,
-        logs: logger.export(),
-        ast: programResult.sourceFiles,
-        compilationSet,
-      }
+  const [moduleAwst, compilationSet] = buildAwst(programResult, options)
+  if (loggerCtx.hasErrors()) {
+    logger.critical(undefined, 'AWST build failure')
+    return {
+      programDirectory: programResult.programDirectory,
+      awst: moduleAwst,
+      ast: programResult.sourceFiles,
+      compilationSet,
     }
-    throw e
   }
   if (hooks?.onAwstBuilt?.(moduleAwst, compilationSet) === false) {
     throw new Error('Compilation halted by onAwstBuilt hook')
@@ -109,7 +109,6 @@ export function compile(options: CompileOptions, passThroughOptions: PuyaPassThr
   return {
     programDirectory: programResult.programDirectory,
     awst: moduleAwst,
-    logs: logger.export(),
     ast: programResult.sourceFiles,
     compilationSet,
   }

diff --git a/src/logger.ts → src/logger/index.ts b/src/logger.ts → src/logger/index.ts
@@ -1,17 +1,6 @@
-import chalk from 'chalk'
-import { SourceLocation } from './awst/source-location'
-import { AwstBuildFailureError, CodeError, PuyaError, TodoError } from './errors'
-
-type ColorFn = (text: string) => string
-const levelConfig: Record<LogEvent['level'], { colorFn: ColorFn; writeFn: (...args: unknown[]) => void; order: number }> = {
-  /* eslint-disable no-console */
-  debug: { colorFn: chalk.green, writeFn: console.debug, order: 0 },
-  info: { colorFn: chalk.green, writeFn: console.info, order: 1 },
-  warn: { colorFn: chalk.yellow, writeFn: console.warn, order: 2 },
-  error: { colorFn: chalk.red, writeFn: console.error, order: 3 },
-  critical: { colorFn: chalk.red, writeFn: console.error, order: 4 },
-  /* eslint-enable no-console */
-}
+import { SourceLocation } from '../awst/source-location'
+import { AwstBuildFailureError, CodeError, PuyaError, TodoError } from '../errors'
+import type { LogSink } from './sinks'
 
 type NodeOrSourceLocation = SourceLocation | { sourceLocation: SourceLocation }
 
@@ -22,6 +11,18 @@ export enum LogLevel {
   Debug = 'debug',
   Critical = 'critical',
 }
+const logLevelToInt = {
+  [LogLevel.Critical]: 4,
+  [LogLevel.Error]: 3,
+  [LogLevel.Info]: 1,
+  [LogLevel.Warn]: 2,
+  [LogLevel.Debug]: 0,
+}
+
+export const isMinLevel = (logLevel: LogLevel, minLevel: LogLevel): boolean => {
+  return logLevelToInt[minLevel] <= logLevelToInt[logLevel]
+}
+
 const errorOrCritical = new Set([LogLevel.Error, LogLevel.Critical])
 
 export const isErrorOrCritical = (l: LogLevel) => errorOrCritical.has(l)
@@ -33,48 +34,21 @@ export type LogEvent = {
 }
 
 class PuyaLogger {
-  private logEvents: LogEvent[] = []
-  private minLogLevel: LogLevel = LogLevel.Debug
-
-  public configure(options?: { outputToConsole?: boolean; minLogLevel?: LogLevel }) {
-    if (options?.outputToConsole !== undefined) this.outputToConsole = options.outputToConsole
-    if (options?.minLogLevel !== undefined) {
-      this.minLogLevel = options.minLogLevel
-    }
+  private logSinks: LogSink[] = []
+  public configure(sinks: LogSink[]) {
+    this.logSinks = sinks
   }
 
-  outputToConsole: boolean = true
-  constructor() {}
-
   private addLog(level: LogEvent['level'], source: NodeOrSourceLocation | undefined, message: string) {
-    const config = levelConfig[level]
-    if (config.order < levelConfig[this.minLogLevel].order) return
-
     const logEvent: LogEvent = {
       sourceLocation: source ? (source instanceof SourceLocation ? source : source.sourceLocation) : undefined,
       message,
       level,
     }
-    this.logEvents.push(logEvent)
-    if (!this.outputToConsole) return
-
-    let logText = `${config.colorFn(logEvent.level)}: ${logEvent.message}`
-    if (logEvent.sourceLocation) {
-      logText = `${logEvent.sourceLocation} ${logText}`
+    LoggingContext.current.logEvents.push(logEvent)
+    for (const sink of this.logSinks) {
+      if (isMinLevel(logEvent.level, sink.minLogLevel)) sink.add(logEvent)
     }
-    config.writeFn(logText)
-  }
-
-  reset(): void {
-    this.logEvents = []
-  }
-
-  hasErrors(): boolean {
-    return this.logEvents.some((e) => e.level === 'error')
-  }
-
-  export(): LogEvent[] {
-    return this.logEvents.slice()
   }
 
   error(error: Error): void
@@ -127,3 +101,38 @@ export const logPuyaExceptions = <T>(action: () => T, sourceLocation: SourceLoca
     throw new AwstBuildFailureError()
   }
 }
+
+export class LoggingContext implements Disposable {
+  logEvents: LogEvent[] = []
+  sourcesByPath: Record<string, string[]> = {}
+
+  private constructor() {}
+
+  hasErrors(): boolean {
+    return this.logEvents.some((e) => isErrorOrCritical(e.level))
+  }
+
+  exitIfErrors(): void {
+    if (this.hasErrors()) process.exit(1)
+  }
+
+  private static contexts: LoggingContext[] = []
+
+  static create(): Disposable & LoggingContext {
+    const ctx = new LoggingContext()
+    this.contexts.push(ctx)
+    return ctx
+  }
+  static get current() {
+    const top = LoggingContext.contexts.at(-1)
+    if (!top) {
+      throw new Error('There is no current context')
+    }
+    return top
+  }
+
+  [Symbol.dispose]() {
+    const top = LoggingContext.contexts.pop()
+    if (top !== this) throw new Error('Parent context is being disposed before a child context')
+  }
+}
diff --git a/src/logger/sinks/console-log-sink.ts b/src/logger/sinks/console-log-sink.ts
@@ -0,0 +1,44 @@
+import chalk from 'chalk'
+import type { SourceLocation } from '../../awst/source-location'
+import type { LogEvent, LogLevel } from '../index'
+import { LoggingContext } from '../index'
+import type { LogSink } from './index'
+
+type ColorFn = (text: string) => string
+const levelConfig: Record<LogEvent['level'], { colorFn: ColorFn; writeFn: (...args: unknown[]) => void }> = {
+  /* eslint-disable no-console */
+  debug: { colorFn: chalk.green, writeFn: console.debug },
+  info: { colorFn: chalk.green, writeFn: console.info },
+  warn: { colorFn: chalk.yellow, writeFn: console.warn },
+  error: { colorFn: chalk.red, writeFn: console.error },
+  critical: { colorFn: chalk.red, writeFn: console.error },
+  /* eslint-enable no-console */
+}
+
+export class ConsoleLogSink implements LogSink {
+  constructor(public readonly minLogLevel: LogLevel) {}
+
+  add(logEvent: LogEvent): void {
+    const config = levelConfig[logEvent.level]
+
+    let logText = `${config.colorFn(logEvent.level)}: ${logEvent.message}`
+    if (logEvent.sourceLocation) {
+      const sourceLocationText = logEvent.sourceLocation.toString()
+      const indentSize = sourceLocationText.length + logEvent.level.length + 4
+
+      logText = `${sourceLocationText} ${logText}${this.getSourceSummary(logEvent.sourceLocation, indentSize)}`
+    }
+    config.writeFn(logText)
+  }
+
+  getSourceSummary(sourceLocation: SourceLocation, indent: number): string {
+    const sourceFile = LoggingContext.current.sourcesByPath[sourceLocation.file]
+    if (!sourceFile) return ''
+
+    const line = sourceFile[sourceLocation.line - 1]
+    const trimmedLine = line.trimStart()
+    const marker = `${''.padStart(sourceLocation.column - (line.length - trimmedLine.length))}^${''.padStart(Math.max(sourceLocation.endColumn - sourceLocation.column - 1, 0), '~')}`
+    const indentChars = ''.padStart(indent, ' ')
+    return `\n${indentChars}${trimmedLine}\n${indentChars}${marker}`
+  }
+}
diff --git a/src/logger/sinks/index.ts b/src/logger/sinks/index.ts
@@ -0,0 +1,6 @@
+import type { LogEvent, LogLevel } from '../index'
+
+export type LogSink = {
+  readonly minLogLevel: LogLevel
+  add(e: LogEvent): void
+}
diff --git a/src/parser/index.ts b/src/parser/index.ts
@@ -1,7 +1,7 @@
 import ts from 'typescript'
 import { SourceLocation } from '../awst/source-location'
 import type { CompileOptions } from '../compile-options'
-import { logger } from '../logger'
+import { logger, LoggingContext } from '../logger'
 import type { DeliberateAny } from '../typescript-helpers'
 import { normalisePath } from '../util'
 import { resolveModuleNameLiterals } from './resolve-module-name-literals'
@@ -33,8 +33,6 @@ export function createTsProgram(options: CompileOptions): CreateProgramResult {
   )
   const programDirectory = program.getCurrentDirectory()
 
-  reportDiagnostics(program)
-
   const sourceFiles = Object.fromEntries(
     program
       .getSourceFiles()
@@ -50,6 +48,14 @@ export function createTsProgram(options: CompileOptions): CreateProgramResult {
       }),
   )
 
+  LoggingContext.current.sourcesByPath = Object.fromEntries(
+    Object.entries(sourceFiles).map(([path, file]) => {
+      return [path, file.getFullText().replace(/\r\n/g, '\n').split(/\n/g)]
+    }),
+  )
+
+  reportDiagnostics(program)
+
   return {
     sourceFiles,
     program,

diff --git a/src/parser/json-serialize-source-files.ts b/src/parser/json-serialize-source-files.ts
@@ -7,7 +7,7 @@ export function jsonSerializeSourceFiles(sourceFiles: SourceFileMapping, program
     Object.fromEntries(Object.entries(sourceFiles).map(([key, value]) => [path.join(programDirectory, key), value] as const)),
     (key, value) => {
       if (ts.isSourceFile(value)) {
-        return value.getFullText().split(/\n/g)
+        return value.getFullText().replace(/\r\n/g, '\n').split(/\n/g)
       }
       return value
     },

diff --git a/tests/approvals/_run.spec.ts b/tests/approvals/_run.spec.ts
@@ -1,11 +1,12 @@
 import { describe, expect, it } from 'vitest'
 import { compile } from '../../src'
 import { buildCompileOptions } from '../../src/compile-options'
-import { isErrorOrCritical, LogLevel } from '../../src/logger'
+import { isErrorOrCritical, LoggingContext, LogLevel } from '../../src/logger'
 import { defaultPuyaOptions } from '../../src/puya/options'
 import { invariant } from '../../src/util'
 
 describe('Approvals', () => {
+  using logCtx = LoggingContext.create()
   const result = compile(
     buildCompileOptions({
       outputAwstJson: false,
@@ -25,10 +26,10 @@ describe('Approvals', () => {
   const paths = Object.entries(result.ast ?? {}).map(([path, ast]) => ({
     path,
     ast,
-    logs: result.logs.filter((l) => l.sourceLocation?.file === path && isErrorOrCritical(l.level)),
+    logs: logCtx.logEvents.filter((l) => l.sourceLocation?.file === path && isErrorOrCritical(l.level)),
   }))
 
-  const generalErrorLogs = result.logs.filter((l) => !l.sourceLocation && isErrorOrCritical(l.level))
+  const generalErrorLogs = logCtx.logEvents.filter((l) => !l.sourceLocation && isErrorOrCritical(l.level))
 
   it('There should be no general error logs', () => {
     if (generalErrorLogs.length) {