SCons / scons

SCons - a software construction tool
http://scons.org
MIT License
2.11k stars 318 forks source link

Setting SCONS_MSCOMMON_DEBUG to a full path throws exception #4605

Closed bdbaddog closed 1 month ago

bdbaddog commented 1 month ago

Describe the bug

set SCONS_MSCOMMON_DEBUG="C:\builds\scons\debug.txt"

And you'll get an exception like this. Apparently the logic is trying to add the debug file to the path of the current SConscript.

OSError: [Errno 22] Invalid argument: 'C:\\builds\\scons\\LAPTOP\\xyz\\src\\"C:\\builds\\scons\\debug.txt"':
  File "C:\builds\test-scons\SConstruct", line 13:
    SConscript('LAPTOP/xyz/src/SConscript')
  File "C:\Python311\Lib\site-packages\SCons\Script\SConscript.py", line 684:
    return method(*args, **kw)
  File "C:\Python311\Lib\site-packages\SCons\Script\SConscript.py", line 620:
    return _SConscript(self.fs, *files, **subst_kw)
  File "C:\Python311\Lib\site-packages\SCons\Script\SConscript.py", line 280:
    exec(compile(scriptdata, scriptname, 'exec'), call_stack[-1].globals)
  File "C:\builds\test-scons\LAPTOP\connectdll\src\SConscript", line 3:
    env = laptop_env(base_env=global_env, project="connectdll")
  File "C:\builds\test-scons\site_scons\laptop.py", line 128:
    setup_msvc6(env, toolchest)
  File "C:\builds\test-scons\site_scons\laptop.py", line 64:
    env.Tool("msvc")
  File "C:\Python311\Lib\site-packages\SCons\Environment.py", line 2044:
    tool = SCons.Tool.Tool(tool, toolpath, **kwargs)
  File "C:\Python311\Lib\site-packages\SCons\Tool\__init__.py", line 118:
    module = self._tool_module()
  File "C:\Python311\Lib\site-packages\SCons\Tool\__init__.py", line 201:
    spec.loader.exec_module(module)
  File "<frozen importlib._bootstrap_external>", line 940:

  File "<frozen importlib._bootstrap>", line 241:

  File "C:\Python311\Lib\site-packages\SCons\Tool\msvc.py", line 42:
    import SCons.Tool.msvs
  File "C:\Python311\Lib\site-packages\SCons\Tool\msvs.py", line 48:
    from SCons.Tool.MSCommon import (
  File "C:\Python311\Lib\site-packages\SCons\Tool\MSCommon\__init__.py", line 33:
    from SCons.Tool.MSCommon.sdk import (  # noqa: F401
  File "C:\Python311\Lib\site-packages\SCons\Tool\MSCommon\sdk.py", line 35:
    from .common import debug, read_reg
  File "C:\Python311\Lib\site-packages\SCons\Tool\MSCommon\common.py", line 132:
    log_handler = logging.FileHandler(filename=LOGFILE)
  File "C:\Python311\Lib\logging\__init__.py", line 1181:
    StreamHandler.__init__(self, self._open())
  File "C:\Python311\Lib\logging\__init__.py", line 1213:
    return open_func(self.baseFilename, self.mode,

Required information

jcbrill commented 1 month ago

I'm struggling to reproduce. Will keep trying...

However, the quotes around the filename argument will eventually cause a problem as they are never removed (i.e., not processed like a command-line argument):

EDITED: the second case still had quotes in the assignment (the console test did not).

jcbrill commented 1 month ago

The double-quoted argument is the problem.

The standard python library logging code is:

        # Issue #27493: add support for Path objects to be passed in
        filename = os.fspath(filename)
        #keep the absolute path, otherwise derived classes which use this
        #may come a cropper when the current directory changes
        self.baseFilename = os.path.abspath(filename)

Calling absolute path with a filename in quotes goes awry:

(_env-311-64-lint) S:\SCons\test-mscommon-debug-filename>python
Python 3.11.3 (tags/v3.11.3:f3909b8, Apr  4 2023, 23:49:59) [MSC v.1934 64 bit (AMD64)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> os.path.abspath(os.fspath(r'C:\builds\scons\debug.txt'))
'C:\\builds\\scons\\debug.txt'
>>> os.path.abspath(os.fspath(r'"C:\builds\scons\debug.txt"'))
'S:\\SCons\\test-mscommon-debug-filename\\"C:\\builds\\scons\\debug.txt"'
>>>
bdbaddog commented 1 month ago

If your path has spaces in it, wouldn't you need the quotes when specifying? If so can we strip the quotes?

jcbrill commented 1 month ago

The quotes go around the variable and assignment (from the third bullet above):

> set "SCONS_MSCOMMON_DEBUG=C:\build with spaces\scons\debug.txt"
> @echo %SCONS_MSCOMMON_DEBUG%
C:\build with spaces\scons\debug.txt
bdbaddog commented 1 month ago

Let's put it another way.. if some user does what I did, getting a stack trace is pretty unfriendly way of handling that error.. ;) Seems trivial to remove those starting/ending quotes if they are extraneous and issue a warning?

jcbrill commented 1 month ago

Sure.

AFAIK, SCONS_MSCOMMON_DEBUG is not documented and was not intended for public use so there is not much in the way of sanity checking.

# SCONS_MSCOMMON_DEBUG is internal-use so undocumented:
# set to '-' to print to console, else set to filename to log to
LOGFILE = os.environ.get('SCONS_MSCOMMON_DEBUG')

I didn't write it: don't shoot the messenger :)

An issue (soon to be opened coincidentally) is for SCONSFLAGS usage for the opposite reason: a quoted argument with spaces should be expected but is not handled correctly:

    sconsflags = os.environ.get('SCONSFLAGS', '')
    all_args = sconsflags.split() + sys.argv[1:]
    ...

A user-defined option expecting a windows path with spaces (--windows-path="C:\Program Files (x86)"):

Simply splitting SCONSFLAGS on spaces yields multiple partial arguments. Using shlex.split(sconsflags) might be better. However, custom processing for windows would be best as shlex.split is for posix and not necessarily for windows.

mwichmann commented 1 month ago

The quoting story continues to be a mess... I just spent a while down that rathole, when I discovered the "quoting rules" in the test framework are different, that is, if you do test.run(args=some_sequence) whatever some_sequence is may not be what the invoked SCons instance sees. Or to put it another way what you would type on an SCons command line is not necessarily the same as you put in the argument list for a test. I naively tried to "fix" that, but the multiple layers of the framework are so intertwined, and there's so much expectation of the current behavior that I actually made things worse. It's clear others have been there before. So... just something to beware of.

mwichmann commented 1 month ago

And... the code comment about intentionally undocumented (that is, in external docs) is mine, a reminder for times such as this. The concept is not mine :-)

jcbrill commented 1 month ago

The comments regarding quoting the variable assignment above may be misleading.

The quotes need to go around the variable assignment when quotes are needed. However, in many instances, quotes are not needed even when the path contains spaces.

  1. Valid - path with spaces: quotes are not required

    
    > set SCONS_MSCOMMON_DEBUG=C:\build with spaces\scons\debug.txt
    > @echo %SCONS_MSCOMMON_DEBUG%
    C:\build with spaces\scons\debug.txt
  2. Valid - path with spaces: quotes around the variable assignment

    > set "SCONS_MSCOMMON_DEBUG=C:\build with spaces\scons\debug.txt"
    > @echo %SCONS_MSCOMMON_DEBUG%
    C:\build with spaces\scons\debug.txt
  3. Invalid - path with spaces: quotes around the value (quotes preserved)

    > set SCONS_MSCOMMON_DEBUG="C:\builds\scons\debug.txt"
    > @echo %SCONS_MSCOMMON_DEBUG%
    "C:\builds\scons\debug.txt"

For discussion purposes, a candidate solution is offered.

Changes:

Known issues:

Branch https://github.com/jcbrill/scons/tree/jbrill-mscommon-debug:

Limited tests https://github.com/jcbrill/scons-prototypes/tree/main/scons/scons-issue-4605:

Examples:

  1. Invalid path with quotes around the value (i.e., this issue):

    SCONS_MSCOMMON_DEBUG="S:\SCons\test-mscommon-debug-filename\Folder With Spaces\debug3.txt"
    scons: Reading SConscript files ...
    
    scons: warning: SCONS_MSCOMMON_DEBUG file name is invalid:
     filename: '"S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\debug3.txt"'
     modified: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\debug3.txt'
       action: leading and trailing double quotes removed
    File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
    scons: done reading SConscript files.
    scons: Building targets ...
    scons: `.' is up to date.
    scons: done building targets.
  2. Using an illegal character:

    SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder With Spaces\qmarkbeg?qmarkend.txt
    scons: Reading SConscript files ...
    
    scons: warning: SCONS_MSCOMMON_DEBUG file name is invalid:
     filename: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\qmarkbeg?qmarkend.txt'
      abspath: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\qmarkbeg?qmarkend.txt'
       reason: file name contains illegal characters ('?')
    File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
    OSError: [Errno 22] Invalid argument: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\qmarkbeg?qmarkend.txt':
     File "S:\SCons\test-mscommon-debug-filename\SConstruct", line 1:
       env = Environment()
    ...
     File "S:\SCons\jbrill-mscommon-debug\scripts\..\SCons\Tool\MSCommon\common.py", line 304:
       raise e.with_traceback(None)
  3. Using a reserved name:

    SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder With Spaces\aux.txt
    scons: Reading SConscript files ...
    
    scons: warning: SCONS_MSCOMMON_DEBUG file name is invalid:
     filename: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\aux.txt'
      abspath: '\\\\.\\aux'
       reason: file name contains a reserved name ('aux')
    File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
    FileNotFoundError: [Errno 2] No such file or directory: '\\\\.\\aux':
     File "S:\SCons\test-mscommon-debug-filename\SConstruct", line 1:
       env = Environment()
    ...
     File "S:\SCons\jbrill-mscommon-debug\scripts\..\SCons\Tool\MSCommon\common.py", line 304:
       raise e.with_traceback(None)

Enjoy

bdbaddog commented 1 month ago

@jcbrill - probably worth promoting such issue to be an error. No one wants to set it wrong, run a non-trivial build and then find out the log wasn't created? (under the fail fast if you're going to fail category).. @mwichmann - seem reasonable?

jcbrill commented 1 month ago

probably worth promoting such issue to be an error. No one wants to set it wrong, run a non-trivial build and then find out the log wasn't created? (under the fail fast if you're going to fail category)..

I'm not clear which issue is worth promoting to an error.

The biggest fear is that there are false positives in the invalid path/file detection. That is, a file name path is declared to be invalid but the logging file handler does not raise an exception upon creation.

Originally, the code only issued an invalid file name warning after an exception was raised (i.e., the exception was caught, a warning issued if necessary, and the exception was re-raised). I was surprised by the behavior with the colon in the file name and learned a bit about ntfs alternate data streams. The sequence changed to: issue a warning if necessary, create the file handler which might fail.

It might take a bit of work to isolate individual causes and treat them as errors instead of warnings.

There are a whole class of errors where there will be no warning and the logging file handler will fail resulting in only a traceback. The most prominent of these is due to lack of permissions (i.e., the file name path is valid, but attempts to write to a location for which the process does not have sufficient permissions).

mwichmann commented 1 month ago

I'm getting a headache, which is not unusual when Windows is involved. The problem comes from the way an environment variable is set in the cmd.exe shell before scons is invoked, right? For the rare case where we do import an environment variable. For an undocumented "known" env var intended for sophisticated SCons developers. So maybe this is just something for "developer docs" and nothing more?

bdbaddog commented 1 month ago

@jcbrill - any time the specified SCONS_MSCOMMON_DEBUG is invalid for any reason, it's not going to log, so best to error?

jcbrill commented 1 month ago

The problem comes from the way an environment variable is set in the cmd.exe shell before scons is invoked, right?

That is my understanding as well.

For the rare case where we do import an environment variable. For an undocumented "known" env var intended for sophisticated SCons developers. So maybe this is just something for "developer docs" and nothing more?

Yes.

Occasionally, end users are asked to define SCONS_MSCOMMON_DEBUG and post the log. Anecdotally, it seems more typical to set it to a file name like set SCONS_MSCOMMON_DEBUG=debug.txt.

any time the specified SCONS_MSCOMMON_DEBUG is invalid for any reason, it's not going to log, so best to error?

If the SCONS_MSCOMMON_DEBUG specification is truly invalid, an exception will be raised by the standard python logging module when the file handler is created due to the file open invocation failing. The exception is not suppressed. As noted in the top post, this may not be particularly illuminating.

From the top post:

OSError: [Errno 22] Invalid argument: 'C:\\builds\\scons\\LAPTOP\\xyz\\src\\"C:\\builds\\scons\\debug.txt"':
  File "C:\builds\test-scons\SConstruct", line 13:

The error message is somewhat confusing, but the double quotes are a clue.

The standard library is simply calling os.path.abspath on the file name passed as an argument. Since the passed string began with a double quote character, an attempt was made to append it to the current directory.

The intent of the warning in the demonstration is to give more diagnostic information on the way out. Hopefully providing just enough information to know why it failed.

So instead of just a traceback like this:

OSError: [Errno 22] Invalid argument: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\qmarkbeg?qmarkend.txt':
...

One would get a warning message first, like this:

scons: warning: SCONS_MSCOMMON_DEBUG file name is invalid:
  filename: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\qmarkbeg?qmarkend.txt'
   abspath: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\qmarkbeg?qmarkend.txt'
    reason: file name contains illegal characters ('?')
File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
OSError: [Errno 22] Invalid argument: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\qmarkbeg?qmarkend.txt':
...

Demonstration code alternatives:

A file specification enclosed in double quotes will yield a warning that the quotes were stripped. This does not guarantee success, just that the leading and trailing quotes were removed. It is entirely possible another warning and logging exception will occur when the log file handler is created.

I'm also onboard with doing nothing.

False Positive - Alternate Data Streams

The case that was new to me, involves alternate data streams. This was the motivation for moving the warning out of the exception handler and before the log file creation call. This was before I understood what exactly was happening with the alternate data streams.

Since this actually behaves in a manner that is consistent with the file specification, it may be worth changing back to just producing invalid file name warnings inside the exception handler on the way out (i.e., the original method).

Example:

SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder With Spaces\colonbeg:colonend.txt
scons: Reading SConscript files ...

scons: warning: SCONS_MSCOMMON_DEBUG file name is invalid:
  filename: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\colonbeg:colonend.txt'
   abspath: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\colonbeg:colonend.txt'
    reason: file name contains illegal characters (':')
File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
scons: done reading SConscript files.
scons: Building targets ...
scons: `.' is up to date.
scons: done building targets.

A warning is produced, but the file open succeeds (false positive).

The only file that appears in File Explorer and a dir command is:

 Directory of S:\SCons\test-mscommon-debug-filename\Folder With Spaces

09/26/2024  10:34 PM    <DIR>          .
09/26/2024  10:34 PM    <DIR>          ..
09/26/2024  07:03 PM                 0 colonbeg
               1 File(s)              0 bytes

However, dir /R reveals:

 Directory of S:\SCons\test-mscommon-debug-filename\Folder With Spaces

09/26/2024  10:34 PM    <DIR>          .
09/26/2024  10:34 PM    <DIR>          ..
09/26/2024  07:03 PM                 0 colonbeg
                                52,546 colonbeg:colonend.txt:$DATA
               1 File(s)              0 bytes

The log file was actually written to the alternate data stream. When file colonbeg is deleted, the alternate data stream is deleted as well. I'm not exactly sure how to read the alternate data stream, but the following command seems to work to redirect the contents to a different file:

more < colonbeg:colonend.txt:$DATA > debug.txt

dir /r:

 Directory of S:\SCons\test-mscommon-debug-filename\Folder With Spaces

09/26/2024  10:40 PM    <DIR>          .
09/26/2024  10:40 PM    <DIR>          ..
09/26/2024  07:03 PM                 0 colonbeg
                                52,546 colonbeg:colonend.txt:$DATA
09/26/2024  10:40 PM            52,546 debug.txt
               2 File(s)         52,546 bytes

The warning really is a false positive. But unless you are aware of the alternate data stream behavior, it looks like an empty partially named output file was created.

There does not seem to be any compelling reason why you would intentionally want this behavior. Other than the drive specification, I'm not sure a typo using a colon would be very frequent.

jcbrill commented 1 month ago

Below are the simplest possible standalone code examples to illustrate the concepts raised in the discussion above.

In all source code examples below, and in current SCons, when SCONS_MSCOMMON_DEBUG is set to a value that eventually causes a python open to fail in the standard library logging module, an exception is raised and causes the script to exit.

The outstanding question is if, and when, a warning message issued prior to the exception message and traceback might be useful to an end user.

The branch referenced above is similar to method 2 [Item 4 below].

However, I am now strongly leaning towards method 1 [Item 3 below].

I'm also OK with chalking this and similar future issues up to invalid input and doing nothing.

A. Mininal Standalone Source Code Examples

All source code examples are module-level code executed when the module is loaded mirroring the current SCons behavior.

Annotated source code examples:

  1. scons-4605-minimal.py

    Current SCons behavior.

    import os
    
    LOGFILE = os.environ.get('SCONS_MSCOMMON_DEBUG')
    if LOGFILE:
       import logging
    
       if LOGFILE == '-':
           log_handler = logging.StreamHandler(sys.stdout)
       else:
           log_handler = logging.FileHandler(filename=LOGFILE)  # <== exception may be raised
  2. scons-4605-minimal-dq.py

    Strip enclosing double quotes and issue a warning.

    import os
    from windows_logging_filename import get_filename_environ
    
    LOGFILE = get_filename_environ('SCONS_MSCOMMON_DEBUG')  # <== strip quotes and issue warning if necessary
    if LOGFILE:
       import logging
    
       if LOGFILE == '-':
           log_handler = logging.StreamHandler(sys.stdout)
       else:
           log_handler = logging.FileHandler(filename=LOGFILE)  # <== exception may be raised
  3. scons-4605-minimal-dq-method1.py

    Strip enclosing double quotes and issue a warning. \ If creating the log handler fails, possibly issue a warning and re-raise the exception (i.e., issue a warning on-the-way-out).

    import os
    from windows_logging_filename import get_filename_environ, check_filename_invalid
    
    LOGFILE = get_filename_environ('SCONS_MSCOMMON_DEBUG')  # <== strip quotes and issue warning if necessary
    if LOGFILE:
       import logging
    
       if LOGFILE == '-':
           log_handler = logging.StreamHandler(sys.stdout)
       else:
           try:
               log_handler = logging.FileHandler(filename=LOGFILE)  # <== exception may be raised
           except:
               check_filename_invalid(LOGFILE, description="SCONS_MSCOMMON_DEBUG")  # <== issue warning if necessary
               raise  # <== re-raise exception
  4. scons-4605-minimal-dq-method2.py

    Strip enclosing double quotes and issue a warning. \ Possibly issue a warning.

    Issuing the warning and a logging module exception are independent which could result in false-positive warning messages (i.e., a warning is issued but the logging module file open succeeds).

    import os
    from windows_logging_filename import get_filename_environ, check_filename_invalid
    
    LOGFILE = get_filename_environ('SCONS_MSCOMMON_DEBUG')  # <== strip quotes and issue warning if necessary
    if LOGFILE:
       import logging
    
       if LOGFILE == '-':
           log_handler = logging.StreamHandler(sys.stdout)
       else:
           check_filename_invalid(LOGFILE, description="SCONS_MSCOMMON_DEBUG") # <== issue warning if necessary
           log_handler = logging.FileHandler(filename=LOGFILE)  # <== exception may be raised

B. Sample Console Sessions

Tests:

  1. scons-4605-minimal.py

    • Pass [valid argument]

      > set SCONS_MSCOMMON_DEBUG=%CD%\debug.txt
      > echo %SCONS_MSCOMMON_DEBUG%
      S:\SCons\test-mscommon-debug-filename\Minimal Example\debug.txt
      > python scons-4605-minimal.py
      > dir /B
      debug.txt
      scons-4605-minimal.py
    • Fail [double quoted, valid argument]

      > set SCONS_MSCOMMON_DEBUG="%CD%\debug.txt"
      > echo %SCONS_MSCOMMON_DEBUG%
      "S:\SCons\test-mscommon-debug-filename\Minimal Example\debug.txt"
      > python scons-4605-minimal.py
      Traceback (most recent call last):
      File "S:\SCons\test-mscommon-debug-filename\Minimal Example\scons-4605-minimal.py", line 12, in <module>
       log_handler = logging.FileHandler(filename=LOGFILE)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "e:\Python\WPy64-31131\python-3.11.3.amd64\Lib\logging\__init__.py", line 1181, in __init__
       StreamHandler.__init__(self, self._open())
                                    ^^^^^^^^^^^^
      File "e:\Python\WPy64-31131\python-3.11.3.amd64\Lib\logging\__init__.py", line 1213, in _open
       return open_func(self.baseFilename, self.mode,
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      OSError: [Errno 22] Invalid argument: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\"S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug.txt"'
  2. scons-4605-minimal-dq.py

    • Warn/Pass [double quoted, valid argument]

      > set SCONS_MSCOMMON_DEBUG="%CD%\debug.txt"
      > echo %SCONS_MSCOMMON_DEBUG%
      "S:\SCons\test-mscommon-debug-filename\Minimal Example\debug.txt"
      > python scons-4605-minimal-dq.py
      S:\SCons\test-mscommon-debug-filename\Minimal Example\windows_logging_filename.py:167: WindowsFileNameWarning: SCONS_MSCOMMON_DEBUG file name is invalid:
      filename: '"S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug.txt"'
      modified: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug.txt'
       action: leading and trailing double quotes removed
      warn(WindowsFileNameWarning, msg)
      > dir /B
      debug.txt
      scons-4605-minimal-dq.py
      windows_logging_filename.py
    • Warn/Fail [double quoted, invalid argument]

      > set SCONS_MSCOMMON_DEBUG="%CD%\debug?.txt"
      > echo %SCONS_MSCOMMON_DEBUG%
      "S:\SCons\test-mscommon-debug-filename\Minimal Example\debug?.txt"
      > python scons-4605-minimal-dq.py
      S:\SCons\test-mscommon-debug-filename\Minimal Example\windows_logging_filename.py:167: WindowsFileNameWarning: SCONS_MSCOMMON_DEBUG file name is invalid:
      filename: '"S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug?.txt"'
      modified: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug?.txt'
       action: leading and trailing double quotes removed
      warn(WindowsFileNameWarning, msg)
      Traceback (most recent call last):
      File "S:\SCons\test-mscommon-debug-filename\Minimal Example\scons-4605-minimal-dq.py", line 13, in <module>
       log_handler = logging.FileHandler(filename=LOGFILE)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "e:\Python\WPy64-31131\python-3.11.3.amd64\Lib\logging\__init__.py", line 1181, in __init__
       StreamHandler.__init__(self, self._open())
                                    ^^^^^^^^^^^^
      File "e:\Python\WPy64-31131\python-3.11.3.amd64\Lib\logging\__init__.py", line 1213, in _open
       return open_func(self.baseFilename, self.mode,
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      OSError: [Errno 22] Invalid argument: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug?.txt'
  3. scons-4605-minimal-dq-method1.py

    • Warn/Warn/Fail [double quoted, invalid argument]

      > set SCONS_MSCOMMON_DEBUG="%CD%\debug?.txt"
      > echo %SCONS_MSCOMMON_DEBUG%
      "S:\SCons\test-mscommon-debug-filename\Minimal Example\debug?.txt"
      > python scons-4605-minimal-dq-method1.py
      S:\SCons\test-mscommon-debug-filename\Minimal Example\windows_logging_filename.py:167: WindowsFileNameWarning: SCONS_MSCOMMON_DEBUG file name is invalid:
      filename: '"S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug?.txt"'
      modified: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug?.txt'
       action: leading and trailing double quotes removed
      warn(WindowsFileNameWarning, msg)
      S:\SCons\test-mscommon-debug-filename\Minimal Example\windows_logging_filename.py:141: WindowsFileNameWarning: SCONS_MSCOMMON_DEBUG file name is invalid:
      filename: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug?.txt'
      abspath: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug?.txt'
       reason: file name contains illegal characters ('?')
      warn(WindowsFileNameWarning, msg)
      Traceback (most recent call last):
      File "S:\SCons\test-mscommon-debug-filename\Minimal Example\scons-4605-minimal-dq-method1.py", line 12, in <module>
       log_handler = logging.FileHandler(filename=LOGFILE)
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "e:\Python\WPy64-31131\python-3.11.3.amd64\Lib\logging\__init__.py", line 1181, in __init__
       StreamHandler.__init__(self, self._open())
                                    ^^^^^^^^^^^^
      File "e:\Python\WPy64-31131\python-3.11.3.amd64\Lib\logging\__init__.py", line 1213, in _open
       return open_func(self.baseFilename, self.mode,
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      OSError: [Errno 22] Invalid argument: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug?.txt'
    • Warn/Pass [double quoted, technically valid argument]

      > set SCONS_MSCOMMON_DEBUG="%CD%\debug:.txt"
      > echo %SCONS_MSCOMMON_DEBUG%
      "S:\SCons\test-mscommon-debug-filename\Minimal Example\debug:.txt"
      > python scons-4605-minimal-dq-method1.py
      S:\SCons\test-mscommon-debug-filename\Minimal Example\windows_logging_filename.py:167: WindowsFileNameWarning: SCONS_MSCOMMON_DEBUG file name is invalid:
      filename: '"S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug:.txt"'
      modified: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug:.txt'
       action: leading and trailing double quotes removed
      warn(WindowsFileNameWarning, msg)
      > dir /B
      debug
      scons-4605-minimal-dq-method1.py
      windows_logging_filename.py
      > dir /R
      ...
      09/27/2024  09:19 AM                 0 debug
                                        0 debug:.txt:$DATA
      09/27/2024  09:10 AM               479 scons-4605-minimal-dq-method1.py
      09/27/2024  08:51 AM             5,836 windows_logging_filename.py
      ...
      > more < debug:.txt:$DATA > debug.txt
      > del debug
      > dir /B
      debug.txt
      scons-4605-minimal-dq-method1.py
      windows_logging_filename.py
      > dir /R
      ...
      09/27/2024  09:25 AM                 0 debug.txt
      09/27/2024  09:10 AM               479 scons-4605-minimal-dq-method1.py
      09/27/2024  08:51 AM             5,836 windows_logging_filename.py
      ...
  4. scons-4605-minimal-dq-method2.py

    • Warn/Warn/Pass [double quoted, technically valid argument, false positive]

      > set SCONS_MSCOMMON_DEBUG="%CD%\debug:.txt"
      > echo %SCONS_MSCOMMON_DEBUG%
      "S:\SCons\test-mscommon-debug-filename\Minimal Example\debug:.txt"
      > python scons-4605-minimal-dq-method2.py
      S:\SCons\test-mscommon-debug-filename\Minimal Example\windows_logging_filename.py:167: WindowsFileNameWarning: SCONS_MSCOMMON_DEBUG file name is invalid:
      filename: '"S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug:.txt"'
      modified: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug:.txt'
       action: leading and trailing double quotes removed
      warn(WindowsFileNameWarning, msg)
      S:\SCons\test-mscommon-debug-filename\Minimal Example\windows_logging_filename.py:141: WindowsFileNameWarning: SCONS_MSCOMMON_DEBUG file name is invalid:
      filename: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug:.txt'
      abspath: 'S:\\SCons\\test-mscommon-debug-filename\\Minimal Example\\debug:.txt'
       reason: file name contains illegal characters (':')
      warn(WindowsFileNameWarning, msg)
      > dir /B
      debug
      scons-4605-minimal-dq-method2.py
      windows_logging_filename.py
      > dir /R
      ...
      09/27/2024  10:34 AM                 0 debug
                                        0 debug:.txt:$DATA
      09/27/2024  09:32 AM               421 scons-4605-minimal-dq-method2.py
      09/27/2024  08:51 AM             5,836 windows_logging_filename.py
      ...
      > more < debug:.txt:$DATA > debug.txt
      > del debug
      > dir /B
      debug.txt
      scons-4605-minimal-dq-method2.py
      windows_logging_filename.py
      > dir /R
      ...
      09/27/2024  10:35 AM                 0 debug.txt
      09/27/2024  09:32 AM               421 scons-4605-minimal-dq-method2.py
      09/27/2024  08:51 AM             5,836 windows_logging_filename.py
      ...
mwichmann commented 1 month ago

SCons.Util has some routines for fetching variables. (I think they're in the wrong submodule, they're in sctypes, which is for type-related stuff, but consider that a different question). In particular, there's get_os_env_bool. Why don't we just add another here, get_os_env_pathname . That is, I'm saying don't put it in a private place - we have other places we might fetch a pathname that's not part of a command-line argument (although only three documented at the moment). I'm assuming for other operations on what are going to be pathname strings, we can use pathlib and don't need to write our own. For example, to check if it's an absolute path - pathlib.Path(string).is_absolute().

mwichmann commented 1 month ago

I'd also say we have the option of catching the logging module's exception and re-raising it as a UserError, which means "we're able to detect that something in your setup is incorrect" and is considered More Useful than a generic Python exception. Whether that's true or not I guess is up for debate.

mwichmann commented 1 month ago

I think there are three exceptions that can occur - as shown above, what's eventually deduced as invalid gets an OSError, and if it's not syntactically invalid but ends up pointing to a path with nonexistent directories you get a FileNotFoundError and if you aren't allowed to create the log file you get PermissionError; both are subclasses of OSError, so catching OSError (not a generic Exception!) seems like what we want.

jcbrill commented 1 month ago

I'd also say we have the option of catching the logging module's exception and re-raising it as a UserError, which means "we're able to detect that something in your setup is incorrect" and is considered More Useful than a generic Python exception. Whether that's true or not I guess is up for debate.

I think there are three exceptions that can occur - as shown above, what's eventually deduced as invalid gets an OSError, and if it's not syntactically invalid but ends up pointing to a path with nonexistent directories you get a FileNotFoundError and if you aren't allowed to create the log file you get PermissionError; both are subclasses of OSError, so catching OSError (not a bare Exception!) seems like what we want.

My current view is if we can't give the user a reason for WHY the logging module couldn't open the file, we shouldn't do anything.

If there is no value added by catching an exception and raising it again (different exception class or not) without any new relevant information, what's the point? In this case, it might be preferable to know exactly where it emanated from in the logging module.

The first line of the issue report above (kudos to @bdbaddog for including the relevant detail) included the actual input value used:

Describe the bug

set SCONS_MSCOMMON_DEBUG="C:\builds\scons\debug.txt"

Upon initial reading, the root cause was hinted at:

However, the quotes around the filename argument will eventually cause a problem as they are never removed (i.e., not processed like a command-line argument)

The issue report exception is:

OSError: [Errno 22] Invalid argument: 'C:\\builds\\scons\\LAPTOP\\xyz\\src\\"C:\\builds\\scons\\debug.txt"':

In this case, the double quote characters are a red flag as would some other characters (e.g., "?", "|", "<", ">", etc).

The logging module is simply using an absolute path (pseudo-code):

filename = os.fspath(filename)
self.baseFilename = os.path.abspath(filename)
StreamHandler.__init__(self, self._open())

Since the user file name is not an absolute or network path, it is treated as relative to the current directory.

The root cause was determined pretty quickly from first read using the bug report and the traceback.

Common reasons for failure are:

In order to tell a user why the open failed, one has to evaluate the absolute path of the input value. As mentioned, the error class can provide clues.

Easy enough to determine after-the-fact:

Harder and probably not worth the effort:

Issuing a warning just prior to the exception may provide enough information for an end user to figure out the problem by themselves.

If this can't be done or deemed not worth the effort, then I'm not sure anything else is particularly useful to an end user (or a developer). The irony being that we can't use the debug log to figure it out.

There may be peculiarities to the windows rules that may not exist on other platforms.

P.S.: I'm not grumpy, I swear. Interest in this particular problem is waning though which is a me problem.

mwichmann commented 1 month ago

P.S.: I'm not grumpy, I swear. Interest in this particular problem is waning though which is a me problem.

Yeah, it's not worth doing much more here. A simple quote stripper for the Windows case might be worthwhile; I can't make the same thing happen on Linux at all. Let's wait to see how @bdbaddog wants to proceed.

My current view is if we can't give the user a reason for WHY the logging module couldn't open the file, we shouldn't do anything.

I think a message like "malformed settings, unable to create logging file" is better than the current long backtrace, but only marginally so.

jcbrill commented 1 month ago

I think a message like "malformed settings, unable to create logging file" is better than the current long backtrace, but only marginally so.

Probably a good idea to propagate the underlying error code (and possibly the class name) from the original logging exception as that is generally really useful information.

Possibly 19 (original) vs 17 (new) stack levels (might be off by 1). It doesn't help that this is module-level code executed when imported/loaded which lengthens the call chain.

mwichmann commented 1 month ago

UserError omits most of the stack so you get only a small number of frames. Like this:

C:\Users\mats\Documents\github\scons\exp\envdump>py ../../scripts/scons.py
scons: Reading SConscript files ...

scons: *** Could not create logfile, check SCONS_MSCOMMON_DEBUG
File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
jcbrill commented 1 month ago

Changes inspired by previous post:

Warning and Error examples:

jcbrill commented 1 month ago

Code fragments for above:

  1. Leading and trailing quotes:

    class MSCommonLogFileWarning(SCons.Warnings.WarningOnByDefault):
       pass
    
    def _check_logfile(logfile):
       if logfile and len(logfile) >= 2:
           if logfile[0] == '"' and logfile[-1] == '"':
               logfile = logfile[1:-1]
               warn_msg = (
                   "SCONS_MSCOMMON_DEBUG value enclosed in double quotes, doubles quotes removed\n"
                   f'  original value="{logfile}"\n'
                   f"  modified value={logfile}"
               )
               SCons.Warnings.warn(MSCommonLogFileWarning, warn_msg)
       return logfile
    
    # SCONS_MSCOMMON_DEBUG is internal-use so undocumented:
    # set to '-' to print to console, else set to filename to log to
    LOGFILE = _check_logfile(os.environ.get('SCONS_MSCOMMON_DEBUG'))
  2. Catch logging exception and raise UserError:

        try:
            log_handler = logging.FileHandler(filename=LOGFILE)
        except (OSError, FileNotFoundError) as e:
            err_msg = (
                f"Could not create logfile, check SCONS_MSCOMMON_DEBUG\n"
                f"  SCONS_MSCOMMON_DEBUG={LOGFILE}\n"
                f"  {e.__class__.__name__}: {str(e)}"
            )
            raise SCons.Errors.UserError(err_msg)
mwichmann commented 1 month ago

Those two are fine by me. Guess the style question is:

Probably this is minor enough it makes little difference in practice which is chosen. @bdbaddog ?

bdbaddog commented 1 month ago

Those two are fine by me. Guess the style question is:

  • [ ] Try to fix silently when retrieving
  • [ ] Check-tryfix-warn
  • [X] Check-exit without fixing or attempting
  • [ ] others?

Probably this is minor enough it makes little difference in practice which is chosen. @bdbaddog ?

@jcbrill option 2, simpler, and can handle other user errors in specifying the log file

jcbrill commented 1 month ago

Just to be clear...

The following two questions take place at different times/locations in the code. The are not mutually exclusive.

Q1: Is there a desire to auto-remove leading and trailing quotes and issue a warning upon reading SCONS_MSCOMMON_DEBUG?

From the initial comments from @bdbaddog, I thought this was desired.

I'm ambivalent about Q1.

Anecdote: Never with files, but I am pretty sure that at least once I have enclosed the stdout file value ("-") in quotes (i.e., SCONS_MSCOMMON_DEBUG="-" instead of SCONS_MSCOMMON_DEBUG=-).

Q2: Is there a desire to rewrite the logging module exception into a UserError exception presenting the SCONS_MSCOMMON_DEBUG value and preserving the logging module exception information?

Q2 is strictly about making the logging module exception and traceback more palatable: catch the exception, format an SCons UserError message containing the value of SCONS_MSCOMMON_DEBUG value, the logging module exception class name, and the logging module exception string (error code and text). This is effectively all of the pertinent information that the logging module exception and traceback would provide in a far more compact and readable format. Thanks to @mwichmann for the example above.

No attempt is made to fix the issue or detect why the file name may be invalid. The lengthy traceback is eliminated. This matches the box check by @bdbaddog above.

The post above (https://github.com/SCons/scons/issues/4605#issuecomment-2379895561) shows most of the typical logging exceptions that arise: OSError (e.g., invalid file name), FileNotFoundError (e.g., reserved name), and PermissionError (e.g., directory path instead of file path).

I think this is far more useful to an end user.

I'm pretty sure we all want Q2.

SCons/Tool/MSCommon/common.py with both Q1 and Q2 changes: https://github.com/jcbrill/scons/blob/jbrill-mscommon-debug/SCons/Tool/MSCommon/common.py

EDIT: didn't actually answer @mwichmann question

Q1 SCONS_MSCOMMON_DEBUG value enclosed in double quotes:

Q2 Logging module exceptions:

jcbrill commented 1 month ago

Revised SCONS_MSCOMMON_DEBUG value handling proposal:

Revised style question for SCONS_MSCOMMON_DEBUG value:

Changes to main branch:

  1. UserError - Double-quote detected in file name specification:

        def _check_logfile(logfile):
            if logfile and '"' in logfile:
                err_msg = (
                    "SCONS_MSCOMMON_DEBUG value contains double quote character(s)\n"
                    f"  SCONS_MSCOMMON_DEBUG={logfile}"
                )
                raise SCons.Errors.UserError(err_msg)
            return logfile
    
        # SCONS_MSCOMMON_DEBUG is internal-use so undocumented:
        # set to '-' to print to console, else set to filename to log to
        LOGFILE = _check_logfile(os.environ.get('SCONS_MSCOMMON_DEBUG'))

    Examples:

    • SCONS_MSCOMMON_DEBUG = "S:\SCons\test-mscommon-debug-filename\Folder With Spaces\debug3.txt"

      scons: Reading SConscript files ...
      
      scons: *** SCONS_MSCOMMON_DEBUG value contains double quote character(s)
      SCONS_MSCOMMON_DEBUG="S:\SCons\test-mscommon-debug-filename\Folder With Spaces\debug3.txt"
      File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
    • SCONS_MSCOMMON_DEBUG = "S:\SCons\test-mscommon-debug-filename\Folder With Spaces\debug4.txt

      scons: Reading SConscript files ...
      
      scons: *** SCONS_MSCOMMON_DEBUG value contains double quote character(s)
      SCONS_MSCOMMON_DEBUG="S:\SCons\test-mscommon-debug-filename\Folder With Spaces\debug4.txt
      File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
    • SCONS_MSCOMMON_DEBUG = S:\SCons\test-mscommon-debug-filename\Folder With Spaces\debug5.txt"

      scons: Reading SConscript files ...
      
      scons: *** SCONS_MSCOMMON_DEBUG value contains double quote character(s)
      SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder With Spaces\debug5.txt"
      File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
    • SCONS_MSCOMMON_DEBUG = S:\SCons\test-mscommon-debug-filename\Folder With Spaces\dqbeg"dqend.txt

      scons: Reading SConscript files ...
      
      scons: *** SCONS_MSCOMMON_DEBUG value contains double quote character(s)
      SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder With Spaces\dqbeg"dqend.txt
      File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
  2. UserError - Logging module open failure:

        try:
            log_handler = logging.FileHandler(filename=LOGFILE)
        except (OSError, FileNotFoundError) as e:
            err_msg = (
                "Could not create logfile, check SCONS_MSCOMMON_DEBUG\n"
                f"  SCONS_MSCOMMON_DEBUG={LOGFILE}\n"
                f"  {e.__class__.__name__}: {str(e)}"
            )
            raise SCons.Errors.UserError(err_msg)

    Examples:

    • SCONS_MSCOMMON_DEBUG = S:\SCons\test-mscommon-debug-filename\Folder With Spaces\qmarkbeg?qmarkend.txt

      Note: file name specification contains an illegal character (?).

      scons: Reading SConscript files ...
      
      scons: *** Could not create logfile, check SCONS_MSCOMMON_DEBUG
      SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder With Spaces\qmarkbeg?qmarkend.txt
      OSError: [Errno 22] Invalid argument: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces\\qmarkbeg?qmarkend.txt'
      File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
    • SCONS_MSCOMMON_DEBUG = S:\SCons\test-mscommon-debug-filename\Folder With Spaces\aux.txt

      Note: file name specification contains a reserved named (aux).

      scons: Reading SConscript files ...
      
      scons: *** Could not create logfile, check SCONS_MSCOMMON_DEBUG
      SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder With Spaces\aux.txt
      FileNotFoundError: [Errno 2] No such file or directory: '\\\\.\\aux'
      File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
    • SCONS_MSCOMMON_DEBUG = S:\SCons\test-mscommon-debug-filename\Folder Does Not Exist\debug.txt

      Note: file name specification path does not exist.

      scons: Reading SConscript files ...
      
      scons: *** Could not create logfile, check SCONS_MSCOMMON_DEBUG
      SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder Does Not Exist\debug.txt
      FileNotFoundError: [Errno 2] No such file or directory: 'S:\\SCons\\test-mscommon-debug-filename\\Folder Does Not Exist\\debug.txt'
      File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed
    • SCONS_MSCOMMON_DEBUG = S:\SCons\test-mscommon-debug-filename\Folder With Spaces\

      Note: file name specification is a directory.

      scons: Reading SConscript files ...
      
      scons: *** Could not create logfile, check SCONS_MSCOMMON_DEBUG
      SCONS_MSCOMMON_DEBUG=S:\SCons\test-mscommon-debug-filename\Folder With Spaces\
      PermissionError: [Errno 13] Permission denied: 'S:\\SCons\\test-mscommon-debug-filename\\Folder With Spaces'
      File "<frozen importlib._bootstrap>", line 219, in _call_with_frames_removed

    Possible enhancements:

    • Detect additional limited set of illegal characters in quick-check.