Saving a class leads to three compiles

[isc-bsaviano]

We have updated to the new version 3.0.1. Now we have the problem described.
After saving, we get this output. The class was compiled three times.
It was a very simple class without any dependencies.

`Compilation started on 04/07/2025 08:40:41 with qualifiers 'cukb'
Class twa.unittests.util.TestHelper is up-to-date.
Compilation finished successfully in 0.099s.

Compilation started on 04/07/2025 08:40:42 with qualifiers 'cukb'
Class twa.unittests.util.TestHelper is up-to-date.
Compilation finished successfully in 0.018s.

Compilation started on 04/07/2025 08:40:43 with qualifiers 'cukb'
Class twa.unittests.util.TestHelper is up-to-date.
Compilation finished successfully in 0.020s.`

Originally posted by @TwaHendrik in #1470 (comment)

[isc-bsaviano]

Hi @TwaHendrik, thanks for that additional info. I created an issue for your problem. This point is very interesting:

We use the default -> All. We also try it with vscodeOnly (the compilation then works as expected), but then we lose the Git functionality.

I would not expect this setting to change the behavior when a class is edited inside of VS Code. Do you have any other programs that might be changing the file after it gets saved, like git hooks? I have not been able to reproduce this issue so far.

[TwaHendrik]

Hi @isc-bsaviano ,

We have simplified the test scenario as much as possible. We have started a completely new Docker with IRIS 2024.1 (Image: containers.intersystems.com/intersystems/iris:2024.1). No custom settings made. The Settings.json also only contains the default settings and a completely new vs code folder. We create only one class in default USER Namespace and save it via crtl + s.

Class

Class twa.testfile Extends %RegisteredObject
{
 
}

Output

Compilation started on 04/10/2025 08:54:58 with qualifiers 'cuk'
Class twa.testfile is up-to-date.
Compilation finished successfully in 0.015s.
 
Compilation started on 04/10/2025 08:54:59 with qualifiers 'cuk'
Class twa.testfile is up-to-date.
Compilation finished successfully in 0.004s.

I hope this helps to reproduce the error.

[isc-bsaviano]

Hi @TwaHendrik, thanks for the detailed reproduction steps.I still cannot get this to occur. Here's what I did:

1. Created a new folder.
2. Copied over a .vscode/settings.json file from another folder that only has an objectscript.conn setting.
3. Opened the new folder in VS Code.
4. Clicked on the InterSystems view to make sure our extensions were active.
5. Created a new cls file by right-clicking in the file explorer and selecting New File....
6. Saw the new class open in an editor tab. The Class scaffolding was filled in, and the document was dirty.
7. I saved the class. It only compiled once.

[TwaHendrik]

Hi @isc-bsaviano ,

We have tested it again on Mac OS and it works there. There seems to be a difference between windows and mac.
The problem does not occur every time. Sometimes it is only compiled once, sometimes twice and sometimes even more frequently. Sometimes the compile fails because the class is already locked by another process of the same compile operation.

1. Do you use mac os or windows?
2. Do you use a clean installation of IRIS?
3. Is it possible to monitor the compile requests fired by vs code to iris?

[isc-bsaviano]

HI @TwaHendrik, I was testing on Mac. I will have access to a Windows machine on Monday so I will test this again then.

[isc-bsaviano]

I was able to reproduce this on Windows.

[isc-bsaviano]

@TwaHendrik I haven't been able to reproduce this reliably, even on Windows. Can you please install the VSIX in the attached zip file and let me know if it fixes the issue? It has a bunch of logging that should help me identify the issue, plus a small change that may have fixed it.

vscode-objectscript-3.0.2-hendrick.1.zip

[TwaHendrik]

Hi @isc-bsaviano ,

we have installed the version and still get the error. The output is:

Will save file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls
ERROR #5864: User 'CSP Gateway' in process '4220' has 'Sample.Test2.cls' open for editing.

