[Bug]: ALS ada log file scrambled (multi-tasking?)

[simonjwright]

Environment

• OS and Version: macOS Sequoia 15.2 (aarch64)
• IDE Version: 1.96.4
• Ada & SPARK Extension Version: 26.0.202412191

Bug Summary and Reproducer

Bug Summary: The [ALS PROJECT] and later [ALS.MAIN] sections of the log are scrambled so they’re very hard to read.

[ALS.PROJECT] Workspace is an Alire crate
[ALS.PROJECT] Determining project from 'alr show' output
[ALS.PR[ALS.PROJECT] Setting environment from 'alr pri[ALS.PR[ALS.PROJECT] Loading project: test.gpr
[ALS.PROJECT] Loading project wit[ALS.PROJECT] GPR2 messages after load:
   [ALS.PROJECT] No GPR2 messages
[ALS.PROJECT] Updating project sources
[ALS.PR[ALS.PROJECT] GPR2 messages after updating so   [ALS   [ALS.PROJECT] No GPR2 me[ALS.PR[ALS.PROJECT] Prepend Context Id: file:///Users/simon/Developer/esp32h2_hal/test/te[ALS.PR[ALS.PROJECT] Project status after loading: 
_ALS.PROJECT_ (PROJECT_TYPE => ALIRE_PROJECT,
_ALS.PROJECT_  STATUS => VALID_PROJECT,
_ALS.PROJECT_  PROJECT_FILE => {GNATCOLL.VFS.VIRTUAL_FILE� object},
_ALS.PROJECT_  MISSING_ADA_RUNTIME => FALSE,
_ALS.PROJECT_  GPR2_MESSAGES => {GPR2.LOG.OBJECT� ob[ALS.MAIN] Creating fallback context
[ALS.MA[ALS.MAIN] Out Message_Handler Text_Document_Did_Open
[ALS.MAIN] In Message_Handler Text_Document_Did_Open URI:
[ALS.MAIN] f[ALS.MAIN] In Message_Handler Text_Document_Did_Open URI:
[ALS.MAIN] file:///Users/simon/Developer/esp32h2_hal/src/esp32h2_hal-gpio.ads
[ALS.MAIN] Out Message_Handler Text_Document_Did_Open
[ALS.MAIN] In Message_Handler Text_Document_Did_Open URI:
[ALS.MAIN] file:///Users/simon/Developer/esp32h2_hal/src/esp32h2_hal-gpio.adb
[ALS.MAIN] Out Message_Handler Text_Document_Did_Open

One possibly unusual thing: this project (esp32h2_hal) contains a nested test project, which refers to the parent project via a pin. Using VSCode, everything works fine (in spite of the scrambled log!), but using ada-ts-mode, when I navigate from a file in esp32h2_hal/test/ to a file in the parent esp32h2_hal/ another ALS is spawned which doesn’t know about settings (e.g. runtime) in the original. I’m trying to debug this undesirable behaviour.

Steps to reproduce:
$ code test.adb

Expected behavior:
The log file isn’t corrupted.

Configuration and Logs

[ALS.MAIN] ALS version: 26.0.202412191 ()
[ALS.MAIN] Initializing server ...
[ALS.MAIN] GPR PATH: 
[ALS.MAIN] PATH: /Library/Frameworks/Python.framework/Versions/3.10/bin:/Users/simon/Library/Python/3.9/bin:/Library/Frameworks/Python.framework/Versions/3.9/bin:/opt/gcc-14.2.0-3-aarch64/bin:/Users/simon/.alire/bin:/Users/simon/local/bin:/opt/homebrew/bin:/opt/homebrew/sbin:/usr/local/bin:/System/Cryptexes/App/usr/bin:/usr/bin:/bin:/usr/sbin:/sbin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/local/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/appleinternal/bin:/opt/X11/bin:/Library/Apple/usr/bin:/usr/local/MacGPG2/bin:/Library/TeX/texbin:/Users/simon/gprbuild-aarch64-darwin-24.0.0-2/bin:/Users/simon/Developer/esp/esp-idf/components/espcoredump:/Users/simon/Developer/esp/esp-idf/components/partition_table:/Users/simon/Developer/esp/esp-idf/components/app_update:/Users/simon/.espressif/tools/riscv32-esp-elf-gdb/14.2_20240403/riscv32-esp-elf-gdb/bin:/Users/simon/.espressif/tools/riscv32-esp-elf/esp-13.2.0_20240530/riscv32-esp-elf/bin:/Users/simon/.espressif/tools/openocd-esp32/v0.12.0-esp32-20241016/openocd-esp32/bin:/Users/simon/.espressif/python_env/idf5.3_py3.10_env/bin:/Users/simon/Developer/esp/esp-idf/tools:/Library/Frameworks/Python.framework/Versions/3.10/bin:/Users/simon/Library/Python/3.9/bin:/Library/Frameworks/Python.framework/Versions/3.9/bin:/opt/gcc-14.2.0-3-aarch64/bin:/Users/simon/.alire/bin:/Users/simon/local/bin:/Users/simon/bin:/Users/simon/bin
[ALS.MAIN] Trying config file: /Users/simon/.config/als/config.json
[ALS.MAIN] /Users/simon/.config/als/config.json doesn't exist
[ALS.MAIN] Trying config file: /Users/simon/Developer/esp32h2_hal/test/.als.json
[ALS.MAIN] /Users/simon/Developer/esp32h2_hal/test/.als.json doesn't exist
[ALS.MAIN] Ada version used for predefined completion: ADA_2020
[ALS.MAIN] Processing initializationOptions from initialize request
[ALS.MAIN] In Message_Handler Text_Document_Did_Open URI:
[ALS.MAIN] file:///Users/simon/Developer/esp32h2_hal/test/src/test.adb
[ALS.PROJECT] Workspace is an Alire crate
[ALS.PROJECT] Determining project from 'alr show' output
[ALS.PR[ALS.PROJECT] Setting environment from 'alr pri[ALS.PR[ALS.PROJECT] Loading project: test.gpr
[ALS.PROJECT] Loading project wit[ALS.PROJECT] GPR2 messages after load:
   [ALS.PROJECT] No GPR2 messages
[ALS.PROJECT] Updating project sources
[ALS.PR[ALS.PROJECT] GPR2 messages after updating so   [ALS   [ALS.PROJECT] No GPR2 me[ALS.PR[ALS.PROJECT] Prepend Context Id: file:///Users/simon/Developer/esp32h2_hal/test/te[ALS.PR[ALS.PROJECT] Project status after loading: 
_ALS.PROJECT_ (PROJECT_TYPE => ALIRE_PROJECT,
_ALS.PROJECT_  STATUS => VALID_PROJECT,
_ALS.PROJECT_  PROJECT_FILE => {GNATCOLL.VFS.VIRTUAL_FILE� object},
_ALS.PROJECT_  MISSING_ADA_RUNTIME => FALSE,
_ALS.PROJECT_  GPR2_MESSAGES => {GPR2.LOG.OBJECT� ob[ALS.MAIN] Creating fallback context
[ALS.MA[ALS.MAIN] Out Message_Handler Text_Document_Did_Open
[ALS.MAIN] In Message_Handler Text_Document_Did_Open URI:
[ALS.MAIN] f[ALS.MAIN] In Message_Handler Text_Document_Did_Open URI:
[ALS.MAIN] file:///Users/simon/Developer/esp32h2_hal/src/esp32h2_hal-gpio.ads
[ALS.MAIN] Out Message_Handler Text_Document_Did_Open
[ALS.MAIN] In Message_Handler Text_Document_Did_Open URI:
[ALS.MAIN] file:///Users/simon/Developer/esp32h2_hal/src/esp32h2_hal-gpio.adb
[ALS.MAIN] Out Message_Handler Text_Document_Did_Open

Other VS Code Extensions

No response

Additional context

No response

[simonjwright]

This issue does not happen with release 26.0.202411173.

[eliericha]

Hello @simonjwright ,

Thank you for the report.

The default log file name is ada_ls_log.$T.log where $T is replaced with the current date and time. If your editor is spawning multiple ALS instances very close together in time, it's possible that they both end up using the same log file.

A workaround is to edit your ~/.als/ada_ls_traces.cfg file and change the log filename to include the PID via $$ as follows:

>ada_ls_log.$T.$$.log:buffer_size=0:buffer_size=0

Does that yield two log files in your use case?

Also to understand a bit more ada-ts-mode, do you know what triggers it to start multiple servers?

[simonjwright]

I did what you suggested (are you sure about the second :buffer_size=0?) and there were two log files.

I tried another project without the possibly-problematic nested test project arrangement, and after a lot of trouble with vscode remembering far too much about previously-opened projects it opened with only one log file.

I then tried ada-ts-mode. It did open two log files, the first when I opened a file in esp32h2_hal/test/src and the second when I navigated from there to a file in esp32h2_hal/src.

I think the ada-ts-mode problem arises when the 'other' file has to be opened - getting info about e.g. an Ada object in the other file isn’t a problem.

[AnthonyLeonardoGracio]

Hi @simonjwright ,

Note that we now append the PID after the timestamp to the ALS log file names by default, to avoid any potential collision.

Regards,