From c0108c08b5b9d0d43aa0486c746175026da67947 Mon Sep 17 00:00:00 2001 From: Fabio Zadrozny Date: Tue, 15 Oct 2019 08:02:54 -0300 Subject: [PATCH] Use pid for files created in pydevd logging. Fixes #1831 --- .../pydevd/_pydev_bundle/pydev_log.py | 83 +++++++++++++--- .../pydevd/_pydev_bundle/pydev_monkey.py | 13 +-- .../pydevd/_pydevd_bundle/pydevd_constants.py | 7 +- .../pydevd/tests_python/debugger_unittest.py | 14 +-- .../pydevd/tests_python/test_debugger.py | 8 +- .../pydevd/tests_python/test_utilities.py | 30 ++++++ tests/debug/session.py | 4 - tests/pydevd_log.py | 26 +++-- tests/pytest_fixtures.py | 30 ++---- tests/tests/test_fixtures.py | 99 +++++++++++++++++++ 10 files changed, 237 insertions(+), 77 deletions(-) create mode 100644 tests/tests/test_fixtures.py diff --git a/src/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_log.py b/src/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_log.py index 8077fd63..6252c00b 100644 --- a/src/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_log.py +++ b/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) diff --git a/src/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_monkey.py b/src/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_monkey.py index 1f616c51..638b84e5 100644 --- a/src/ptvsd/_vendored/pydevd/_pydev_bundle/pydev_monkey.py +++ b/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 diff --git a/src/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_constants.py b/src/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_constants.py index 28ded6c0..36ecbe79 100644 --- a/src/ptvsd/_vendored/pydevd/_pydevd_bundle/pydevd_constants.py +++ b/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(): diff --git a/src/ptvsd/_vendored/pydevd/tests_python/debugger_unittest.py b/src/ptvsd/_vendored/pydevd/tests_python/debugger_unittest.py index a1755207..b0c8ef01 100644 --- a/src/ptvsd/_vendored/pydevd/tests_python/debugger_unittest.py +++ b/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) + diff --git a/src/ptvsd/_vendored/pydevd/tests_python/test_debugger.py b/src/ptvsd/_vendored/pydevd/tests_python/test_debugger.py index 968d6cc4..a0b97f11 100644 --- a/src/ptvsd/_vendored/pydevd/tests_python/test_debugger.py +++ b/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 diff --git a/src/ptvsd/_vendored/pydevd/tests_python/test_utilities.py b/src/ptvsd/_vendored/pydevd/tests_python/test_utilities.py index 559eb9c9..36ce1519 100644 --- a/src/ptvsd/_vendored/pydevd/tests_python/test_utilities.py +++ b/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 diff --git a/tests/debug/session.py b/tests/debug/session.py index 54dacd94..4983fc30 100644 --- a/tests/debug/session.py +++ b/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, } ) diff --git a/tests/pydevd_log.py b/tests/pydevd_log.py index f254cbe3..2c0472f9 100644 --- a/tests/pydevd_log.py +++ b/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)) diff --git a/tests/pytest_fixtures.py b/tests/pytest_fixtures.py index 17c8495a..2fc19896 100644 --- a/tests/pytest_fixtures.py +++ b/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 diff --git a/tests/tests/test_fixtures.py b/tests/tests/test_fixtures.py new file mode 100644 index 00000000..1a10352b --- /dev/null +++ b/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 +