feat: zisi system logging (#1214)

* feat: zisi system logging

src/utils/logger.ts

@@ -0,0 +1,26 @@
+// adapted from https://github.com/netlify/edge-bundler/blob/main/node/logger.ts
+type LogFunction = (...args: unknown[]) => void
+
+const noopLogger: LogFunction = () => {
+  // no-op
+}
+
+interface Logger {
+  system: LogFunction
+  user: LogFunction
+}
+
+const getLogger = (systemLogger?: LogFunction, debug = false): Logger => {
+  // If there is a system logger configured, we'll use that. If there isn't,
+  // we'll pipe system logs to stdout if `debug` is enabled and swallow them
+  // otherwise.
+  const system = systemLogger ?? (debug ? console.log : noopLogger)
+
+  return {
+    system,
+    user: console.log,
+  }
+}
+
+export { getLogger }
+export type { LogFunction, Logger }

src/utils/timer.ts

@@ -0,0 +1,15 @@
+import { hrtime } from 'process'
+
+const NANOSECS_TO_SECS = 1e9
+
+export const startTimer = function () {
+  return hrtime()
+}
+
+// returns the time in nanoseconds
+export const endTimer = function ([startSecs, startNsecs]: [number, number]) {
+  const [endSecs, endNsecs] = hrtime()
+  const durationNs = (endSecs - startSecs) * NANOSECS_TO_SECS + endNsecs - startNsecs
+
+  return durationNs
+}

src/zip.ts

@@ -14,7 +14,9 @@ import { addArchiveSize } from './utils/archive_size.js'
 import { RuntimeCache } from './utils/cache.js'
 import { formatZipResult } from './utils/format_result.js'
 import { listFunctionsDirectories, resolveFunctionsDirectories } from './utils/fs.js'
+import { getLogger, LogFunction } from './utils/logger.js'
 import { nonNullable } from './utils/non_nullable.js'
+import { endTimer, startTimer } from './utils/timer.js'
 
 interface ZipFunctionOptions {
   archiveFormat?: ArchiveFormat
@@ -23,6 +25,8 @@ interface ZipFunctionOptions {
   featureFlags?: FeatureFlags
   repositoryRoot?: string
   zipGo?: boolean
+  systemLog?: LogFunction
+  debug?: boolean
 }
 
 export type ZipFunctionsOptions = ZipFunctionOptions & {
@@ -54,10 +58,13 @@ export const zipFunctions = async function (
     manifest,
     parallelLimit = DEFAULT_PARALLEL_LIMIT,
     repositoryRoot = basePath,
+    systemLog,
+    debug,
   }: ZipFunctionsOptions = {},
 ) {
   validateArchiveFormat(archiveFormat)
 
+  const logger = getLogger(systemLog, debug)
   const cache = new RuntimeCache()
   const featureFlags = getFlags(inputFeatureFlags)
   const srcFolders = resolveFunctionsDirectories(relativeSrcFolders)
@@ -80,6 +87,7 @@ export const zipFunctions = async function (
         ...(func.config.nodeModuleFormat === ModuleFormat.ESM ? { zisi_pure_esm_mjs: true } : {}),
       }
 
+      const startIntervalTime = startTimer()
       const zipResult = await func.runtime.zipFunction({
         archiveFormat,
         basePath,
@@ -97,6 +105,15 @@ export const zipFunctions = async function (
         srcPath: func.srcPath,
         stat: func.stat,
       })
+      const durationNs = endTimer(startIntervalTime)
+      const logObject = {
+        name: func.name,
+        config: func.config,
+        featureFlags: functionFlags,
+        durationNs,
+      }
+
+      logger.system(`Function details: ${JSON.stringify(logObject, null, 2)}`)
 
       return { ...zipResult, mainFile: func.mainFile, name: func.name, runtime: func.runtime }
     },
@@ -119,6 +136,7 @@ export const zipFunctions = async function (
   return formattedResults
 }
 
+// eslint-disable-next-line max-statements
 export const zipFunction = async function (
   relativeSrcPath: string,
   destFolder: string,
@@ -128,10 +146,13 @@ export const zipFunction = async function (
     config: inputConfig = {},
     featureFlags: inputFeatureFlags,
     repositoryRoot = basePath,
+    systemLog,
+    debug,
   }: ZipFunctionOptions = {},
 ) {
   validateArchiveFormat(archiveFormat)
 
+  const logger = getLogger(systemLog, debug)
   const featureFlags = getFlags(inputFeatureFlags)
   const srcPath = resolve(relativeSrcPath)
   const cache = new RuntimeCache()
@@ -161,6 +182,7 @@ export const zipFunction = async function (
     // extend the feature flags with `zisi_pure_esm_mjs` enabled.
     ...(config.nodeModuleFormat === ModuleFormat.ESM ? { zisi_pure_esm_mjs: true } : {}),
   }
+  const startIntervalTime = startTimer()
   const zipResult = await runtime.zipFunction({
     archiveFormat,
     basePath,
@@ -178,6 +200,15 @@ export const zipFunction = async function (
     srcPath,
     stat: stats,
   })
+  const durationNs = endTimer(startIntervalTime)
+  const logObject = {
+    name,
+    config,
+    featureFlags: functionFlags,
+    durationNs,
+  }
+
+  logger.system(`Function details: ${JSON.stringify(logObject, null, 2)}`)
 
   return formatZipResult({ ...zipResult, mainFile, name, runtime })
 }

tests/unit/utils/logger.test.ts

@@ -0,0 +1,60 @@
+import { afterEach, test, expect, vi } from 'vitest'
+
+import { getLogger } from '../../../src/utils/logger.js'
+
+const consoleLog = console.log
+
+const noopLogger = () => {
+  // no-op
+}
+
+afterEach(() => {
+  // Restoring global `console.log`.
+  console.log = consoleLog
+})
+
+test('Prints user logs to stdout', () => {
+  const mockConsoleLog = vi.fn()
+  console.log = mockConsoleLog
+
+  const logger1 = getLogger(noopLogger, true)
+  const logger2 = getLogger(noopLogger, false)
+
+  logger1.user('Hello with `debug: true`')
+  logger2.user('Hello with `debug: false`')
+
+  expect(mockConsoleLog).toHaveBeenCalledTimes(2)
+  expect(mockConsoleLog).toHaveBeenNthCalledWith(1, 'Hello with `debug: true`')
+  expect(mockConsoleLog).toHaveBeenNthCalledWith(2, 'Hello with `debug: false`')
+})
+
+test('Prints system logs to the system logger provided', () => {
+  const mockSystemLog = vi.fn()
+  const mockConsoleLog = vi.fn()
+  console.log = mockSystemLog
+
+  const logger1 = getLogger(mockSystemLog, true)
+  const logger2 = getLogger(mockSystemLog, false)
+
+  logger1.system('Hello with `debug: true`')
+  logger2.system('Hello with `debug: false`')
+
+  expect(mockConsoleLog).toHaveBeenCalledTimes(0)
+  expect(mockSystemLog).toHaveBeenCalledTimes(2)
+  expect(mockSystemLog).toHaveBeenNthCalledWith(1, 'Hello with `debug: true`')
+  expect(mockSystemLog).toHaveBeenNthCalledWith(2, 'Hello with `debug: false`')
+})
+
+test('Prints system logs to stdout if there is no system logger provided and `debug` is enabled', () => {
+  const mockConsoleLog = vi.fn()
+  console.log = mockConsoleLog
+
+  const logger1 = getLogger(undefined, true)
+  const logger2 = getLogger(undefined, false)
+
+  logger1.system('Hello with `debug: true`')
+  logger2.system('Hello with `debug: false`')
+
+  expect(mockConsoleLog).toHaveBeenCalledTimes(1)
+  expect(mockConsoleLog).toHaveBeenNthCalledWith(1, 'Hello with `debug: true`')
+})