feat: improves the reporting of msgs in the logs

Adds substantial error and debug reporting in the logs.
It also converts a lot of the `info` messages to `debug`

Author: gnikit

src/extension.ts

@@ -32,11 +32,11 @@ export async function activate(context: vscode.ExtensionContext) {
 
   logger.info(`Extension Name: ${pkg.displayName}`);
   logger.info(`Extension Version: ${pkg.version}`);
-  logger.info(`Linter set to: ${linterType}`);
-  logger.info(`Formatter set to: ${formatterType}`);
-  logger.info(`Autocomplete set to: ${autocompleteType}`);
-  logger.info(`Hover set to: ${hoverType}`);
-  logger.info(`Symbols set to: ${symbolsType}`);
+  logger.info(`Linter set to: "${linterType}"`);
+  logger.info(`Formatter set to: "${formatterType}"`);
+  logger.info(`Autocomplete set to: "${autocompleteType}"`);
+  logger.info(`Hover set to: "${hoverType}"`);
+  logger.info(`Symbols set to: "${symbolsType}"`);
 
   context.subscriptions.push(
     vscode.workspace.onDidChangeConfiguration(e => {

src/features/formatting-provider.ts

@@ -32,7 +32,7 @@ export class FortranFormattingProvider implements vscode.DocumentFormattingEditP
     } else if (formatterName === 'findent') {
       return this.doFormatFindent(document);
     } else {
-      this.logger.error('Cannot format document with formatter set to Disabled');
+      this.logger.error('[format] Cannot format document with formatter set to Disabled');
     }
 
     return undefined;
@@ -46,7 +46,7 @@ export class FortranFormattingProvider implements vscode.DocumentFormattingEditP
   private async doFormatFprettify(document: vscode.TextDocument): Promise<vscode.TextEdit[]> {
     // fprettify can only do FortranFreeFrom
     if (document.languageId !== 'FortranFreeForm') {
-      this.logger.error(`fprettify can only format FortranFreeForm, change
+      this.logger.error(`[format] fprettify can only format FortranFreeForm, change
                             to findent for FortranFixedForm formatting`);
       return undefined;
     }
@@ -56,17 +56,17 @@ export class FortranFormattingProvider implements vscode.DocumentFormattingEditP
     const formatter: string = path.join(formatterPath, formatterName);
     // If no formatter is detected try and install it
     if (!which.sync(formatter, { nothrow: true })) {
-      this.logger.warn(`Formatter: ${formatterName} not detected in your system.
-                                Attempting to install now.`);
+      this.logger.warn(`[format] ${formatterName} not found. Attempting to install now.`);
       const msg = `Installing ${formatterName} through pip with --user option`;
       promptForMissingTool(formatterName, msg, 'Python', ['Install'], this.logger);
     }
 
     const args: string[] = ['--stdout', ...this.getFormatterArgs()];
+    this.logger.debug(`[format] fprettify args:`, args);
     const edits: vscode.TextEdit[] = [];
     const [stdout, stderr] = await spawnAsPromise(formatter, args, undefined, document.getText());
     edits.push(new vscode.TextEdit(getWholeFileRange(document), stdout));
-    if (stderr) this.logger.info(`fprettify error output: ${stderr}`);
+    if (stderr) this.logger.error(`[format] fprettify error output: ${stderr}`);
     return edits;
   }
 
@@ -81,17 +81,17 @@ export class FortranFormattingProvider implements vscode.DocumentFormattingEditP
     const formatter: string = path.join(formatterPath, formatterName);
     // If no formatter is detected try and install it
     if (!which.sync(formatter, { nothrow: true })) {
-      this.logger.warn(`Formatter: ${formatterName} not detected in your system.
-                                    Attempting to install now.`);
+      this.logger.warn(`[format] ${formatterName} not found! Attempting to install now.`);
       const msg = `Installing ${formatterName} through pip with --user option`;
       promptForMissingTool(formatterName, msg, 'Python', ['Install'], this.logger);
     }
 
     const args: string[] = this.getFormatterArgs();
+    this.logger.debug(`[format] findent args:`, args);
     const edits: vscode.TextEdit[] = [];
     const [stdout, stderr] = await spawnAsPromise(formatter, args, undefined, document.getText());
     edits.push(new vscode.TextEdit(getWholeFileRange(document), stdout));
-    if (stderr) this.logger.info(`findent error output: ${stderr}`);
+    if (stderr) this.logger.error(`[format] findent error output: ${stderr}`);
     return edits;
   }
 
@@ -107,7 +107,7 @@ export class FortranFormattingProvider implements vscode.DocumentFormattingEditP
     this.formatter = this.workspace.get('formatting.formatter', 'Disabled');
 
     if (!FORMATTERS.includes(this.formatter)) {
-      this.logger.error(`Unsupported formatter: ${this.formatter}`);
+      this.logger.error(`[format] Unsupported formatter: ${this.formatter}`);
     }
     return this.formatter;
   }
@@ -130,7 +130,7 @@ export class FortranFormattingProvider implements vscode.DocumentFormattingEditP
   private getFormatterPath(): string {
     const formatterPath: string = this.workspace.get('formatting.path', '');
     if (formatterPath !== '') {
-      this.logger.info(`Formatter located in: ${formatterPath}`);
+      this.logger.info(`[format] Formatter located in: ${formatterPath}`);
     }
 
     return formatterPath;

src/features/linter-provider.ts

@@ -88,6 +88,7 @@ export class FortranLintingProvider {
         env.Path = `${path.dirname(command)}${path.delimiter}${env.Path}`;
       }
     }
+    this.logger.info(`[lint] Compiler query command line: ${command} ${argList.join(' ')}`);
     const childProcess = cp.spawn(command, argList, {
       cwd: filePath,
       env: env,
@@ -101,11 +102,13 @@ export class FortranLintingProvider {
         compilerOutput += data;
       });
       childProcess.stderr.on('end', () => {
+        this.logger.debug(`[lint] Compiler output:`, compilerOutput);
         let diagnostics = this.getLinterResults(compilerOutput);
         diagnostics = [...new Map(diagnostics.map(v => [JSON.stringify(v), v])).values()];
         this.diagnosticCollection.set(textDocument.uri, diagnostics);
       });
       childProcess.on('error', err => {
+        this.logger.error(`[lint] Compiler error:`, err);
         console.log(`ERROR: ${err}`);
       });
     } else {
@@ -167,7 +170,7 @@ export class FortranLintingProvider {
     }
 
     modout = resolveVariables(modout);
-    this.logger.info(`Linter.moduleOutput: ${modFlag} ${modout}`);
+    this.logger.debug(`[lint] moduleOutput: ${modFlag} ${modout}`);
     return [modFlag, modout];
   }
 
@@ -195,7 +198,7 @@ export class FortranLintingProvider {
     // Update our cache input
     this.cache['includePaths'] = includePaths;
     // Output the original include paths
-    this.logger.info(`Linter.include:\n${includePaths.join('\r\n')}`);
+    if (includePaths.length > 0) this.logger.debug(`[lint] include:`, includePaths);
     // Resolve internal variables and expand glob patterns
     const resIncludePaths = includePaths.map(e => resolveVariables(e));
     // fast-glob cannot work with Windows paths
@@ -212,12 +215,12 @@ export class FortranLintingProvider {
       // Try to recover from fast-glob failing due to EACCES using slower more
       // robust glob.
     } catch (eacces) {
-      this.logger.warn(`You lack read permissions for an include directory
+      this.logger.warn(`[lint] You lack read permissions for an include directory
           or more likely a glob match from the input 'includePaths' list. This can happen when
           using overly broad root level glob patters e.g. /usr/lib/** .
           No reason to worry. I will attempt to recover. 
           You should consider adjusting your 'includePaths' if linting performance is slow.`);
-      this.logger.warn(`${eacces.message}`);
+      this.logger.warn(`[lint] ${eacces.message}`);
       try {
         const globIncPaths: string[] = [];
         for (const i of resIncludePaths) {
@@ -228,7 +231,7 @@ export class FortranLintingProvider {
         return globIncPaths;
         // if we failed again then our includes are somehow wrong. Abort
       } catch (error) {
-        this.logger.error(`Failed to recover: ${error}`);
+        this.logger.error(`[lint] Include path glob resolution failed to recover: ${error}`);
       }
     }
   }
@@ -243,7 +246,7 @@ export class FortranLintingProvider {
     this.compiler = config.get<string>('compiler', 'gfortran');
     this.compilerPath = config.get<string>('compilerPath', '');
     if (this.compilerPath === '') this.compilerPath = which.sync(this.compiler);
-    this.logger.info(`using linter: ${this.compiler} located in: ${this.compilerPath}`);
+    this.logger.debug(`[lint] binary: "${this.compiler}" located in: "${this.compilerPath}"`);
     return this.compilerPath;
   }
 
@@ -287,7 +290,7 @@ export class FortranLintingProvider {
       const lnStr: string = ln === -1 ? 'none' : ln.toString();
       args.push(`-ffree-line-length-${lnStr}`, `-ffixed-line-length-${lnStr}`);
     }
-    this.logger.info(`Linter.arguments:\n${args.join('\r\n')}`);
+    if (args.length > 0) this.logger.debug(`[lint] arguments:`, args);
 
     // Resolve internal variables but do not apply glob pattern matching
     return args.map(e => resolveVariables(e));
@@ -540,7 +543,10 @@ export class FortranLintingProvider {
    * Regenerate the cache for the include files paths of the linter
    */
   private rescanLinter() {
+    this.logger.debug(`[lint] Resetting linter include paths cache`);
+    this.logger.debug(`[lint] Current linter include paths cache:`, this.cache['includePaths']);
     this.cache['includePaths'] = [];
     this.getIncludePaths();
+    this.logger.debug(`[lint] New linter include paths cache:`, this.cache['includePaths']);
   }
 }

src/lsp/client.ts

@@ -22,7 +22,7 @@ export const clients: Map<string, LanguageClient> = new Map();
 
 export class FortlsClient {
   constructor(private logger: Logger, private context?: vscode.ExtensionContext) {
-    this.logger.info('Fortran Language Server');
+    this.logger.debug('[lsp.client] Fortran Language Server -- constructor');
 
     // if context is present
     if (context !== undefined) {
@@ -85,6 +85,7 @@ export class FortlsClient {
 
     // Detect language server version and verify selected options
     this.version = this.getLSVersion(executablePath, args);
+    this.logger.debug(`[lsp.client] Language Server version: ${this.version}`);
     if (!this.version) return;
     const serverOptions: ServerOptions = {
       command: executablePath,
@@ -110,9 +111,9 @@ export class FortlsClient {
       const fileRoot: string = path.dirname(document.uri.fsPath);
       if (clients.has(fileRoot)) return; // already registered
       this.logger.info(
-        'Initialising Language Server for file: ' +
-          `${document.uri.fsPath} with command-line options: ${args.join(', ')}`
+        `[lsp.client] Initialising Language Server for file: ${document.uri.fsPath}`
       );
+      this.logger.info(`[lsp.client] Language Server arguments: ${args.join(' ')}`);
       // Options to control the language client
       const clientOptions: LanguageClientOptions = {
         documentSelector: FortranDocumentSelector(fileRoot),
@@ -134,9 +135,9 @@ export class FortlsClient {
       folder = getOuterMostWorkspaceFolder(folder);
       if (clients.has(folder.uri.toString())) return; // already registered
       this.logger.info(
-        'Initialising Language Server for workspace: ' +
-          `${document.uri.fsPath} with command-line options: ${args.join(', ')}`
+        `[lsp.client] Initialising Language Server for workspace: ${folder.uri.toString()}`
       );
+      this.logger.info(`[lsp.client] Language Server arguments: ${args.join(' ')}`);
       // Options to control the language client
       const clientOptions: LanguageClientOptions = {
         documentSelector: FortranDocumentSelector(folder.uri.fsPath),
@@ -243,6 +244,7 @@ export class FortlsClient {
       args.push(`--pp_defs=${JSON.stringify(pp_defs)}`);
     }
 
+    this.logger.debug(`[lsp.client] Language Server arguments:`, args);
     return args;
   }
 
@@ -259,6 +261,7 @@ export class FortlsClient {
   private getLSVersion(executablePath: string, args: string[]) {
     const results = spawnSync(executablePath, args.concat(['--version']));
     if (results.error) {
+      this.logger.error(`[lsp.client] Unable to launch LS to check version:`, results.error);
       const selected = window.showErrorMessage(
         'Modern Fortran Error starting fortls: Check that fortls is in your PATH or that "fortran.fortls.path" is pointing to a fortls binary.',
         'Settings',
@@ -275,6 +278,7 @@ export class FortlsClient {
       return null;
     }
     if (results.status !== 0) {
+      this.logger.error(`[lsp.client] Unable to verify input arguments with LS:`);
       const selected = window.showErrorMessage(
         'Error launching fortls: Please check that all selected options are supported by your language server version.',
         'Settings',
@@ -313,11 +317,12 @@ export class FortlsClient {
           if (opt === 'Install') {
             const install = spawnSync('pip', ['install', '--user', '--upgrade', LS_NAME]);
             if (install.error) {
+              this.logger.error(`[lsp.client] Unable to install fortls:`, install.error);
               window.showErrorMessage('Had trouble installing fortls, please install manually');
               fortlsDisabled = true;
             }
             if (install.stdout) {
-              this.logger.info(install.stdout.toString());
+              this.logger.info(`[lsp.client] ${install.stdout.toString()}`);
               fortlsDisabled = false;
             }
           } else if (opt == 'Disable') {
@@ -336,9 +341,10 @@ export class FortlsClient {
    * Restart the language server
    */
   private async restartLS(): Promise<void> {
-    this.logger.info('Restarting language server...');
+    this.logger.info('[lsp.client] Restarting language server...');
     vscode.window.showInformationMessage('Restarting language server...');
     await this.deactivate();
     await this.activate();
+    this.logger.info('[lsp.client] Language server restarted');
   }
 }