Error handling getting ghc version

jneira · jneira · commit 52c8d9e4fe22 · 2021-08-04T11:16:12.000+02:00
diff --git a/package.json b/package.json
@@ -103,6 +103,17 @@
           "default": "off",
           "description": "Traces the communication between VS Code and the language server."
         },
+        "haskell.trace.client": {
+          "scope": "resource",
+          "type": "string",
+          "enum": [
+            "off",
+            "error",
+            "debug"
+          ],
+          "default": "error",
+          "description": "Traces the communication between VS Code and the language server."
+        },
         "haskell.logFile": {
           "scope": "resource",
           "type": "string",
diff --git a/src/extension.ts b/src/extension.ts
@@ -15,6 +15,7 @@ import {
   ExecutableOptions,
   LanguageClient,
   LanguageClientOptions,
+  Logger,
   RevealOutputChannelOn,
   ServerOptions,
   TransportKind,
@@ -23,7 +24,7 @@ import { CommandNames } from './commands/constants';
 import { ImportIdentifier } from './commands/importIdentifier';
 import { DocsBrowser } from './docsBrowser';
 import { downloadHaskellLanguageServer } from './hlsBinaries';
-import { executableExists } from './utils';
+import { executableExists, ExtensionLogger } from './utils';
 
 // The current map of documents & folders to language servers.
 // It may be null to indicate that we are in the process of launching a server,
@@ -45,7 +46,11 @@ export async function activate(context: ExtensionContext) {
     for (const folder of event.removed) {
       const client = clients.get(folder.uri.toString());
       if (client) {
-        clients.delete(folder.uri.toString());
+        const uri = folder.uri.toString();
+        client.info('Deleting folder for clients: ${uri}');
+        clients.delete(uri);
+        client.info;
+        client.info('Stopping the client');
         client.stop();
       }
     }
@@ -54,10 +59,13 @@ export async function activate(context: ExtensionContext) {
   // Register editor commands for HIE, but only register the commands once at activation.
   const restartCmd = commands.registerCommand(CommandNames.RestartServerCommandName, async () => {
     for (const langClient of clients.values()) {
+      langClient?.info('Stopping the client');
       await langClient?.stop();
+      langClient?.info('Starting the client');
       langClient?.start();
     }
   });
+
   context.subscriptions.push(restartCmd);
 
   context.subscriptions.push(ImportIdentifier.registerCommand());
@@ -70,30 +78,31 @@ export async function activate(context: ExtensionContext) {
   context.subscriptions.push(openOnHackageDisposable);
 }
 
-function findManualExecutable(uri: Uri, folder?: WorkspaceFolder): string | null {
+function findManualExecutable(logger: Logger, uri: Uri, folder?: WorkspaceFolder): string | null {
   let exePath = workspace.getConfiguration('haskell', uri).serverExecutablePath;
   if (exePath === '') {
     return null;
   }
-
+  logger.info('Trying to find the server executable in: ${exePath}');
   // Substitute path variables with their corresponding locations.
   exePath = exePath.replace('${HOME}', os.homedir).replace('${home}', os.homedir).replace(/^~/, os.homedir);
   if (folder) {
     exePath = exePath.replace('${workspaceFolder}', folder.uri.path).replace('${workspaceRoot}', folder.uri.path);
   }
-
+  logger.info('Location after path variables subsitution: ${exePath}');
   if (!executableExists(exePath)) {
     throw new Error(`serverExecutablePath is set to ${exePath} but it doesn't exist and is not on the PATH`);
   }
   return exePath;
 }
 
 /** Searches the PATH for whatever is set in serverVariant */
-function findLocalServer(context: ExtensionContext, uri: Uri, folder?: WorkspaceFolder): string | null {
+function findLocalServer(context: ExtensionContext, logger: Logger, uri: Uri, folder?: WorkspaceFolder): string | null {
   const exes: string[] = ['haskell-language-server-wrapper', 'haskell-language-server'];
-
+  logger.info('Searching for server executables ${exes} in PATH');
   for (const exe of exes) {
     if (executableExists(exe)) {
+      logger.info('Found server executable in PATH: ${exe}');
       return exe;
     }
   }
@@ -120,6 +129,9 @@ async function activeServer(context: ExtensionContext, document: TextDocument) {
 
 async function activateServerForFolder(context: ExtensionContext, uri: Uri, folder?: WorkspaceFolder) {
   const clientsKey = folder ? folder.uri.toString() : uri.toString();
+  // Set a unique name per workspace folder (useful for multi-root workspaces).
+  const langName = 'Haskell' + (folder ? ` (${folder.name})` : '');
+  const outputChannel: OutputChannel = window.createOutputChannel(langName);
 
   // If the client already has an LSP server for this uri/folder, then don't start a new one.
   if (clients.has(clientsKey)) {
@@ -129,21 +141,25 @@ async function activateServerForFolder(context: ExtensionContext, uri: Uri, fold
   clients.set(clientsKey, null);
 
   const logLevel = workspace.getConfiguration('haskell', uri).trace.server;
+  const clientLogLevel = workspace.getConfiguration('haskell', uri).trace.client;
   const logFile = workspace.getConfiguration('haskell', uri).logFile;
 
+  const logger: Logger = new ExtensionLogger('client', clientLogLevel, outputChannel);
+
   let serverExecutable;
   try {
     // Try and find local installations first
-    serverExecutable = findManualExecutable(uri, folder) ?? findLocalServer(context, uri, folder);
+    serverExecutable = findManualExecutable(logger, uri, folder) ?? findLocalServer(context, logger, uri, folder);
     if (serverExecutable === null) {
       // If not, then try to download haskell-language-server binaries if it's selected
-      serverExecutable = await downloadHaskellLanguageServer(context, uri, folder);
+      serverExecutable = await downloadHaskellLanguageServer(context, logger, uri, folder);
       if (!serverExecutable) {
         return;
       }
     }
   } catch (e) {
     if (e instanceof Error) {
+      logger.error('Error getting the server executable: ${e.message}');
       window.showErrorMessage(e.message);
     }
     return;
@@ -173,13 +189,9 @@ async function activateServerForFolder(context: ExtensionContext, uri: Uri, fold
     debug: { command: serverExecutable, transport: TransportKind.stdio, args, options: exeOptions },
   };
 
-  // Set a unique name per workspace folder (useful for multi-root workspaces).
-  const langName = 'Haskell' + (folder ? ` (${folder.name})` : '');
-  const outputChannel: OutputChannel = window.createOutputChannel(langName);
-  outputChannel.appendLine('[client] run command: "' + serverExecutable + ' ' + args.join(' ') + '"');
-  outputChannel.appendLine('[client] debug command: "' + serverExecutable + ' ' + args.join(' ') + '"');
-
-  outputChannel.appendLine(`[client] server cwd: ${exeOptions.cwd}`);
+  logger.info('run command: "' + serverExecutable + ' ' + args.join(' ') + '"');
+  logger.info('debug command: "' + serverExecutable + ' ' + args.join(' ') + '"');
+  logger.info(`server cwd: ${exeOptions.cwd}`);
 
   const pat = folder ? `${folder.uri.fsPath}/**/*` : '**/*';
   const clientOptions: LanguageClientOptions = {
@@ -213,6 +225,7 @@ async function activateServerForFolder(context: ExtensionContext, uri: Uri, fold
   langClient.registerProposedFeatures();
 
   // Finally start the client and add it to the list of clients.
+  logger.info('Starting language client');
   langClient.start();
   clients.set(clientsKey, langClient);
 }
diff --git a/src/hlsBinaries.ts b/src/hlsBinaries.ts
@@ -6,6 +6,7 @@ import * as path from 'path';
 import * as url from 'url';
 import { promisify } from 'util';
 import { env, ExtensionContext, ProgressLocation, Uri, window, workspace, WorkspaceFolder } from 'vscode';
+import { Logger } from 'vscode-languageclient';
 import { downloadFile, executableExists, httpsGetSilently } from './utils';
 import * as validate from './validation';
 
@@ -97,33 +98,59 @@ class NoBinariesError extends Error {
  * if needed. Returns null if there was an error in either downloading the wrapper or
  * in working out the ghc version
  */
-async function getProjectGhcVersion(context: ExtensionContext, dir: string, release: IRelease): Promise<string> {
+async function getProjectGhcVersion(
+  context: ExtensionContext,
+  logger: Logger,
+  dir: string,
+  release: IRelease
+): Promise<string> {
+  const title: string = 'Working out the project GHC version. This might take a while...';
+  logger.info(title);
   const callWrapper = (wrapper: string) => {
     return window.withProgress(
       {
-        location: ProgressLocation.Window,
-        title: 'Working out the project GHC version. This might take a while...',
+        location: ProgressLocation.Notification,
+        title: title,
+        cancellable: true,
       },
-      async () => {
+      async (progress, token) => {
         return new Promise<string>((resolve, reject) => {
+          const command: string = wrapper + ' --project-ghc-version';
+          logger.info('Executing `${command}` in cwd ${dir} to get the project ghc version');
+          token.onCancellationRequested(() => {
+            logger.warn('User canceled the executon of `${command}`');
+          });
           // Need to set the encoding to 'utf8' in order to get back a string
-          child_process.exec(
-            wrapper + ' --project-ghc-version',
-            { encoding: 'utf8', cwd: dir },
-            (err, stdout, stderr) => {
-              if (err) {
-                const regex = /Cradle requires (.+) but couldn't find it/;
-                const res = regex.exec(stderr);
-                if (res) {
-                  throw new MissingToolError(res[1]);
+          // We execute the command in a shell for windows, to allow use cmd or bat scripts
+          let childProcess = child_process
+            .execFile(
+              command,
+              { encoding: 'utf8', cwd: dir, shell: getGithubOS() == 'Windows' },
+              (err, stdout, stderr) => {
+                if (err) {
+                  logger.error('Error executing `${command}` with error code ${err.code}');
+                  logger.error('stderr: ${stderr}');
+                  logger.error('stdout: ${stdout}');
+                  const regex = /Cradle requires (.+) but couldn't find it/;
+                  const res = regex.exec(stderr);
+                  if (res) {
+                    throw new MissingToolError(res[1]);
+                  }
+                  throw Error(
+                    `${wrapper} --project-ghc-version exited with exit code ${err.code}:\n${stdout}\n${stderr}`
+                  );
                 }
-                throw Error(
-                  `${wrapper} --project-ghc-version exited with exit code ${err.code}:\n${stdout}\n${stderr}`
-                );
+                resolve(stdout.trim());
               }
-              resolve(stdout.trim());
-            }
-          );
+            )
+            .on('close', (code, signal) => {
+              logger.info('Execution of `${command}` closed with code ${err.code} and signal ${signal}');
+            })
+            .on('error', (err) => {
+              logger.error('Error execution `${command}`: name = ${err.name}, message = ${err.message}');
+              throw err;
+            });
+          token.onCancellationRequested((_) => childProcess.kill());
         });
       }
     );
@@ -250,10 +277,12 @@ async function getLatestReleaseMetadata(context: ExtensionContext): Promise<IRel
  */
 export async function downloadHaskellLanguageServer(
   context: ExtensionContext,
+  logger: Logger,
   resource: Uri,
   folder?: WorkspaceFolder
 ): Promise<string | null> {
   // Make sure to create this before getProjectGhcVersion
+  logger.info('Downloading haskell-language-server');
   if (!fs.existsSync(context.globalStoragePath)) {
     fs.mkdirSync(context.globalStoragePath);
   }
@@ -265,7 +294,7 @@ export async function downloadHaskellLanguageServer(
     return null;
   }
 
-  // Fetch the latest release from GitHub or from cache
+  logger.info('Fetching the latest release from GitHub or from cache');
   const release = await getLatestReleaseMetadata(context);
   if (!release) {
     let message = "Couldn't find any pre-built haskell-language-server binaries";
@@ -276,12 +305,12 @@ export async function downloadHaskellLanguageServer(
     window.showErrorMessage(message);
     return null;
   }
-
-  // Figure out the ghc version to use or advertise an installation link for missing components
+  logger.info('The latest release is ${release.tag_name}');
+  logger.info('Figure out the ghc version to use or advertise an installation link for missing components');
   const dir: string = folder?.uri?.fsPath ?? path.dirname(resource.fsPath);
   let ghcVersion: string;
   try {
-    ghcVersion = await getProjectGhcVersion(context, dir, release);
+    ghcVersion = await getProjectGhcVersion(context, logger, dir, release);
   } catch (error) {
     if (error instanceof MissingToolError) {
       const link = error.installLink();
@@ -304,8 +333,10 @@ export async function downloadHaskellLanguageServer(
   // When searching for binaries, use startsWith because the compression may differ
   // between .zip and .gz
   const assetName = `haskell-language-server-${githubOS}-${ghcVersion}${exeExt}`;
+  logger.info('Search for binary ${assetName} in release assests');
   const asset = release?.assets.find((x) => x.name.startsWith(assetName));
   if (!asset) {
+    logger.error('No binary ${assetName} found in the release assets: ' + release?.assets.map((value) => value.name));
     window.showInformationMessage(new NoBinariesError(release.tag_name, ghcVersion).message);
     return null;
   }
@@ -314,12 +345,14 @@ export async function downloadHaskellLanguageServer(
   const binaryDest = path.join(context.globalStoragePath, serverName);
 
   const title = `Downloading haskell-language-server ${release.tag_name} for GHC ${ghcVersion}`;
+  logger.info(title);
   await downloadFile(title, asset.browser_download_url, binaryDest);
   if (ghcVersion.startsWith('9.')) {
-    window.showWarningMessage(
+    let warning =
       'Currently, HLS supports GHC 9 only partially. ' +
-        'See [issue #297](https://github.com/haskell/haskell-language-server/issues/297) for more detail.'
-    );
+      'See [issue #297](https://github.com/haskell/haskell-language-server/issues/297) for more detail.';
+    logger.warn(warning);
+    window.showWarningMessage(warning);
   }
   return binaryDest;
 }
diff --git a/src/utils.ts b/src/utils.ts
@@ -7,10 +7,58 @@ import * as https from 'https';
 import { extname } from 'path';
 import * as url from 'url';
 import { promisify } from 'util';
-import { ProgressLocation, window } from 'vscode';
+import { OutputChannel, ProgressLocation, window } from 'vscode';
+import { Logger } from 'vscode-languageclient';
 import * as yazul from 'yauzl';
 import { createGunzip } from 'zlib';
 
+enum LogLevel {
+  Off,
+  Error,
+  Warn,
+  Info,
+}
+export class ExtensionLogger implements Logger {
+  public readonly name: string;
+  public readonly level: LogLevel;
+  public readonly channel: OutputChannel;
+
+  constructor(name: string, level: string, channel: OutputChannel) {
+    this.name = name;
+    this.level = this.getLogLevel(level);
+    this.channel = channel;
+  }
+  warn(message: string): void {
+    this.logLevel(LogLevel.Warn, message);
+  }
+  info(message: string): void {
+    this.logLevel(LogLevel.Info, message);
+  }
+
+  error(message: string) {
+    this.logLevel(LogLevel.Error, message);
+  }
+
+  log(msg: string) {
+    this.channel.appendLine(msg);
+  }
+
+  private logLevel(level: LogLevel, msg: string) {
+    if (level <= this.level) this.log('[${name}][${level}] ${msg}');
+  }
+
+  private getLogLevel(level: string) {
+    switch (level) {
+      case 'off':
+        return LogLevel.Off;
+      case 'error':
+        return LogLevel.Error;
+      default:
+        return LogLevel.Info;
+    }
+  }
+}
+
 /** When making http requests to github.com, use this header otherwise
  * the server will close the request
  */
