Investigate thread contention on windows logfiles

[nathaniel-may]

Is there an existing feature request for this?

• I have searched the existing issues

Describe the Feature

in #4055 a single test failed because a process was already using the log file. I suspect this is because of how our tests are run and not because there is a glaring problem with dbt. It should be investigated though since windows tests might currently be non-deterministic with the new structured logging.

Describe alternatives you've considered

No response

Who will this benefit?

No response

Are you interested in contributing this feature?

No response

Anything else?

Test Summary

=========================== short test summary info ===========================
FAILED test/integration/015_cli_invocation_tests/test_cli_invocation.py::TestCLIInvocationWithProfilesAndProjectDir::test_postgres_debug_with_profiles_separate_from_project_dir
==== 1 failed, 475 passed, 2 skipped, 19252 warnings in 1114.59s (0:18:34) ====
ERROR: InvocationError for command 'D:\a\dbt-core\dbt-core\.tox\integration-postgres\Scripts\python' -m pytest -m profile_postgres test/integration (exited with code 1)
___________________________________ summary ___________________________________

Full Trace

================================== FAILURES ===================================
_ TestCLIInvocationWithProfilesAndProjectDir.test_postgres_debug_with_profiles_separate_from_project_dir _
[gw0] win32 -- Python 3.8.10 D:\a\dbt-core\dbt-core\.tox\integration-postgres\Scripts\python.exe

path = 'C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\tmpi71v804g\\logs'
onerror = <function TemporaryDirectory._rmtree.<locals>.onerror at 0x000002980BBC43A0>

    def _rmtree_unsafe(path, onerror):
        try:
            with os.scandir(path) as scandir_it:
                entries = list(scandir_it)
        except OSError:
            onerror(os.scandir, path, sys.exc_info())
            entries = []
        for entry in entries:
            fullname = entry.path
            if _rmtree_isdir(entry):
                try:
                    if entry.is_symlink():
                        # This can only happen if someone replaces
                        # a directory with a symlink after the call to
                        # os.scandir or entry.is_dir above.
                        raise OSError("Cannot call rmtree on a symbolic link")
                except OSError:
                    onerror(os.path.islink, fullname, sys.exc_info())
                    continue
                _rmtree_unsafe(fullname, onerror)
            else:
                try:
>                   os.unlink(fullname)
E                   PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: 'C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\tmpi71v804g\\logs\\dbt.log'

c:\hostedtoolcache\windows\python\3.8.10\x64\lib\shutil.py:616: PermissionError

During handling of the above exception, another exception occurred:

func = <built-in function unlink>
path = 'C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\tmpi71v804g\\logs\\dbt.log'
exc_info = (<class 'PermissionError'>, PermissionError(13, 'The process cannot access the file because it is being used by another process'), <traceback object at 0x000002980BD425C0>)

    def onerror(func, path, exc_info):
        if issubclass(exc_info[0], PermissionError):
            def resetperms(path):
                try:
                    _os.chflags(path, 0)
                except AttributeError:
                    pass
                _os.chmod(path, 0o700)
    
            try:
                if path != name:
                    resetperms(_os.path.dirname(path))
                resetperms(path)
    
                try:
>                   _os.unlink(path)
E                   PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: 'C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\tmpi71v804g\\logs\\dbt.log'

c:\hostedtoolcache\windows\python\3.8.10\x64\lib\tempfile.py:802: PermissionError

During handling of the above exception, another exception occurred:

self = <test_cli_invocation.TestCLIInvocationWithProfilesAndProjectDir testMethod=test_postgres_debug_with_profiles_separate_from_project_dir>

    @use_profile("postgres")
    def test_postgres_debug_with_profiles_separate_from_project_dir(self):
>       self._test_postgres_sub_command_with_profiles_separate_from_project_dir("debug")

test\integration\015_cli_invocation_tests\test_cli_invocation.py:296: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
test\integration\015_cli_invocation_tests\test_cli_invocation.py:277: in _test_postgres_sub_command_with_profiles_separate_from_project_dir
    self.run_dbt(other_args, profiles_dir=False)
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\contextlib.py:120: in __exit__
    next(self.gen)
test\integration\015_cli_invocation_tests\test_cli_invocation.py:46: in temporary_working_directory
    yield tmpdir
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\tempfile.py:827: in __exit__
    self.cleanup()
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\tempfile.py:831: in cleanup
    self._rmtree(self.name)
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\tempfile.py:813: in _rmtree
    _shutil.rmtree(name, onerror=onerror)
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\shutil.py:740: in rmtree
    return _rmtree_unsafe(path, onerror)
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\shutil.py:613: in _rmtree_unsafe
    _rmtree_unsafe(fullname, onerror)
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\shutil.py:618: in _rmtree_unsafe
    onerror(os.unlink, fullname, sys.exc_info())
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\tempfile.py:805: in onerror
    cls._rmtree(path)
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\tempfile.py:813: in _rmtree
    _shutil.rmtree(name, onerror=onerror)
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\shutil.py:740: in rmtree
    return _rmtree_unsafe(path, onerror)
c:\hostedtoolcache\windows\python\3.8.10\x64\lib\shutil.py:599: in _rmtree_unsafe
    onerror(os.scandir, path, sys.exc_info())
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

path = 'C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\tmpi71v804g\\logs\\dbt.log'
onerror = <function TemporaryDirectory._rmtree.<locals>.onerror at 0x000002980BC5D040>

    def _rmtree_unsafe(path, onerror):
        try:
>           with os.scandir(path) as scandir_it:
E           NotADirectoryError: [WinError 267] The directory name is invalid: 'C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\tmpi71v804g\\logs\\dbt.log'

c:\hostedtoolcache\windows\python\3.8.10\x64\lib\shutil.py:596: NotADirectoryError
---------------------------- Captured stdout call -----------------------------

[jtcohen6]

Good news is, it does seem to be limited to that one test each time

[jtcohen6]

Fixed by #4380!