Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SCons: silence_msvc implementation issues #91883

Closed
jcbrill opened this issue May 12, 2024 · 3 comments · Fixed by #91890
Closed

SCons: silence_msvc implementation issues #91883

jcbrill opened this issue May 12, 2024 · 3 comments · Fixed by #91890

Comments

@jcbrill
Copy link

jcbrill commented May 12, 2024

Tested versions

There are issues with the silence_msvc implementation as a result of changes made in PRs #90626 and #90551.

System information

Windows 11, Godot master, SCons 4.7.0

Issue description

There are issues with the silence_msvc implementation as a result of changes made in PRs #90626 and #90551.

A similar PR was recently opened on the SCons project that linked to the one of the merged PRs above. A detailed explanation that goes beyond the content presented below has not been posted on SCons yet.

Environment: Windows 11, Godot master (2024/05/10), SCons 4.7.0.

Executive Summary

As currently implemented:

  1. The first line of an msvc linker warning, error, and diagnostic message may be erroneously deleted.

    This is due to a combination of the inherent assumptions made in the Godot implementation, the differences in output stream behavior between the msvc compiler and msvc linker, and the differences in timing when the filtered records are produced.

  2. The binary read of the temporary stdout file followed by a decoded write to the stderr stream will likely contain extra newline characters for each line.

    The binary read of the temporary stdout file contains CRLF (i.e., \r\n) line endings. The CRLF sequence remains after decoding. This effectively causes an extra new line for each line of content written.

  3. There may be unnecessary unicode replacement characters introduced in the written stderr content due to the implemented encoding.

    The encoding selected is that of python's stdout stream. However, the temporary stdout file is populated by the output of the msvc compiler and linker commands. SCons uses encoding "oem" in some cases when processing msvc command output.

Suggested Changes

At a bare minimum, the following changes are suggested for the current Godot implementation:

  1. Delete the first record only for the msvc compiler. The risks with erroneously deleting the wrong msvc linker record far outweigh the benefit of suppressing a couple lines of output.
  2. Replace the CRLF sequence with a LF in the decoded stream.
  3. Change the encoding from sys.stdout.encoding to "oem".

Suggested changes to godot/platform/windows/detect.py master:

    if env["silence_msvc"]:
        from tempfile import mkstemp

        old_spawn = env["SPAWN"]

        def spawn_capture(sh, escape, cmd, args, env):
            # We only care about cl/link, process everything else as normal.
            if args[0] not in ["cl", "link"]:
                return old_spawn(sh, escape, cmd, args, env)

            tmp_stdout, tmp_stdout_name = mkstemp()
            os.close(tmp_stdout)
            args.append(f">{tmp_stdout_name}")
            ret = old_spawn(sh, escape, cmd, args, env)

            try:
                with open(tmp_stdout_name, "rb") as tmp_stdout:
                    # First line is always bloat, subsequent lines are always errors. If content
                    # exists after discarding the first line, safely decode & send to stderr.
-                   tmp_stdout.readline()
+                   if args[0] in ["cl"]:
+                       tmp_stdout.readline()
                    content = tmp_stdout.read()
                    if content:
-                       sys.stderr.write(content.decode(sys.stdout.encoding, "replace"))
+                       sys.stderr.write(content.decode("oem", "replace").replace("\r\n", "\n"))
                os.remove(tmp_stdout_name)
            except OSError:
                pass

            return ret

        env["SPAWN"] = spawn_capture

Additional concerns such as potentially causing a user stream redirection argument to be ignored are beyond the scope of this post.

MSVC Compiler and Linker Default Output Streams

Default Output Stream Category cl.exe link.exe
Executable banner messages Diagnostic $\color{red}\textit{stderr}$ $\color{red}\textit{stdout}$
Command-line warning messages Warning $\color{red}\textit{stderr}$ $\color{red}\textit{stdout}$
Command-line error messages Error $\color{red}\textit{stderr}$1 $\color{red}\textit{stdout}$
Diagnostic messages Diagnostic stdout stdout
Warning messages Warning stdout stdout
Error messages Error stdout stdout
User pragma messages Diagnostic stdout $\color{gray}\textit{n/a}$
User command wrapper2 Diagnostic stderr and/or stdout stderr and/or stdout

