Merge pull request #606 from fortran-lang/feat/improve-logs

Improves extension logger

Author: gnikit

CHANGELOG.md

@@ -7,8 +7,17 @@ and this project adheres to [Semantic Versioning](http://semver.org/).
 
 ## [Unreleased]
 
+### Added
+
+- Added option to set the verbosity of the Output Channel
+  ([#606](https://github.com/fortran-lang/vscode-fortran-support/pull/606))
+- Added increased logging messages in various parts of the extension
+  ([#606](https://github.com/fortran-lang/vscode-fortran-support/pull/606))
+
 ### Changed
 
+- Changed the way messages are logged and added `log` syntax highlighting
+  ([#606](https://github.com/fortran-lang/vscode-fortran-support/pull/606))
 - Removes duplicate diagnostic messages from the linter
   ([#598](https://github.com/fortran-lang/vscode-fortran-support/issues/598))
 

package.json

@@ -180,6 +180,19 @@
             ],
             "markdownDescription": "Specify the word case to use when suggesting autocomplete options.",
             "order": 60
+          },
+          "fortran.logging.level": {
+            "type": "string",
+            "default": "Info",
+            "enum": [
+              "None",
+              "Error",
+              "Warn",
+              "Info",
+              "Debug"
+            ],
+            "markdownDescription": "The log level for the extension.",
+            "order": 70
           }
         }
       },
@@ -560,5 +573,11 @@
     "glob": "^8.0.3",
     "vscode-languageclient": "^8.0.2",
     "which": "^2.0.2"
+  },
+  "__metadata": {
+    "id": "64379b4d-40cd-415a-8643-b07572d4a243",
+    "publisherDisplayName": "The Fortran Programming Language",
+    "publisherId": "0fb8288f-2952-4d83-8d25-46814faecc34",
+    "isPreReleaseVersion": false
   }
 }

src/extension.ts

@@ -12,11 +12,14 @@ import { FortlsClient } from './lsp/client';
 import { FortranHoverProvider } from './features/hover-provider';
 import { FortranLintingProvider } from './features/linter-provider';
 import { EXTENSION_ID, FortranDocumentSelector } from './lib/tools';
-import { LoggingService } from './services/logging-service';
+import { getConfigLogLevel, Logger } from './services/logging';
 import { WhatsNew } from './features/commands';
 
 // Make it global to catch errors when activation fails
-const loggingService = new LoggingService();
+const logger = new Logger(
+  vscode.window.createOutputChannel('Modern Fortran', 'log'),
+  getConfigLogLevel()
+);
 
 export async function activate(context: vscode.ExtensionContext) {
   const config = vscode.workspace.getConfiguration(EXTENSION_ID);
@@ -27,34 +30,42 @@ export async function activate(context: vscode.ExtensionContext) {
   const symbolsType = config.get<string>('provide.symbols');
   detectDeprecatedOptions();
 
-  loggingService.logInfo(`Extension Name: ${pkg.displayName}`);
-  loggingService.logInfo(`Extension Version: ${pkg.version}`);
-  loggingService.logInfo(`Linter set to: ${linterType}`);
-  loggingService.logInfo(`Formatter set to: ${formatterType}`);
-  loggingService.logInfo(`Autocomplete set to: ${autocompleteType}`);
-  loggingService.logInfo(`Hover set to: ${hoverType}`);
-  loggingService.logInfo(`Symbols set to: ${symbolsType}`);
+  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}"`);
 
+  context.subscriptions.push(
+    vscode.workspace.onDidChangeConfiguration(e => {
+      if (e.affectsConfiguration(`${EXTENSION_ID}.logging.level`)) {
+        // Leave config field empty to fetch the most updated config values
+        logger.setLogLevel(getConfigLogLevel());
+      }
+    })
+  );
   // Linter is always activated but will only lint if compiler !== Disabled
-  const linter = new FortranLintingProvider(loggingService);
+  const linter = new FortranLintingProvider(logger);
   linter.activate(context.subscriptions);
   vscode.languages.registerCodeActionsProvider(FortranDocumentSelector(), linter);
 
   if (formatterType !== 'Disabled') {
     const disposable: vscode.Disposable = vscode.languages.registerDocumentFormattingEditProvider(
       FortranDocumentSelector(),
-      new FortranFormattingProvider(loggingService)
+      new FortranFormattingProvider(logger)
     );
     context.subscriptions.push(disposable);
   }
 
   if (autocompleteType === 'Built-in') {
-    const completionProvider = new FortranCompletionProvider(loggingService);
+    const completionProvider = new FortranCompletionProvider(logger);
     vscode.languages.registerCompletionItemProvider(FortranDocumentSelector(), completionProvider);
   }
 
   if (hoverType === 'Built-in' || hoverType === 'Both') {
-    const hoverProvider = new FortranHoverProvider(loggingService);
+    const hoverProvider = new FortranHoverProvider(logger);
     vscode.languages.registerHoverProvider(FortranDocumentSelector(), hoverProvider);
   }
 
@@ -64,7 +75,7 @@ export async function activate(context: vscode.ExtensionContext) {
   }
 
   if (!config.get<boolean>('fortls.disabled')) {
-    new FortlsClient(loggingService, context).activate();
+    new FortlsClient(logger, context).activate();
   }
   // override VS Code's default implementation of the debug hover
   // here we match Fortran derived types and scope them appropriately
@@ -129,7 +140,7 @@ function detectDeprecatedOptions() {
         if (selected === 'Open Settings') {
           vscode.commands.executeCommand('workbench.action.openGlobalSettings');
         }
-        loggingService.logError(`The following deprecated options have been detected:\n${oldArgs}`);
+        logger.error(`The following deprecated options have been detected:\n${oldArgs}`);
       });
   }
 

src/features/completion-provider.ts

@@ -4,7 +4,7 @@ import * as vscode from 'vscode';
 import { isPositionInString, FORTRAN_KEYWORDS } from '../lib/helper';
 import { getDeclaredFunctions } from '../lib/functions';
 import { EXTENSION_ID } from '../lib/tools';
-import { LoggingService } from '../services/logging-service';
+import { Logger } from '../services/logging';
 import intrinsics from './intrinsics.json';
 
 class CaseCoverter {
@@ -35,7 +35,7 @@ class CaseCoverter {
 }
 
 export class FortranCompletionProvider implements vscode.CompletionItemProvider {
-  constructor(private loggingService: LoggingService) {}
+  constructor(private logger: Logger) {}
   public provideCompletionItems(
     document: vscode.TextDocument,
     position: vscode.Position,

src/features/formatting-provider.ts

@@ -6,7 +6,7 @@ import * as which from 'which';
 import * as vscode from 'vscode';
 import * as cp from 'child_process';
 
-import { LoggingService } from '../services/logging-service';
+import { Logger } from '../services/logging';
 import {
   FORMATTERS,
   EXTENSION_ID,
@@ -18,7 +18,7 @@ import {
 export class FortranFormattingProvider implements vscode.DocumentFormattingEditProvider {
   private readonly workspace = vscode.workspace.getConfiguration(EXTENSION_ID);
   private formatter: string | undefined;
-  constructor(private logger: LoggingService) {}
+  constructor(private logger: Logger) {}
 
   public async provideDocumentFormattingEdits(
     document: vscode.TextDocument,
@@ -32,7 +32,7 @@ export class FortranFormattingProvider implements vscode.DocumentFormattingEditP
     } else if (formatterName === 'findent') {
       return this.doFormatFindent(document);
     } else {
-      this.logger.logError('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.logError(`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.logWarning(`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.logInfo(`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.logWarning(`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.logInfo(`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.logError(`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.logInfo(`Formatter located in: ${formatterPath}`);
+      this.logger.info(`[format] Formatter located in: ${formatterPath}`);
     }
 
     return formatterPath;

src/features/hover-provider.ts

@@ -1,9 +1,9 @@
 import { CancellationToken, TextDocument, Position, Hover } from 'vscode';
-import { LoggingService } from '../services/logging-service';
+import { Logger } from '../services/logging';
 import intrinsics from './intrinsics.json';
 
 export class FortranHoverProvider {
-  constructor(private loggingService: LoggingService) {}
+  constructor(private logger: Logger) {}
   public provideHover(
     document: TextDocument,
     position: Position,

src/features/linter-provider.ts

@@ -5,15 +5,15 @@ import * as cp from 'child_process';
 import which from 'which';
 
 import * as vscode from 'vscode';
-import { LoggingService } from '../services/logging-service';
+import { Logger } from '../services/logging';
 import { FortranDocumentSelector, resolveVariables } from '../lib/tools';
 import * as fg from 'fast-glob';
 import { glob } from 'glob';
 import { arraysEqual } from '../lib/helper';
 import { RescanLint } from './commands';
 
 export class FortranLintingProvider {
-  constructor(private logger: LoggingService = new LoggingService()) {}
+  constructor(private logger: Logger = new Logger()) {}
 
   private diagnosticCollection: vscode.DiagnosticCollection;
   private compiler: string;
@@ -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:\n${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.logInfo(`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.logInfo(`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.logWarning(`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.logWarning(`${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.logError(`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.logInfo(`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.logInfo(`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']);
   }
 }