Use pid for files created in pydevd logging. Fixes #1831

src/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_log.py

@@ -1,12 +1,62 @@
-from _pydevd_bundle.pydevd_constants import DebugInfoHolder, SHOW_COMPILE_CYTHON_COMMAND_LINE
+from _pydevd_bundle.pydevd_constants import DebugInfoHolder, SHOW_COMPILE_CYTHON_COMMAND_LINE, NULL
 from _pydev_imps._pydev_saved_modules import threading
 from contextlib import contextmanager
 import traceback
 import os
 import sys
+
 currentThread = threading.currentThread
 
-WARN_ONCE_MAP = {}
+
+class _LoggingGlobals(object):
+
+    _warn_once_map = {}
+    _debug_stream_filename = None
+    _debug_stream = sys.stderr
+    _debug_stream_initialized = False
+
+
+def initialize_debug_stream(force=False):
+    if _LoggingGlobals._debug_stream_initialized and not force:
+        return
+    _LoggingGlobals._debug_stream_initialized = True
+
+    # Note: we cannot initialize with sys.stderr because when forking we may end up logging things in 'os' calls.
+    _LoggingGlobals._debug_stream = NULL  
+    _LoggingGlobals._debug_stream_filename = None
+
+    if not DebugInfoHolder.PYDEVD_DEBUG_FILE:
+        _LoggingGlobals._debug_stream = sys.stderr
+    else:
+        # Add pid to the filename.
+        try:
+            dirname = os.path.dirname(DebugInfoHolder.PYDEVD_DEBUG_FILE)
+            basename = os.path.basename(DebugInfoHolder.PYDEVD_DEBUG_FILE)
+            try:
+                os.makedirs(dirname)
+            except:
+                pass  # Ignore error if it already exists.
+
+            name, ext = os.path.splitext(basename)
+            debug_file = os.path.join(dirname, name + '.' + str(os.getpid()) + ext)
+            _LoggingGlobals._debug_stream = open(debug_file, 'w')
+            _LoggingGlobals._debug_stream_filename = debug_file
+        except:
+            _LoggingGlobals._debug_stream = sys.stderr
+            # Don't fail when trying to setup logging, just show the exception.
+            traceback.print_exc()
+
+
+def list_log_files(pydevd_debug_file):
+    log_files = []
+    dirname = os.path.dirname(pydevd_debug_file)
+    basename = os.path.basename(pydevd_debug_file)
+    if os.path.isdir(dirname):
+        name, ext = os.path.splitext(basename)
+        for f in os.listdir(dirname):
+            if f.startswith(name) and f.endswith(ext):
+                log_files.append(os.path.join(dirname, f))
+    return log_files
 
 
 @contextmanager
