Output window always one instruction behind when using ninja

[jmigual]

Brief Issue Summary

Issue: vscode-cmake-tools waits until it sees a carriage return or a new line to print a line of the build output

Explanation:

If I'm using the ninja generator and I build my project this is the output I see (added line numbers because it's important later):

 1: [proc] Executing command: /home/<user>/.local/bin/cmake --build /home/<user>/<project_dir>/build/Udefault --config Debug --target all
 2: [build] [0/2] Re-checking globbed directories...
 3: [build] [1/8] Creating test case directories
 4: [build] [2/8] Running utility command for fms-test_files
 5: [build] [3/8] Generating version file
 6: [build] [4/7] Building CXX object src/CMakeFiles/common.dir/Debug/FORPFSSPSD/xmlParser.cpp.o
 7: [build] [5/7] Linking CXX static library lib/Debug/libcommon.a
 8: [build] [6/7] Linking CXX executable bin/Debug/app
 9: [build] [7/7] Linking CXX executable bin/Debug/fms-test
10: [driver] Build completed: 00:00:15.990
11: [build] Build finished with exit code 0

And during the build I may see something like this:

 1: [proc] Executing command: /home/<user>/.local/bin/cmake --build /home/<user>/<project_dir>/build/Udefault --config Debug --target all
 2: [build] [0/2] Re-checking globbed directories...
 3: [build] [1/8] Creating test case directories
 4: [build] [2/8] Running utility command for fms-test_files
 5: [build] [3/8] Generating version file
 6: [build] [4/7] Building CXX object src/CMakeFiles/common.dir/Debug/FORPFSSPSD/xmlParser.cpp.o

So, based on the output we would assume that the xmlParser.cpp.o is being built. NOPE! Upon inspecting the task manager I see that the libcommon.a file is being linked but the output only displays line 6 instead of 7.

I believe that the reason for this behavior is that Ninja tries to print all of these statements in a single line by erasing it / moving the cursor and vscode-cmake-tools only displays the line when a new line or a carriage return is printed. Thus what's happening is:

1. Ninja executes line 6 and prints line 6.
2. Execution of line 6 finishes
3. Ninja prints a carriage return
4. vscode-cmake-tools sees the carriage return and prints line 6 to the user
5. Ninja starts executing line 7 and prints line 7 but this is not seen by the user until it finishes and ninja prints a carriage return.

Given that [build] is appended in front of each build line I'm not sure what would be the appropriate solution. Maybe, just wait for a string and print it immediately and, only after the build tool prints a new line or carriage return, then add the [build] ?

CMake Tools Diagnostics

{
  "os": "linux",
  "vscodeVersion": "1.79.1",
  "cmtVersion": "1.14.33",
  "configurations": [
    {
      "folder": "/home/<user>/<project_dir>",
      "cmakeVersion": "3.26.0",
      "configured": true,
      "generator": "Ninja Multi-Config",
      "usesPresets": true,
      "compilers": {
        "C": "gcc-12",
        "CXX": "g++-12"
      }
    }
  ],
  "cpptoolsIntegration": {
    "isReady": false,
    "hasCodeModel": false,
    "activeBuildType": "",
    "buildTypesSeen": [],
    "requests": [],
    "responses": [],
    "partialMatches": [],
    "targetCount": 0,
    "executablesCount": 0,
    "librariesCount": 0,
    "targets": []
  },
  "settings": [
    {
      "communicationMode": "automatic",
      "useCMakePresets": "auto",
      "configureOnOpen": true
    }
  ]
}

Debug Log

No response

Additional Information

No response

[benmcmorran]

Thanks for the detailed feedback. I haven't checked the code closely, but I suspect this could be fixed simply by immediately flushing output from Ninja to the output window instead of waiting for newline characters. We probably won't be able to get to this in the 1.15 timeframe, but I'm marking it for 1.16. We'd also be happy to accept a PR if someone else fixes it first.

[pdicerbo]