Compilation started on 04/22/2025 13:44:57 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.058s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 13:45:01 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.002s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true

Hope this will help you to find the problem.

[isc-bsaviano]

Thanks for trying that. Was that the entire contents of the ObjectScript Output channel? It looks like two file events were triggered at the same time, which is strange. I've added a few more log events to the attached VSIX. Can you try this again and send me the entire contents of the Output channel? Thanks again for your help.

vscode-objectscript-3.0.2-hendrick.2.zip

[TwaHendrik]

Hi @isc-bsaviano ,

yes, it was the complete output. Here is the new output. This time there was a lot of compeling again:

Will save file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:00:53 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.030s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:00:55 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.002s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:00:57 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.190s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:00:59 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.005s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:01:02 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.005s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:01:05 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.003s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:01:06 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.004s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:01:08 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.003s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:01:10 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.002s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

Compilation started on 04/22/2025 15:01:11 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.003s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true

[isc-bsaviano]

Thanks, that log output is much more useful. Here's what's going on:

Will save file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

You saved the class, the index of the workspace folder was updated, and the change is about to be synced with the server.

Compilation started on 04/22/2025 15:00:53 with qualifiers 'cuk'
Class Sample.Test2 is up-to-date.
Compilation finished successfully in 0.030s.
About to write file:///d:/projects/wops/src/cls/Sample/Test2.cls
ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): true
Wrote file:///d:/projects/wops/src/cls/Sample/Test2.cls

The class was synced with the server and compiled. The text of the class was retrieved from the server in case it was changed due to the sync/compile. The retrieved text was written to the file, which triggered a file system event. The event did not attempt to re-sync, because it was triggered by an export from the server. Everything looks good so far.

ondidchange file:///d:/projects/wops/src/cls/Sample/Test2.cls
exportedUris.has(uriString): false
About to index file:///d:/projects/wops/src/cls/Sample/Test2.cls
About to sync file:///d:/projects/wops/src/cls/Sample/Test2.cls

This is where the problem starts. For some reason, a second file system event is triggered. Since the "exported" flag is cleared, our extension thinks this is a change that needs to be synced with the server. This causes the multi-compile loop. I don't know why that extra event is happening, or why it only happens some of the time. Just to confirm, you have a single folder open, not a .code-workspace file? You also don't have any other programs that could be touching these files, like git hooks, another text editor open, or even a VS Code auto-formatting setting on? I think my best bet for fixing this may be to add debounce functionality to the file system event listener.

[TwaHendrik]

Hi @isc-bsaviano ,

• we don't use .code-workspace
• we don't use any other program (we create a blank new folder, without git and only the default settings.json)
• we also disable our security program for a test, as well
• we don't use any auto formatting tool

Let use know, if you need any further informations.

[isc-bsaviano]

Thanks for the confirmation. I think I have a fix. I've added some code that sores the timestamp of the last file system event and if the current one occurred very close to that timestamp, the second event is ignored. I've added a temporary setting "objectscript.TEST" that controls the time limit for an event to be considered a duplicate so we can change the value without me having to send you another VSIX. The default value is 25 ms, which I think is short enough that no human-triggered duplicate events would be ignored. If this works, you should not see the multi-compile issue and a line starting with "duplicate" will appear in the Output channel.

vscode-objectscript-3.0.2-hendrick.3.zip

[TwaHendrik]

Hi @isc-bsaviano ,

if we use the value ‘objectscript.TEST’:300, it seems to work with only one compilation.

[isc-bsaviano]

Thanks for checking @TwaHendrik. Did any value lower than that work? I will clean up the code and open the PR on Monday. Unfortunately my remote desktop into my Windows machine is not working.

[TwaHendrik]

Thanks @isc-bsaviano . I tried with lower values but that doesn't work. This period is sometimes not enough.

[isc-bsaviano]

@TwaHendrik Thanks again for helping me debug this! Version 3.0.2-beta.6 has the fix.