@@ -15,15 +65,22 @@ def log_context(trace_level, stream):
     To be used to temporarily change the logging settings.
     '''
     original_trace_level = DebugInfoHolder.DEBUG_TRACE_LEVEL
-    original_stream = DebugInfoHolder.DEBUG_STREAM
+    original_debug_stream = _LoggingGlobals._debug_stream
+    original_pydevd_debug_file = DebugInfoHolder.PYDEVD_DEBUG_FILE
+    original_debug_stream_filename = _LoggingGlobals._debug_stream_filename
+    original_initialized = _LoggingGlobals._debug_stream_initialized
 
     DebugInfoHolder.DEBUG_TRACE_LEVEL = trace_level
-    DebugInfoHolder.DEBUG_STREAM = stream
+    _LoggingGlobals._debug_stream = stream
+    _LoggingGlobals._debug_stream_initialized = True
     try:
         yield
     finally:
         DebugInfoHolder.DEBUG_TRACE_LEVEL = original_trace_level
-        DebugInfoHolder.DEBUG_STREAM = original_stream
+        _LoggingGlobals._debug_stream = original_debug_stream
+        DebugInfoHolder.PYDEVD_DEBUG_FILE = original_pydevd_debug_file
+        _LoggingGlobals._debug_stream_filename = original_debug_stream_filename
+        _LoggingGlobals._debug_stream_initialized = original_initialized
 
 
 def _pydevd_log(level, msg, *args):
@@ -45,13 +102,14 @@ def _pydevd_log(level, msg, *args):
                 msg = '%s - %s' % (msg, args)
             msg = '%s\n' % (msg,)
             try:
-                DebugInfoHolder.DEBUG_STREAM.write(msg)
+                initialize_debug_stream()  # Do it as late as possible
+                _LoggingGlobals._debug_stream.write(msg)
             except TypeError:
                 if isinstance(msg, bytes):
                     # Depending on the StringIO flavor, it may only accept unicode.
                     msg = msg.decode('utf-8', 'replace')
-                    DebugInfoHolder.DEBUG_STREAM.write(msg)
-            DebugInfoHolder.DEBUG_STREAM.flush()
+                    _LoggingGlobals._debug_stream.write(msg)
+            _LoggingGlobals._debug_stream.flush()
         except:
             pass
         return True
@@ -61,8 +119,9 @@ def _pydevd_log_exception(msg='', *args):
     if msg or args:
         _pydevd_log(0, msg, *args)
     try:
-        traceback.print_exc(file=DebugInfoHolder.DEBUG_STREAM)
-        DebugInfoHolder.DEBUG_STREAM.flush()
+        initialize_debug_stream()  # Do it as late as possible
+        traceback.print_exc(file=_LoggingGlobals._debug_stream)
+        _LoggingGlobals._debug_stream.flush()
     except:
         raise
 
@@ -108,8 +167,8 @@ def error_once(msg, *args):
     except:
         message = '%s - %s' % (msg, args)
 
-    if message not in WARN_ONCE_MAP:
-        WARN_ONCE_MAP[message] = True
+    if message not in _LoggingGlobals._warn_once_map:
+        _LoggingGlobals._warn_once_map[message] = True
         critical(message)
 
 

src/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_monkey.py

@@ -63,17 +63,8 @@ def _is_managed_arg(arg):
 
 def _on_forked_process(setup_tracing=True):
     pydevd_constants.after_fork()
-    pydevd_constants.DebugInfoHolder.DEBUG_STREAM = NULL
-
-    # TODO: We should use the pid for logging in pydevd to deal with multiple processes.
-    # if pydevd_constants.PYDEVD_DEBUG_FILE:
-    #     debug_file = pydevd_constants.PYDEVD_DEBUG_FILE
-    #     path, ext = os.path.splitext(debug_file)
-    #     debug_file = path + '.' + str(os.getpid()) + ext
-    #     pydevd_constants.PYDEVD_DEBUG_FILE = debug_file
-    #     pydevd_constants.DebugInfoHolder.DEBUG_STREAM = open(debug_file, 'w')
-    #
-    # pydev_log.debug('pydevd on forked process: %s', os.getpid())
+    pydev_log.initialize_debug_stream(force=True)
+    pydev_log.debug('pydevd on forked process: %s', os.getpid())
 
     import pydevd
     pydevd.threadingCurrentThread().__pydevd_main_thread = True

src/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_constants.py

@@ -31,12 +31,13 @@ class DebugInfoHolder:
 
     # General information
     DEBUG_TRACE_LEVEL = 0  # 0 = critical, 1 = info, 2 = debug, 3 = verbose
-    DEBUG_STREAM = sys.stderr
 
     # Flags to debug specific points of the code.
     DEBUG_RECORD_SOCKET_READS = False
     DEBUG_TRACE_BREAKPOINTS = -1
 
+    PYDEVD_DEBUG_FILE = None
+
 
 IS_CPYTHON = platform.python_implementation() == 'CPython'
 
@@ -169,7 +170,6 @@ ASYNC_EVAL_TIMEOUT_SEC = 60
 NEXT_VALUE_SEPARATOR = "__pydev_val__"
 BUILTINS_MODULE_NAME = '__builtin__' if IS_PY2 else 'builtins'
 SHOW_DEBUG_INFO_ENV = os.getenv('PYCHARM_DEBUG') == 'True' or os.getenv('PYDEV_DEBUG') == 'True' or os.getenv('PYDEVD_DEBUG') == 'True'
-PYDEVD_DEBUG_FILE = os.getenv('PYDEVD_DEBUG_FILE')
 
 if SHOW_DEBUG_INFO_ENV:
     # show debug info before the debugger start
@@ -177,8 +177,7 @@ if SHOW_DEBUG_INFO_ENV:
     DebugInfoHolder.DEBUG_TRACE_LEVEL = 3
     DebugInfoHolder.DEBUG_TRACE_BREAKPOINTS = 1
 
-    if PYDEVD_DEBUG_FILE:
-        DebugInfoHolder.DEBUG_STREAM = open(PYDEVD_DEBUG_FILE, 'w')
+DebugInfoHolder.PYDEVD_DEBUG_FILE = os.getenv('PYDEVD_DEBUG_FILE')
 
 
 def protect_libraries_from_patching():

src/ptvsd/_vendored/pydevd/tests_python/debugger_unittest.py

@@ -14,7 +14,7 @@ import time
 import traceback
 from tests_python.debug_constants import *
 
-from _pydev_bundle import pydev_localhost
+from _pydev_bundle import pydev_localhost, pydev_log
 
 # Note: copied (don't import because we want it to be independent on the actual code because of backward compatibility).
 CMD_RUN = 101
@@ -379,7 +379,7 @@ def start_in_daemon_thread(target, args):
 class DebuggerRunner(object):
 
     def __init__(self, tmpdir):
-        self.tmpfile = os.path.join(str(tmpdir), 'pydevd_debug_file_%s.txt' % (os.getpid(),))
+        self.pydevd_debug_file = os.path.join(str(tmpdir), 'pydevd_debug_file_%s.txt' % (os.getpid(),))
 
     def get_command_line(self):
         '''