Hi! I'm experimenting the same problem. Is there any update on this?

[gcampbell-msft]

@pdicerbo Thank you for following up. We don't currently have any updates, but we have it in the On Deck milestone, which is where we try to grab items for our next release from, thank you for your patience.

[pdicerbo]

Thank you very much for the answer, I'll wait :)

[v-frankwang]

@pdicerbo Thank you for contributing to the development of the community! If you have any other questions, don't hesitate to let us know. We'll be happy to help you. 🙂

[gcampbell-msft]

@jmigual I'm currently debugging this, and from what I can tell, I don't think there is much that we can do about this. When debugging, I find that we are simply reacting to the output proc.ts line 223, child?.stdout?.on('data', and when I tested a simple project, when hitting a breakpoint at line 226 I see that 2 of the lines of output are given, multiple lines of output.

Do you find that this happens on the command-line as well?

[gcampbell-msft]

Here is a screenshot from my debugging, when building the CMake open source project from Kitware:

[jmigual]

Wouldn't the issue be related to the condition of lines.length > 1 ? So, basically, it is never printing the last line which is the current one. I see however that the output function immediately prints a new line. So, handling the partially sent line (7/1152 is still missing the substring c.obj) would require not adding a new line and the [build] text yet.

I agree that it's difficult and there's not much that can be done. :/ Maybe I will take it one day for fun, you pointed me to the right part of the code to look at :)

[jmigual]

I've been digging in how ninja detects whether to print as a terminal or as a "file". (link). Basically, if we could make ninja detect that the subprocess is not a terminal it would print all lines terminated with a \n and the above mentioned code would work fine. This is probably the easiest and nicest fix.

[pdicerbo]

basically we have to try to persuade the ninja developers?

[jmigual]

Well, if they could add a flag that would be ideal. However, on the meanwhile, if we make sure to not emulate a terminal when executing the ninja commands this would also work. It seems that we have the option to run programs as a shell or not:

https://github.com/microsoft/vscode-cmake-tools/blob/7b621f45ca9ab4df486f9ea3bcc5439034cea7a9/src/proc.ts#L96-L106

Maybe setting shell to false would be enough. I'll try it this evening and see.

[jmigual]

Okay, so I played a bit with it and we are doing the right thing of setting shell==false when calling the cmake --build ... command. However, it seems that CMake calls ninja in an interactive way and there's nothing we can do about this. I suggest closing this issue as it cannot be solved for now.

[gcampbell-msft]

@jmigual @pdicerbo Thanks for the discussion and your all's effort to help investigate! I'll close this issue for now, but if you create any type of issue on ninja to track this, we could possibly track it here as well. Closing this issue.

[pdicerbo]

Thank you for all the effort. Sincerely speaking I'm quite sad, probably I'll come back to use make instead of ninja.. Actually I didn't understood the issue about the way CMake calls ninja, I could try to study in deep and maybe open an issue to CMake developers..

[jmigual]

Thank you for all the effort. Sincerely speaking I'm quite sad, probably I'll come back to use make instead of ninja.. Actually I didn't understood the issue about the way CMake calls ninja, I could try to study in deep and maybe open an issue to CMake developers..

So, ninja prints \r instead of \n when it thinks it's in a terminal-like environment. We don't call ninja, we call cmake --build and CMake calls ninja. When we do the build call in these lines:

https://github.com/microsoft/vscode-cmake-tools/blob/a63562f0a877c571c90ba2531fe3fc0329572f8d/src/drivers/cmakeDriver.ts#L1981-L1982

We are implicitly setting shell = false, thus we call CMake as a non-terminal option. However, it seems that CMake internally calls Ninja as a terminal because Ninja still prints \r.

This is assuming that setting shell = false is enough for Ninja to think that it's in a non-terminal environment.

[pdicerbo]

Thank you very much, now is much more clear! I'll try to do some research and eventually open an issue. If something happens, I'll keep you up to date :)