Table Notes:

  1. VS 2022 introduced compiler option /options:strict which treats unrecognized compiler options as errors.
  2. Due to the current implementation of using the program name without an extension to invoke the msvc compiler (cl) and msvc linker (link), it is trivial to insert a user command wrapper (i.e., "man-in-the-middle") batch file for the compiler (cl.bat) and linker (link.bat) that calls the compiler executable (cl.exe) and linker executable (link.exe) when manually configuring the Godot MSVC environment (i.e., "VCVARS" method). Such a command wrapper may write to stdout and stderr, unwittingly redirect the command stderr stream to stdout, and otherwise change the expected record sequence.

Implementation Assumptions

First line is always bloat, subsequent lines are always errors. If content
exists after discarding the first line, safely decode & send to stderr.

Most of the immediate concerns have to do with deleting the first line of the msvc linker output.

MSVC compiler:

  • The diagnostic message containing the file name appears to be written after the command-line options are evaluated and before the source files are processed.

  • The compiler command line accepts a list of files. Diagnostic messages containing the source file name are issued for each source file processed. This is useful information outside of SCons when compiling multiple files with a single command. The file name diagnostic message is not as useful with SCons as the compiler command is written to stdout and only a single source file is compiled per command.

  • The first line of stdout content is not always the diagnostic message containing the file name due to command-line option warnings possibly being treated as errors in VS2022 and later (i.e., the file name diagnostic message may not be present).

  • If an external command wrapper were to redirect the compiler command stderr to stdout, then the first line of the banner message, command-line warning, or command-line error would be erroneously deleted.

  • Subsequent lines following the first line are not always errors.

    There are diagnostic options such as /Bt, /showIncludes and source code pragma messages which produce stdout messages that are neither errors or warnings.

  • If the command output ever interleaves writes to stdout and stderr, the resulting output would not be in the correct order (i.e., command stderr written directly, followed by filtered stdout). While largely theoretical, this can be demonstrated with a command wrapper.

MSVC linker:

  • The linker does not always produce a diagnostic message.

    I believe that the "Creating library ..." message is produced as a result of the linker detecting exported symbols.

  • The banner message, command-line warnings, command-line errors, diagnostic messages, warnings, and errors (e.g., multiply defined symbols) may be produced before the expected diagnostic message. In these cases, deleting the first line is erroneous.

  • For linker commands that do not produce the expected diagnostic message, deleting the first line is guaranteed to be erroneous.

  • Subsequent lines following the first line are not always errors.

    There are diagnostic options such as /time and /VERBOSE which produce stdout messages that are neither errors or warnings.

The compiler and linker may produce other diagnostic messages like "Generating Code ..." and "Compiling ..." which could affect the expected record sequence.

Opinions will vary with regard to writing diagnostic messages (e.g., source code pragma messages) to stderr.

In my experience, deleting an output record based solely on record count without verifying the record content is asking for trouble. It does not help that the deleted content is not logged anywhere.

Examples