@@ -458,7 +458,7 @@ class DebuggerRunner(object):
             env = os.environ.copy()
 
         env['PYDEVD_DEBUG'] = 'True'
-        env['PYDEVD_DEBUG_FILE'] = self.tmpfile
+        env['PYDEVD_DEBUG_FILE'] = self.pydevd_debug_file
         process = subprocess.Popen(
             args,
             stdout=subprocess.PIPE,
@@ -574,9 +574,11 @@ class DebuggerRunner(object):
 
     def fail_with_message(self, msg, stdout, stderr, writerThread):
         log_contents = ''
-        if os.path.exists(self.tmpfile):
-            with open(self.tmpfile, 'r') as stream:
-                log_contents = stream.read()
+        for f in pydev_log.list_log_files(self.pydevd_debug_file):
+            if os.path.exists(f):
+                with open(f, 'r') as stream:
+                    log_contents += '\n-------------------- %s ------------------\n\n' % (f,)
+                    log_contents += stream.read()
         raise AssertionError(msg +
             "\n\n===========================\nStdout: \n" + ''.join(stdout) +
             "\n\n===========================\nStderr:" + ''.join(stderr) +

src/ptvsd/_vendored/pydevd/tests_python/test_debugger.py

@@ -25,6 +25,7 @@ import pydevd_file_utils
 import subprocess
 import threading
 from tests_python.debug_constants import IS_PY26
+from _pydev_bundle import pydev_log
 try:
     from urllib import unquote
 except ImportError:
@@ -2422,8 +2423,8 @@ def test_multiprocessing_simple(case_setup_multiprocessing, file_to_check):
 
 
 @pytest.mark.skipif(not IS_CPYTHON, reason='CPython only test.')
-@pytest.mark.parametrize('count', range(10))  # Call multiple times to exercise timing issues.
-def test_multiprocessing_with_stopped_breakpoints(case_setup_multiprocessing, count):
+@pytest.mark.parametrize('count', range(5))  # Call multiple times to exercise timing issues.
+def test_multiprocessing_with_stopped_breakpoints(case_setup_multiprocessing, count, debugger_runner_simple):
     import threading
     from tests_python.debugger_unittest import AbstractWriterThread
     with case_setup_multiprocessing.test_file('_debugger_case_multiprocessing_stopped_threads.py') as writer:
@@ -2499,6 +2500,9 @@ def test_multiprocessing_with_stopped_breakpoints(case_setup_multiprocessing, co
         writer.write_run_thread(hit2.thread_id)
         writer.write_run_thread(main_hit.thread_id)
 
+        # We must have found at least 2 debug files when doing multiprocessing (one for
+        # each pid).
+        assert len(pydev_log.list_log_files(debugger_runner_simple.pydevd_debug_file)) == 2
         writer.finished_ok = True
 
 

src/ptvsd/_vendored/pydevd/tests_python/test_utilities.py

@@ -162,6 +162,36 @@ def test_pydevd_log():
     assert stream.getvalue() == 'always %s %s - (1,)\n'
 
 
+def test_pydevd_logging_files(tmpdir):
+    from _pydev_bundle import pydev_log
+    from _pydevd_bundle.pydevd_constants import DebugInfoHolder
+    import os.path
+    from _pydev_bundle.pydev_log import _LoggingGlobals
+
+    try:
+        import StringIO as io
+    except:
+        import io
+    from _pydev_bundle.pydev_log import log_context
+
+    stream = io.StringIO()
+    with log_context(0, stream=stream):
+        d1 = str(tmpdir.join('d1'))
+        d2 = str(tmpdir.join('d2'))
+
+        for d in (d1, d2):
+            DebugInfoHolder.PYDEVD_DEBUG_FILE = os.path.join(d, 'file.txt')
+            pydev_log.initialize_debug_stream(force=True)
+
+            assert os.path.normpath(_LoggingGlobals._debug_stream_filename) == \
+                os.path.normpath(os.path.join(d, 'file.%s.txt' % os.getpid()))
+
+            assert os.path.exists(_LoggingGlobals._debug_stream_filename)
+
+            assert pydev_log.list_log_files(DebugInfoHolder.PYDEVD_DEBUG_FILE) == [
+                _LoggingGlobals._debug_stream_filename]
+
+
 def _check_tracing_other_threads():
     import pydevd_tracing
     import time

tests/debug/session.py

@@ -21,10 +21,8 @@ from tests import code, timeline, watchdog
 from tests.debug import comms, config, output
 from tests.patterns import some
 
-
 DEBUGGEE_PYTHONPATH = tests.root / "DEBUGGEE_PYTHONPATH"
 
-
 StopInfo = collections.namedtuple(
     "StopInfo", ["body", "frames", "thread_id", "frame_id"]
 )
@@ -296,8 +294,6 @@ class Session(object):
             env.update(
                 {
                     "PTVSD_LOG_DIR": self.log_dir.strpath,
-                    "PYDEVD_DEBUG": "True",
-                    "PYDEVD_DEBUG_FILE": (self.log_dir / "pydevd.log").strpath,
                 }
             )
 

tests/pydevd_log.py

@@ -4,22 +4,16 @@
 
 from __future__ import absolute_import, print_function, unicode_literals
 
-import contextlib
 import os
 
-from ptvsd.common import log
+from ptvsd.common import log, compat
+from _pydev_bundle import pydev_log
 
 
-@contextlib.contextmanager
-def enabled(filename):
-    os.environ["PYDEVD_DEBUG"] = "True"
-    os.environ["PYDEVD_DEBUG_FILE"] = filename
+def enable(filename):
+    os.environ[str("PYDEVD_DEBUG")] = str("True")
+    os.environ[str("PYDEVD_DEBUG_FILE")] = compat.filename_str(filename)
     log.debug("pydevd log will be at {0}", filename)
-    try:
-        yield
-    finally:
-        del os.environ["PYDEVD_DEBUG"]
-        del os.environ["PYDEVD_DEBUG_FILE"]
 
 
 def dump(why):
@@ -29,10 +23,12 @@ def dump(why):
     if not pydevd_debug_file:
         return
 
+    log_contents = []
     try:
-        f = open(pydevd_debug_file)
-        with f:
-            pydevd_log = f.read()
+        for filename in pydev_log.list_log_files(pydevd_debug_file):
+            with open(filename) as stream:
+                log_contents.append("---------- %s ------------\n\n" % (filename,))
+                log_contents.append(stream.read())
     except Exception:
         log.exception(
             "Test {0}, but pydevd log {1} could not be retrieved.",
@@ -41,4 +37,4 @@ def dump(why):
         )
         return
 
-    log.info("Test {0}; pydevd log:\n\n{1}", why, pydevd_log)
+    log.info("Test {0}; pydevd log:\n\n{1}", why, "".join(log_contents))

tests/pytest_fixtures.py

@@ -9,7 +9,6 @@ import os
 import platform
 import py.path
 import pytest
-import tempfile
 import threading
 import types
 
@@ -17,7 +16,6 @@ from ptvsd.common import compat, fmt, log, options, timestamp
 from tests import code, pydevd_log
 from tests.debug import runners, session, targets
 
-
 # Set up the test matrix for various code types and attach methods. Most tests will
 # use both run_as and start_method, so the matrix is a cross product of them.
 
@@ -53,6 +51,8 @@ def test_wrapper(request, long_tmpdir):
     try:
         if options.log_dir is None:
             write_log = lambda filename, data: None
+            pydevd_filename = os.path.join(str(long_tmpdir), 'pydevd.log')
+
         else:
             original_log_dir = options.log_dir
             log_subdir = request.node.nodeid
@@ -64,6 +64,7 @@ def test_wrapper(request, long_tmpdir):
                 py.path.local(options.log_dir).remove()
             except Exception:
                 pass
+            pydevd_filename = os.path.join(str(options.log_dir), 'pydevd.log')
 
             def write_log(filename, data):
                 filename = os.path.join(options.log_dir, filename)
@@ -72,6 +73,8 @@ def test_wrapper(request, long_tmpdir):
                 with open(filename, "wb") as f:
                     f.write(data)
 
+        pydevd_log.enable(pydevd_filename)
+
         print("\n")  # make sure on-screen logs start on a new line
         with log.to_file(prefix="tests"):
             log.info("{0} started.", request.node.nodeid)
@@ -100,31 +103,13 @@ def test_wrapper(request, long_tmpdir):
 
                 if failed:
                     write_log("FAILED.log", "")
+                    if options.log_dir is None:
+                        pydevd_log.dump("failed")
     finally:
         if original_log_dir is not None:
             options.log_dir = original_log_dir
 
 
-@pytest.fixture(autouse=True)
-def with_pydevd_log(request, tmpdir):
-    """Enables pydevd logging during the test run, and dumps the log if the test fails.
-    """
-
-    prefix = "pydevd_debug_file-{0}".format(os.getpid())
-    filename = tempfile.mktemp(suffix=".log", prefix=prefix, dir=str(tmpdir))
-
-    with pydevd_log.enabled(filename):
-        yield
-
-    if request.node.setup_report.passed:
-        if not request.node.call_report.failed:
-            return
-    elif not request.node.setup_report.failed:
-        return
-
-    pydevd_log.dump("failed")
-
-
 @pytest.fixture
 def daemon(request):
     """Provides a factory function for daemon threads. The returned thread is
@@ -159,7 +144,6 @@ if platform.system() != "Windows":
     def long_tmpdir(request, tmpdir):
         return tmpdir
 
-
 else:
     import ctypes
 

tests/tests/test_fixtures.py

@@ -0,0 +1,99 @@
+import os
+import sys
+import pytest
+
+pytest_plugins = ['pytester']
+
+
+@pytest.mark.parametrize('use_ptvsd_logs', [True, False])
+def test_logs_in_test_wrapper(testdir, use_ptvsd_logs):
+    # Use the same conftest we usually use.
+    with open(os.path.join(os.path.dirname(os.path.dirname(__file__)), 'conftest.py'), 'r') as stream:
+        conftest_contents = stream.read()
+
+    testdir.makeconftest(conftest_contents)
+    testdir.makepyfile(
+        """
+        import pytest
+        import ptvsd
+        import os
+        import subprocess
+        import sys
+
+        def create_pydevd_log_file():
+            subprocess.call([
+                sys.executable,
+                '-c',
+                "from ptvsd._vendored import force_pydevd;"
+                "from _pydev_bundle import pydev_log;"
+                "pydev_log.critical('ERROR LOGGED TO PYDEVD LOG')"
+            ])
+
+        def test_error():
+            create_pydevd_log_file()
+            assert False
+
+        def test_ok():
+            create_pydevd_log_file()
+            assert True
+        """
+    )
+    testdir.monkeypatch.setenv("PYTHONPATH", os.pathsep.join(sys.path))
+
+    def find_and_remove_from_set(s, expected_condition):
+        for f in s.copy():
+            if expected_condition(f):
+                s.discard(f)
+                return f
+        raise AssertionError('Could not find expected condition in %s' % (s,))
+
+    args = []
+    if use_ptvsd_logs:
+        args.append('--ptvsd-logs')
+    result = testdir.runpytest_subprocess(*args)
+
+    result.assert_outcomes(failed=1, passed=1)
+
+    tmpdir = testdir.tmpdir
+    logs_dir = os.path.join(str(tmpdir), 'tests', '_logs')
+    if not use_ptvsd_logs:
+        assert not os.path.isdir(logs_dir)
+        runpytest_dir = os.path.join(str(tmpdir), 'runpytest-0')
+        assert os.path.isdir(runpytest_dir)
+        for dirname in ['test_error0', 'test_ok0']:
+            dir_contents = set(os.listdir(os.path.join(runpytest_dir, dirname)))
+            find_and_remove_from_set(dir_contents, lambda f: f.startswith('pydevd') and f.endswith('.log'))
+
+        full_contents = ('\n'.join(result.outlines) + '\n'.join(result.errlines))
+        assert full_contents.count('ERROR LOGGED TO PYDEVD LOG') == 1  # Should show on error.
+    else:
+        assert os.path.isdir(logs_dir)
+        dir_contents = os.listdir(logs_dir)
+        assert len(dir_contents) == 1
+        logs_dir = os.path.join(logs_dir, next(iter(dir_contents)))
+
+        test_logs_dir = os.path.join(logs_dir, 'test_logs_in_test_wrapper.py')
+        assert os.path.isdir(test_logs_dir)
+        expected_test_dirs = ['test_error', 'test_ok']
+        assert set(os.listdir(test_logs_dir)) == set(expected_test_dirs)
+
+        for d in expected_test_dirs:
+            found_in_test_dir = set(os.listdir(os.path.join(test_logs_dir, d)))
+
+            # Make sure we find and remove the ones which have the pid in it.
+            find_and_remove_from_set(found_in_test_dir, lambda f: f.startswith('pydevd') and f.endswith('.log'))
+            find_and_remove_from_set(found_in_test_dir, lambda f: f.startswith('tests-') and f.endswith('.log'))
+
+            expected = set([
+                'call_report.log',
+                'call_report.stderr.log',
+                'call_report.stdout.log',
+                'setup_report.log',
+                'setup_report.stderr.log',
+                'setup_report.stdout.log',
+            ])
+            if d == 'test_error':
+                expected.add('FAILED.log')
+
+            assert expected == found_in_test_dir
+