diff --git a/client/src/extension.ts b/client/src/extension.ts index 913daa3..dd553bc 100644 --- a/client/src/extension.ts +++ b/client/src/extension.ts @@ -3,6 +3,8 @@ * Licensed under the MIT License. See License.txt in the project root for license information. * ------------------------------------------------------------------------------------------ */ +import 'source-map-support/register'; + import * as path from 'path'; import { diff --git a/esbuild.js b/esbuild.js index 932dae4..9599ae0 100644 --- a/esbuild.js +++ b/esbuild.js @@ -1,8 +1,12 @@ import * as esbuild from 'esbuild'; -const production = process.argv.includes('--production'); const watch = process.argv.includes('--watch'); +let production = process.argv.includes('--production'); +if (process.env.LFORTRAN_LSP_MODE === "debug") { + production = false; +} + async function main() { const ctx = await esbuild.context({ entryPoints: [ diff --git a/eslint.config.mjs b/eslint.config.mjs index a7b856f..ac6cbd8 100644 --- a/eslint.config.mjs +++ b/eslint.config.mjs @@ -17,7 +17,8 @@ export default [ ...tseslint.configs.recommended, { rules: { - "@typescript-eslint/no-namespace": "off" + "@typescript-eslint/no-namespace": "off", + "@typescript-eslint/no-explicit-any": "off" } } ]; diff --git a/integ/spec/function_call1.f90.spec.ts b/integ/spec/function_call1.f90.spec.ts index a6eab88..8842aec 100644 --- a/integ/spec/function_call1.f90.spec.ts +++ b/integ/spec/function_call1.f90.spec.ts @@ -154,7 +154,6 @@ async function getErrorAlert(): Promise { "return arguments[0].firstChild.nodeValue", errorAlert); return errorMessage; - // eslint-disable-next-line @typescript-eslint/no-explicit-any } catch (error: any) { const retryMessage: string = "stale element reference: stale element not found in the current frame"; diff --git a/package-lock.json b/package-lock.json index bf3d1df..f3d8566 100644 --- a/package-lock.json +++ b/package-lock.json @@ -10,7 +10,10 @@ "hasInstallScript": true, "license": "MIT", "dependencies": { - "@types/which": "^3.0.4" + "@types/shell-escape": "^0.2.3", + "@types/which": "^3.0.4", + "shell-escape": "^0.2.0", + "source-map-support": "^0.5.21" }, "devDependencies": { "@aws-sdk/client-s3": "^3.699.0", @@ -2874,6 +2877,12 @@ "@types/ws": "*" } }, + "node_modules/@types/shell-escape": { + "version": "0.2.3", + "resolved": "https://registry.npmjs.org/@types/shell-escape/-/shell-escape-0.2.3.tgz", + "integrity": "sha512-xZWkMuQkn1I20gEzhYRa4/t1pwZ8XiIkqGA1Iee1D2IgAUIRLr57nrgJgF2QmHEfkfVzOM59gi/4xp6V+Aq+4A==", + "license": "MIT" + }, "node_modules/@types/sinon": { "version": "17.0.3", "resolved": "https://registry.npmjs.org/@types/sinon/-/sinon-17.0.3.tgz", @@ -3682,6 +3691,12 @@ "dev": true, "license": "MIT" }, + "node_modules/buffer-from": { + "version": "1.1.2", + "resolved": "https://registry.npmjs.org/buffer-from/-/buffer-from-1.1.2.tgz", + "integrity": "sha512-E+XQCRwSbaaiChtv6k6Dwgc+bx+Bs6vuKJHHl5kox/BaKbhiXzqQOwK4cO22yElGp2OCmjwVhT3HmxgyPGnJfQ==", + "license": "MIT" + }, "node_modules/c8": { "version": "10.1.2", "resolved": "https://registry.npmjs.org/c8/-/c8-10.1.2.tgz", @@ -7894,6 +7909,12 @@ "node": ">=8" } }, + "node_modules/shell-escape": { + "version": "0.2.0", + "resolved": "https://registry.npmjs.org/shell-escape/-/shell-escape-0.2.0.tgz", + "integrity": "sha512-uRRBT2MfEOyxuECseCZd28jC1AJ8hmqqneWQ4VWUTgCAFvb3wKU1jLqj6egC4Exrr88ogg3dp+zroH4wJuaXzw==", + "license": "MIT" + }, "node_modules/side-channel": { "version": "1.0.6", "resolved": "https://registry.npmjs.org/side-channel/-/side-channel-1.0.6.tgz", @@ -8027,6 +8048,25 @@ "node": ">=8" } }, + "node_modules/source-map": { + "version": "0.6.1", + "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.6.1.tgz", + "integrity": "sha512-UjgapumWlbMhkBgzT7Ykc5YXUT46F0iKu8SGXq0bcwP5dz/h0Plj6enJqjz1Zbq2l5WaqYnrVbwWOWMyF3F47g==", + "license": "BSD-3-Clause", + "engines": { + "node": ">=0.10.0" + } + }, + "node_modules/source-map-support": { + "version": "0.5.21", + "resolved": "https://registry.npmjs.org/source-map-support/-/source-map-support-0.5.21.tgz", + "integrity": "sha512-uBHU3L3czsIyYXKX88fdrGovxdSCoTGDRZ6SYXtSRxLZUzHg5P/66Ht6uoUlHu9EZod+inXhKo3qQgwXUT/y1w==", + "license": "MIT", + "dependencies": { + "buffer-from": "^1.0.0", + "source-map": "^0.6.0" + } + }, "node_modules/stoppable": { "version": "1.1.0", "resolved": "https://registry.npmjs.org/stoppable/-/stoppable-1.1.0.tgz", diff --git a/package.json b/package.json index 3c2cbb9..d30fc18 100644 --- a/package.json +++ b/package.json @@ -62,6 +62,46 @@ "type": "string", "default": "lfortran", "description": "The path to the LFortran compiler executable." + }, + "LFortranLanguageServer.log.level": { + "scope": "resource", + "type": "string", + "enum": [ + "off", + "fatal", + "error", + "warn", + "info", + "debug", + "trace", + "all" + ], + "default": "info", + "description": "Lowest level of logs to include in the extension's console output." + }, + "LFortranLanguageServer.log.benchmark": { + "scope": "resource", + "type": "boolean", + "default": false, + "description": "Whether to benchmark event handlers and related operations." + }, + "LFortranLanguageServer.log.filter": { + "scope": "resource", + "type": "string", + "default": "", + "description": "Regular expression for filtering log messages." + }, + "LFortranLanguageServer.log.prettyPrint": { + "scope": "resource", + "type": "boolean", + "default": true, + "description": "Whether to pretty-print JSON objects and arrays." + }, + "LFortranLanguageServer.log.indentSize": { + "scope": "resource", + "type": "number", + "default": 2, + "description": "Number of spaces to indent the pretty-printed JSON." } } } @@ -105,6 +145,9 @@ "vscode-extension-tester": "^8.9.0" }, "dependencies": { - "@types/which": "^3.0.4" + "@types/shell-escape": "^0.2.3", + "@types/which": "^3.0.4", + "shell-escape": "^0.2.0", + "source-map-support": "^0.5.21" } } diff --git a/server/src/lfortran-accessors.ts b/server/src/lfortran-accessors.ts index dfcc7c0..2a7fd08 100644 --- a/server/src/lfortran-accessors.ts +++ b/server/src/lfortran-accessors.ts @@ -12,8 +12,8 @@ import { } from 'vscode-languageserver/node'; import { - ExampleSettings, ErrorDiagnostics, + LFortranSettings, } from './lfortran-types'; import which from 'which'; @@ -24,6 +24,10 @@ import tmp from 'tmp'; import { spawnSync } from 'node:child_process'; +import { Logger } from './logger'; + +import shellescape from 'shell-escape'; + /** * Accessor interface for interacting with LFortran. Possible implementations * include a CLI accessor and service accessor. @@ -35,7 +39,7 @@ export interface LFortranAccessor { */ showDocumentSymbols(uri: string, text: string, - settings: ExampleSettings): Promise; + settings: LFortranSettings): Promise; /** * Looks-up the location and range of the definition of the symbol within the @@ -45,7 +49,7 @@ export interface LFortranAccessor { text: string, line: number, column: number, - settings: ExampleSettings): Promise; + settings: LFortranSettings): Promise; /** * Identifies the errors and warnings about the statements within the given @@ -53,20 +57,21 @@ export interface LFortranAccessor { */ showErrors(uri: string, text: string, - settings: ExampleSettings): Promise; + settings: LFortranSettings): Promise; renameSymbol(uri: string, text: string, line: number, column: number, newName: string, - settings: ExampleSettings): Promise; + settings: LFortranSettings): Promise; } /** - * Interacts with LFortran through its command-line interface. + * Interacts with LFortran through its escapedCommand-line interface. */ export class LFortranCLIAccessor implements LFortranAccessor { + static LOG_CONTEXT: string = "LFortranCLIAccessor"; // File handle representing the temporary file used to pass document text to // LFortran. @@ -75,48 +80,98 @@ export class LFortranCLIAccessor implements LFortranAccessor { postfix: ".tmp" }); - constructor() { + public logger: Logger; + private cleanUpHandler: () => void; + + constructor(logger: Logger) { + const fnid: string = "constructor(...)"; + const start: number = performance.now(); + + this.logger = logger; + // Be sure to delete the temporary file when possible. - const cleanUp = this.cleanUp.bind(this); - process.on("exit", cleanUp); - process.on("SIGINT", cleanUp); - process.on("uncaughtException", cleanUp); + this.cleanUpHandler = this.cleanUp.bind(this); + process.on("exit", this.cleanUpHandler); + process.on("SIGINT", this.cleanUpHandler); + process.on("uncaughtException", this.cleanUpHandler); + + this.logger.benchmarkAndTrace( + LFortranCLIAccessor.LOG_CONTEXT, + fnid, start, + [logger] + ); } - cleanUp(/* exitCode: number */) { - if (fs.existsSync(this.tmpFile.name)) { - try { - console.debug("Deleting temporary file: %s", this.tmpFile.name); - this.tmpFile.removeCallback(); - // eslint-disable-next-line @typescript-eslint/no-explicit-any - } catch (error: any) { - console.error("Failed to delete temporary file: %s", this.tmpFile.name); - console.error(error); + cleanUp(...args: any[]): void { + const fnid: string = "cleanUp(...)"; + const start: number = performance.now(); + + try { + if (fs.existsSync(this.tmpFile.name)) { + try { + this.logger.debug( + LFortranCLIAccessor.LOG_CONTEXT, + "Deleting temporary file: %s", + this.tmpFile.name); + this.tmpFile.removeCallback(); + } catch (error: any) { + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to delete temporary file: %s", + this.tmpFile.name); + this.logger.error(LFortranCLIAccessor.LOG_CONTEXT, error); + } } + } finally { + process.removeListener("uncaughtException", this.cleanUpHandler); + process.removeListener("SIGINT", this.cleanUpHandler); + process.removeListener("exit", this.cleanUpHandler); } + + this.logger.benchmarkAndTrace( + LFortranCLIAccessor.LOG_CONTEXT, + fnid, start, args + ); } async checkPathExistsAndIsExecutable(path: string): Promise { + const fnid: string = "checkPathExistsAndIsExecutable(...)"; + const start: number = performance.now(); + + let pathExistsAndIsExecutable: boolean = false; + try { const stats = await fs.promises.stat(path); - return stats.isFile() && (stats.mode & 0o111) !== 0; - // eslint-disable-next-line @typescript-eslint/no-explicit-any + pathExistsAndIsExecutable = stats.isFile() && + (stats.mode & 0o111) !== 0; } catch (err: any) { - if (err.code === 'ENOENT') { - return false; // Path doesn't exist + if (err.code !== 'ENOENT') { + throw err; // Other errors } - throw err; // Other errors } + + this.logger.benchmarkAndTrace( + LFortranCLIAccessor.LOG_CONTEXT, + fnid, start, + [path], + pathExistsAndIsExecutable + ); + return pathExistsAndIsExecutable; } /** * Invokes LFortran through its command-line interface with the given * settings, flags, and document text. */ - async runCompiler(settings: ExampleSettings, - flags: string[], - text: string): Promise { - let stdout: string = "{}"; + async runCompiler(settings: LFortranSettings, + params: string[], + text: string, + defaultValue: string = "", + noResponseIsSuccess: boolean = false): Promise { + const fnid: string = "runCompiler(...)"; + const start: number = performance.now(); + + let output: string = defaultValue; try { fs.writeFileSync(this.tmpFile.name, text); @@ -124,74 +179,125 @@ export class LFortranCLIAccessor implements LFortranAccessor { let lfortranPath: string | null = settings.compiler.lfortranPath; if (lfortranPath === "lfortran" || !(await this.checkPathExistsAndIsExecutable(lfortranPath))) { lfortranPath = await which("lfortran", { nothrow: true }); - console.debug("lfortranPath = %s", lfortranPath); + this.logger.debug( + LFortranCLIAccessor.LOG_CONTEXT, + "lfortranPath = %s", + lfortranPath); } if (lfortranPath === null) { - console.error( + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, "Failed to locate lfortran, please specify its path in the configuration."); - return ""; + return output; } try { try { fs.accessSync(lfortranPath, fs.constants.X_OK); - console.debug("[%s] is executable", lfortranPath); + this.logger.debug( + LFortranCLIAccessor.LOG_CONTEXT, + "[%s] is executable", + lfortranPath); } catch (err) { - console.error("[%s] is NOT executable", lfortranPath); - console.error(err); + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "[%s] is NOT executable", + lfortranPath); + this.logger.error(LFortranCLIAccessor.LOG_CONTEXT, err); } - flags = flags.concat([this.tmpFile.name]); - const response = spawnSync(lfortranPath, flags, { + + params = params.concat([this.tmpFile.name]); + + let escapedCommand: string | undefined; + let commandStart: number | undefined; + if (this.logger.isBenchmarkEnabled()) { + escapedCommand = shellescape([lfortranPath].concat(params)); + commandStart = performance.now(); + } + + const response = spawnSync(lfortranPath, params, { encoding: "utf-8", stdio: "pipe" }); + this.logger.benchmark( + LFortranCLIAccessor.LOG_CONTEXT, + escapedCommand as string, + commandStart as number); + if (response.error) { if (response.stderr) { - stdout = response.stderr.toString(); + output = response.stderr.toString(); } else { - console.error("Failed to get stderr from lfortran"); - stdout = ""; + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to get stderr from lfortran"); } } else { if (response.stdout) { - stdout = response.stdout.toString(); + output = response.stdout.toString(); + } else if (!noResponseIsSuccess) { + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to get stdout from lfortran"); } else { - console.error("Failed to get stdout from lfortran"); - stdout = ""; + this.logger.debug( + LFortranCLIAccessor.LOG_CONTEXT, + "lfortran responded successfully with an empty string."); } } - // eslint-disable-next-line @typescript-eslint/no-explicit-any } catch (compileError: any) { - stdout = compileError.stdout; + output = compileError.stdout; if (compileError.signal !== null) { - console.error("Compilation failed."); + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Compilation failed."); } throw compileError; } - // eslint-disable-next-line @typescript-eslint/no-explicit-any } catch (error: any) { - console.error(error); + this.logger.error(LFortranCLIAccessor.LOG_CONTEXT, error); } - return stdout; + + this.logger.benchmarkAndTrace( + LFortranCLIAccessor.LOG_CONTEXT, + fnid, start, [ + settings, + params, + text, + defaultValue, + noResponseIsSuccess, + ], + output + ); + + return output; } async showDocumentSymbols(uri: string, text: string, - settings: ExampleSettings): Promise { + settings: LFortranSettings): Promise { + const fnid: string = "showDocumentSymbols(...)"; + const start: number = performance.now(); + const flags = ["--show-document-symbols"]; - const stdout = await this.runCompiler(settings, flags, text); - let results: SymbolInformation[]; + const stdout = await this.runCompiler(settings, flags, text, "[]"); + + let symbols: SymbolInformation[]; + try { - results = JSON.parse(stdout); + symbols = JSON.parse(stdout); } catch (error) { - console.warn("Failed to parse response: %s", stdout); - console.warn(error); - return []; + this.logger.warn( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to parse response: %s", + stdout); + this.logger.warn(LFortranCLIAccessor.LOG_CONTEXT, error); + symbols = []; } - if (Array.isArray(results)) { - const symbols: SymbolInformation[] = results; + + if (Array.isArray(symbols)) { for (let i = 0, k = symbols.length; i < k; i++) { const symbol: SymbolInformation = symbols[i]; @@ -206,27 +312,38 @@ export class LFortranCLIAccessor implements LFortranAccessor { const end: Position = range.end; end.character--; } - return symbols; } - return []; + + this.logger.benchmarkAndTrace( + LFortranCLIAccessor.LOG_CONTEXT, + fnid, start, + [uri, text, settings], + symbols + ); + return symbols; } async lookupName(uri: string, text: string, line: number, column: number, - settings: ExampleSettings): Promise { + settings: LFortranSettings): Promise { + const fnid: string = "lookupName(...)"; + const start: number = performance.now(); + + const definitions: DefinitionLink[] = []; + try { const flags = [ "--lookup-name", "--line=" + (line + 1), "--column=" + (column + 1) ]; - const stdout = await this.runCompiler(settings, flags, text); - const obj = JSON.parse(stdout); - for (let i = 0, k = obj.length; i < k; i++) { - const location = obj[i].location; - if (location) { + const stdout = await this.runCompiler(settings, flags, text, "[]"); + const results = JSON.parse(stdout); + for (let i = 0, k = results.length; i < k; i++) { + const location = results[i].location; + if (location !== undefined) { const range: Range = location.range; const start: Position = range.start; @@ -235,45 +352,71 @@ export class LFortranCLIAccessor implements LFortranAccessor { const end: Position = range.end; end.character--; - return [{ + definitions.push({ targetUri: uri, targetRange: range, targetSelectionRange: range - }]; + }); + + break; } } - // eslint-disable-next-line @typescript-eslint/no-explicit-any } catch (error: any) { - console.error("Failed to lookup name at line=%d, column=%d", line, column); - console.error(error); + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to lookup name at line=%d, column=%d", + line, column); + this.logger.error(LFortranCLIAccessor.LOG_CONTEXT, error); } - return []; + + this.logger.benchmarkAndTrace( + LFortranCLIAccessor.LOG_CONTEXT, + fnid, start, [ + uri, + text, + line, + column, + settings, + ], + definitions + ); + + return definitions; } async showErrors(uri: string, text: string, - settings: ExampleSettings): Promise { + settings: LFortranSettings): Promise { + const fnid: string = "showErrors(...)"; + const start: number = performance.now(); + const diagnostics: Diagnostic[] = []; let stdout: string | null = null; try { const flags = ["--show-errors"]; - stdout = await this.runCompiler(settings, flags, text); + stdout = + await this.runCompiler(settings, flags, text, "[]", true); if (stdout.length > 0) { let results: ErrorDiagnostics; try { results = JSON.parse(stdout); - // eslint-disable-next-line @typescript-eslint/no-explicit-any } catch (error: any) { // FIXME: Remove this repair logic once the respective bug has been // fixed (lfortran/lfortran issue #5525) // ---------------------------------------------------------------- - console.warn("Failed to parse response, attempting to repair and re-parse it."); + this.logger.warn( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to parse response, attempting to repair and re-parse it."); const repaired: string = stdout.substring(0, 28) + "{" + stdout.substring(28); try { results = JSON.parse(repaired); - console.log("Repair succeeded, see: https://github.com/lfortran/lfortran/issues/5525"); + this.logger.log( + LFortranCLIAccessor.LOG_CONTEXT, + "Repair succeeded, see: https://github.com/lfortran/lfortran/issues/5525"); } catch { - console.error("Failed to repair response"); + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to repair response"); throw error; } } @@ -287,14 +430,25 @@ export class LFortranCLIAccessor implements LFortranAccessor { } } } - // eslint-disable-next-line @typescript-eslint/no-explicit-any } catch (error: any) { - console.error("Failed to show errors"); + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to show errors"); if (stdout !== null) { - console.error("Failed to parse response: %s", stdout); + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to parse response: %s", + stdout); } - console.error(error); + this.logger.error(LFortranCLIAccessor.LOG_CONTEXT, error); } + + this.logger.benchmarkAndTrace( + LFortranCLIAccessor.LOG_CONTEXT, + fnid, start, + [uri, text, settings], + diagnostics + ); return diagnostics; } @@ -303,7 +457,10 @@ export class LFortranCLIAccessor implements LFortranAccessor { line: number, column: number, newName: string, - settings: ExampleSettings): Promise { + settings: LFortranSettings): Promise { + const fnid: string = "renameSymbol(...)"; + const start: number = performance.now(); + const edits: TextEdit[] = []; try { const flags = [ @@ -311,7 +468,7 @@ export class LFortranCLIAccessor implements LFortranAccessor { "--line=" + (line + 1), "--column=" + (column + 1) ]; - const stdout = await this.runCompiler(settings, flags, text); + const stdout = await this.runCompiler(settings, flags, text, "[]"); const obj = JSON.parse(stdout); for (let i = 0, k = obj.length; i < k; i++) { const location = obj[i].location; @@ -332,11 +489,27 @@ export class LFortranCLIAccessor implements LFortranAccessor { edits.push(edit); } } - // eslint-disable-next-line @typescript-eslint/no-explicit-any } catch (error: any) { - console.error("Failed to rename symbol at line=%d, column=%d", line, column); - console.error(error); + this.logger.error( + LFortranCLIAccessor.LOG_CONTEXT, + "Failed to rename symbol at line=%d, column=%d", + line, column); + this.logger.error(LFortranCLIAccessor.LOG_CONTEXT, error); } + + this.logger.benchmarkAndTrace( + LFortranCLIAccessor.LOG_CONTEXT, + fnid, start, [ + uri, + text, + line, + column, + newName, + settings + ], + edits + ); + return edits; } } diff --git a/server/src/lfortran-language-server.ts b/server/src/lfortran-language-server.ts index 952c56d..015df56 100644 --- a/server/src/lfortran-language-server.ts +++ b/server/src/lfortran-language-server.ts @@ -13,8 +13,6 @@ import { Diagnostic, DidChangeConfigurationNotification, DidChangeConfigurationParams, - // DidChangeTextDocumentParams, - // DidChangeWatchedFilesParams, DocumentHighlight, DocumentHighlightParams, DocumentSymbolParams, @@ -38,50 +36,83 @@ import { import { TextDocument } from 'vscode-languageserver-textdocument'; -import { ExampleSettings } from './lfortran-types'; +import { LFortranSettings } from './lfortran-types'; import { LFortranAccessor } from './lfortran-accessors'; import { PrefixTrie } from './prefix-trie'; +import { Logger } from './logger'; + // The global settings, used when the `workspace/configuration` request is not // supported by the client. Please note that this is not the case when using // this server with the client provided in this example but could happen with // other clients. -const defaultSettings: ExampleSettings = { +const defaultSettings: LFortranSettings = { maxNumberOfProblems: 100, compiler: { - lfortranPath: "lfortran" - } + lfortranPath: "lfortran", + }, + log: { + level: "info", + benchmark: false, + filter: "", + }, }; const RE_IDENTIFIABLE: RegExp = /^[a-zA-Z0-9_]$/; export class LFortranLanguageServer { + static LOG_CONTEXT: string = "LFortranLanguageServer"; + public lfortran: LFortranAccessor; public connection: _Connection; public documents: TextDocuments; + public logger: Logger; public hasConfigurationCapability: boolean = false; public hasWorkspaceFolderCapability: boolean = false; public hasDiagnosticRelatedInformationCapability: boolean = false; - public settings: ExampleSettings = defaultSettings; + public settings: LFortranSettings; // Cache the settings of all open documents - public documentSettings: Map> = new Map(); + public documentSettings: Map> = new Map(); public dictionaries = new Map(); constructor(lfortran: LFortranAccessor, connection: _Connection, - documents: TextDocuments) { + documents: TextDocuments, + logger: Logger, + settings: LFortranSettings = defaultSettings) { + const fnid: string = "constructor(...)"; + const start: number = performance.now(); + this.lfortran = lfortran; this.connection = connection; this.documents = documents; + this.logger = logger; + this.settings = settings; + + logger.configure(settings); + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [ + lfortran, + connection, + documents, + logger, + settings, + ] + ); } onInitialize(params: InitializeParams): InitializeResult { + const fnid: string = "onInitialize(...)"; + const start: number = performance.now(); + const capabilities = params.capabilities; // Does the client support the `workspace/configuration` request? // If not, we fall back using global settings. @@ -120,25 +151,36 @@ export class LFortranLanguageServer { }; } + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [params], + result + ); return result; } - // eslint-disable-next-line @typescript-eslint/no-unused-vars onInitialized(params: InitializedParams): void { + const fnid: string = "onInitialized(...)"; + const start: number = performance.now(); + if (this.hasConfigurationCapability) { // Register for all configuration changes. this.connection.client .register(DidChangeConfigurationNotification.type, undefined); } - // if (hasWorkspaceFolderCapability) { - // // eslint-disable-next-line @typescript-eslint/no-unused-vars - // connection.workspace.onDidChangeWorkspaceFolders(_event => { - // // connection.console.log('Workspace folder change event received.'); - // }); - // } + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [params] + ); } - extractDefinition(location: Location): string | undefined { + extractDefinition(location: Location): string | null { + const fnid: string = "extractDefinition(...)"; + const start: number = performance.now(); + let definition: string | null = null; const document = this.documents.get(location.uri); if (document !== undefined) { const range: Range = location.range; @@ -176,8 +218,8 @@ export class LFortranLanguageServer { currCol++; } } - const definition: string = text.substring(i, j); - return definition; + definition = text.substring(i, j); + break; } else { c = text[i]; if (c === '\n') { @@ -196,16 +238,26 @@ export class LFortranLanguageServer { } } } + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [location], + definition); + return definition; } index(uri: string, symbols: SymbolInformation[]): void { + const fnid: string = "index(...)"; + const start: number = performance.now(); + // (symbols.length == 0) => error with document, but we still need to // support auto-completion. const terms: string[] = []; const values: CompletionItem[] = []; for (let i = 0, k = symbols.length; i < k; i++) { const symbol: SymbolInformation = symbols[i]; - const definition: string | undefined = + const definition: string | null = this.extractDefinition(symbol.location); terms.push(symbol.name); values.push({ @@ -218,99 +270,190 @@ export class LFortranLanguageServer { detail: definition, }); } - // TODO: Index temporary file by URI (maybe) + // TODO: Consider indexing temporary file by URI. const dictionary = PrefixTrie.from(terms, values); this.dictionaries.set(uri, dictionary); + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [uri, symbols] + ); } - async onDocumentSymbol(request: DocumentSymbolParams): Promise { + async onDocumentSymbol(request: DocumentSymbolParams): Promise { + const fnid: string = "onDocumentSymbol(...)"; + const start: number = performance.now(); + + let symbols: SymbolInformation[] | null = null; const uri = request.textDocument.uri; + this.settings = await this.getDocumentSettings(uri); + this.logger.configure(this.settings); const document = this.documents.get(uri); - const settings = await this.getDocumentSettings(uri); const text = document?.getText(); if (typeof text === "string") { - const symbols: SymbolInformation[] = - await this.lfortran.showDocumentSymbols(uri, text, settings); + symbols = + await this.lfortran.showDocumentSymbols(uri, text, this.settings); if (symbols.length > 0) { // (symbols.length == 0) => error with document, but we still need to // support auto-completion. this.index(uri, symbols); } - return symbols; } + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [request], + symbols + ); + + return symbols; } - async onDefinition(request: DefinitionParams): Promise { + async onDefinition(request: DefinitionParams): Promise { + const fnid: string = "onDefinition(...)"; + const start: number = performance.now(); + + let definitions: DefinitionLink[] | null = null; const uri = request.textDocument.uri; + this.settings = await this.getDocumentSettings(uri); + this.logger.configure(this.settings); const document = this.documents.get(uri); - const settings = await this.getDocumentSettings(uri); const text = document?.getText(); if (typeof text === "string") { const line = request.position.line; const column = request.position.character; - return await this.lfortran.lookupName(uri, text, line, column, settings); + definitions = + await this.lfortran.lookupName(uri, text, line, column, this.settings); } + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [request], + definitions + ); + + return definitions; } onDidChangeConfiguration(change: DidChangeConfigurationParams): void { + const fnid: string = "onDidChangeConfiguration(...)"; + const start: number = performance.now(); + if (this.hasConfigurationCapability) { // Reset all cached document settings this.documentSettings.clear(); } else { - this.settings = ( + this.settings = ( (change.settings.LFortranLanguageServer || defaultSettings) ); + this.logger.configure(this.settings); } // Revalidate all open text documents - this.documents.all().forEach(this.validateTextDocument); + this.documents.all().forEach(this.validateTextDocument.bind(this)); + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [change] + ); } - getDocumentSettings(resource: string): Thenable { + getDocumentSettings(uri: string): Thenable { + const fnid: string = "getDocumentSettings(...)"; + const start: number = performance.now(); + if (!this.hasConfigurationCapability) { + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [uri], + this.settings + ); return Promise.resolve(this.settings); } - let result = this.documentSettings.get(resource); - if (!result) { - result = this.connection.workspace.getConfiguration({ - scopeUri: resource, + + let settings: Thenable | undefined = + this.documentSettings.get(uri); + + if (settings === undefined) { + settings = this.connection.workspace.getConfiguration({ + scopeUri: uri, section: 'LFortranLanguageServer' }); - this.documentSettings.set(resource, result); + this.documentSettings.set(uri, settings); } - return result; + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [uri], + settings + ); + return settings; } // Only keep settings for open documents onDidClose(event: TextDocumentChangeEvent): void { + const fnid: string = "onDidClose(...)"; + const start: number = performance.now(); + this.documentSettings.delete(event.document.uri); + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [event] + ); } onDidChangeContent(event: TextDocumentChangeEvent): void { + const fnid: string = "onDidChangeContent(...)"; + const start: number = performance.now(); + this.validateTextDocument(event.document); + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [event] + ); } async validateTextDocument(textDocument: TextDocument): Promise { - if (!this.hasDiagnosticRelatedInformationCapability) { - console.error('Trying to validate a document with no diagnostic capability'); - return; + const fnid: string = "validateTextDocument(...)"; + const start: number = performance.now(); + + if (this.hasDiagnosticRelatedInformationCapability) { + const uri = textDocument.uri; + this.settings = await this.getDocumentSettings(uri); + this.logger.configure(this.settings); + const text = textDocument.getText(); + const diagnostics: Diagnostic[] = + await this.lfortran.showErrors(uri, text, this.settings); + // Send the computed diagnostics to VSCode. + this.connection.sendDiagnostics({ uri: uri, diagnostics }); + } else { + this.logger.error( + LFortranLanguageServer.LOG_CONTEXT, + 'Cannot validate a document with no diagnostic capability'); } - const uri = textDocument.uri; - const settings = await this.getDocumentSettings(uri); - const text = textDocument.getText(); - const diagnostics: Diagnostic[] = - await this.lfortran.showErrors(uri, text, settings); - // Send the computed diagnostics to VSCode. - this.connection.sendDiagnostics({ uri: uri, diagnostics }); - } - // // eslint-disable-next-line @typescript-eslint/no-unused-vars - // onDidChangeWatchedFiles(change: DidChangeWatchedFilesParams): void { - // // Monitored files have change in VSCode - // this.connection.console.log('We received an file change event'); - // } + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [textDocument] + ); + } extractQuery(text: string, line: number, column: number): string | null { + const fnid: string = "extractQuery(...)"; + const start: number = performance.now(); + + let query: string | null = null; let currLine: number = 0; let currCol: number = 0; @@ -328,8 +471,8 @@ export class LFortranLanguageServer { while ((u < k) && re_identifiable.test(text[u])) { u++; } - const query = text.substring(l, u); - return query; + query = text.substring(l, u); + break; } } @@ -348,10 +491,20 @@ export class LFortranLanguageServer { } } - return null; + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [text, line, column], + query + ); + return query; } - onCompletion(documentPosition: TextDocumentPositionParams): CompletionItem[] | CompletionList | undefined { + onCompletion(documentPosition: TextDocumentPositionParams): CompletionItem[] | CompletionList | null { + const fnid: string = "onCompletion(...)"; + const start: number = performance.now(); + + let completions: CompletionItem[] | null = null; const uri: string = documentPosition.textDocument.uri; const document = this.documents.get(uri); const dictionary = this.dictionaries.get(uri); @@ -362,17 +515,36 @@ export class LFortranLanguageServer { const column: number = pos.character - 1; const query: string | null = this.extractQuery(text, line, column); if (query !== null) { - const completions: CompletionItem[] = Array.from(dictionary.lookup(query)) as CompletionItem[]; - return completions; + completions = Array.from(dictionary.lookup(query)) as CompletionItem[]; } } + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [documentPosition], + completions + ); + return completions; } onCompletionResolve(item: CompletionItem): CompletionItem { + const fnid: string = "onCompletionResolve(...)"; + const start: number = performance.now(); + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [item], + item + ); return item; } - onHover(params: HoverParams): Hover | undefined { + onHover(params: HoverParams): Hover | null { + const fnid: string = "onHover(...)"; + const start: number = performance.now(); + + let hover: Hover | null = null; const uri: string = params.textDocument.uri; const document = this.documents.get(uri); const dictionary = this.dictionaries.get(uri); @@ -387,7 +559,7 @@ export class LFortranLanguageServer { dictionary.exactLookup(query) as CompletionItem; const definition: string | undefined = completion?.detail; if (definition !== undefined) { - return { + hover = { contents: { language: "fortran", value: definition, @@ -396,9 +568,20 @@ export class LFortranLanguageServer { } } } + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [params], + hover + ); + return hover; } highlightSymbol(text: string, symbol: string): Range[] { + const fnid: string = "highlightSymbol(...)"; + const start: number = performance.now(); + // case-insensitive search text = text.toLowerCase(); symbol = symbol.toLowerCase(); @@ -466,30 +649,53 @@ export class LFortranLanguageServer { } } + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [text, symbol], + highlights + ); return highlights; } renameSymbol(text: string, symbol: string, newName: string): TextEdit[] { - return this.highlightSymbol(text, symbol).map(range => ({ + const fnid: string = "renameSymbol(...)"; + const start: number = performance.now(); + + const edits: TextEdit[] = this.highlightSymbol(text, symbol).map(range => ({ range: range, newText: newName, })); + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [text, symbol, newName], + edits + ); + return edits; } - async onRenameRequest(params: RenameParams): Promise { + async onRenameRequest(params: RenameParams): Promise { + const fnid: string = "onRenameRequest(...)"; + const start: number = performance.now(); + + let workspaceEdit: WorkspaceEdit | null = null; const newName: string = params.newName; const uri: string = params.textDocument.uri; const document = this.documents.get(uri); + if (document !== undefined) { const text: string = document.getText(); const pos: Position = params.position; + this.settings = await this.getDocumentSettings(uri); + this.logger.configure(this.settings); // ===================================================================================== // FIXME: Once lfortran/lfortran issue #5524 is resolved, restore this call to lfortran: // ===================================================================================== - // const settings = await this.getDocumentSettings(uri); // const edits: TextEdit[] = - // await this.lfortran.renameSymbol(uri, text, pos.line, pos.character, newName, settings); - // return { + // await this.lfortran.renameSymbol(uri, text, pos.line, pos.character, newName, this.settings); + // workspaceEdit = { // changes: { // [uri]: edits, // }, @@ -499,22 +705,37 @@ export class LFortranLanguageServer { const dictionary = this.dictionaries.get(uri); if ((dictionary !== undefined) && dictionary.contains(query)) { const edits: TextEdit[] = this.renameSymbol(text, query, newName); - const workspaceEdit: WorkspaceEdit = { + workspaceEdit = { changes: { [uri]: edits, }, }; - return workspaceEdit; } else { - console.warn('Cannot find symbol to rename: "%s"', query); + this.logger.warn( + LFortranLanguageServer.LFortranLanguageServer.LOG_CONTEXT, + 'Cannot find symbol to rename: "%s"', + query); } } } + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [params], + workspaceEdit + ); + return workspaceEdit; } - async onDocumentHighlight(params: DocumentHighlightParams): Promise { + async onDocumentHighlight(params: DocumentHighlightParams): Promise { + const fnid: string = "onDocumentHighlight(...)"; + const start: number = performance.now(); + + let highlights: DocumentHighlight[] | null = null; const uri: string = params.textDocument.uri; const document = this.documents.get(uri); + if (document !== undefined) { const text: string = document.getText(); const pos: Position = params.position; @@ -522,14 +743,25 @@ export class LFortranLanguageServer { if (query !== null) { const dictionary = this.dictionaries.get(uri); if ((dictionary !== undefined) && dictionary.contains(query)) { - const highlights: DocumentHighlight[] = this.highlightSymbol(text, query).map(range => ({ + highlights = this.highlightSymbol(text, query).map(range => ({ range: range, })); - return highlights; } else { - console.warn('Cannot find symbol to highlight: "%s"', query); + this.logger.warn( + LFortranLanguageServer.LOG_CONTEXT, + 'Cannot find symbol to highlight: "%s"', + query); } } } + + this.logger.benchmarkAndTrace( + LFortranLanguageServer.LOG_CONTEXT, + fnid, start, + [params], + highlights + ); + return highlights; } } + diff --git a/server/src/lfortran-types.ts b/server/src/lfortran-types.ts index daf5fec..0de3df4 100644 --- a/server/src/lfortran-types.ts +++ b/server/src/lfortran-types.ts @@ -1,11 +1,18 @@ import { Diagnostic } from 'vscode-languageserver/node'; // The example settings -export interface ExampleSettings { +export interface LFortranSettings { maxNumberOfProblems: number; compiler: { lfortranPath: string; }; + log: { + level: string; + benchmark: boolean; + filter: string; + prettyPrint: boolean; + indentSize: number; + }; } export interface ErrorDiagnostics { diff --git a/server/src/logger.ts b/server/src/logger.ts new file mode 100644 index 0000000..3e5975d --- /dev/null +++ b/server/src/logger.ts @@ -0,0 +1,325 @@ +import * as util from "util"; + +import { LFortranSettings } from "./lfortran-types"; + +import { MovingStats } from "./moving-stats"; + +export enum LogLevel { + OFF = 0, + FATAL = 1, + ERROR = 2, + WARN = 3, + INFO = 4, + DEBUG = 5, + TRACE = 6, + ALL = 7, +} + +export function logLevelFromName(lowerName: string): LogLevel { + const upperName: string = lowerName.toUpperCase(); + const level: LogLevel | undefined = LogLevel[upperName]; + if (level === undefined) { + throw new Error(`Invalid LogLevel: ${lowerLevel}`); + } + return level; +} + +export class Logger { + + /** Current `LogLevel` for filtering and formatting messages. */ + public level: LogLevel = LogLevel.INFO; + + /** Whether to enable benchmarking. */ + public enableBenchmark: boolean = false; + + public filter: RegExp = /(?:)/; + + public prettyPrint: boolean = true; + + public indentSize: number = 2; + + private stats: Map = new Map(); + + /** + * @param level Initial `LogLevel` of this `Logger`. + */ + constructor(settings?: LFortranSettings) { + if (settings !== undefined) { + this.configure(settings); + } + } + + configure(settings: LFortranSettings): void { + this.level = logLevelFromName(settings.log.level); + this.enableBenchmark = settings.log.benchmark; + this.filter = new RegExp(settings.log.filter); + this.prettyPrint = settings.log.prettyPrint; + this.indentSize = settings.log.indentSize; + } + + includeString(value: string): boolean { + return this.filter.test(value); + } + + includeError(error: Error): boolean { + const message: string = error.message; + return this.includeString(message); + } + + includeTrace(array: any[]): boolean { + if ((array.length > 0) && (typeof array[0] === "string")) { + const fnid: string = array[0]; + return this.includeString(fnid); + } + return true; + } + + include(value: any): boolean { + if (typeof value === "string") { + return this.includeString(value); + } + if (Array.isArray(value) && (value.length > 0)) { + const first: any = value[0]; + if (Array.isArray(first)) { + return this.includeTrace(first); + } + if (typeof first === "string") { + if (value.length > 1) { + const formatted: string = util.format(...value); + return this.includeString(formatted); + } + return this.includeString(first); + } + } + if (value instanceof Error) { + return this.includeError(value); + } + return true; + } + + /** + * Returns whether benchmark requests will be logged. + * @return Value of `this.enableBenchmark`. + */ + isBenchmarkEnabled(): boolean { + return this.enableBenchmark; + } + + /** + * Returns true if no log level is enabled. + * @return Whether all log levels are disabled. + */ + areAllDisabled(): boolean { + return this.level === LogLevel.OFF; + } + + /** + * Returns true when the log level is at least `LogLevel.FATAL`. + * @return Whether fatal logs are enabled. + */ + isFatalEnabled(): boolean { + return this.level >= LogLevel.FATAL; + } + + /** + * Returns true when the log level is at least `LogLevel.ERROR`. + * @return Whether error logs are enabled. + */ + isErrorEnabled(): boolean { + return this.level >= LogLevel.ERROR; + } + + /** + * Returns true when the log level is at least `LogLevel.WARN`. + * @return Whether warn logs are enabled. + */ + isWarnEnabled(): boolean { + return this.level >= LogLevel.WARN; + } + + /** + * Returns true when the log level is at least `LogLevel.INFO`. + * @return Whether info logs are enabled. + */ + isInfoEnabled(): boolean { + return this.level >= LogLevel.INFO; + } + + /** + * Returns true when the log level is at least `LogLevel.DEBUG`. + * @return Whether debug logs are enabled. + */ + isDebugEnabled(): boolean { + return this.level >= LogLevel.DEBUG; + } + + /** + * Returns true when the log level is at least `LogLevel.TRACE`. + * @return Whether trace logs are enabled. + */ + isTraceEnabled(): boolean { + return this.level >= LogLevel.TRACE; + } + + /** + * Returns true if all the log levels are enabled. + * @return Whether all the log levels are enabled. + */ + areAllEnabled(): boolean { + return this.level >= LogLevel.TRACE; // LogLevel.TRACE => Log all messages + } + + benchmark(context: string, identifier: string, start: number): void { + if (this.isBenchmarkEnabled()) { + const stop: number = performance.now(); + const millis: number = stop - start; + + let stats: MovingStats | undefined = this.stats.get(identifier); + if (stats === undefined) { + stats = new MovingStats(); + this.stats.set(identifier, stats); + } + stats.observe(millis); + + this.printFormat(console.log, context, "TIME", [ + "%s took %s ms (samples: %d, mean: %s +/- %s ms, min: %s ms, max: %s ms)", + identifier, + millis.toFixed(2), + stats.getNumSamples(), + stats.getMean().toFixed(2), + stats.getStdDev().toFixed(2), + stats.getMin().toFixed(2), + stats.getMax().toFixed(2), + ]); + } + } + + /** + * Prepends the log level to the given statement. + * @param log Prints the log message. + * @param level Identifies the log level of the message. + * @param message_and_args An optional vararg array that may contain either a + * string message followed by positional arguments or a single element + * consisting of an object to debug (such as a caught `Error`). + */ + printFormat(log: (...messages_and_args: any[]) => void, + context: string, + level: string, + message_and_args: any[]): void { + if ((message_and_args.length > 0) && (typeof message_and_args[0] === "string")) { + const message: string = message_and_args[0]; + const args: any[] = message_and_args.slice(1); + const pattern: string = `[${context}][${level}] ${message}`; + const formatted: string = util.format(pattern, ...args); + message_and_args = [formatted]; + } + if (this.include(message_and_args)) { + log.apply(console, message_and_args); + } + } + + /** + * Prints a message to `console.error` with the prefix `[FATAL]`. This should + * only be used to log errors that cannot be recovered from. In order to use + * this method, the log level must be set to at least `LogLevel.FATAL`. + * @param message_and_args An optional vararg array that may contain either a + * string message followed by positional arguments or a single element + * consisting of an object to debug (such as a caught `Error`). + */ + fatal(context: string, ...message_and_args: any[]): void { + if (this.isFatalEnabled()) { + this.printFormat(console.error, context, "FATAL", message_and_args); + } + } + + /** + * Prints a message to `console.error` with the prefix `[ERROR]`. This should + * be used when logging non-fatal errors that prevent functionality. In order + * to use this method, the log level must be set to at least `LogLevel.ERROR`. + * @param message_and_args An optional vararg array that may contain either a + * string message followed by positional arguments or a single element + * consisting of an object to debug (such as a caught `Error`). + */ + error(context: string, ...message_and_args: any[]): void { + if (this.isErrorEnabled()) { + this.printFormat(console.error, context, "ERROR", message_and_args); + } + } + + /** + * Prints a message to `console.warn` with the prefix `[WARN]`. This should be + * used when logging non-fatal errors that do not prevent functionality. In + * order to use this method, the log level must be set to at least + * `LogLevel.WARN`. + * @param message_and_args An optional vararg array that may contain either a + * string message followed by positional arguments or a single element + * consisting of an object to debug (such as a caught `Error`). + */ + warn(context: string, ...message_and_args: any[]): void { + if (this.isWarnEnabled()) { + this.printFormat(console.warn, context, "WARN", message_and_args); + } + } + + /** + * Prints a message to `console.info` with the prefix `[INFO]`. This should be + * used when logging standard messages. In order to use this method, the log + * level must be set to at least `LogLevel.INFO`. + * @param message_and_args An optional vararg array that may contain either a + * string message followed by positional arguments or a single element + * consisting of an object to debug (such as a caught `Error`). + */ + info(context: string, ...message_and_args: any[]): void { + if (this.isInfoEnabled()) { + this.printFormat(console.info, context, "INFO", message_and_args); + } + } + + /** + * Prints a message to `console.debug` with the prefix `[DEBUG]`. This should be + * used when logging information for debugging purposes. In order to use this + * method, the log level must be set to at least `LogLevel.DEBUG`. + * @param message_and_args An optional vararg array that may contain either a + * string message followed by positional arguments or a single element + * consisting of an object to debug (such as a caught `Error`). + */ + debug(context: string, ...message_and_args: any[]): void { + if (this.isDebugEnabled()) { + this.printFormat(console.debug, context, "DEBUG", message_and_args); + } + } + + /** + * Prints a message to `console.debug` with the prefix `[TRACE]`. This should + * be used when logging extraneous information for debugging purposes that + * would pollute the terminal output with unnecessary messages unless the + * messages are explicitly desired. Such messages may include the names and + * parameters of every method called. In order to use this method, the log + * level must be set to at least `LogLevel.TRACE`. + * @param message_and_args An optional vararg array that may contain either a + * string message followed by positional arguments or a single element + * consisting of an object to debug (such as a caught `Error`). + */ + trace(context: string, ...message_and_args: any[]): void { + if (this.isTraceEnabled()) { + this.printFormat(console.debug, context, "TRACE", message_and_args); + } + } + + benchmarkAndTrace(context: string, + fnid: string, + start: number, + params: any[], + retval?: any): void { + this.benchmark(context, fnid, start); + if (this.isTraceEnabled()) { + const indentSize = (this.prettyPrint) ? this.indentSize : undefined; + const stringified: string = JSON.stringify([ + fnid, + params, + retval + ], undefined, indentSize); + this.debug(context, stringified); + } + } +} diff --git a/server/src/main.ts b/server/src/main.ts index e71a758..77e2b05 100644 --- a/server/src/main.ts +++ b/server/src/main.ts @@ -1,3 +1,5 @@ +import 'source-map-support/register'; + import { _Connection, createConnection, @@ -14,7 +16,11 @@ import { import { LFortranLanguageServer } from './lfortran-language-server'; -const lfortran: LFortranAccessor = new LFortranCLIAccessor(); +import { Logger } from './logger'; + +const logger: Logger = new Logger(); + +const lfortran: LFortranAccessor = new LFortranCLIAccessor(logger); // Create a connection for the server, using Node's IPC as a transport. // Also include all preview / proposed LSP features. @@ -23,14 +29,18 @@ const connection: _Connection = createConnection(ProposedFeatures.all); // Create a simple text document manager. const documents: TextDocuments = new TextDocuments(TextDocument); -const server = new LFortranLanguageServer(lfortran, connection, documents); +const server = new LFortranLanguageServer( + lfortran, + connection, + documents, + logger +); connection.onInitialize(server.onInitialize.bind(server)); connection.onInitialized(server.onInitialized.bind(server)); connection.onDocumentSymbol(server.onDocumentSymbol.bind(server)); connection.onDefinition(server.onDefinition.bind(server)); connection.onDidChangeConfiguration(server.onDidChangeConfiguration.bind(server)); -// connection.onDidChangeWatchedFiles(server.onDidChangeWatchedFiles.bind(server)); connection.onCompletion(server.onCompletion.bind(server)); connection.onCompletionResolve(server.onCompletionResolve.bind(server)); connection.onHover(server.onHover.bind(server)); diff --git a/server/src/moving-stats.ts b/server/src/moving-stats.ts new file mode 100644 index 0000000..2cfc08b --- /dev/null +++ b/server/src/moving-stats.ts @@ -0,0 +1,66 @@ +/** + * Computes the moving average and variance using Welford's online algorithm, + * along with various other moving statistics. + */ +export class MovingStats { + public numSamples: number = 0; + public mean: number = 0.0; + public variance: number = 0.0; + public min: number = Number.MAX_VALUE; + public max: number = Number.MIN_VALUE; + + public getNumSamples(): number { + return this.numSamples; + } + + public getMean(): number { + return this.mean; + } + + public getVariance(): number { + return this.variance; + } + + public getStdDev(): number { + if (this.variance != 0.0) { + return Math.sqrt(this.variance); + } + return 0.0; + } + + public getMin(): number { + return this.min; + } + + public getMax(): number { + return this.max; + } + + observe(value: number): void { + const numSamples = 1 + this.numSamples; + if (this.numSamples > 1) { + let mean: number = this.mean; + let variance: number = this.variance; + + const p1: number = value - mean; + mean += (p1 / numSamples); + + const p2: number = value - mean; + variance += (((p1 * p2) - variance) / numSamples); + + this.mean = mean; + this.variance = variance; + } else { + this.mean = value; + } + this.numSamples = numSamples; + + if (value < this.min) { + this.min = value; + } + + if (value > this.max) { + this.max = value; + } + } +} diff --git a/server/src/prefix-trie.ts b/server/src/prefix-trie.ts index 02061ed..63f2736 100644 --- a/server/src/prefix-trie.ts +++ b/server/src/prefix-trie.ts @@ -54,7 +54,6 @@ export class PrefixNode { return ss.join(""); } - // eslint-disable-next-line @typescript-eslint/no-explicit-any equalsPrefix(that: any): boolean { return (that instanceof PrefixNode) && ((this.parent === undefined) === (that.parent === undefined)) && @@ -63,7 +62,6 @@ export class PrefixNode { (this.label === that.label); } - // eslint-disable-next-line @typescript-eslint/no-explicit-any equalsSuffix(that: any): boolean { return (that instanceof PrefixNode) && (this.isFinal === that.isFinal) && @@ -75,7 +73,6 @@ export class PrefixNode { }); } - // eslint-disable-next-line @typescript-eslint/no-explicit-any equals(that: any): boolean { return this.equalsPrefix(that) && this.equalsSuffix(that); } @@ -164,7 +161,6 @@ export class PrefixIterator { return buffer.join(""); } - // eslint-disable-next-line @typescript-eslint/no-explicit-any equals(that: any): boolean { return (that instanceof PrefixIterator) && (this.value === that.value) && @@ -223,7 +219,6 @@ export class PrefixCursor { return `PrefixCursor{prev=${prev},curr=${curr}}`; } - // eslint-disable-next-line @typescript-eslint/no-explicit-any equals(that: any): boolean { return (that instanceof PrefixCursor) && ((this.curr === undefined) === (that.curr === undefined)) && @@ -379,7 +374,6 @@ export class PrefixTrie { return buffer.join(""); } - // eslint-disable-next-line @typescript-eslint/no-explicit-any equals(that: any): boolean { return (that instanceof PrefixTrie) && (this.size === that.size) && diff --git a/server/test/spec/lfortran-accessors.spec.ts b/server/test/spec/lfortran-accessors.spec.ts index 101cd75..23a151c 100644 --- a/server/test/spec/lfortran-accessors.spec.ts +++ b/server/test/spec/lfortran-accessors.spec.ts @@ -10,6 +10,8 @@ import { import { LFortranCLIAccessor } from "../../src/lfortran-accessors"; +import { Logger } from "../../src/logger"; + import { settings } from "./lfortran-common"; import { assert } from "chai"; @@ -19,12 +21,14 @@ import "mocha"; import * as sinon from 'sinon'; describe("LFortranCLIAccessor", () => { + let logger: Logger; let lfortran: LFortranCLIAccessor; const uri: string = __filename; beforeEach(() => { - lfortran = new LFortranCLIAccessor(); + logger = new Logger(settings); + lfortran = new LFortranCLIAccessor(logger); }); afterEach(() => { diff --git a/server/test/spec/lfortran-common.ts b/server/test/spec/lfortran-common.ts index 87e4fc5..3608abb 100644 --- a/server/test/spec/lfortran-common.ts +++ b/server/test/spec/lfortran-common.ts @@ -1,8 +1,15 @@ -import { ExampleSettings } from "../../src/lfortran-types"; +import { LFortranSettings } from "../../src/lfortran-types"; -export const settings: ExampleSettings = { +export const settings: LFortranSettings = { maxNumberOfProblems: 100, compiler: { lfortranPath: "", - } + }, + log: { + level: "off", + benchmark: false, + filter: "", + prettyPrint: false, + indentSize: 0, + }, }; diff --git a/server/test/spec/lfortran-language-server.spec.ts b/server/test/spec/lfortran-language-server.spec.ts index 4853ee4..ce59263 100644 --- a/server/test/spec/lfortran-language-server.spec.ts +++ b/server/test/spec/lfortran-language-server.spec.ts @@ -31,9 +31,7 @@ import { import { TextDocument } from "vscode-languageserver-textdocument"; -import { - ExampleSettings, -} from '../../src/lfortran-types'; +import { LFortranSettings } from '../../src/lfortran-types'; import { LFortranCLIAccessor } from "../../src/lfortran-accessors"; @@ -41,6 +39,8 @@ import { LFortranLanguageServer } from "../../src/lfortran-language-server"; import { settings } from "./lfortran-common"; +import { Logger } from "../../src/logger"; + import * as sinon from "sinon"; import { stubInterface } from "ts-sinon"; @@ -49,6 +49,7 @@ import { assert } from "chai"; import "mocha"; describe("LFortranLanguageServer", () => { + let logger: Logger; let lfortran: LFortranCLIAccessor; let connection: _Connection; let documents: TextDocuments; @@ -58,7 +59,8 @@ describe("LFortranLanguageServer", () => { const uri: string = __filename; beforeEach(() => { - lfortran = new LFortranCLIAccessor(); + logger = new Logger(settings); + lfortran = new LFortranCLIAccessor(logger); connection = stubInterface<_Connection>(); connection.workspace = stubInterface(); @@ -71,8 +73,13 @@ describe("LFortranLanguageServer", () => { documents.get.returns(document); documents.all.returns([document]); - server = new LFortranLanguageServer(lfortran, connection, documents); - server.settings = settings; + server = new LFortranLanguageServer( + lfortran, + connection, + documents, + logger, + settings + ); server.hasDiagnosticRelatedInformationCapability = true; }); @@ -167,7 +174,7 @@ describe("LFortranLanguageServer", () => { it("Returns nothing when the document has not been defined", async () => { const actual = await server.onDocumentSymbol(request); - assert.isUndefined(actual); + assert.isNull(actual); }); }); @@ -231,14 +238,15 @@ describe("LFortranLanguageServer", () => { it("returns nothing when the document has not been defined", async () => { const actual = await server.onDefinition(request); - assert.isUndefined(actual); + assert.isNull(actual); }); }); describe("onDidChangeConfiguration", () => { - const updatedSettings: ExampleSettings = { + const updatedSettings: LFortranSettings = { maxNumberOfProblems: 1234, - compiler: settings.compiler + compiler: settings.compiler, + log: settings.log, }; const configChange: DidChangeConfigurationParams = { settings: { @@ -263,6 +271,7 @@ describe("LFortranLanguageServer", () => { describe("onDidClose", () => { it("removes the document from the cache", () => { + document.getText.returns(""); const event: TextDocumentChangeEvent = { document: document }; @@ -273,6 +282,7 @@ describe("LFortranLanguageServer", () => { describe("onDidChangeContent", () => { it("validates document from event", () => { + document.getText.returns(""); const event: TextDocumentChangeEvent = { document: document }; @@ -1069,7 +1079,7 @@ describe("LFortranLanguageServer", () => { }; const actual: DocumentHighlight[] | undefined | null = await server.onDocumentHighlight(params); - assert.isUndefined(actual); + assert.isNull(actual); }); it("highlights symbols when they are recognized", async () => { diff --git a/server/test/spec/logger.spec.ts b/server/test/spec/logger.spec.ts new file mode 100644 index 0000000..a3052bc --- /dev/null +++ b/server/test/spec/logger.spec.ts @@ -0,0 +1,515 @@ +import { + Logger, + LogLevel, +} from "../../src/logger"; + +import { assert } from "chai"; + +import "mocha"; + +import * as sinon from 'sinon'; + +const LOG_CONTEXT: string = "LOGGER_SPEC"; + +describe("Logger", () => { + let logger: Logger; + + beforeEach(() => { + logger = new Logger(); + sinon.stub(logger, "printFormat").returns(undefined); + }); + + describe("isBenchmarkEnabled", () => { + it("returns false when enableBenchmark is false", () => { + logger.enableBenchmark = false; + assert.isFalse(logger.isBenchmarkEnabled()); + }); + + it("returns true when enableBenchmark is true", () => { + logger.enableBenchmark = true; + assert.isTrue(logger.isBenchmarkEnabled()); + }); + }); + + describe("benchmark", () => { + it("does nothing when enableBenchmark is false", () => { + logger.enableBenchmark = false; + logger.benchmark(LOG_CONTEXT, "foo", performance.now()); + assert.isFalse(logger.printFormat.called); + }); + + it("logs a message when enableBenchmark is true", () => { + logger.enableBenchmark = true; + logger.benchmark(LOG_CONTEXT, "foo", performance.now()); + assert.isTrue(logger.printFormat.called); + }); + }); + + describe("areAllDisabled", () => { + it("returns true when logger.level is LogLevel.OFF", () => { + logger.level = LogLevel.OFF; + assert.isTrue(logger.areAllDisabled()); + }); + + it("returns false when logger.level is anything but LogLevel.OFF", () => { + logger.level = LogLevel.FATAL; + assert.isFalse(logger.areAllDisabled()); + + logger.level = LogLevel.ERROR; + assert.isFalse(logger.areAllDisabled()); + + logger.level = LogLevel.WARN; + assert.isFalse(logger.areAllDisabled()); + + logger.level = LogLevel.INFO; + assert.isFalse(logger.areAllDisabled()); + + logger.level = LogLevel.DEBUG; + assert.isFalse(logger.areAllDisabled()); + + logger.level = LogLevel.TRACE; + assert.isFalse(logger.areAllDisabled()); + + logger.level = LogLevel.ALL; + assert.isFalse(logger.areAllDisabled()); + }); + }); + + describe("isFatalEnabled", () => { + it("returns false when logger.level is below LogLevel.FATAL", () => { + logger.level = LogLevel.OFF; + assert.isFalse(logger.isFatalEnabled()); + }); + + it("returns true when logger.level is at least LogLevel.FATAL", () => { + logger.level = LogLevel.FATAL; + assert.isTrue(logger.isFatalEnabled()); + + logger.level = LogLevel.ERROR; + assert.isTrue(logger.isFatalEnabled()); + + logger.level = LogLevel.WARN; + assert.isTrue(logger.isFatalEnabled()); + + logger.level = LogLevel.INFO; + assert.isTrue(logger.isFatalEnabled()); + + logger.level = LogLevel.DEBUG; + assert.isTrue(logger.isFatalEnabled()); + + logger.level = LogLevel.TRACE; + assert.isTrue(logger.isFatalEnabled()); + + logger.level = LogLevel.ALL; + assert.isTrue(logger.isFatalEnabled()); + }); + }); + + describe("isErrorEnabled", () => { + it("returns false when logger.level is below LogLevel.ERROR", () => { + logger.level = LogLevel.OFF; + assert.isFalse(logger.isErrorEnabled()); + + logger.level = LogLevel.FATAL; + assert.isFalse(logger.isErrorEnabled()); + }); + + it("returns true when logger.level is at least LogLevel.ERROR", () => { + logger.level = LogLevel.ERROR; + assert.isTrue(logger.isErrorEnabled()); + + logger.level = LogLevel.WARN; + assert.isTrue(logger.isErrorEnabled()); + + logger.level = LogLevel.INFO; + assert.isTrue(logger.isErrorEnabled()); + + logger.level = LogLevel.DEBUG; + assert.isTrue(logger.isErrorEnabled()); + + logger.level = LogLevel.TRACE; + assert.isTrue(logger.isErrorEnabled()); + + logger.level = LogLevel.ALL; + assert.isTrue(logger.isErrorEnabled()); + }); + }); + + describe("isWarnEnabled", () => { + it("returns false when logger.level is below LogLevel.WARN", () => { + logger.level = LogLevel.OFF; + assert.isFalse(logger.isWarnEnabled()); + + logger.level = LogLevel.FATAL; + assert.isFalse(logger.isWarnEnabled()); + + logger.level = LogLevel.ERROR; + assert.isFalse(logger.isWarnEnabled()); + }); + + it("returns true when logger.level is at least LogLevel.WARN", () => { + logger.level = LogLevel.WARN; + assert.isTrue(logger.isWarnEnabled()); + + logger.level = LogLevel.INFO; + assert.isTrue(logger.isWarnEnabled()); + + logger.level = LogLevel.DEBUG; + assert.isTrue(logger.isWarnEnabled()); + + logger.level = LogLevel.TRACE; + assert.isTrue(logger.isWarnEnabled()); + + logger.level = LogLevel.ALL; + assert.isTrue(logger.isWarnEnabled()); + }); + }); + + describe("isInfoEnabled", () => { + it("returns false when logger.level is below LogLevel.INFO", () => { + logger.level = LogLevel.OFF; + assert.isFalse(logger.isInfoEnabled()); + + logger.level = LogLevel.FATAL; + assert.isFalse(logger.isInfoEnabled()); + + logger.level = LogLevel.ERROR; + assert.isFalse(logger.isInfoEnabled()); + + logger.level = LogLevel.WARN; + assert.isFalse(logger.isInfoEnabled()); + }); + + it("returns true when logger.level is at least LogLevel.INFO", () => { + logger.level = LogLevel.INFO; + assert.isTrue(logger.isInfoEnabled()); + + logger.level = LogLevel.DEBUG; + assert.isTrue(logger.isInfoEnabled()); + + logger.level = LogLevel.TRACE; + assert.isTrue(logger.isInfoEnabled()); + + logger.level = LogLevel.ALL; + assert.isTrue(logger.isInfoEnabled()); + }); + }); + + describe("isDebugEnabled", () => { + it("returns false when logger.level is below LogLevel.DEBUG", () => { + logger.level = LogLevel.OFF; + assert.isFalse(logger.isDebugEnabled()); + + logger.level = LogLevel.FATAL; + assert.isFalse(logger.isDebugEnabled()); + + logger.level = LogLevel.ERROR; + assert.isFalse(logger.isDebugEnabled()); + + logger.level = LogLevel.WARN; + assert.isFalse(logger.isDebugEnabled()); + + logger.level = LogLevel.INFO; + assert.isFalse(logger.isDebugEnabled()); + }); + + it("returns true when logger.level is at least LogLevel.DEBUG", () => { + logger.level = LogLevel.DEBUG; + assert.isTrue(logger.isDebugEnabled()); + + logger.level = LogLevel.TRACE; + assert.isTrue(logger.isDebugEnabled()); + + logger.level = LogLevel.ALL; + assert.isTrue(logger.isDebugEnabled()); + }); + }); + + describe("isTraceEnabled", () => { + it("returns false when logger.level is below LogLevel.TRACE", () => { + logger.level = LogLevel.OFF; + assert.isFalse(logger.isTraceEnabled()); + + logger.level = LogLevel.FATAL; + assert.isFalse(logger.isTraceEnabled()); + + logger.level = LogLevel.ERROR; + assert.isFalse(logger.isTraceEnabled()); + + logger.level = LogLevel.WARN; + assert.isFalse(logger.isTraceEnabled()); + + logger.level = LogLevel.INFO; + assert.isFalse(logger.isTraceEnabled()); + + logger.level = LogLevel.DEBUG; + assert.isFalse(logger.isTraceEnabled()); + }); + + it("returns true when logger.level is at least LogLevel.TRACE", () => { + logger.level = LogLevel.TRACE; + assert.isTrue(logger.isTraceEnabled()); + + logger.level = LogLevel.ALL; + assert.isTrue(logger.isTraceEnabled()); + }); + }); + + describe("areAllEnabled", () => { + it("returns false when logger.level is below LogLevel.TRACE", () => { + logger.level = LogLevel.OFF; + assert.isFalse(logger.areAllEnabled()); + + logger.level = LogLevel.FATAL; + assert.isFalse(logger.areAllEnabled()); + + logger.level = LogLevel.ERROR; + assert.isFalse(logger.areAllEnabled()); + + logger.level = LogLevel.WARN; + assert.isFalse(logger.areAllEnabled()); + + logger.level = LogLevel.INFO; + assert.isFalse(logger.areAllEnabled()); + + logger.level = LogLevel.DEBUG; + assert.isFalse(logger.areAllEnabled()); + }); + + it("returns true when logger.level is at least LogLevel.TRACE", () => { + logger.level = LogLevel.TRACE; + assert.isTrue(logger.areAllEnabled()); + + logger.level = LogLevel.ALL; + assert.isTrue(logger.areAllEnabled()); + }); + }); + + describe("fatal", () => { + it("logs nothing when logger.level is below LogLevel.FATAL", () => { + logger.level = LogLevel.OFF; + logger.fatal(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + }); + + it("returns true when logger.level is at least LogLevel.FATAL", () => { + logger.level = LogLevel.FATAL; + logger.fatal(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.ERROR; + logger.fatal(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.WARN; + logger.fatal(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.INFO; + logger.fatal(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.DEBUG; + logger.fatal(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.TRACE; + logger.fatal(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.ALL; + logger.fatal(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + }); + }); + + describe("error", () => { + it("returns false when logger.level is below LogLevel.ERROR", () => { + logger.level = LogLevel.OFF; + logger.error(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.FATAL; + logger.error(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + }); + + it("returns true when logger.level is at least LogLevel.ERROR", () => { + logger.level = LogLevel.ERROR; + logger.error(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.WARN; + logger.error(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.INFO; + logger.error(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.DEBUG; + logger.error(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.TRACE; + logger.error(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.ALL; + logger.error(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + }); + }); + + describe("warn", () => { + it("returns false when logger.level is below LogLevel.WARN", () => { + logger.level = LogLevel.OFF; + logger.warn(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.FATAL; + logger.warn(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.ERROR; + logger.warn(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + }); + + it("returns true when logger.level is at least LogLevel.WARN", () => { + logger.level = LogLevel.WARN; + logger.warn(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.INFO; + logger.warn(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.DEBUG; + logger.warn(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.TRACE; + logger.warn(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.ALL; + logger.warn(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + }); + }); + + describe("info", () => { + it("returns false when logger.level is below LogLevel.INFO", () => { + logger.level = LogLevel.OFF; + logger.info(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.FATAL; + logger.info(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.ERROR; + logger.info(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.WARN; + logger.info(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + }); + + it("returns true when logger.level is at least LogLevel.INFO", () => { + logger.level = LogLevel.INFO; + logger.info(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.DEBUG; + logger.info(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.TRACE; + logger.info(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.ALL; + logger.info(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + }); + }); + + describe("debug", () => { + it("returns false when logger.level is below LogLevel.DEBUG", () => { + logger.level = LogLevel.OFF; + logger.debug(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.FATAL; + logger.debug(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.ERROR; + logger.debug(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.WARN; + logger.debug(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.INFO; + logger.debug(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + }); + + it("returns true when logger.level is at least LogLevel.DEBUG", () => { + logger.level = LogLevel.DEBUG; + logger.debug(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.TRACE; + logger.debug(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.ALL; + logger.debug(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + }); + }); + + describe("trace", () => { + it("returns false when logger.level is below LogLevel.TRACE", () => { + logger.level = LogLevel.OFF; + logger.trace(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.FATAL; + logger.trace(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.ERROR; + logger.trace(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.WARN; + logger.trace(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.INFO; + logger.trace(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + + logger.level = LogLevel.DEBUG; + logger.trace(LOG_CONTEXT, "message"); + assert.isFalse(logger.printFormat.called); + }); + + it("returns true when logger.level is at least LogLevel.TRACE", () => { + logger.level = LogLevel.TRACE; + logger.trace(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + + logger.level = LogLevel.ALL; + logger.trace(LOG_CONTEXT, "message"); + assert.isTrue(logger.printFormat.called); + }); + }); +}); diff --git a/server/test/spec/stats.spec.ts b/server/test/spec/stats.spec.ts new file mode 100644 index 0000000..00ffed3 --- /dev/null +++ b/server/test/spec/stats.spec.ts @@ -0,0 +1,73 @@ +import { MovingStats } from "../../src/moving-stats"; + +import { assert } from "chai"; + +import "mocha"; + +import fc from "fast-check"; + +describe("MovingStats", () => { + it("correctly summarizes the sequence of events", () => { + fc.assert( + fc.property( + fc.array( + fc.double({ + min: 1e-3, + max: 50.0, + noNaN: true, + noDefaultInfinity: true, + }), + { + minLength: 10, + } + ), + (xs: number[]): void => { + const n: number = xs.length; + + let expectedMean: number = 0.0; + for (let i = 0; i < n; i++) { + expectedMean += (xs[i] / n); + } + + let expectedVariance: number = 0.0; + for (let i = 0; i < n; i++) { + const p = xs[i] - expectedMean; + expectedVariance += (p * p) / n; + } + + const expectedStdDev: number = Math.sqrt(expectedVariance); + + let expectedMin: number = Number.MAX_VALUE; + let expectedMax: number = Number.MIN_VALUE; + for (let i = 0; i < n; i++) { + const x = xs[i]; + if (x < expectedMin) { + expectedMin = x; + } + if (x > expectedMax) { + expectedMax = x; + } + } + + const stats: MovingStats = new MovingStats(); + for (let i = 0; i < n; i++) { + stats.observe(xs[i]); + } + + assert.equal(stats.getNumSamples(), n); + assert.equal(stats.getMin(), expectedMin); + assert.equal(stats.getMax(), expectedMax); + + // NOTE: These are a bit harder to test since the moving statistics + // are approximate. It is possible that something here may fail when + // there is not actually a problem -- be especially mindful of the + // variance assertion. + const delta: number = 20.0; + assert.closeTo(stats.getMean(), expectedMean, delta); + assert.closeTo(stats.getVariance(), expectedVariance, delta * delta); + assert.closeTo(stats.getStdDev(), expectedStdDev, delta); + } + ) + ); + }); +});