DSL register/unregister race (log based)

.github/workflows/build.yaml

@@ -52,7 +52,7 @@ jobs:
         os: [buildjet-4vcpu-ubuntu-2204, windows-latest, macos-latest]
       fail-fast: true
     env:
-      CODE_VERSION: "1.90.2"
+      CODE_VERSION: "1.97.0"
     runs-on:  ${{ matrix.os }}
     steps:
       - uses: actions/checkout@v5

rascal-lsp/src/main/java/org/rascalmpl/vscode/lsp/BaseLanguageServer.java

@@ -243,22 +243,24 @@ public CompletableFuture<Two<String, URI[]>[]> supplyPathConfig(PathConfigParame
 
         @Override
         public CompletableFuture<Void> sendRegisterLanguage(LanguageParameter lang) {
+            logger.debug("sendRegisterLanguage({})", lang.getName());
             return CompletableFuture.runAsync(() -> lspDocumentService.registerLanguage(lang), executor);
         }
         @Override
         public CompletableFuture<Void> sendUnregisterLanguage(LanguageParameter lang) {
+            logger.debug("sendUnregisterLanguage({})", lang.getName());
             return CompletableFuture.runAsync(() -> lspDocumentService.unregisterLanguage(lang), executor);
         }
 
         @Override
         public CompletableFuture<InitializeResult> initialize(InitializeParams params) {
             return CompletableFuture.supplyAsync(() -> {
                 logger.info("LSP connection started (connected to {} version {})", params.getClientInfo().getName(), params.getClientInfo().getVersion());
-                logger.debug("LSP client capabilities: {}", params.getCapabilities());
+                logger.trace("LSP client capabilities: {}", params.getCapabilities());
                 final InitializeResult initializeResult = new InitializeResult(new ServerCapabilities());
                 lspDocumentService.initializeServerCapabilities(initializeResult.getCapabilities());
                 lspWorkspaceService.initialize(params.getCapabilities(), params.getWorkspaceFolders(), initializeResult.getCapabilities());
-                logger.debug("Initialized LSP connection with capabilities: {}", initializeResult);
+                logger.trace("Initialized LSP connection with capabilities: {}", initializeResult);
                 return initializeResult;
             }, executor);
         }

rascal-lsp/src/main/java/org/rascalmpl/vscode/lsp/parametric/ParametricTextDocumentService.java

@@ -919,7 +919,7 @@ public CompletableFuture<List<CallHierarchyOutgoingCall>> callHierarchyOutgoingC
 
     @Override
     public synchronized void registerLanguage(LanguageParameter lang) {
-        logger.info("registerLanguage({})", lang.getName());
+        logger.info("registerLanguage({})/begin", lang.getName());
 
         var multiplexer = contributions.computeIfAbsent(lang.getName(),
             t -> new LanguageContributionsMultiplexer(lang.getName(), exec)
@@ -963,6 +963,8 @@ public synchronized void registerLanguage(LanguageParameter lang) {
                 updateFileState(lang, f);
             }
         }
+
+        logger.info("registerLanguage({})/end", lang.getName());
     }
 
     private void updateFileState(LanguageParameter lang, ISourceLocation f) {
@@ -985,6 +987,7 @@ private static String buildContributionKey(LanguageParameter lang) {
 
     @Override
     public synchronized void unregisterLanguage(LanguageParameter lang) {
+        logger.info("unregisterLanguage({})/begin", lang.getName());
         boolean removeAll = lang.getMainModule() == null || lang.getMainModule().isEmpty();
         if (!removeAll) {
             var contrib = contributions.get(lang.getName());
@@ -1010,6 +1013,7 @@ public synchronized void unregisterLanguage(LanguageParameter lang) {
             facts.remove(lang.getName());
             contributions.remove(lang.getName());
         }
+        logger.info("unregisterLanguage({})/end", lang.getName());
     }
 
     @Override

rascal-lsp/src/main/java/org/rascalmpl/vscode/lsp/parametric/RascalInterface.java

@@ -31,7 +31,8 @@
 import java.util.concurrent.ExecutionException;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.TimeoutException;
-
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 import org.checkerframework.checker.nullness.qual.Nullable;
 import org.eclipse.lsp4j.jsonrpc.Launcher;
 import org.rascalmpl.debug.IRascalMonitor;
@@ -53,6 +54,8 @@
     private final @Nullable LanguageRegistry languageRegistry;
     private final IRascalMonitor monitor;
 
+    private static final Logger logger = LogManager.getLogger(ParametricTextDocumentService.class);
+
     @SuppressWarnings("resource")
     public RascalInterface(IRascalMonitor monitor) {
         this.monitor = monitor;
@@ -68,7 +71,7 @@
                     .setInput(socket.getInputStream())
                     .setOutput(socket.getOutputStream())
                     .create();
-                
+
                 clientLauncher.startListening();
                 registry = clientLauncher.getRemoteProxy();
             }
@@ -79,6 +82,7 @@
     }
 
     public void registerLanguage(IConstructor lang) {
+        logger.info("registerLanguage({})", lang);
         if (languageRegistry == null) {
             monitor.warning("Could not register language: no connection", URIUtil.unknownLocation());
         } else {
@@ -94,6 +98,7 @@
     }
 
     public void unregisterLanguage(IConstructor lang) {
+        logger.info("unregisterLanguage({})", lang);
         if (languageRegistry == null) {
             monitor.warning("Could not unregister language: no connection", URIUtil.unknownLocation());
         } else {

rascal-lsp/src/main/rascal/library/demo/lang/pico/LanguageServer.rsc

@@ -313,7 +313,10 @@ in the presence of error trees. See ((util::LanguageServer)) for more details.
 * You can run each contribution on an example in the terminal to test it first.
 Any feedback (errors and exceptions) is faster and more clearly printed in the terminal.
 }
-void main(bool errorRecovery=false) {
+void main(bool errorRecovery=false, bool unregister=false) {
+    if (unregister) {
+        unregisterLanguage("Pico", {"pico", "pico-new"});
+    }
     registerLanguage(
         language(
             pathConfig(),

rascal-vscode-extension/package.json

@@ -16,7 +16,7 @@
   },
   "version": "0.13.0-head",
   "engines": {
-    "vscode": "^1.90.0",
+    "vscode": "^1.97.0",
     "node": ">=20.9.0"
   },
   "type": "commonjs",
@@ -289,7 +289,7 @@
     "@types/mocha": "10.x",
     "@types/node": "20.x",
     "@types/tar": "6.x",
-    "@types/vscode": "1.90.0",
+    "@types/vscode": "1.97.0",
     "@types/yauzl": "2.x",
     "@typescript-eslint/eslint-plugin": "7.x",
     "@typescript-eslint/parser": "7.x",

rascal-vscode-extension/src/RascalExtension.ts

@@ -48,7 +48,7 @@ export class RascalExtension implements vscode.Disposable {
     constructor(private readonly context: vscode.ExtensionContext, private readonly jarRootPath: string, private readonly icon: vscode.Uri, private readonly isDeploy = true) {
         this.vfsServer = new VSCodeUriResolverServer(!isDeploy, this.log);
 
-        this.dsls = new ParameterizedLanguageServer(context, this.vfsServer, jarRootPath, isDeploy);
+        this.dsls = new ParameterizedLanguageServer(context, this.vfsServer, jarRootPath, this.log, isDeploy);
         this.rascal = new RascalLanguageServer(context, this.vfsServer, jarRootPath, this.dsls, this.log, isDeploy);
 
         this.registerTerminalCommand();

rascal-vscode-extension/src/lsp/ParameterizedLanguageServer.ts

@@ -39,6 +39,7 @@ export class ParameterizedLanguageServer implements vscode.Disposable {
         context: vscode.ExtensionContext,
         private readonly vfsServer: VSCodeUriResolverServer,
         private readonly absoluteJarPath: string,
+        private readonly log: vscode.LogOutputChannel,
         private readonly deployMode = true,
         private readonly languageId = 'parametric-rascalmpl',
         private readonly title = 'Language Parametric Rascal Language Server',
@@ -94,9 +95,11 @@ export class ParameterizedLanguageServer implements vscode.Disposable {
 
 
     async registerLanguage(lang:LanguageParameter) {
-        const client = this.getLanguageClient();
+        const client = await this.getLanguageClient();
         // first we load the new language into the parametric server
-        await (await client).sendRequest("rascal/sendRegisterLanguage", lang);
+        this.log.debug(`rascal/sendRegisterLanguage(${lang.name})`);
+        await client.sendRequest("rascal/sendRegisterLanguage", lang);
+        this.log.debug(`rascal/sendRegisterLanguage(${lang.name}) [done]`);
 
         if (this.dedicatedLanguage === undefined) {
             for (const editor of vscode.window.visibleTextEditors) {
@@ -120,8 +123,10 @@ export class ParameterizedLanguageServer implements vscode.Disposable {
     }
 
     async unregisterLanguage(lang: LanguageParameter) {
-        const client = this.getLanguageClient();
-        (await client).sendRequest("rascal/sendUnregisterLanguage", lang);
+        const client = await this.getLanguageClient();
+        this.log.debug(`rascal/sendUnregisterLanguage(${lang.name})`);
+        await client.sendRequest("rascal/sendUnregisterLanguage", lang);
+        this.log.debug(`rascal/sendUnregisterLanguage(${lang.name}) [done]`);
 
         if (this.dedicatedLanguage === undefined) {
             for (const ext of lang.extensions) {

rascal-vscode-extension/src/test/vscode-suite/dsl-unregister-register-race.test.ts

@@ -0,0 +1,94 @@
+/*
+ * Copyright (c) 2018-2025, NWO-I CWI and Swat.engineering
+ * All rights reserved.
+ *
+ * Redistribution and use in source and binary forms, with or without
+ * modification, are permitted provided that the following conditions are met:
+ *
+ * 1. Redistributions of source code must retain the above copyright notice,
+ * this list of conditions and the following disclaimer.
+ *
+ * 2. Redistributions in binary form must reproduce the above copyright notice,
+ * this list of conditions and the following disclaimer in the documentation
+ * and/or other materials provided with the distribution.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS"
+ * AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
+ * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
+ * ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT HOLDER OR CONTRIBUTORS BE
+ * LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
+ * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF
+ * SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS
+ * INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN
+ * CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE)
+ * ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
+ * POSSIBILITY OF SUCH DAMAGE.
+ */
+
+import assert, { fail } from 'assert';
+import { BottomBarPanel, VSBrowser, WebDriver, Workbench } from 'vscode-extension-tester';
+import { loadPico } from './dsl.test';
+import { Delays, IDEOperations, getLogs, ignoreFails, printRascalOutputOnFailure } from './utils';
+
+describe('DSL unregister/register race', function () {
+    let browser: VSBrowser;
+    let driver: WebDriver;
+    let bench: Workbench;
+    let ide : IDEOperations;
+
+    let failed: boolean = false;
+
+    this.timeout(Delays.extremelySlow * 2);
+
+    printRascalOutputOnFailure(() => driver, () => ide);
+
+    before(async () => {
+        browser = VSBrowser.instance;
+        driver = browser.driver;
+        bench = new Workbench();
+        await ignoreFails(browser.waitForWorkbench());
+        ide = new IDEOperations(browser);
+        await ide.load();
+    });
+
+    beforeEach(async function () {
+    });
+
+    afterEach(async function () {
+        if (this.currentTest && this.currentTest.state === 'failed') {
+            failed = true;
+        }
+        if (this.currentTest) {
+            await ide.cleanup();
+        }
+    });
+
+    after(async function() {
+    });
+
+    for (let i = 0; i < 100; i++) {
+        it.only("Try trigger race", async function () {
+            if (failed) {
+                this.skip();
+            }
+            const bbp = new BottomBarPanel();
+            await bbp.openOutputView();
+            await bench.executeCommand("workbench.output.action.clearOutput");
+            await loadPico(bench, driver, browser, false, true);
+            const logs = await driver.wait(async() => await ignoreFails(getLogs(driver)));
+            if (!logs) {
+                fail("No logs");
+            }
+            assert(logs.length > 0);
+            console.log(logs);
+            const lastUnregister = logs.findLastIndex(l => l.match(/ParametricTextDocumentService unregisterLanguage/i));
+            const allRegisters = logs.filter(l => l.match(/ParametricTextDocumentService registerLanguage/i)).map(l => logs.indexOf(l)).sort().slice(-4);
+            assert(lastUnregister > 0, "No `unregisterLanguage` log found");
+            assert(allRegisters.length === 4, "No `registerLanguage` log found");
+            for (const r of allRegisters) {
+                assert(lastUnregister < r, `Language unregistration was not finished before registration started:\n${logs[r]}\n${logs[lastUnregister]}`);
+            }
+        });
+    }
+});
+

rascal-vscode-extension/src/test/vscode-suite/dsl.test.ts

@@ -38,6 +38,32 @@ function parameterizedDescribe(body: (this: Suite, errorRecovery: boolean) => vo
     describe('DSL+recovery', function() { body.apply(this, [true]); });
 }
 
+export async function loadPico(bench: Workbench, driver: WebDriver, browser: VSBrowser, errorRecovery: boolean = false, unregister: boolean = false) {
+    const repl = new RascalREPL(bench, driver);
+    await repl.start();
+    await repl.execute("import demo::lang::pico::LanguageServer;");
+
+    // If Pico was registered before as part of another series of tests,
+    // then it needs to be unregistered first (because error recovery
+    // en/disabledness affects which contributors to use). Until issue #630
+    // is fixed (race between `unregister` and `register`), the
+    // unregistration can't reliably be done as part of `main` (tried in
+    // commit `a955a05`). Instead, it's done here and followed by a suitably
+    // long sleep.
+    await repl.execute("import util::LanguageServer;");
+    await repl.execute('unregisterLanguage("Pico", {"pico", "pico-new"});');
+    await sleep(Delays.normal);
+
+    const replExecuteMain = repl.execute(`main(errorRecovery=${errorRecovery}, unregister=${unregister});`); // we don't wait yet, because we might miss pico loading window
+    const ide = new IDEOperations(browser);
+    const isPicoLoading = ide.statusContains("Pico");
+    await driver.wait(isPicoLoading, Delays.slow, "Pico DSL should start loading");
+    // now wait for the Pico loader to disappear
+    await driver.wait(async () => !(await isPicoLoading()), Delays.extremelySlow, "Pico DSL should be finished starting", 100);
+    await replExecuteMain;
+    await repl.terminate();
+}
+
 parameterizedDescribe(function (errorRecovery: boolean) {
     let browser: VSBrowser;
     let driver: WebDriver;
@@ -47,33 +73,9 @@ parameterizedDescribe(function (errorRecovery: boolean) {
 
     this.timeout(Delays.extremelySlow * 2);
 
-    printRascalOutputOnFailure('Language Parametric Rascal');
-
-    async function loadPico() {
-        const repl = new RascalREPL(bench, driver);
-        await repl.start();
-        await repl.execute("import demo::lang::pico::LanguageServer;");
-
-        // If Pico was registered before as part of another series of tests,
-        // then it needs to be unregistered first (because error recovery
-        // en/disabledness affects which contributors to use). Until issue #630
-        // is fixed (race between `unregister` and `register`), the
-        // unregistration can't reliably be done as part of `main` (tried in
-        // commit `a955a05`). Instead, it's done here and followed by a suitably
-        // long sleep.
-        await repl.execute("import util::LanguageServer;");
-        await repl.execute('unregisterLanguage("Pico", {"pico", "pico-new"});');
-        await sleep(Delays.normal);
-
-        const replExecuteMain = repl.execute(`main(errorRecovery=${errorRecovery});`); // we don't wait yet, because we might miss pico loading window
-        const ide = new IDEOperations(browser);
-        const isPicoLoading = ide.statusContains("Pico");
-        await driver.wait(isPicoLoading, Delays.slow, "Pico DSL should start loading");
-        // now wait for the Pico loader to disappear
-        await driver.wait(async () => !(await isPicoLoading()), Delays.extremelySlow, "Pico DSL should be finished starting", 100);
-        await replExecuteMain;
-        await repl.terminate();
-    }
+    printRascalOutputOnFailure(() => driver, () => ide);
+
+
 
 
     before(async () => {
@@ -83,7 +85,7 @@ parameterizedDescribe(function (errorRecovery: boolean) {
         await ignoreFails(browser.waitForWorkbench());
         ide = new IDEOperations(browser);
         await ide.load();
-        await loadPico();
+        await loadPico(bench, driver, browser, errorRecovery);
         picoFileBackup = await fs.readFile(TestWorkspace.picoFile);
         ide = new IDEOperations(browser);
         await ide.load();