The output fragments shown below are from a locally modified copy of the Godot source that writes the filtered line to stderr.

  • Binary read CRLF sequences:

    • Extra new lines:

      ccflags="/Bt" linkflags="/time"

      cl ...  /Bt ...
      *** FILTER CL ***: console_wrapper_windows.cpp
      time(C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.39.33519\bin\HostX64\x64\c1xx.dll)=0.433s
      
      time(C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.39.33519\bin\HostX64\x64\c2.dll)=0.064s
      
      
      link ... /time ...
      *** FILTER LINK ***:    Creating library bin\godot.windows.template_release.x86_64.lib and object bin\godot.windows.template_release.x86_64.exp
      LibDef: Total time = 0.000s
      
        OptRef: Total time = 0.187s
      
        OptIcf: Total time = 2.453s
      
      Pass 1: Interval #1, time = 7.063s
      
      Pass 2: Interval #2, time = 2.812s
      
      Final: Total time = 9.875s
      
      

      Erroneous deletion:

      link ... /time ...
      *** FILTER LINK ***:   OptRef: Total time = 0.000s
        OptIcf: Total time = 0.000s
      
      Pass 1: Interval #1, time = 0.563s
      
      Pass 2: Interval #2, time = 0.000s
      
      Final: Total time = 0.563s
      
      
    • With CRLF replaced with LF:

      ccflags="/Bt" linkflags="/time"

      cl ... /Bt ...
      *** FILTER CL ***: console_wrapper_windows.cpp
      time(C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.39.33519\bin\HostX64\x64\c1xx.dll)=0.385s
      time(C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.39.33519\bin\HostX64\x64\c2.dll)=0.025s
      
      link ... /time ...
      *** FILTER LINK ***:    Creating library bin\godot.windows.template_release.x86_64.lib and object bin\godot.windows.template_release.x86_64.exp
      LibDef: Total time = 0.016s
        OptRef: Total time = 0.172s
        OptIcf: Total time = 2.531s
      Pass 1: Interval #1, time = 7.266s
      Pass 2: Interval #2, time = 3.359s
      Final: Total time = 10.625s
      

      Erroneous deletion:

      link ... /time ...
      *** FILTER LINK ***:   OptRef: Total time = 0.000s
        OptIcf: Total time = 0.000s
      Pass 1: Interval #1, time = 0.546s
      Pass 2: Interval #2, time = 0.000s
      Final: Total time = 0.546s
      
  • Encoding (with CRLF replacement) shown for German:

    • Original encoding:

      werror=yes linkflags="/SUBSYSTEM:CONSOLE,1.0"

      Erroneous deletion:

      link ... /SUBSYSTEM:CONSOLE,1.0 ...
      *** FILTER LINK ***: LINK : warning LNK4010: Ung\ufffdltige Versionsnummer 1.0; Standardversion des Subsystems wird angenommen.
      LINK : error LNK1218: Warnung wird als Fehler interpretiert; es wurde keine Ausgabedatei generiert.
      

      Filtered line contains: Ung\ufffdltige.

    • Modified encoding:

      werror=yes linkflags="/SUBSYSTEM:CONSOLE,1.0"

      Erroneous deletion:

      link ... /SUBSYSTEM:CONSOLE,1.0 ...
      *** FILTER LINK ***: LINK : warning LNK4010: Ungültige Versionsnummer 1.0; Standardversion des Subsystems wird angenommen.
      LINK : error LNK1218: Warnung wird als Fehler interpretiert; es wurde keine Ausgabedatei generiert.
      

      Filtered line contains: Ungültige.

  • Additional erroneous deletion examples:

    • werror=yes linkflags="/CmdLineOpt"

      link ... /CmdLineOpt ...
      *** FILTER LINK ***: LINK : warning LNK4044: unrecognized option '/CmdLineOpt'; ignored
      LINK : error LNK1218: warning treated as error; no output file generated
      
    • werror=no linkflags="/CmdLineOpt"

      link ... /CmdLineOpt ...
      *** FILTER LINK ***: LINK : warning LNK4044: unrecognized option '/CmdLineOpt'; ignored
         Creating library bin\godot.windows.template_release.x86_64.lib and object bin\godot.windows.template_release.x86_64.exp
      
      link ... /CmdLineOpt
      *** FILTER LINK ***: LINK : warning LNK4044: unrecognized option '/CmdLineOpt'; ignored
      Building compilation database compile_commands.json
      
    • linkflags="/VERBOSE:LIB"

      link ... /VERBOSE:LIB ...
      *** FILTER LINK ***: 
      Searching libraries
          Searching C:\Program Files (x86)\Windows Kits\10\Lib\10.0.22621.0\um\x64\winmm.lib:
          ...
          Searching C:\Program Files (x86)\Windows Kits\10\Lib\10.0.22621.0\um\x64\uuid.lib:
      
      Finished searching libraries
         Creating library bin\godot.windows.template_release.x86_64.lib and object bin\godot.windows.template_release.x86_64.exp
      ...   
      

