Enhance logging/trace for vscode extension

.chronus/changes/more-logging-vscode-2024-5-6-16-57-48.md

@@ -0,0 +1,10 @@
+---
+changeKind: feature
+packages:
+  - typespec-vscode
+---
+
+Enhance logging and trace
+ 1. Support "Developer: Set Log Level..." command to filter logs in TypeSpec output channel
+ 2. Add "typespecLanguageServer.trace.server" config for whether and how to send the traces from TypeSpec language server to client. (It still depends on client to decide whether to show these traces based on the configured Log Level.)
+ 3. More logs and traces are added for diagnostic and troubleshooting

.chronus/changes/more-logging-vscode-2024-5-7-12-41-0.md

@@ -0,0 +1,7 @@
+---
+changeKind: feature
+packages:
+  - "@typespec/compiler"
+---
+
+More logs and traces are added for diagnostic and troubleshooting in TypeSpec language server

packages/compiler/src/server/compile-service.ts

@@ -24,7 +24,7 @@ import { doIO, loadFile, resolveTspMain } from "../utils/misc.js";
 import { serverOptions } from "./constants.js";
 import { FileService } from "./file-service.js";
 import { FileSystemCache } from "./file-system-cache.js";
-import { CompileResult, ServerHost } from "./types.js";
+import { CompileResult, ServerHost, ServerLog } from "./types.js";
 import { UpdateManger } from "./update-manager.js";
 
 /**
@@ -63,7 +63,7 @@ export interface CompileServiceOptions {
   readonly fileService: FileService;
   readonly serverHost: ServerHost;
   readonly compilerHost: CompilerHost;
-  readonly log: (message: string, details?: unknown) => void;
+  readonly log: (log: ServerLog) => void;
 }
 
 export function createCompileService({
@@ -100,12 +100,14 @@ export function createCompileService({
     const path = await fileService.getPath(document);
     const mainFile = await getMainFileForDocument(path);
     const config = await getConfig(mainFile);
+    log({ level: "debug", message: `config resolved`, detail: config });
 
     const [optionsFromConfig, _] = resolveOptionsFromConfig(config, { cwd: path });
     const options: CompilerOptions = {
       ...optionsFromConfig,
       ...serverOptions,
     };
+    log({ level: "debug", message: `compiler options resolved`, detail: options });
 
     if (!fileService.upToDate(document)) {
       return undefined;
@@ -122,6 +124,10 @@ export function createCompileService({
       if (mainFile !== path && !program.sourceFiles.has(path)) {
         // If the file that changed wasn't imported by anything from the main
         // file, retry using the file itself as the main file.
+        log({
+          level: "debug",
+          message: `target file was not included in compiling, try to compile ${path} as main file directly`,
+        });
         program = await compileProgram(compilerHost, path, options, oldPrograms.get(path));
         oldPrograms.set(path, program);
       }
@@ -166,6 +172,10 @@ export function createCompileService({
     const lookupDir = entrypointStat.isDirectory() ? mainFile : getDirectoryPath(mainFile);
     const configPath = await findTypeSpecConfigPath(compilerHost, lookupDir, true);
     if (!configPath) {
+      log({
+        level: "debug",
+        message: `can't find path with config file, try to use default config`,
+      });
       return { ...defaultConfig, projectRoot: getDirectoryPath(mainFile) };
     }
 
@@ -210,6 +220,7 @@ export function createCompileService({
    */
   async function getMainFileForDocument(path: string) {
     if (path.startsWith("untitled:")) {
+      log({ level: "debug", message: `untitled document treated as its own main file: ${path}` });
       return path;
     }
 
@@ -237,6 +248,10 @@ export function createCompileService({
 
       const tspMain = resolveTspMain(pkg);
       if (typeof tspMain === "string") {
+        log({
+          level: "debug",
+          message: `tspMain resolved from package.json (${pkgPath}) as ${tspMain}`,
+        });
         mainFile = tspMain;
       }
 
@@ -249,23 +264,30 @@ export function createCompileService({
       );
 
       if (stat?.isFile()) {
+        log({ level: "debug", message: `main file found as ${candidate}` });
         return candidate;
       }
 
       const parentDir = getDirectoryPath(dir);
       if (parentDir === dir) {
         break;
       }
+      log({
+        level: "debug",
+        message: `main file not found in ${dir}, search in parent directory ${parentDir}`,
+      });
       dir = parentDir;
     }
 
+    log({ level: "debug", message: `reached directory root, using ${path} as main file` });
     return path;
 
     function logMainFileSearchDiagnostic(diagnostic: TypeSpecDiagnostic) {
-      log(
-        `Unexpected diagnostic while looking for main file of ${path}`,
-        formatDiagnostic(diagnostic)
-      );
+      log({
+        level: `error`,
+        message: `Unexpected diagnostic while looking for main file of ${path}`,
+        detail: formatDiagnostic(diagnostic),
+      });
     }
   }
 }

packages/compiler/src/server/file-system-cache.ts

@@ -1,6 +1,7 @@
 import { FileEvent } from "vscode-languageserver";
 import { SourceFile } from "../core/types.js";
 import { FileService } from "./file-service.js";
+import { ServerLog } from "./types.js";
 
 export interface FileSystemCache {
   get(path: string): Promise<CachedFile | CachedError | undefined>;
@@ -27,19 +28,32 @@ export interface CachedError {
 }
 export function createFileSystemCache({
   fileService,
+  log,
 }: {
   fileService: FileService;
+  log: (log: ServerLog) => void;
 }): FileSystemCache {
   const cache = new Map<string, CachedFile | CachedError>();
   let changes: FileEvent[] = [];
   return {
     async get(path: string) {
       for (const change of changes) {
         const path = await fileService.fileURLToRealPath(change.uri);
+        log({
+          level: "trace",
+          message: `FileSystemCache entry with key '${path}' removed`,
+        });
         cache.delete(path);
       }
       changes = [];
-      return cache.get(path);
+      const r = cache.get(path);
+      if (!r) {
+        const target: any = {};
+        Error.captureStackTrace(target);
+        const callstack = target.stack.substring("Error\n".length);
+        log({ level: "trace", message: `FileSystemCache miss for ${path}`, detail: callstack });
+      }
+      return r;
     },
     set(path: string, entry: CachedFile | CachedError) {
       cache.set(path, entry);

packages/compiler/src/server/server.ts

@@ -15,7 +15,7 @@ import {
 import { NodeHost } from "../core/node-host.js";
 import { typespecVersion } from "../utils/misc.js";
 import { createServer } from "./serverlib.js";
-import { Server, ServerHost } from "./types.js";
+import { Server, ServerHost, ServerLog } from "./types.js";
 
 let server: Server | undefined = undefined;
 
@@ -45,8 +45,38 @@ function main() {
     sendDiagnostics(params: PublishDiagnosticsParams) {
       void connection.sendDiagnostics(params);
     },
-    log(message: string) {
-      connection.console.log(message);
+    log(log: ServerLog) {
+      const message = log.message;
+      let detail: string | undefined = undefined;
+      let fullMessage = message;
+      if (log.detail) {
+        detail =
+          typeof log.detail === "string" ? log.detail : JSON.stringify(log.detail, undefined, 2);
+        fullMessage = `${message}:\n${detail}`;
+      }
+
+      switch (log.level) {
+        case "trace":
+          connection.tracer.log(message, detail);
+          break;
+        case "debug":
+          connection.console.debug(fullMessage);
+          break;
+        case "info":
+          connection.console.info(fullMessage);
+          break;
+        case "warning":
+          connection.console.warn(fullMessage);
+          break;
+        case "error":
+          connection.console.error(fullMessage);
+          break;
+        default:
+          connection.console.error(
+            `Log Message with invalid LogLevel (${log.level}). Raw Message: ${fullMessage}`
+          );
+          break;
+      }
     },
     getOpenDocumentByURL(url: string) {
       return documents.get(url);
@@ -58,13 +88,13 @@ function main() {
 
   const s = createServer(host);
   server = s;
-  s.log(`TypeSpec language server v${typespecVersion}`);
-  s.log("Module", fileURLToPath(import.meta.url));
-  s.log("Process ID", process.pid);
-  s.log("Command Line", process.argv);
+  s.log({ level: `info`, message: `TypeSpec language server v${typespecVersion}` });
+  s.log({ level: `info`, message: `Module: ${fileURLToPath(import.meta.url)}` });
+  s.log({ level: `info`, message: `Process ID: ${process.pid}` });
+  s.log({ level: `info`, message: `Command Line`, detail: process.argv });
 
   if (profileDir) {
-    s.log("CPU profiling enabled", profileDir);
+    s.log({ level: `info`, message: `CPU profiling enabled with dir: ${profileDir}` });
     profileSession = new inspector.Session();
     profileSession.connect();
   }
@@ -152,7 +182,7 @@ function time<T extends (...args: any) => any>(func: T): T {
     const start = Date.now();
     const ret = await func.apply(undefined!, args);
     const end = Date.now();
-    server!.log(func.name, end - start + " ms");
+    server!.log({ level: `trace`, message: `${func.name}: ${end - start + " ms"}` });
     return ret;
   }) as T;
 }

packages/compiler/src/server/serverlib.ts

@@ -92,6 +92,7 @@ import {
   SemanticTokenKind,
   Server,
   ServerHost,
+  ServerLog,
   ServerSourceFile,
   ServerWorkspaceFolder,
 } from "./types.js";
@@ -105,6 +106,7 @@ export function createServer(host: ServerHost): Server {
   // a file change.
   const fileSystemCache = createFileSystemCache({
     fileService,
+    log,
   });
   const compilerHost = createCompilerHost();
 
@@ -121,7 +123,7 @@ export function createServer(host: ServerHost): Server {
 
   let workspaceFolders: ServerWorkspaceFolder[] = [];
   let isInitialized = false;
-  let pendingMessages: string[] = [];
+  let pendingMessages: ServerLog[] = [];
 
   return {
     get pendingMessages() {
@@ -236,17 +238,17 @@ export function createServer(host: ServerHost): Server {
       ];
     }
 
-    log("Workspace Folders", workspaceFolders);
+    log({ level: "info", message: `Workspace Folders`, detail: workspaceFolders });
     return { capabilities };
   }
 
   function initialized(params: InitializedParams): void {
     isInitialized = true;
-    log("Initialization complete.");
+    log({ level: "info", message: "Initialization complete." });
   }
 
   async function workspaceFoldersChanged(e: WorkspaceFoldersChangeEvent) {
-    log("Workspace Folders Changed", e);
+    log({ level: "info", message: "Workspace Folders Changed", detail: e });
     const map = new Map(workspaceFolders.map((f) => [f.uri, f]));
     for (const folder of e.removed) {
       map.delete(folder.uri);
@@ -258,7 +260,7 @@ export function createServer(host: ServerHost): Server {
       });
     }
     workspaceFolders = Array.from(map.values());
-    log("Workspace Folders", workspaceFolders);
+    log({ level: "info", message: `Workspace Folders`, detail: workspaceFolders });
   }
 
   function watchedFilesChanged(params: DidChangeWatchedFilesParams) {
@@ -383,6 +385,7 @@ export function createServer(host: ServerHost): Server {
         // we report diagnostics with no location on the document that changed to
         // trigger.
         diagDocument = document;
+        log({ level: "debug", message: `Diagnostic with no location: ${each.message}` });
       }
 
       if (!diagDocument || !fileService.upToDate(diagDocument)) {
@@ -883,14 +886,9 @@ export function createServer(host: ServerHost): Server {
     }
   }
 
-  function log(message: string, details: any = undefined) {
-    message = `[${new Date().toLocaleTimeString()}] ${message}`;
-    if (details) {
-      message += ": " + JSON.stringify(details, undefined, 2);
-    }
-
+  function log(log: ServerLog) {
     if (!isInitialized) {
-      pendingMessages.push(message);
+      pendingMessages.push(log);
       return;
     }
 
@@ -899,7 +897,7 @@ export function createServer(host: ServerHost): Server {
     }
 
     pendingMessages = [];
-    host.log(message);
+    host.log(log);
   }
 
   function sendDiagnostics(document: TextDocument, diagnostics: VSDiagnostic[]) {

packages/compiler/src/server/types.ts

@@ -39,12 +39,19 @@ import {
 import { TextDocument, TextEdit } from "vscode-languageserver-textdocument";
 import type { CompilerHost, Program, SourceFile, TypeSpecScriptNode } from "../core/index.js";
 
+export type ServerLogLevel = "trace" | "debug" | "info" | "warning" | "error";
+export interface ServerLog {
+  level: ServerLogLevel;
+  message: string;
+  detail?: unknown;
+}
+
 export interface ServerHost {
   readonly compilerHost: CompilerHost;
   readonly throwInternalErrors?: boolean;
   readonly getOpenDocumentByURL: (url: string) => TextDocument | undefined;
   readonly sendDiagnostics: (params: PublishDiagnosticsParams) => void;
-  readonly log: (message: string) => void;
+  readonly log: (log: ServerLog) => void;
   readonly applyEdit: (
     paramOrEdit: ApplyWorkspaceEditParams | WorkspaceEdit
   ) => Promise<ApplyWorkspaceEditResult>;
@@ -57,7 +64,7 @@ export interface CompileResult {
 }
 
 export interface Server {
-  readonly pendingMessages: readonly string[];
+  readonly pendingMessages: readonly ServerLog[];
   readonly workspaceFolders: readonly ServerWorkspaceFolder[];
   compile(document: TextDocument | TextDocumentIdentifier): Promise<CompileResult | undefined>;
   initialize(params: InitializeParams): Promise<InitializeResult>;
@@ -81,7 +88,7 @@ export interface Server {
   documentClosed(change: TextDocumentChangeEvent<TextDocument>): void;
   getCodeActions(params: CodeActionParams): Promise<CodeAction[]>;
   executeCommand(params: ExecuteCommandParams): Promise<void>;
-  log(message: string, details?: any): void;
+  log(log: ServerLog): void;
 }
 
 export interface ServerSourceFile extends SourceFile {

packages/compiler/src/testing/test-server-host.ts

@@ -68,8 +68,8 @@ export async function createTestServerHost(options?: TestHostOptions & { workspa
       }
       diagnostics.set(params.uri, params.diagnostics);
     },
-    log(message) {
-      logMessages.push(message);
+    log(log) {
+      logMessages.push(`[${log.level}] ${log.message}`);
     },
     getURL(path: string) {
       if (path.startsWith("untitled:")) {