Runme logging in output channel (#521)

* Improve logging

* colored error logging

* remove demo lines

* Update src/extension/survey.ts

Co-authored-by: Max Stoumen <max@mxs.dev>

* Update src/extension/survey.ts

Co-authored-by: Max Stoumen <max@mxs.dev>

* Update src/extension/logger.ts

Co-authored-by: Max Stoumen <max@mxs.dev>

* Update src/extension/index.ts

Co-authored-by: Max Stoumen <max@mxs.dev>

* PR feedback

* make logLevel uppercase

* re-use strip ansi regex

---------

Co-authored-by: Max Stoumen <max@mxs.dev>

__mocks__/vscode.ts

@@ -74,6 +74,9 @@ export const terminal = {
 }
 
 export const window = {
+  createOutputChannel: vi.fn().mockReturnValue({
+    appendLine: vi.fn()
+  }),
   showWarningMessage: vi.fn(),
   showInformationMessage: vi.fn(),
   showErrorMessage: vi.fn(),

src/extension/executors/runner.ts

@@ -16,6 +16,7 @@ import {
 } from 'vscode'
 import { Subject, debounceTime } from 'rxjs'
 
+import getLogger from '../logger'
 import { ClientMessages } from '../../constants'
 import { ClientMessage } from '../../types'
 import { PLATFORM_OS } from '../constants'
@@ -41,6 +42,7 @@ import { handleVercelDeployOutput, isVercelDeployScript } from './vercel'
 
 import type { IEnvironmentManager } from '.'
 
+const log = getLogger('executeRunner')
 const LABEL_LIMIT = 15
 const BACKGROUND_TASK_HIDE_TIMEOUT = 2000
 const MIME_TYPES_WITH_CUSTOM_RENDERERS = ['text/plain']
@@ -285,7 +287,8 @@ export async function executeRunner(
         // runs `program.close()` implicitly
         execution.terminate()
       } catch (err: any) {
-        throw new Error(`[Runme] Failed to terminate task: ${(err as Error).message}`)
+        log.error(`Failed to terminate task: ${(err as Error).message}`)
+        throw new Error(err)
       }
     })
 

src/extension/executors/shell.ts

@@ -8,10 +8,12 @@ import { NotebookCellOutputManager } from '../cell'
 import { ENV_STORE } from '../constants'
 import type { Kernel } from '../kernel'
 import { getAnnotations } from '../utils'
+import getLogger from '../logger'
 
 import { handleVercelDeployOutput, isVercelDeployScript } from './vercel'
 
 const MIME_TYPES_WITH_CUSTOM_RENDERERS = ['text/plain']
+const log = getLogger('shellExecutor')
 
 async function shellExecutor(
   this: Kernel,
@@ -30,7 +32,7 @@ async function shellExecutor(
   }
   const outputItems: Buffer[] = []
   const child = spawn(postScript, { cwd, shell: true, env })
-  console.log(`[Runme] Started process on pid ${child.pid}`)
+  log.info(`Started process on pid ${child.pid}`)
   /**
    * this needs more work / specification
    */

src/extension/executors/task.ts

@@ -6,6 +6,7 @@ import {
   ShellExecution
 } from 'vscode'
 
+import getLogger from '../logger'
 // import { ExperimentalTerminal } from "../terminal"
 import { getCmdShellSeq, getAnnotations, getTerminalRunmeId } from '../utils'
 import { PLATFORM_OS, ENV_STORE } from '../constants'
@@ -17,6 +18,7 @@ import { sh as inlineSh } from './shell'
 
 const BACKGROUND_TASK_HIDE_TIMEOUT = 2000
 const LABEL_LIMIT = 15
+const log = getLogger('taskExecutor')
 
 export function closeTerminalByEnvID (id: string, kill?: boolean) {
   const terminal = window.terminals.find(t => getTerminalRunmeId(t) === id)
@@ -99,7 +101,7 @@ async function taskExecutor(
         closeTerminalByEnvID(RUNME_ID)
         resolve(0)
       } catch (err: any) {
-        console.error(`[Runme] Failed to terminate task: ${(err as Error).message}`)
+        log.error(`Failed to terminate task: ${(err as Error).message}`)
         resolve(1)
       }
     }))

src/extension/executors/vercel/deploy.ts

@@ -10,6 +10,7 @@ import { OutputType } from '../../../constants'
 import type { Kernel } from '../../kernel'
 import type { VercelState } from '../../../types'
 import { NotebookCellOutputManager, updateCellMetadata } from '../../cell'
+import getLogger from '../../logger'
 
 import { listTeams, getUser, getProject, getProjects, createProject, cancelDeployment, VercelProject } from './api'
 import { getAuthToken, quickPick, updateGitIgnore, createVercelFile } from './utils'
@@ -20,6 +21,7 @@ const LINK_OPTIONS = [
   'Link Project to existing Vercel project',
   'Create a new Vercel Project'
 ]
+const log = getLogger('Vercel - deploy')
 
 export async function deploy (
   this: Kernel,
@@ -131,7 +133,7 @@ export async function deploy (
     /**
      * deploy application
      */
-    console.log(`[Runme] Deploy project "${deployParams.name}"`)
+    log.info(`Deploy project "${deployParams.name}"`)
     let deploymentId: string | null = null
     let deployCanceled = false
     this.context.subscriptions.push(exec.token.onCancellationRequested(async () => {

src/extension/handler/uri.ts

@@ -8,12 +8,15 @@ import got from 'got'
 import { v4 as uuidv4 } from 'uuid'
 import { TelemetryReporter } from 'vscode-telemetry'
 
+import getLogger from '../logger'
+
 import {
   getProjectDir, getTargetDirName, getSuggestedProjectName, writeBootstrapFile,
   parseParams
 } from './utils'
 
 const REGEX_WEB_RESOURCE = /^https?:\/\//
+const log = getLogger('RunmeUriHandler')
 
 export class RunmeUriHandler implements UriHandler {
   #context: ExtensionContext
@@ -22,7 +25,7 @@ export class RunmeUriHandler implements UriHandler {
   }
 
   async handleUri(uri: Uri) {
-    console.log(`[Runme] triggered RunmeUriHandler with ${uri}`)
+    log.info(`triggered RunmeUriHandler with ${uri}`)
     const params = new URLSearchParams(uri.query)
     const command = params.get('command')
 
@@ -152,7 +155,7 @@ export class RunmeUriHandler implements UriHandler {
       .then(() => writeBootstrapFile(targetDirUri, fileToOpen))
 
     progress.report({ increment: 50, message: 'Opening project...' })
-    console.log(`[Runme] Attempt to open folder ${targetDirUri.fsPath}`)
+    log.info(`Attempt to open folder ${targetDirUri.fsPath}`)
     await commands.executeCommand('vscode.openFolder', targetDirUri, {
       forceNewWindow: true
     })

src/extension/handler/utils.ts

@@ -2,9 +2,11 @@ import url from 'node:url'
 
 import { workspace, window, Uri, ExtensionContext } from 'vscode'
 
+import getLogger from '../logger'
 import { BOOTFILE } from '../constants'
 
 const config = workspace.getConfiguration('runme.checkout')
+const log = getLogger('RunmeUriHandler')
 
 /**
  * Get the project directory from the settings object.
@@ -86,7 +88,7 @@ export async function writeBootstrapFile(targetDirUri: Uri, fileToOpen: string)
     Uri.joinPath(targetDirUri, BOOTFILE),
     enc.encode(fileToOpen)
   )
-  console.log(`[Runme] Created temporary bootstrap file to open ${fileToOpen}`)
+  log.info(`Created temporary bootstrap file to open ${fileToOpen}`)
 }
 
 /**

src/extension/index.ts

@@ -2,25 +2,27 @@ import type { ExtensionContext } from 'vscode'
 import { TelemetryReporter } from 'vscode-telemetry'
 
 import { RunmeExtension } from './extension'
+import getLogger from './logger'
 
 declare const INSTRUMENTATION_KEY: string
 
 const ext = new RunmeExtension()
+const log = getLogger()
 
 export async function activate (context: ExtensionContext) {
   TelemetryReporter.configure(context, INSTRUMENTATION_KEY)
-  console.log('[Runme] Activating Extension')
+  log.info('Activating Extension')
   try {
     await ext.initialize(context)
-    console.log('[Runme] Extension successfully activated')
+    log.info('Extension successfully activated')
   } catch (err: any) {
-    console.log(`[Runme] Failed to initialize the extension: ${err.message}`)
+    log.error(`Failed to initialize the extension: ${err.message}`)
   }
 
   TelemetryReporter.sendTelemetryEvent('activate')
 }
 
 export function deactivate () {
-  console.log('[Runme] Deactivating Extension')
+  log.info('Deactivating Extension')
   TelemetryReporter.sendTelemetryEvent('deactivate')
 }

src/extension/kernel.ts

@@ -20,6 +20,7 @@ import { ClientMessages } from '../constants'
 import { API } from '../utils/deno/api'
 import { postClientMessage } from '../utils/messaging'
 
+import getLogger from './logger'
 import executor, { type IEnvironmentManager, ENV_STORE_MANAGER } from './executors'
 import { DENO_ACCESS_TOKEN_KEY } from './constants'
 import { resetEnv, getKey, getAnnotations, hashDocumentUri, processEnviron, isWindows } from './utils'
@@ -36,6 +37,8 @@ enum ConfirmationItems {
   Cancel = 'Cancel'
 }
 
+const log = getLogger('Kernel')
+
 export class Kernel implements Disposable {
   static readonly type = 'runme' as const
 
@@ -146,7 +149,7 @@ export class Kernel implements Disposable {
           }
 
           if (cell.metadata?.['runme.dev/uuid'] === undefined) {
-            console.error(`[Runme] Cell with index ${cell.index} lacks uuid`)
+            log.error(`Cell with index ${cell.index} lacks uuid`)
             continue
           }
 
@@ -215,7 +218,7 @@ export class Kernel implements Disposable {
       return
     }
 
-    console.error(`[Runme] Unknown kernel event type: ${message.type}`)
+    log.error(`Unknown kernel event type: ${message.type}`)
   }
 
   private async _executeAll(cells: NotebookCell[]) {
@@ -323,7 +326,7 @@ export class Kernel implements Disposable {
       )
         .catch((e) => {
           window.showErrorMessage(`Internal failure executing runner: ${e.message}`)
-          console.error('[Runme] Internal failure executing runner', e.message)
+          log.error('Internal failure executing runner', e.message)
           return false
         })
 
@@ -364,7 +367,7 @@ export class Kernel implements Disposable {
           this.environment = env
         } catch (e: any) {
           window.showErrorMessage(`Failed to create environment for gRPC Runner: ${e.message}`)
-          console.error('[Runme] Failed to create gRPC Runner environment', e)
+          log.error('Failed to create gRPC Runner environment', e)
         }
       })
     }

src/extension/logger.ts

@@ -0,0 +1,48 @@
+import util from 'node:util'
+
+import { window } from 'vscode'
+
+import { stripANSI } from '../utils/ansi'
+
+const outputChannel = window.createOutputChannel('Runme')
+
+const DEFAULT_LOG_LEVEL: LogLevel = 'info'
+
+/**
+ * VS Code currently doesn't support colors, see
+ * https://github.com/microsoft/vscode/issues/571
+ * Therefor keep this minimal.
+ */
+const colors = {
+  reset: '\x1b[0m',
+  red: '\x1b[31m',
+  green: '\x1b[32m',
+  yellow: '\x1b[33m'
+} as const
+type LogLevel = 'trace' | 'info' | 'warn' | 'error'
+
+function color (color: keyof typeof colors, text: string) {
+  return `${colors[color]}${text}${colors.reset}`
+}
+
+function log (scope?: string, logLevel: LogLevel = DEFAULT_LOG_LEVEL, ...logParams: string[]) {
+  const now = new Date()
+  const scopeAddition = scope ? color('yellow', `(${scope})`) : ''
+  const prefix = util.format(
+    `${color('green' ,'[%s]')} ${color('yellow', '%s')} Runme%s:`,
+    now.toISOString(),
+    (logLevel && logLevel.toUpperCase()) ?? '',
+    scopeAddition
+  )
+  console.log(prefix, ...logParams)
+  outputChannel.appendLine(stripANSI([prefix, ...logParams].join(' ')))
+}
+
+export default function getLogger (scope?: string) {
+  return {
+    trace: (...logParams: string[]) => log(scope, 'trace', ...logParams),
+    info: (...logParams: string[]) => log(scope, 'info', ...logParams),
+    warn: (...logParams: string[]) => log(scope, 'warn', ...logParams),
+    error: (...logParams: string[]) => log(scope, 'error', ...logParams)
+  }
+}

src/extension/provider/runmeTask.ts

@@ -18,6 +18,7 @@ import {
   NotebookCellData,
 } from 'vscode'
 
+import getLogger from '../logger'
 import { getAnnotations, getWorkspaceEnvs, prepareCmdSeq } from '../utils'
 import { Serializer, RunmeTaskDefinition } from '../../types'
 import { SerializerBase } from '../serializer'
@@ -26,6 +27,7 @@ import { getShellPath, parseCommandSeq } from '../executors/utils'
 import { Kernel } from '../kernel'
 
 type TaskOptions = Pick<RunmeTaskDefinition, 'closeTerminalOnSuccess' | 'isBackground' | 'cwd'>
+const log = getLogger('RunmeTaskProvider')
 
 export interface RunmeTask extends Task {
   definition: Required<RunmeTaskDefinition>
@@ -43,7 +45,7 @@ export class RunmeTaskProvider implements TaskProvider {
 
   public async provideTasks(token: CancellationToken): Promise<Task[]> {
     if(!this.runner) {
-      console.error('Tasks only supported with gRPC runner enabled')
+      log.error('Tasks only supported with gRPC runner enabled')
       return []
     }
 
@@ -61,7 +63,7 @@ export class RunmeTaskProvider implements TaskProvider {
       mdContent = (await workspace.fs.readFile(current))
     } catch (err: any) {
       if (err.code !== 'FileNotFound') {
-        console.log(err)
+        log.error(`${err.message}`)
       }
       return []
     }

src/extension/server/runmeServer.ts

@@ -6,6 +6,7 @@ import { ChannelCredentials } from '@grpc/grpc-js'
 import { GrpcTransport } from '@protobuf-ts/grpc-transport'
 import { Disposable, Uri, EventEmitter } from 'vscode'
 
+import getLogger from '../logger'
 import {
   HealthCheckRequest,
   HealthCheckResponse_ServingStatus
@@ -34,6 +35,8 @@ export interface IServerConfig {
     }
 }
 
+const log = getLogger('RunmeServer')
+
 class RunmeServer implements Disposable {
     #port: number
     #process: ChildProcessWithoutNullStreams | undefined
@@ -195,7 +198,7 @@ class RunmeServer implements Disposable {
 
         process.on('close', (code) => {
             if (this.#loggingEnabled) {
-                console.log(`[Runme] Server process #${this.#process?.pid} closed with code ${code}`)
+                log.info(`Server process #${this.#process?.pid} closed with code ${code}`)
             }
             this.#onClose.fire({ code })
 
@@ -204,12 +207,12 @@ class RunmeServer implements Disposable {
 
 
         process.stderr.once('data', () => {
-            console.log(`[Runme] Server process #${this.#process?.pid} started on port ${this.#port}`)
+            log.info(`Server process #${this.#process?.pid} started on port ${this.#port}`)
         })
 
         process.stderr.on('data', (data) => {
             if (this.#loggingEnabled) {
-                console.log(data.toString())
+                log.info(data.toString())
             }
         })
 

src/extension/survey.ts

@@ -20,6 +20,9 @@ import { TelemetryReporter } from 'vscode-telemetry'
 
 import { Kernel } from './kernel'
 import { isWindows } from './utils'
+import getLogger from './logger'
+
+const log = getLogger('WinDefaultShell')
 
 export class WinDefaultShell implements Disposable {
   static readonly #id: string = 'runme.surveyWinDefaultShell'
@@ -85,7 +88,7 @@ export class WinDefaultShell implements Disposable {
       unlinkSync(tmpfile)
     } catch (err) {
       if (err instanceof Error) {
-        console.log(err.message)
+        log.error(`Failed to remove temporary default shell: ${err.message}`)
       }
     }
     // eslint-disable-next-line max-len
@@ -131,7 +134,7 @@ export class WinDefaultShell implements Disposable {
       unlinkSync(tmpfile)
     } catch (err) {
       if (err instanceof Error) {
-        console.log(err.message)
+        log.error(`Failed to remove temporary default shell: ${err.message}`)
       }
     }
   }