Postscript

I believe there is an issue with the current Godot implementation of msvc auto-detection (i.e., setup_msvc_auto).

By forcing SCons to re-initialize the environment and then reloading the msvc compiler tool, some Godot SConstruct command-line options for the msvc compiler that were configured earlier will be lost due to being overwritten by SCons when re-initialized. At a minimum, this likely affects ccflags, CCFLAGS, and the system path. There may be other consequences.

Steps to reproduce

See the Examples section above for command-line options that produce anomalous behavior.

The following should produce a linker warning that is suppressed/deleted by silence_msvc implementation.

scons platform=windows target=template_release tests=false module_text_server_fb_enabled=yes d3d12=no debug_symbols=no verbose=yes warnings=extra werror=yes linkflags="/CmdLineOpt"

Note: configuring the msvc environment manually (i.e., from the command-line and relying on Godot's VCVARS version) is necessary as the msvc auto-detection seems to ignore the ccflags and linkflags command-line options. See the Postscript above for more details.

Minimal reproduction project (MRP)

N/A

Edit:

  • Fixed typographical error: VSVARS to VCVARS
@akien-mga akien-mga changed the title silence_msvc implementation issues SCons: silence_msvc implementation issues May 12, 2024
@akien-mga
Copy link
Member

CC @Repiteo

@Repiteo
Copy link
Contributor

Repiteo commented May 12, 2024

The hoops we gotta jump through because Microsoft really, really, really wants people to know what file they were asked to work on.

This is an impressively thorough breakdown! Been racking my brain to see what the best approach can be to account for all these cases that wouldn't end up bogging down the logic, but some degree of clutter is probably unavoidable.

@jcbrill
Copy link
Author

jcbrill commented May 13, 2024

That is very kind.

If you are interested, I can make available the simple c source files, sconstruct file, and some of the batch files that I used for testing the various msvc compiler and linker output options. It may take a couple days to get everything together so that it is useful to someone else though. You would have to tweak the files as they are tailored to my testing folder layout and executable locations.

An alternative SCons implementation was developed locally and used as a basis for comparison to the SCons PR and the SCons main branch.

The relevant code in the local alternative is shown here:
https://github.com/jcbrill/scons/blob/jbrill-msvc-4513/SCons/Platform/win32.py#L209-L623

The branch is:
https://github.com/jcbrill/scons/tree/jbrill-msvc-4513

Logically, the alternative implementation rewrites the combined output streams (i.e., stdout and stderr) and optionally includes a destructive filter:

---
    config:
        flowchart:
            curve: linear
---
     flowchart LR
       
       classDef combined height:60px,width:60px,text-align:center
       classDef stream height:40px,width:60px,text-align:center
       classDef filter height:130px,width:120px,text-align:center
    
       IOUT["stdout\nstderr"]:::combined
       
       subgraph jbrill-msvc-4513["jbrill-msvc-4513"]
       FANY[stream rewrite\nand\noptional\ndestructive\nfilter]:::filter
       end
    
       IOUT ---> FANY
    
       STDOUT[stdout]:::stream
       DELETE[delete]:::stream
       STDERR[stderr]:::stream
       
       FANY ---> STDOUT
       FANY .- DELETE
       FANY ---> STDERR
    
       linkStyle 2 stroke-width:2px,fill:none,stroke:red;
Loading

I sincerely doubt that it is bug free. However, it is another way of looking at the problem. Perhaps there is a useful idea or two.

And yes, to "do it right" will take a fair bit of work. Due to the nature of the problem, it is going to be very difficult to get right all the time for all cases.

By default, only errors and warnings are written to stderr and all other records are written to stdout. When running scons, if stdout is redirected to one file and stderr is redirected to a different file, the stderr file would be empty if there were no errors or warnings.

The filter jumps through a few hoops to try and make sure the expected record is deleted. However, it is not infallible. Only known records will be filtered.

Configuration is done via a hierarchy of environment variables. Not desirable for production but extremely quick for testing various alternatives.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants