From 53bc524b7eb0801d2900aede0e2141a3c482423f Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Fri, 13 Sep 2019 20:08:33 +0300 Subject: [PATCH 01/89] Reject coroutine functions and async generator functions #152 --- pysnooper/pycompat.py | 5 ++++ pysnooper/tracer.py | 3 +- tests/test_async.py | 69 +++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 76 insertions(+), 1 deletion(-) create mode 100644 tests/test_async.py diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index 1748ccd..ce7566e 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -47,6 +47,11 @@ try: except AttributeError: iscoroutinefunction = lambda whatever: False # Lolz +try: + isasyncgenfunction = inspect.isasyncgenfunction +except AttributeError: + isasyncgenfunction = lambda whatever: False # Lolz + if PY3: string_types = (str,) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index f9625c3..b1b1a16 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -267,7 +267,8 @@ class Tracer: method, incoming = gen.throw, e if pycompat.iscoroutinefunction(function): - # return decorate(function, coroutine_wrapper) + raise NotImplementedError + if pycompat.isasyncgenfunction(function): raise NotImplementedError elif inspect.isgeneratorfunction(function): return generator_wrapper diff --git a/tests/test_async.py b/tests/test_async.py new file mode 100644 index 0000000..3a7e477 --- /dev/null +++ b/tests/test_async.py @@ -0,0 +1,69 @@ +# Copyright 2019 Ram Rachum and collaborators. +# This program is distributed under the MIT license. + +import io +import textwrap +import threading +import collections +import types +import os +import sys + +from pysnooper.utils import truncate +import pytest + +import pysnooper +from pysnooper.variables import needs_parentheses +from pysnooper import pycompat +from .utils import (assert_output, assert_sample_output, VariableEntry, + CallEntry, LineEntry, ReturnEntry, OpcodeEntry, + ReturnValueEntry, ExceptionEntry, SourcePathEntry) +from . import mini_toolbox + + +def test_rejecting_coroutine_functions(): + if sys.version_info[:2] <= (3, 4): + pytest.skip() + + class Thing: + pass + + thing = Thing() + + code = textwrap.dedent(''' + async def foo(x): + return 'lol' + thing.foo = foo + ''') + exec(code) + foo = thing.foo + + assert pycompat.iscoroutinefunction(foo) + assert not pycompat.isasyncgenfunction(foo) + with pytest.raises(NotImplementedError): + pysnooper.snoop()(foo) + + +def test_rejecting_async_generator_functions(): + if sys.version_info[:2] <= (3, 6): + pytest.skip() + + class Thing: + pass + + thing = Thing() + + code = textwrap.dedent(''' + async def foo(x): + yield 'lol' + thing.foo = foo + ''') + exec(code) + foo = thing.foo + + assert not pycompat.iscoroutinefunction(foo) + assert pycompat.isasyncgenfunction(foo) + with pytest.raises(NotImplementedError): + pysnooper.snoop()(foo) + + From 1ef8beb90b49d134282b5c21708e5c9717745886 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Fri, 13 Sep 2019 21:03:45 +0300 Subject: [PATCH 02/89] Make tests nicer --- .../{test_async.py => test_not_implemented.py} | 18 ++---------------- 1 file changed, 2 insertions(+), 16 deletions(-) rename tests/{test_async.py => test_not_implemented.py} (85%) diff --git a/tests/test_async.py b/tests/test_not_implemented.py similarity index 85% rename from tests/test_async.py rename to tests/test_not_implemented.py index 3a7e477..245a184 100644 --- a/tests/test_async.py +++ b/tests/test_not_implemented.py @@ -25,18 +25,11 @@ def test_rejecting_coroutine_functions(): if sys.version_info[:2] <= (3, 4): pytest.skip() - class Thing: - pass - - thing = Thing() - code = textwrap.dedent(''' async def foo(x): return 'lol' - thing.foo = foo ''') - exec(code) - foo = thing.foo + exec(code, globals()) assert pycompat.iscoroutinefunction(foo) assert not pycompat.isasyncgenfunction(foo) @@ -48,18 +41,11 @@ def test_rejecting_async_generator_functions(): if sys.version_info[:2] <= (3, 6): pytest.skip() - class Thing: - pass - - thing = Thing() - code = textwrap.dedent(''' async def foo(x): yield 'lol' - thing.foo = foo ''') - exec(code) - foo = thing.foo + exec(code, globals()) assert not pycompat.iscoroutinefunction(foo) assert pycompat.isasyncgenfunction(foo) From 85c929285efb03922db85a06e9795e0907735f9a Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Sat, 14 Sep 2019 10:17:26 +0300 Subject: [PATCH 03/89] Make tests even nicer --- tests/test_not_implemented.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/tests/test_not_implemented.py b/tests/test_not_implemented.py index 245a184..65b2645 100644 --- a/tests/test_not_implemented.py +++ b/tests/test_not_implemented.py @@ -29,7 +29,9 @@ def test_rejecting_coroutine_functions(): async def foo(x): return 'lol' ''') - exec(code, globals()) + namespace = {} + exec(code, namespace) + foo = namespace['foo'] assert pycompat.iscoroutinefunction(foo) assert not pycompat.isasyncgenfunction(foo) @@ -45,7 +47,9 @@ def test_rejecting_async_generator_functions(): async def foo(x): yield 'lol' ''') - exec(code, globals()) + namespace = {} + exec(code, namespace) + foo = namespace['foo'] assert not pycompat.iscoroutinefunction(foo) assert pycompat.isasyncgenfunction(foo) From e2aa42bd6d834e9eb51104c5fc8d053571f09179 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Sat, 14 Sep 2019 10:28:53 +0300 Subject: [PATCH 04/89] Tests: Better time regex and placeholder --- tests/utils.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/utils.py b/tests/utils.py index 6c03e74..3f7d376 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -299,11 +299,11 @@ def assert_sample_output(module): stderr=True) as output_capturer: module.main() - time = '21:10:42.298924' - time_pattern = re.sub(r'\d', r'\\d', time) + placeholder_time = '00:00:00.000000' + time_pattern = '[0-9:.]{15}' def normalise(out): - out = re.sub(time_pattern, time, out).strip() + out = re.sub(time_pattern, placeholder_time, out).strip() out = re.sub( r'^( *)Source path:\.\.\. .*$', r'\1Source path:... Whatever', From bd05c1686fe5145d2a9bb271bbe72d47f5af2dfe Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Sat, 14 Sep 2019 10:41:24 +0300 Subject: [PATCH 05/89] Force time.isoformat to show microseconds every time Fix #158 --- pysnooper/pycompat.py | 16 ++++++++++++++++ pysnooper/tracer.py | 3 ++- 2 files changed, 18 insertions(+), 1 deletion(-) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index ce7566e..5b9a481 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -6,6 +6,7 @@ import abc import os import inspect import sys +import datetime as datetime_module PY3 = (sys.version_info[0] == 3) PY2 = not PY3 @@ -64,3 +65,18 @@ try: from collections import abc as collections_abc except ImportError: # Python 2.7 import collections as collections_abc + +if sys.version_info[:2] >= (3, 6): + time_isoformat = datetime_module.time.isoformat +else: + def time_isoformat(time, timespec='microseconds'): + assert isinstance(time, datetime_module.time) + if timespec != 'microseconds': + raise NotImplementedError + result = '{:02d}:{:02d}:{:02d}.{:06d}'.format( + time.hour, time.minute, time.second, time.microsecond + ) + assert len(result) == 15 + return result + + diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index b1b1a16..c62da1b 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -346,7 +346,8 @@ class Tracer: # # ### Finished checking whether we should trace this line. ############## - now_string = datetime_module.datetime.now().time().isoformat() + now = datetime_module.datetime.now().time() + now_string = pycompat.time_isoformat(now, timespec='microseconds') line_no = frame.f_lineno source_path, source = get_path_and_source_from_frame(frame) if self.last_source_path != source_path: From e3e09d31b5b429016f1c42001091ac6aff2855b5 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Sat, 14 Sep 2019 13:35:18 +0300 Subject: [PATCH 06/89] Add test for decorating when DISABLED = True Fix #154 --- tests/test_pysnooper.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index ade570c..22e5e4c 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -1233,8 +1233,12 @@ def test_disable(): return x + y with mini_toolbox.TempValueSetter((pysnooper.tracer, 'DISABLED'), True): - with pysnooper.snoop(string_io): + tracer = pysnooper.snoop(string_io) + with tracer: result = my_function('baba') + my_decorated_function = tracer(my_function) + my_decorated_function('booboo') + output = string_io.getvalue() assert not output From e5fe6986dd97964da442f304f159d08ad8bb4b8e Mon Sep 17 00:00:00 2001 From: Guoqiang Ding Date: Fri, 23 Aug 2019 16:45:16 +0800 Subject: [PATCH 07/89] Add truncate option support --- pysnooper/tracer.py | 23 ++++++++++++++++++----- pysnooper/utils.py | 8 +++----- tests/test_pysnooper.py | 4 ++-- 3 files changed, 23 insertions(+), 12 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index c62da1b..f64f749 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -22,11 +22,13 @@ if pycompat.PY2: ipython_filename_pattern = re.compile('^$') -def get_local_reprs(frame, watch=(), custom_repr=()): +def get_local_reprs(frame, watch=(), custom_repr=(), max_length=None): code = frame.f_code vars_order = code.co_varnames + code.co_cellvars + code.co_freevars + tuple(frame.f_locals.keys()) - result_items = [(key, utils.get_shortish_repr(value, custom_repr=custom_repr)) for key, value in frame.f_locals.items()] + result_items = [(key, utils.get_shortish_repr(value, custom_repr, + max_length)) + for key, value in frame.f_locals.items()] result_items.sort(key=lambda key_value: vars_order.index(key_value[0])) result = collections.OrderedDict(result_items) @@ -187,6 +189,10 @@ class Tracer: @pysnooper.snoop(custom_repr=((type1, custom_repr_func1), (condition2, custom_repr_func2), ...)) + Customize the length of truncated result:: + + @pysnooper.snoop(max_variable_length=100) + ''' def __init__( self, @@ -198,6 +204,7 @@ class Tracer: overwrite=False, thread_info=False, custom_repr=(), + max_variable_length=None, ): self._write = get_write_function(output, overwrite) @@ -222,6 +229,7 @@ class Tracer: custom_repr = (custom_repr,) self.custom_repr = custom_repr self.last_source_path = None + self.max_variable_length = max_variable_length def __call__(self, function_or_class): if DISABLED: @@ -366,7 +374,9 @@ class Tracer: # # old_local_reprs = self.frame_to_local_reprs.get(frame, {}) self.frame_to_local_reprs[frame] = local_reprs = \ - get_local_reprs(frame, watch=self.watch, custom_repr=self.custom_repr) + get_local_reprs(frame, + watch=self.watch, custom_repr=self.custom_repr, + max_length=self.max_variable_length) newish_string = ('Starting var:.. ' if event == 'call' else 'New var:....... ') @@ -429,13 +439,16 @@ class Tracer: thread_global.depth -= 1 if not ended_by_exception: - return_value_repr = utils.get_shortish_repr(arg, custom_repr=self.custom_repr) + return_value_repr = utils.get_shortish_repr(arg, + custom_repr=self.custom_repr, + max_length=self.max_variable_length) self.write('{indent}Return value:.. {return_value_repr}'. format(**locals())) if event == 'exception': exception = '\n'.join(traceback.format_exception_only(*arg[:2])).strip() - exception = utils.truncate(exception, utils.MAX_EXCEPTION_LENGTH) + if self.max_variable_length: + exception = utils.truncate(exception, self.max_variable_length) self.write('{indent}{exception}'. format(**locals())) diff --git a/pysnooper/utils.py b/pysnooper/utils.py index b569698..a675a09 100644 --- a/pysnooper/utils.py +++ b/pysnooper/utils.py @@ -6,9 +6,6 @@ import abc import sys from .pycompat import ABC, string_types, collections_abc -MAX_VARIABLE_LENGTH = 100 -MAX_EXCEPTION_LENGTH = 200 - def _check_methods(C, *methods): mro = C.__mro__ for method in methods: @@ -58,14 +55,15 @@ def get_repr_function(item, custom_repr): return repr -def get_shortish_repr(item, custom_repr=()): +def get_shortish_repr(item, custom_repr=(), max_length=None): repr_function = get_repr_function(item, custom_repr) try: r = repr_function(item) except Exception: r = 'REPR FAILED' r = r.replace('\r', '').replace('\n', '') - r = truncate(r, MAX_VARIABLE_LENGTH) + if max_length: + r = truncate(r, max_length) return r diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 22e5e4c..9f190d1 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -385,8 +385,8 @@ def test_single_watch_no_comma(): ) -def test_long_variable(): - @pysnooper.snoop() +def test_long_variable_with_truncate(): + @pysnooper.snoop(max_variable_length=100) def my_function(): foo = list(range(1000)) return foo From 32c86da200f8b61933fa5a3c790e75c4ede42604 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Sun, 15 Sep 2019 21:51:14 +0300 Subject: [PATCH 08/89] Massaging some code --- README.md | 10 +++++++ misc/generate_authors.py | 1 - pysnooper/tracer.py | 28 ++++++++----------- pysnooper/utils.py | 7 +++-- tests/test_pysnooper.py | 60 ++++++++++++++++++++++++++++++++++++++-- 5 files changed, 83 insertions(+), 23 deletions(-) diff --git a/README.md b/README.md index 6112552..ac82704 100644 --- a/README.md +++ b/README.md @@ -178,6 +178,16 @@ sum_to_x(10000) You will get `l = list(size=10000)` for the list, and `a = ndarray(shape=(10, 10), dtype=float64)` for the ndarray. The `custom_repr` are matched in order, if one condition matches, no further conditions will be checked. +Variables and exceptions get truncated to 100 characters by default. You +can customize that: + +```python + @pysnooper.snoop(max_variable_length=200) +``` + +You can also use `max_variable_length=None` to never truncate them. + + # Installation # You can install **PySnooper** by: diff --git a/misc/generate_authors.py b/misc/generate_authors.py index 582e077..5836dd7 100644 --- a/misc/generate_authors.py +++ b/misc/generate_authors.py @@ -54,5 +54,4 @@ if __name__ == '__main__': branch = sys.argv[1] except IndexError: branch = 'master' - print_authors(branch) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index f64f749..3ea6580 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -24,7 +24,8 @@ ipython_filename_pattern = re.compile('^$') def get_local_reprs(frame, watch=(), custom_repr=(), max_length=None): code = frame.f_code - vars_order = code.co_varnames + code.co_cellvars + code.co_freevars + tuple(frame.f_locals.keys()) + vars_order = (code.co_varnames + code.co_cellvars + code.co_freevars + + tuple(frame.f_locals.keys())) result_items = [(key, utils.get_shortish_repr(value, custom_repr, max_length)) @@ -187,25 +188,20 @@ class Tracer: Customize how values are represented as strings:: - @pysnooper.snoop(custom_repr=((type1, custom_repr_func1), (condition2, custom_repr_func2), ...)) + @pysnooper.snoop(custom_repr=((type1, custom_repr_func1), + (condition2, custom_repr_func2), ...)) - Customize the length of truncated result:: + Variables and exceptions get truncated to 100 characters by default. You + can customize that: - @pysnooper.snoop(max_variable_length=100) + @pysnooper.snoop(max_variable_length=200) + + You can also use `max_variable_length=None` to never truncate them. ''' - def __init__( - self, - output=None, - watch=(), - watch_explode=(), - depth=1, - prefix='', - overwrite=False, - thread_info=False, - custom_repr=(), - max_variable_length=None, - ): + def __init__(self, output=None, watch=(), watch_explode=(), depth=1, + prefix='', overwrite=False, thread_info=False, custom_repr=(), + max_variable_length=100): self._write = get_write_function(output, overwrite) self.watch = [ diff --git a/pysnooper/utils.py b/pysnooper/utils.py index a675a09..15dbc3b 100644 --- a/pysnooper/utils.py +++ b/pysnooper/utils.py @@ -68,11 +68,12 @@ def get_shortish_repr(item, custom_repr=(), max_length=None): def truncate(string, max_length): - if len(string) > max_length: + if (max_length is None) or (len(string) <= max_length): + return string + else: left = (max_length - 3) // 2 right = max_length - 3 - left - string = u'{}...{}'.format(string[:left], string[-right:]) - return string + return u'{}...{}'.format(string[:left], string[-right:]) def ensure_tuple(x): diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 9f190d1..500c959 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -385,8 +385,8 @@ def test_single_watch_no_comma(): ) -def test_long_variable_with_truncate(): - @pysnooper.snoop(max_variable_length=100) +def test_long_variable(): + @pysnooper.snoop() def my_function(): foo = list(range(1000)) return foo @@ -396,7 +396,7 @@ def test_long_variable_with_truncate(): result = my_function() assert result == list(range(1000)) output = output_capturer.string_io.getvalue() - regex = r'^\[0, 1, 2, .*\.\.\..*, 997, 998, 999\]$' + regex = r'^(?=.{100}$)\[0, 1, 2, .*\.\.\..*, 997, 998, 999\]$' assert_output( output, ( @@ -411,6 +411,60 @@ def test_long_variable_with_truncate(): ) + +def test_long_variable_with_custom_max_variable_length(): + @pysnooper.snoop(max_variable_length=200) + def my_function(): + foo = list(range(1000)) + return foo + + with mini_toolbox.OutputCapturer(stdout=False, + stderr=True) as output_capturer: + result = my_function() + assert result == list(range(1000)) + output = output_capturer.string_io.getvalue() + regex = r'^(?=.{200}$)\[0, 1, 2, .*\.\.\..*, 997, 998, 999\]$' + assert_output( + output, + ( + SourcePathEntry(), + CallEntry('def my_function():'), + LineEntry('foo = list(range(1000))'), + VariableEntry('foo', value_regex=regex), + LineEntry(), + ReturnEntry(), + ReturnValueEntry(value_regex=regex) + ) + ) + + +def test_long_variable_with_infinite_max_variable_length(): + @pysnooper.snoop(max_variable_length=None) + def my_function(): + foo = list(range(1000)) + return foo + + with mini_toolbox.OutputCapturer(stdout=False, + stderr=True) as output_capturer: + result = my_function() + assert result == list(range(1000)) + output = output_capturer.string_io.getvalue() + regex = r'^(?=.{1000,100000}$)\[0, 1, 2, [^.]+ 997, 998, 999\]$' + assert_output( + output, + ( + SourcePathEntry(), + CallEntry('def my_function():'), + LineEntry('foo = list(range(1000))'), + VariableEntry('foo', value_regex=regex), + LineEntry(), + ReturnEntry(), + ReturnValueEntry(value_regex=regex) + ) + ) + + + def test_repr_exception(): class Bad(object): def __repr__(self): From dd196d1c99064021749fedae6bd4f29b13e30bfd Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Sun, 15 Sep 2019 21:52:17 +0300 Subject: [PATCH 09/89] Add Guoqiang Ding to authors --- AUTHORS | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/AUTHORS b/AUTHORS index adb2971..89d1718 100644 --- a/AUTHORS +++ b/AUTHORS @@ -18,4 +18,4 @@ Diego Volpatto Alexander Bersenev Xiang Gao pikez -Jonathan Reichelt Gjertsen +Guoqiang Ding From f782bab2af59d64acf1153bb8cc19aa30f24b636 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Sun, 15 Sep 2019 21:57:02 +0300 Subject: [PATCH 10/89] Bump version --- pysnooper/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pysnooper/__init__.py b/pysnooper/__init__.py index d590647..81c1996 100644 --- a/pysnooper/__init__.py +++ b/pysnooper/__init__.py @@ -24,7 +24,7 @@ import collections __VersionInfo = collections.namedtuple('VersionInfo', ('major', 'minor', 'micro')) -__version__ = '0.2.7' +__version__ = '0.2.8' __version_info__ = __VersionInfo(*(map(int, __version__.split('.')))) del collections, __VersionInfo # Avoid polluting the namespace From c0bf4bd0067d8d7618e40d27b2626e6f3cba4fce Mon Sep 17 00:00:00 2001 From: Guoqiang Ding Date: Sun, 15 Sep 2019 22:14:14 +0800 Subject: [PATCH 11/89] Fix unit tests on thread_info The length of thread's ident between "MainThread" and others are not always equal. So use another way to check it. --- tests/test_pysnooper.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 500c959..24b0868 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -86,6 +86,9 @@ def test_multi_thread_info(): y = 8 return y + x + def parse_call_content(line): + return line.split('{event:9} '.format(event='call'))[-1] + with mini_toolbox.OutputCapturer(stdout=False, stderr=True) as output_capturer: my_function('baba') @@ -98,11 +101,8 @@ def test_multi_thread_info(): output = output_capturer.string_io.getvalue() calls = [line for line in output.split("\n") if "call" in line] main_thread = calls[0] - assert len(main_thread) == len(calls[1]) - assert len(main_thread) == len(calls[2]) - main_thread_call_str = main_thread.find("call") - assert main_thread_call_str == calls[1].find("call") - assert main_thread_call_str == calls[2].find("call") + assert parse_call_content(main_thread) == parse_call_content(calls[1]) + assert parse_call_content(main_thread) == parse_call_content(calls[2]) thread_info_regex = '([0-9]+-{name}+[ ]+)' assert_output( output, From 0c5834196a8a305956ee15d4f4e665bbf87cd0f1 Mon Sep 17 00:00:00 2001 From: "Itamar.Raviv" Date: Tue, 19 Nov 2019 18:08:54 +0200 Subject: [PATCH 12/89] Add normalize flag to remove machine-specific data This allows for diffing between multiple PySnooper outputs. --- README.md | 6 + pysnooper/tracer.py | 23 ++- pysnooper/utils.py | 13 +- pysnooper/variables.py | 14 +- tests/test_pysnooper.py | 328 ++++++++++++++++++++++++++++------------ tests/utils.py | 29 +++- 6 files changed, 301 insertions(+), 112 deletions(-) diff --git a/README.md b/README.md index ac82704..d5fb417 100644 --- a/README.md +++ b/README.md @@ -144,6 +144,12 @@ Start all snoop lines with a prefix, to grep for them easily: @pysnooper.snoop(prefix='ZZZ ') ``` +Remove all machine-related data (paths, timestamps, memory addresses) to compare with other traces easily: + +```python +@pysnooper.snoop(normalize=True) +``` + On multi-threaded apps identify which thread are snooped in output: ```python diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 3ea6580..be177bf 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -22,19 +22,19 @@ if pycompat.PY2: ipython_filename_pattern = re.compile('^$') -def get_local_reprs(frame, watch=(), custom_repr=(), max_length=None): +def get_local_reprs(frame, watch=(), custom_repr=(), max_length=None, normalize=False): code = frame.f_code vars_order = (code.co_varnames + code.co_cellvars + code.co_freevars + tuple(frame.f_locals.keys())) result_items = [(key, utils.get_shortish_repr(value, custom_repr, - max_length)) + max_length, normalize)) for key, value in frame.f_locals.items()] result_items.sort(key=lambda key_value: vars_order.index(key_value[0])) result = collections.OrderedDict(result_items) for variable in watch: - result.update(sorted(variable.items(frame))) + result.update(sorted(variable.items(frame, normalize))) return result @@ -201,7 +201,7 @@ class Tracer: ''' def __init__(self, output=None, watch=(), watch_explode=(), depth=1, prefix='', overwrite=False, thread_info=False, custom_repr=(), - max_variable_length=100): + max_variable_length=100, normalize=False): self._write = get_write_function(output, overwrite) self.watch = [ @@ -226,6 +226,7 @@ class Tracer: self.custom_repr = custom_repr self.last_source_path = None self.max_variable_length = max_variable_length + self.normalize = normalize def __call__(self, function_or_class): if DISABLED: @@ -351,9 +352,10 @@ class Tracer: ### Finished checking whether we should trace this line. ############## now = datetime_module.datetime.now().time() - now_string = pycompat.time_isoformat(now, timespec='microseconds') + now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 line_no = frame.f_lineno source_path, source = get_path_and_source_from_frame(frame) + source_path = source_path if not self.normalize else os.path.basename(source_path) if self.last_source_path != source_path: self.write(u'{indent}Source path:... {source_path}'. format(**locals())) @@ -361,6 +363,9 @@ class Tracer: source_line = source[line_no - 1] thread_info = "" if self.thread_info: + if self.normalize: + raise NotImplementedError("normalize is not supported with " + "thread_info") current_thread = threading.current_thread() thread_info = "{ident}-{name} ".format( ident=current_thread.ident, name=current_thread.getName()) @@ -372,7 +377,9 @@ class Tracer: self.frame_to_local_reprs[frame] = local_reprs = \ get_local_reprs(frame, watch=self.watch, custom_repr=self.custom_repr, - max_length=self.max_variable_length) + max_length=self.max_variable_length, + normalize=self.normalize, + ) newish_string = ('Starting var:.. ' if event == 'call' else 'New var:....... ') @@ -437,7 +444,9 @@ class Tracer: if not ended_by_exception: return_value_repr = utils.get_shortish_repr(arg, custom_repr=self.custom_repr, - max_length=self.max_variable_length) + max_length=self.max_variable_length, + normalize=self.normalize, + ) self.write('{indent}Return value:.. {return_value_repr}'. format(**locals())) diff --git a/pysnooper/utils.py b/pysnooper/utils.py index 15dbc3b..ff9b9e8 100644 --- a/pysnooper/utils.py +++ b/pysnooper/utils.py @@ -2,6 +2,7 @@ # This program is distributed under the MIT license. import abc +import re import sys from .pycompat import ABC, string_types, collections_abc @@ -55,13 +56,23 @@ def get_repr_function(item, custom_repr): return repr -def get_shortish_repr(item, custom_repr=(), max_length=None): +DEFAULT_REPR_RE = re.compile(r' at 0x[a-f0-9A-F]{4,}') + + +def normalize_repr(item_repr): + """Remove memory address (0x...) from a default python repr""" + return DEFAULT_REPR_RE.sub('', item_repr) + + +def get_shortish_repr(item, custom_repr=(), max_length=None, normalize=False): repr_function = get_repr_function(item, custom_repr) try: r = repr_function(item) except Exception: r = 'REPR FAILED' r = r.replace('\r', '').replace('\n', '') + if normalize: + r = normalize_repr(r) if max_length: r = truncate(r, max_length) return r diff --git a/pysnooper/variables.py b/pysnooper/variables.py index fe0176a..2229c38 100644 --- a/pysnooper/variables.py +++ b/pysnooper/variables.py @@ -27,15 +27,15 @@ class BaseVariable(pycompat.ABC): else: self.unambiguous_source = source - def items(self, frame): + def items(self, frame, normalize=False): try: main_value = eval(self.code, frame.f_globals or {}, frame.f_locals) except Exception: return () - return self._items(main_value) + return self._items(main_value, normalize) @abc.abstractmethod - def _items(self, key): + def _items(self, key, normalize=False): raise NotImplementedError @property @@ -51,8 +51,8 @@ class BaseVariable(pycompat.ABC): class CommonVariable(BaseVariable): - def _items(self, main_value): - result = [(self.source, utils.get_shortish_repr(main_value))] + def _items(self, main_value, normalize=False): + result = [(self.source, utils.get_shortish_repr(main_value, normalize=normalize))] for key in self._safe_keys(main_value): try: if key in self.exclude: @@ -122,7 +122,7 @@ class Indices(Keys): class Exploding(BaseVariable): - def _items(self, main_value): + def _items(self, main_value, normalize=False): if isinstance(main_value, Mapping): cls = Keys elif isinstance(main_value, Sequence): @@ -130,4 +130,4 @@ class Exploding(BaseVariable): else: cls = Attrs - return cls(self.source, self.exclude)._items(main_value) + return cls(self.source, self.exclude)._items(main_value, normalize) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 24b0868..44852f4 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -159,13 +159,14 @@ def test_multi_thread_info(): ) -def test_callable(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_callable(normalize): string_io = io.StringIO() def write(msg): string_io.write(msg) - @pysnooper.snoop(write) + @pysnooper.snoop(write, normalize=normalize) def my_function(foo): x = 7 y = 8 @@ -187,13 +188,13 @@ def test_callable(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), - ) + ), + normalize=normalize, ) - -def test_watch(): - +@pytest.mark.parametrize("normalize", (True, False)) +def test_watch(normalize): class Foo(object): def __init__(self): self.x = 2 @@ -205,7 +206,7 @@ def test_watch(): 'foo.x', 'io.__name__', 'len(foo.__dict__["x"] * "abc")', - )) + ), normalize=normalize) def my_function(): foo = Foo() for i in range(2): @@ -240,18 +241,19 @@ def test_watch(): LineEntry(), ReturnEntry(), ReturnValueEntry('None') - ) + ), + normalize=normalize, ) -def test_watch_explode(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_watch_explode(normalize): class Foo: def __init__(self, x, y): self.x = x self.y = y - - @pysnooper.snoop(watch_explode=('_d', '_point', 'lst + []')) + @pysnooper.snoop(watch_explode=('_d', '_point', 'lst + []'), normalize=normalize) def my_function(): _d = {'a': 1, 'b': 2, 'c': 'ignore'} _point = Foo(x=3, y=4) @@ -290,11 +292,13 @@ def test_watch_explode(): VariableEntry('lst + []'), ReturnEntry(), ReturnValueEntry('None') - ) + ), + normalize=normalize, ) -def test_variables_classes(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_variables_classes(normalize): class WithSlots(object): __slots__ = ('x', 'y') @@ -307,7 +311,7 @@ def test_variables_classes(): pysnooper.Attrs('_d'), # doesn't have attributes pysnooper.Attrs('_s'), pysnooper.Indices('_lst')[-3:], - )) + ), normalize=normalize) def my_function(): _d = {'a': 1, 'b': 2, 'c': 'ignore'} _s = WithSlots() @@ -339,13 +343,13 @@ def test_variables_classes(): VariableEntry('_lst[999]', '999'), ReturnEntry(), ReturnValueEntry('None') - ) + ), + normalize=normalize, ) - -def test_single_watch_no_comma(): - +@pytest.mark.parametrize("normalize", (True, False)) +def test_single_watch_no_comma(normalize): class Foo(object): def __init__(self): self.x = 2 @@ -353,7 +357,7 @@ def test_single_watch_no_comma(): def square(self): self.x **= 2 - @pysnooper.snoop(watch='foo') + @pysnooper.snoop(watch='foo', normalize=normalize) def my_function(): foo = Foo() for i in range(2): @@ -381,12 +385,14 @@ def test_single_watch_no_comma(): LineEntry(), ReturnEntry(), ReturnValueEntry('None') - ) + ), + normalize=normalize, ) -def test_long_variable(): - @pysnooper.snoop() +@pytest.mark.parametrize("normalize", (True, False)) +def test_long_variable(normalize): + @pysnooper.snoop(normalize=normalize) def my_function(): foo = list(range(1000)) return foo @@ -407,13 +413,14 @@ def test_long_variable(): LineEntry(), ReturnEntry(), ReturnValueEntry(value_regex=regex) - ) + ), + normalize=normalize, ) - -def test_long_variable_with_custom_max_variable_length(): - @pysnooper.snoop(max_variable_length=200) +@pytest.mark.parametrize("normalize", (True, False)) +def test_long_variable_with_custom_max_variable_length(normalize): + @pysnooper.snoop(max_variable_length=200, normalize=normalize) def my_function(): foo = list(range(1000)) return foo @@ -434,12 +441,14 @@ def test_long_variable_with_custom_max_variable_length(): LineEntry(), ReturnEntry(), ReturnValueEntry(value_regex=regex) - ) + ), + normalize=normalize, ) -def test_long_variable_with_infinite_max_variable_length(): - @pysnooper.snoop(max_variable_length=None) +@pytest.mark.parametrize("normalize", (True, False)) +def test_long_variable_with_infinite_max_variable_length(normalize): + @pysnooper.snoop(max_variable_length=None, normalize=normalize) def my_function(): foo = list(range(1000)) return foo @@ -460,17 +469,18 @@ def test_long_variable_with_infinite_max_variable_length(): LineEntry(), ReturnEntry(), ReturnValueEntry(value_regex=regex) - ) + ), + normalize=normalize, ) - -def test_repr_exception(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_repr_exception(normalize): class Bad(object): def __repr__(self): 1 / 0 - @pysnooper.snoop() + @pysnooper.snoop(normalize=normalize) def my_function(): bad = Bad() @@ -489,11 +499,13 @@ def test_repr_exception(): VariableEntry('bad', value='REPR FAILED'), ReturnEntry(), ReturnValueEntry('None') - ) + ), + normalize=normalize, ) -def test_depth(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_depth(normalize): string_io = io.StringIO() def f4(x4): @@ -508,7 +520,7 @@ def test_depth(): result2 = f3(x2) return result2 - @pysnooper.snoop(string_io, depth=3) + @pysnooper.snoop(string_io, depth=3, normalize=normalize) def f1(x1): result1 = f2(x1) return result1 @@ -549,16 +561,18 @@ def test_depth(): LineEntry(), ReturnEntry(), ReturnValueEntry('20'), - ) + ), + normalize=normalize, ) -def test_method_and_prefix(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_method_and_prefix(normalize): class Baz(object): def __init__(self): self.x = 2 - @pysnooper.snoop(watch=('self.x',), prefix='ZZZ') + @pysnooper.snoop(watch=('self.x',), prefix='ZZZ', normalize=normalize) def square(self): foo = 7 self.x **= 2 @@ -587,15 +601,17 @@ def test_method_and_prefix(): ReturnEntry(prefix='ZZZ'), ReturnValueEntry(prefix='ZZZ'), ), - prefix='ZZZ' + prefix='ZZZ', + normalize=normalize, ) -def test_file_output(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_file_output(normalize): with mini_toolbox.create_temp_folder(prefix='pysnooper') as folder: path = folder / 'foo.log' - @pysnooper.snoop(path) + @pysnooper.snoop(path, normalize=normalize) def my_function(_foo): x = 7 y = 8 @@ -618,18 +634,20 @@ def test_file_output(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), - ) + ), + normalize=normalize, ) -def test_confusing_decorator_lines(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_confusing_decorator_lines(normalize): string_io = io.StringIO() def empty_decorator(function): return function @empty_decorator - @pysnooper.snoop(string_io, + @pysnooper.snoop(string_io, normalize=normalize, depth=2) # Multi-line decorator for extra confusion! @empty_decorator @empty_decorator @@ -661,13 +679,15 @@ def test_confusing_decorator_lines(): # back in my_function ReturnEntry(), ReturnValueEntry('15'), - ) + ), + normalize=normalize, ) -def test_lambda(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_lambda(normalize): string_io = io.StringIO() - my_function = pysnooper.snoop(string_io)(lambda x: x ** 2) + my_function = pysnooper.snoop(string_io, normalize=normalize)(lambda x: x ** 2) result = my_function(7) assert result == 49 output = string_io.getvalue() @@ -680,7 +700,8 @@ def test_lambda(): LineEntry(source_regex='^my_function = pysnooper.*'), ReturnEntry(source_regex='^my_function = pysnooper.*'), ReturnValueEntry('49'), - ) + ), + normalize=normalize, ) @@ -820,9 +841,10 @@ def test_needs_parentheses(): assert needs_parentheses('x if z else y') -def test_with_block(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_with_block(normalize): # Testing that a single Tracer can handle many mixed uses - snoop = pysnooper.snoop() + snoop = pysnooper.snoop(normalize=normalize) def foo(x): if x == 0: @@ -940,10 +962,12 @@ def test_with_block(): ReturnEntry('qux()'), ReturnValueEntry('None'), ), + normalize=normalize, ) -def test_with_block_depth(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_with_block_depth(normalize): string_io = io.StringIO() def f4(x4): @@ -960,7 +984,7 @@ def test_with_block_depth(): def f1(x1): str(3) - with pysnooper.snoop(string_io, depth=3): + with pysnooper.snoop(string_io, depth=3, normalize=normalize): result1 = f2(x1) return result1 @@ -974,6 +998,7 @@ def test_with_block_depth(): VariableEntry(), VariableEntry(), VariableEntry(), + VariableEntry(), LineEntry('result1 = f2(x1)'), VariableEntry(), @@ -995,10 +1020,13 @@ def test_with_block_depth(): LineEntry(), ReturnEntry(), ReturnValueEntry('20'), - ) + ), + normalize=normalize, ) -def test_cellvars(): + +@pytest.mark.parametrize("normalize", (True, False)) +def test_cellvars(normalize): string_io = io.StringIO() def f2(a): @@ -1012,7 +1040,7 @@ def test_cellvars(): return f3(a) def f1(a): - with pysnooper.snoop(string_io, depth=4): + with pysnooper.snoop(string_io, depth=4, normalize=normalize): result1 = f2(a) return result1 @@ -1026,6 +1054,7 @@ def test_cellvars(): VariableEntry(), VariableEntry(), VariableEntry(), + VariableEntry(), LineEntry('result1 = f2(a)'), VariableEntry(), @@ -1057,10 +1086,13 @@ def test_cellvars(): ReturnValueEntry(), ReturnEntry(), ReturnValueEntry(), - ) + ), + normalize=normalize, ) -def test_var_order(): + +@pytest.mark.parametrize("normalize", (True, False)) +def test_var_order(normalize): string_io = io.StringIO() def f(one, two, three, four): @@ -1070,7 +1102,7 @@ def test_var_order(): five, six, seven = 5, 6, 7 - with pysnooper.snoop(string_io, depth=2): + with pysnooper.snoop(string_io, depth=2, normalize=normalize): result = f(1, 2, 3, 4) output = string_io.getvalue() @@ -1080,6 +1112,7 @@ def test_var_order(): SourcePathEntry(), VariableEntry(), VariableEntry(), + VariableEntry(), LineEntry('result = f(1, 2, 3, 4)'), VariableEntry("one", "1"), @@ -1100,7 +1133,8 @@ def test_var_order(): VariableEntry("seven", "7"), ReturnEntry(), ReturnValueEntry(), - ) + ), + normalize=normalize, ) @@ -1209,7 +1243,8 @@ def test_generator(): ) -def test_custom_repr(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_custom_repr(normalize): string_io = io.StringIO() def large(l): @@ -1227,7 +1262,8 @@ def test_custom_repr(): @pysnooper.snoop(string_io, custom_repr=( (large, print_list_size), (dict, print_dict), - (evil_condition, lambda x: 'I am evil'))) + (evil_condition, lambda x: 'I am evil')), + normalize=normalize,) def sum_to_x(x): l = list(range(x)) a = {'1': 1, '2': 2} @@ -1249,13 +1285,16 @@ def test_custom_repr(): LineEntry(), ReturnEntry(), ReturnValueEntry('49995000'), - ) + ), + normalize=normalize, ) -def test_custom_repr_single(): + +@pytest.mark.parametrize("normalize", (True, False)) +def test_custom_repr_single(normalize): string_io = io.StringIO() - @pysnooper.snoop(string_io, custom_repr=(list, lambda l: 'foofoo!')) + @pysnooper.snoop(string_io, custom_repr=(list, lambda l: 'foofoo!'), normalize=normalize) def sum_to_x(x): l = list(range(x)) return 7 @@ -1274,7 +1313,8 @@ def test_custom_repr_single(): LineEntry(), ReturnEntry(), ReturnValueEntry('7'), - ) + ), + normalize=normalize, ) @@ -1297,10 +1337,11 @@ def test_disable(): assert not output -def test_class(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_class(normalize): string_io = io.StringIO() - @pysnooper.snoop(string_io) + @pysnooper.snoop(string_io, normalize=normalize) class MyClass(object): def __init__(self): self.x = 7 @@ -1317,12 +1358,12 @@ def test_class(): output, ( SourcePathEntry(), - VariableEntry('self', value_regex="u?.+MyClass object at"), + VariableEntry('self', value_regex="u?.+MyClass object"), CallEntry('def __init__(self):'), LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), - VariableEntry('self', value_regex="u?.+MyClass object at"), + VariableEntry('self', value_regex="u?.+MyClass object"), VariableEntry('foo', value_regex="u?'baba'"), CallEntry('def my_method(self, foo):'), LineEntry('y = 8'), @@ -1330,10 +1371,13 @@ def test_class(): LineEntry('return y + self.x'), ReturnEntry('return y + self.x'), ReturnValueEntry('15'), - ) + ), + normalize=normalize, ) -def test_class_with_decorated_method(): + +@pytest.mark.parametrize("normalize", (True, False)) +def test_class_with_decorated_method(normalize): string_io = io.StringIO() def decorator(function): @@ -1342,7 +1386,7 @@ def test_class_with_decorated_method(): return result return wrapper - @pysnooper.snoop(string_io) + @pysnooper.snoop(string_io, normalize=normalize) class MyClass(object): def __init__(self): self.x = 7 @@ -1360,25 +1404,27 @@ def test_class_with_decorated_method(): output, ( SourcePathEntry(), - VariableEntry('self', value_regex="u?.+MyClass object at"), + VariableEntry('self', value_regex="u?.+MyClass object"), CallEntry('def __init__(self):'), LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), VariableEntry('args', value_regex=r"\(<.+>, 'baba'\)"), VariableEntry('kwargs', value_regex=r"\{\}"), - VariableEntry('function', value_regex="u?.+my_method at"), + VariableEntry('function', value_regex="u?.+my_method"), CallEntry('def wrapper(*args, **kwargs):'), LineEntry('result = function(*args, **kwargs)'), VariableEntry('result', '15'), LineEntry('return result'), ReturnEntry('return result'), ReturnValueEntry('15'), - ) + ), + normalize=normalize, ) -def test_class_with_decorated_method_and_snoop_applied_to_method(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_class_with_decorated_method_and_snoop_applied_to_method(normalize): string_io = io.StringIO() def decorator(function): @@ -1387,13 +1433,13 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(): return result return wrapper - @pysnooper.snoop(string_io) + @pysnooper.snoop(string_io, normalize=normalize) class MyClass(object): def __init__(self): self.x = 7 @decorator - @pysnooper.snoop(string_io) + @pysnooper.snoop(string_io, normalize=normalize) def my_method(self, foo): y = 8 return y + self.x @@ -1406,18 +1452,18 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(): output, ( SourcePathEntry(), - VariableEntry('self', value_regex="u?.*MyClass object at"), + VariableEntry('self', value_regex="u?.*MyClass object"), CallEntry('def __init__(self):'), LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), VariableEntry('args', value_regex=r"u?\(<.+>, 'baba'\)"), VariableEntry('kwargs', value_regex=r"u?\{\}"), - VariableEntry('function', value_regex="u?.*my_method at"), + VariableEntry('function', value_regex="u?.*my_method"), CallEntry('def wrapper(*args, **kwargs):'), LineEntry('result = function(*args, **kwargs)'), SourcePathEntry(), - VariableEntry('self', value_regex="u?.*MyClass object at"), + VariableEntry('self', value_regex="u?.*MyClass object"), VariableEntry('foo', value_regex="u?'baba'"), CallEntry('def my_method(self, foo):'), LineEntry('y = 8'), @@ -1429,14 +1475,16 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(): LineEntry('return result'), ReturnEntry('return result'), ReturnValueEntry('15'), - ) + ), + normalize=normalize, ) -def test_class_with_property(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_class_with_property(normalize): string_io = io.StringIO() - @pysnooper.snoop(string_io) + @pysnooper.snoop(string_io, normalize=normalize) class MyClass(object): def __init__(self): self._x = 0 @@ -1478,37 +1526,39 @@ def test_class_with_property(): output, ( SourcePathEntry(), - VariableEntry('self', value_regex="u?.*MyClass object at"), + VariableEntry('self', value_regex="u?.*MyClass object"), CallEntry('def __init__(self):'), LineEntry('self._x = 0'), ReturnEntry('self._x = 0'), ReturnValueEntry('None'), # Called from getter - VariableEntry('self', value_regex="u?.*MyClass object at"), + VariableEntry('self', value_regex="u?.*MyClass object"), CallEntry('def plain_method(self):'), LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), # Called from setter - VariableEntry('self', value_regex="u?.*MyClass object at"), + VariableEntry('self', value_regex="u?.*MyClass object"), CallEntry('def plain_method(self):'), LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), # Called from deleter - VariableEntry('self', value_regex="u?.*MyClass object at"), + VariableEntry('self', value_regex="u?.*MyClass object"), CallEntry('def plain_method(self):'), LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), - ) + ), + normalize=normalize, ) -def test_snooping_on_class_does_not_cause_base_class_to_be_snooped(): +@pytest.mark.parametrize("normalize", (True, False)) +def test_snooping_on_class_does_not_cause_base_class_to_be_snooped(normalize): string_io = io.StringIO() class UnsnoopedBaseClass(object): @@ -1518,7 +1568,7 @@ def test_snooping_on_class_does_not_cause_base_class_to_be_snooped(): def method_on_base_class(self): self.method_on_base_class_was_called = True - @pysnooper.snoop(string_io) + @pysnooper.snoop(string_io, normalize=normalize) class MyClass(UnsnoopedBaseClass): def method_on_child_class(self): self.method_on_base_class() @@ -1534,10 +1584,100 @@ def test_snooping_on_class_does_not_cause_base_class_to_be_snooped(): output, ( SourcePathEntry(), - VariableEntry('self', value_regex="u?.*MyClass object at"), + VariableEntry('self', value_regex="u?.*MyClass object"), CallEntry('def method_on_child_class(self):'), LineEntry('self.method_on_base_class()'), ReturnEntry('self.method_on_base_class()'), ReturnValueEntry('None'), - ) + ), + normalize=normalize, ) + + +def test_normalize(): + string_io = io.StringIO() + + class A: + def __init__(self, a): + self.a = a + + @pysnooper.snoop(string_io, normalize=True) + def add(): + a = A(19) + b = A(22) + res = a.a + b.a + return res + + add() + output = string_io.getvalue() + assert_output( + output, + ( + SourcePathEntry('test_pysnooper.py'), + VariableEntry('A', value_regex=r""), + CallEntry('def add():'), + LineEntry('a = A(19)'), + VariableEntry('a', value_regex=r"<.*\.A (?:object|instance)>"), + LineEntry('b = A(22)'), + VariableEntry('b', value_regex=r"<.*\.A (?:object|instance)>"), + LineEntry('res = a.a + b.a'), + VariableEntry('res', value="41"), + LineEntry('return res'), + ReturnEntry('return res'), + ReturnValueEntry('41'), + ) + ) + + +def test_normalize_prefix(): + string_io = io.StringIO() + _prefix = 'ZZZZ' + + class A: + def __init__(self, a): + self.a = a + + @pysnooper.snoop(string_io, normalize=True, prefix=_prefix) + def add(): + a = A(19) + b = A(22) + res = a.a + b.a + return res + + add() + output = string_io.getvalue() + assert_output( + output, + ( + SourcePathEntry('test_pysnooper.py', prefix=_prefix), + VariableEntry('A', value_regex=r"", prefix=_prefix), + CallEntry('def add():', prefix=_prefix), + LineEntry('a = A(19)', prefix=_prefix), + VariableEntry('a', value_regex=r"<.*\.A (?:object|instance)>", prefix=_prefix), + LineEntry('b = A(22)', prefix=_prefix), + VariableEntry('b', value_regex=r"<.*\.A (?:object|instance)>", prefix=_prefix), + LineEntry('res = a.a + b.a', prefix=_prefix), + VariableEntry('res', value="41", prefix=_prefix), + LineEntry('return res', prefix=_prefix), + ReturnEntry('return res', prefix=_prefix), + ReturnValueEntry('41', prefix=_prefix), + ) + ) + + +def test_normalize_thread_info(): + string_io = io.StringIO() + + class A: + def __init__(self, a): + self.a = a + + @pysnooper.snoop(string_io, normalize=True, thread_info=True) + def add(): + a = A(19) + b = A(22) + res = a.a + b.a + return res + + with pytest.raises(NotImplementedError): + add() diff --git a/tests/utils.py b/tests/utils.py index 3f7d376..48e98cc 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -1,10 +1,12 @@ # Copyright 2019 Ram Rachum and collaborators. # This program is distributed under the MIT license. - +import os import re import abc import inspect +from pysnooper.utils import DEFAULT_REPR_RE + try: from itertools import zip_longest except ImportError: @@ -202,7 +204,7 @@ class _BaseEventEntry(_BaseEntry): if source is not None: assert source_regex is None self.line_pattern = re.compile( - r"""^%s(?P(?: {4})*)[0-9:.]{15} """ + r"""^%s(?P(?: {4})*)(?:(?:[0-9:.]{15})|(?: {15})) """ r"""(?P[0-9]+-[0-9A-Za-z_-]+[ ]+)?""" r"""(?P[a-z_]*) +(?P[0-9]*) """ r"""+(?P.*)$""" % (re.escape(self.prefix,)) @@ -269,7 +271,25 @@ class OutputFailure(Exception): pass -def assert_output(output, expected_entries, prefix=None): +def verify_normalize(lines, prefix): + time_re = re.compile(r"[0-9:.]{15}") + src_re = re.compile(r'^(?: *)Source path:\.\.\. (.*)$') + for line in lines: + if DEFAULT_REPR_RE.search(line): + msg = "normalize is active, memory address should not appear" + raise OutputFailure(line, msg) + no_prefix = line.replace(prefix if prefix else '', '').strip() + if time_re.match(no_prefix): + msg = "normalize is active, time should not appear" + raise OutputFailure(line, msg) + m = src_re.match(line) + if m: + if not os.path.basename(m.group(1)) == m.group(1): + msg = "normalize is active, path should be only basename" + raise OutputFailure(line, msg) + + +def assert_output(output, expected_entries, prefix=None, normalize=False): lines = tuple(filter(None, output.split('\n'))) if prefix is not None: @@ -277,6 +297,9 @@ def assert_output(output, expected_entries, prefix=None): if not line.startswith(prefix): raise OutputFailure(line) + if normalize: + verify_normalize(lines, prefix) + any_mismatch = False result = '' template = u'\n{line!s:%s} {expected_entry} {arrow}' % max(map(len, lines)) From 0af30a1ddc53828e8495fa9cbb6d90a5f70444c4 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Tue, 19 Nov 2019 18:22:44 +0200 Subject: [PATCH 13/89] Update authors --- AUTHORS | 2 ++ 1 file changed, 2 insertions(+) diff --git a/AUTHORS b/AUTHORS index 89d1718..1066728 100644 --- a/AUTHORS +++ b/AUTHORS @@ -18,4 +18,6 @@ Diego Volpatto Alexander Bersenev Xiang Gao pikez +Jonathan Reichelt Gjertsen Guoqiang Ding +Itamar.Raviv From 76b7466d4dfbcf05ed23853a8cc7243af065b205 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Tue, 19 Nov 2019 18:23:01 +0200 Subject: [PATCH 14/89] Bump version to 0.3.0 --- pysnooper/__init__.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pysnooper/__init__.py b/pysnooper/__init__.py index 81c1996..d299fa8 100644 --- a/pysnooper/__init__.py +++ b/pysnooper/__init__.py @@ -24,7 +24,7 @@ import collections __VersionInfo = collections.namedtuple('VersionInfo', ('major', 'minor', 'micro')) -__version__ = '0.2.8' +__version__ = '0.3.0' __version_info__ = __VersionInfo(*(map(int, __version__.split('.')))) del collections, __VersionInfo # Avoid polluting the namespace From 487fa5317e7f9a0f9bd9dd1abe0fd473610266f4 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Fri, 29 Nov 2019 23:55:33 +0200 Subject: [PATCH 15/89] Split readme to 2 files, fix #146 --- ADVANCED_USAGE.md | 89 +++++++++++++++++++++++++++++++++++++++++++++ README.md | 91 +---------------------------------------------- 2 files changed, 90 insertions(+), 90 deletions(-) create mode 100644 ADVANCED_USAGE.md diff --git a/ADVANCED_USAGE.md b/ADVANCED_USAGE.md new file mode 100644 index 0000000..5a95899 --- /dev/null +++ b/ADVANCED_USAGE.md @@ -0,0 +1,89 @@ +# Advanced Usage # + +Use `watch_explode` to expand values to see all their attributes or items of lists/dictionaries: + +```python +@pysnooper.snoop(watch_explode=('foo', 'self')) +``` + +`watch_explode` will automatically guess how to expand the expression passed to it based on its class. You can be more specific by using one of the following classes: + +```python +import pysnooper + +@pysnooper.snoop(watch=( + pysnooper.Attrs('x'), # attributes + pysnooper.Keys('y'), # mapping (e.g. dict) items + pysnooper.Indices('z'), # sequence (e.g. list/tuple) items +)) +``` + +Exclude specific keys/attributes/indices with the `exclude` parameter, e.g. `Attrs('x', exclude=('_foo', '_bar'))`. + +Add a slice after `Indices` to only see the values within that slice, e.g. `Indices('z')[-3:]`. + +```console +$ export PYSNOOPER_DISABLED=1 # This makes PySnooper not do any snooping +``` + +This will output lines like: + +``` +Modified var:.. foo[2] = 'whatever' +New var:....... self.baz = 8 +``` + +Start all snoop lines with a prefix, to grep for them easily: + +```python +@pysnooper.snoop(prefix='ZZZ ') +``` + +Remove all machine-related data (paths, timestamps, memory addresses) to compare with other traces easily: + +```python +@pysnooper.snoop(normalize=True) +``` + +On multi-threaded apps identify which thread are snooped in output: + +```python +@pysnooper.snoop(thread_info=True) +``` + +PySnooper supports decorating generators. + +If you decorate a class with `snoop`, it'll automatically apply the decorator to all the methods. (Not including properties and other special cases.) + +You can also customize the repr of an object: + +```python +def large(l): + return isinstance(l, list) and len(l) > 5 + +def print_list_size(l): + return 'list(size={})'.format(len(l)) + +def print_ndarray(a): + return 'ndarray(shape={}, dtype={})'.format(a.shape, a.dtype) + +@pysnooper.snoop(custom_repr=((large, print_list_size), (numpy.ndarray, print_ndarray))) +def sum_to_x(x): + l = list(range(x)) + a = numpy.zeros((10,10)) + return sum(l) + +sum_to_x(10000) +``` + +You will get `l = list(size=10000)` for the list, and `a = ndarray(shape=(10, 10), dtype=float64)` for the ndarray. +The `custom_repr` are matched in order, if one condition matches, no further conditions will be checked. + +Variables and exceptions get truncated to 100 characters by default. You +can customize that: + +```python + @pysnooper.snoop(max_variable_length=200) +``` + +You can also use `max_variable_length=None` to never truncate them. \ No newline at end of file diff --git a/README.md b/README.md index d5fb417..12686e8 100644 --- a/README.md +++ b/README.md @@ -117,81 +117,13 @@ See values of some expressions that aren't local variables: @pysnooper.snoop(watch=('foo.bar', 'self.x["whatever"]')) ``` -Expand values to see all their attributes or items of lists/dictionaries: - -```python -@pysnooper.snoop(watch_explode=('foo', 'self')) -``` - -This will output lines like: - -``` -Modified var:.. foo[2] = 'whatever' -New var:....... self.baz = 8 -``` - -(see [Advanced Usage](#advanced-usage) for more control) - Show snoop lines for functions that your function calls: ```python @pysnooper.snoop(depth=2) ``` -Start all snoop lines with a prefix, to grep for them easily: - -```python -@pysnooper.snoop(prefix='ZZZ ') -``` - -Remove all machine-related data (paths, timestamps, memory addresses) to compare with other traces easily: - -```python -@pysnooper.snoop(normalize=True) -``` - -On multi-threaded apps identify which thread are snooped in output: - -```python -@pysnooper.snoop(thread_info=True) -``` - -PySnooper supports decorating generators. - -If you decorate a class with `snoop`, it'll automatically apply the decorator to all the methods. (Not including properties and other special cases.) - -You can also customize the repr of an object: - -```python -def large(l): - return isinstance(l, list) and len(l) > 5 - -def print_list_size(l): - return 'list(size={})'.format(len(l)) - -def print_ndarray(a): - return 'ndarray(shape={}, dtype={})'.format(a.shape, a.dtype) - -@pysnooper.snoop(custom_repr=((large, print_list_size), (numpy.ndarray, print_ndarray))) -def sum_to_x(x): - l = list(range(x)) - a = numpy.zeros((10,10)) - return sum(l) - -sum_to_x(10000) -``` - -You will get `l = list(size=10000)` for the list, and `a = ndarray(shape=(10, 10), dtype=float64)` for the ndarray. -The `custom_repr` are matched in order, if one condition matches, no further conditions will be checked. - -Variables and exceptions get truncated to 100 characters by default. You -can customize that: - -```python - @pysnooper.snoop(max_variable_length=200) -``` - -You can also use `max_variable_length=None` to never truncate them. +**See [Advanced Usage](https://github.com/cool-RR/PySnooper/blob/master/ADVANCED_USAGE.md) for more options.** <------ # Installation # @@ -208,27 +140,6 @@ $ pip install pysnooper $ conda install -c conda-forge pysnooper ``` -# Advanced Usage # - -`watch_explode` will automatically guess how to expand the expression passed to it based on its class. You can be more specific by using one of the following classes: - -```python -import pysnooper - -@pysnooper.snoop(watch=( - pysnooper.Attrs('x'), # attributes - pysnooper.Keys('y'), # mapping (e.g. dict) items - pysnooper.Indices('z'), # sequence (e.g. list/tuple) items -)) -``` - -Exclude specific keys/attributes/indices with the `exclude` parameter, e.g. `Attrs('x', exclude=('_foo', '_bar'))`. - -Add a slice after `Indices` to only see the values within that slice, e.g. `Indices('z')[-3:]`. - -```console -$ export PYSNOOPER_DISABLED=1 # This makes PySnooper not do any snooping -``` # License # From 6416a11d390b8975644363a54ca9484aec244a60 Mon Sep 17 00:00:00 2001 From: iory Date: Thu, 16 Apr 2020 04:27:36 +0900 Subject: [PATCH 16/89] Add total elapsed time --- pysnooper/tracer.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index be177bf..4c51553 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -296,6 +296,7 @@ class Tracer: 'original_trace_functions', [] ) stack.append(sys.gettrace()) + self.start_time = datetime_module.datetime.now() sys.settrace(self.trace) def __exit__(self, exc_type, exc_value, exc_traceback): @@ -307,6 +308,11 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) + now = (datetime_module.datetime.min + ( + datetime_module.datetime.now() - self.start_time)).time() + now_string = pycompat.time_isoformat(now, timespec='microseconds') + self.write('Total elapsed time: {now_string}'.format(**locals())) + def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename From f822104feb84c14dbd88c1329ef43ee80f0f89ab Mon Sep 17 00:00:00 2001 From: iory Date: Thu, 16 Apr 2020 04:27:56 +0900 Subject: [PATCH 17/89] Add relative_time format --- pysnooper/tracer.py | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 4c51553..e43b5bf 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -201,7 +201,8 @@ class Tracer: ''' def __init__(self, output=None, watch=(), watch_explode=(), depth=1, prefix='', overwrite=False, thread_info=False, custom_repr=(), - max_variable_length=100, normalize=False): + max_variable_length=100, normalize=False, + relative_time=False): self._write = get_write_function(output, overwrite) self.watch = [ @@ -227,6 +228,7 @@ class Tracer: self.last_source_path = None self.max_variable_length = max_variable_length self.normalize = normalize + self.relative_time = relative_time def __call__(self, function_or_class): if DISABLED: @@ -357,7 +359,11 @@ class Tracer: # # ### Finished checking whether we should trace this line. ############## - now = datetime_module.datetime.now().time() + if self.relative_time: + now = (datetime_module.datetime.min + + (datetime_module.datetime.now() - self.start_time)).time() + else: + now = datetime_module.datetime.now().time() now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 line_no = frame.f_lineno source_path, source = get_path_and_source_from_frame(frame) From caf1e1a63a2538fee519625f9095c3ab72854dbf Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 17:01:56 +0900 Subject: [PATCH 18/89] Add timedelta_isoformat --- pysnooper/pycompat.py | 6 ++++++ pysnooper/tracer.py | 12 ++++++------ 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index 5b9a481..c6b1bf7 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -80,3 +80,9 @@ else: return result +def timedelta_isoformat(timedelta, timespec='microseconds'): + assert isinstance(timedelta, datetime_module.timedelta) + if timespec != 'microseconds': + raise NotImplementedError + time = (datetime_module.datetime.min + timedelta).time() + return time_isoformat(time, timespec) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index e43b5bf..7dbd748 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -310,9 +310,8 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - now = (datetime_module.datetime.min + ( - datetime_module.datetime.now() - self.start_time)).time() - now_string = pycompat.time_isoformat(now, timespec='microseconds') + duration = datetime_module.datetime.now() - self.start_time + now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') self.write('Total elapsed time: {now_string}'.format(**locals())) def _is_internal_frame(self, frame): @@ -360,11 +359,12 @@ class Tracer: ### Finished checking whether we should trace this line. ############## if self.relative_time: - now = (datetime_module.datetime.min + - (datetime_module.datetime.now() - self.start_time)).time() + duration = datetime_module.datetime.now() - self.start_time + now_string = pycompat.timedelta_isoformat( + duration, timespec='microseconds') if not self.normalize else ' ' * 15 else: now = datetime_module.datetime.now().time() - now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 + now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 line_no = frame.f_lineno source_path, source = get_path_and_source_from_frame(frame) source_path = source_path if not self.normalize else os.path.basename(source_path) From c39a68760d555e625fe202afdfbd4009c5a250bf Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 18:29:21 +0900 Subject: [PATCH 19/89] Add depth case --- pysnooper/tracer.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 7dbd748..c02153c 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -310,9 +310,10 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - duration = datetime_module.datetime.now() - self.start_time - now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') - self.write('Total elapsed time: {now_string}'.format(**locals())) + if thread_global.depth == -1: + duration = datetime_module.datetime.now() - self.start_time + now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') + self.write('Total elapsed time: {now_string}'.format(**locals())) def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename From 32183e0489c37518d0d4453f39a2ced14570c349 Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 18:30:43 +0900 Subject: [PATCH 20/89] Add BasePrintEntry and ElapsedPrintEntry --- tests/utils.py | 40 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/tests/utils.py b/tests/utils.py index 48e98cc..169d184 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -77,6 +77,31 @@ class _BaseValueEntry(_BaseEntry): self._check_content(content)) +class _BasePrintEntry(_BaseEntry): + def __init__(self, prefix=''): + _BaseEntry.__init__(self, prefix=prefix) + self.line_pattern = re.compile( + r"""^%s(?P(?: {4})*)(?P[^:]*):""" + r""" (?P.*)$""" % (re.escape(self.prefix),) + ) + + @abc.abstractmethod + def _check_preamble(self, preamble): + pass + + @abc.abstractmethod + def _check_content(self, preamble): + pass + + def check(self, s): + match = self.line_pattern.match(s) + if not match: + return False + _, preamble, content = match.groups() + return (self._check_preamble(preamble) and + self._check_content(content)) + + class VariableEntry(_BaseValueEntry): def __init__(self, name=None, value=None, stage=None, prefix='', name_regex=None, value_regex=None): @@ -195,6 +220,21 @@ class SourcePathEntry(_BaseValueEntry): return True +class ElapsedTimeEntry(_BasePrintEntry): + def __init__(self, prefix=''): + _BasePrintEntry.__init__(self, prefix=prefix) + + _preamble_pattern = re.compile( + r"""^Total elapsed time$""" + ) + + def _check_preamble(self, preamble): + return bool(self._preamble_pattern.match(preamble)) + + def _check_content(self, content): + return True + + class _BaseEventEntry(_BaseEntry): def __init__(self, source=None, source_regex=None, thread_info=None, thread_info_regex=None, prefix=''): From 57cec2b9af96b9234bdfdf9fe0f07a1df6bb525d Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 18:31:12 +0900 Subject: [PATCH 21/89] Fixed test for elapsed time --- tests/samples/exception.py | 1 + tests/samples/indentation.py | 1 + tests/samples/recursion.py | 1 + tests/test_chinese.py | 6 ++- tests/test_pysnooper.py | 71 +++++++++++++++++++++++++++++++----- 5 files changed, 68 insertions(+), 12 deletions(-) diff --git a/tests/samples/exception.py b/tests/samples/exception.py index aa663de..87642c8 100644 --- a/tests/samples/exception.py +++ b/tests/samples/exception.py @@ -46,4 +46,5 @@ TypeError: bad 12:18:08.018787 line 21 pass 12:18:08.018813 return 21 pass Return value:.. None +Total elapsed time: 00:00:00.000885 ''' diff --git a/tests/samples/indentation.py b/tests/samples/indentation.py index 9ea0318..65cb7b4 100644 --- a/tests/samples/indentation.py +++ b/tests/samples/indentation.py @@ -42,4 +42,5 @@ Source path:... Whatever Return value:.. None 21:10:42.299627 return 6 f2() Return value:.. None +Total elapsed time: 00:00:00.000885 ''' diff --git a/tests/samples/recursion.py b/tests/samples/recursion.py index 1570d1a..7edbaac 100644 --- a/tests/samples/recursion.py +++ b/tests/samples/recursion.py @@ -59,4 +59,5 @@ Starting var:.. x = 4 Return value:.. 24 20:28:17.876646 return 8 return mul(x, factorial(x - 1)) Return value:.. 24 +Total elapsed time: 00:00:00.000651 ''' diff --git a/tests/test_chinese.py b/tests/test_chinese.py index 828ad1c..90e52aa 100644 --- a/tests/test_chinese.py +++ b/tests/test_chinese.py @@ -16,7 +16,8 @@ from pysnooper import pycompat from pysnooper.variables import needs_parentheses from .utils import (assert_output, assert_sample_output, VariableEntry, CallEntry, LineEntry, ReturnEntry, OpcodeEntry, - ReturnValueEntry, ExceptionEntry, SourcePathEntry) + ReturnValueEntry, ExceptionEntry, SourcePathEntry, + ElapsedTimeEntry) from . import mini_toolbox @@ -44,6 +45,7 @@ def test_chinese(): VariableEntry(u'x', (u"'失败'" if pycompat.PY3 else None)), LineEntry(), ReturnEntry(), - ReturnValueEntry('7') + ReturnValueEntry('7'), + ElapsedTimeEntry(), ), ) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 44852f4..b321d95 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -15,7 +15,8 @@ import pysnooper from pysnooper.variables import needs_parentheses from .utils import (assert_output, assert_sample_output, VariableEntry, CallEntry, LineEntry, ReturnEntry, OpcodeEntry, - ReturnValueEntry, ExceptionEntry, SourcePathEntry) + ReturnValueEntry, ExceptionEntry, SourcePathEntry, + ElapsedTimeEntry) from . import mini_toolbox @@ -44,6 +45,7 @@ def test_string_io(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -74,6 +76,7 @@ def test_thread_info(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -125,6 +128,7 @@ def test_multi_thread_info(): name="MainThread")), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), VariableEntry('foo', value_regex="u?'bubu'"), CallEntry('def my_function(foo):', thread_info_regex=thread_info_regex.format( @@ -142,6 +146,7 @@ def test_multi_thread_info(): name="test123")), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), VariableEntry('foo', value_regex="u?'bibi'"), CallEntry('def my_function(foo):', thread_info_regex=thread_info_regex.format(name='bibi')), @@ -155,6 +160,7 @@ def test_multi_thread_info(): thread_info_regex=thread_info_regex.format(name='bibi')), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -188,6 +194,7 @@ def test_callable(normalize): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -240,7 +247,8 @@ def test_watch(normalize): VariableEntry('len(foo.__dict__["x"] * "abc")', '48'), LineEntry(), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -291,7 +299,8 @@ def test_watch_explode(normalize): VariableEntry('(lst + [])[3]', '10'), VariableEntry('lst + []'), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -342,7 +351,8 @@ def test_variables_classes(normalize): VariableEntry('_lst[998]', '998'), VariableEntry('_lst[999]', '999'), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -384,7 +394,8 @@ def test_single_watch_no_comma(normalize): LineEntry(), LineEntry(), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -412,7 +423,8 @@ def test_long_variable(normalize): VariableEntry('foo', value_regex=regex), LineEntry(), ReturnEntry(), - ReturnValueEntry(value_regex=regex) + ReturnValueEntry(value_regex=regex), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -440,7 +452,8 @@ def test_long_variable_with_custom_max_variable_length(normalize): VariableEntry('foo', value_regex=regex), LineEntry(), ReturnEntry(), - ReturnValueEntry(value_regex=regex) + ReturnValueEntry(value_regex=regex), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -468,7 +481,8 @@ def test_long_variable_with_infinite_max_variable_length(normalize): VariableEntry('foo', value_regex=regex), LineEntry(), ReturnEntry(), - ReturnValueEntry(value_regex=regex) + ReturnValueEntry(value_regex=regex), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -498,7 +512,8 @@ def test_repr_exception(normalize): LineEntry('bad = Bad()'), VariableEntry('bad', value='REPR FAILED'), ReturnEntry(), - ReturnValueEntry('None') + ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -561,6 +576,7 @@ def test_depth(normalize): LineEntry(), ReturnEntry(), ReturnValueEntry('20'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -600,6 +616,7 @@ def test_method_and_prefix(normalize): LineEntry(prefix='ZZZ'), ReturnEntry(prefix='ZZZ'), ReturnValueEntry(prefix='ZZZ'), + ElapsedTimeEntry(prefix='ZZZ'), ), prefix='ZZZ', normalize=normalize, @@ -634,6 +651,7 @@ def test_file_output(normalize): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -679,6 +697,7 @@ def test_confusing_decorator_lines(normalize): # back in my_function ReturnEntry(), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -700,6 +719,7 @@ def test_lambda(normalize): LineEntry(source_regex='^my_function = pysnooper.*'), ReturnEntry(source_regex='^my_function = pysnooper.*'), ReturnValueEntry('49'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -734,6 +754,7 @@ def test_unavailable_source(): LineEntry('SOURCE IS UNAVAILABLE'), ReturnEntry('SOURCE IS UNAVAILABLE'), ReturnValueEntry('7'), + ElapsedTimeEntry(), ) ) @@ -767,6 +788,7 @@ def test_no_overwrite_by_default(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -800,6 +822,7 @@ def test_overwrite(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), VariableEntry('foo', value_regex="u?'baba'"), CallEntry('def my_function(foo):'), @@ -810,6 +833,7 @@ def test_overwrite(): LineEntry('return y + x'), ReturnEntry('return y + x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ) ) @@ -914,6 +938,7 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # In with in recursive call LineEntry('bar2(x)'), @@ -925,9 +950,11 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # In with in recursive call LineEntry('qux()'), + ElapsedTimeEntry(), # Call to bar3 from after with VariableEntry('_x', '9'), @@ -936,6 +963,7 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # -- Similar to previous few sections, # -- but from first call to foo @@ -950,9 +978,11 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # In with in first call LineEntry('qux()'), + ElapsedTimeEntry(), # Call to bar3 from after with VariableEntry('_x', '9'), @@ -961,6 +991,7 @@ def test_with_block(normalize): LineEntry('qux()'), ReturnEntry('qux()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1020,6 +1051,7 @@ def test_with_block_depth(normalize): LineEntry(), ReturnEntry(), ReturnValueEntry('20'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1086,6 +1118,7 @@ def test_cellvars(normalize): ReturnValueEntry(), ReturnEntry(), ReturnValueEntry(), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1133,6 +1166,7 @@ def test_var_order(normalize): VariableEntry("seven", "7"), ReturnEntry(), ReturnValueEntry(), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1207,6 +1241,7 @@ def test_generator(): LineEntry(), ReturnEntry(), ReturnValueEntry('0'), + ElapsedTimeEntry(), # Pause and resume: @@ -1223,6 +1258,7 @@ def test_generator(): LineEntry(), ReturnEntry(), ReturnValueEntry('2'), + ElapsedTimeEntry(), # Pause and resume: @@ -1238,7 +1274,7 @@ def test_generator(): LineEntry(), ReturnEntry(), ReturnValueEntry(None), - + ElapsedTimeEntry(), ) ) @@ -1285,6 +1321,7 @@ def test_custom_repr(normalize): LineEntry(), ReturnEntry(), ReturnValueEntry('49995000'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1313,6 +1350,7 @@ def test_custom_repr_single(normalize): LineEntry(), ReturnEntry(), ReturnValueEntry('7'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1363,6 +1401,7 @@ def test_class(normalize): LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), + ElapsedTimeEntry(), VariableEntry('self', value_regex="u?.+MyClass object"), VariableEntry('foo', value_regex="u?'baba'"), CallEntry('def my_method(self, foo):'), @@ -1371,6 +1410,7 @@ def test_class(normalize): LineEntry('return y + self.x'), ReturnEntry('return y + self.x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1409,6 +1449,7 @@ def test_class_with_decorated_method(normalize): LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), + ElapsedTimeEntry(), VariableEntry('args', value_regex=r"\(<.+>, 'baba'\)"), VariableEntry('kwargs', value_regex=r"\{\}"), VariableEntry('function', value_regex="u?.+my_method"), @@ -1418,6 +1459,7 @@ def test_class_with_decorated_method(normalize): LineEntry('return result'), ReturnEntry('return result'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1457,6 +1499,7 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(normalize): LineEntry('self.x = 7'), ReturnEntry('self.x = 7'), ReturnValueEntry('None'), + ElapsedTimeEntry(), VariableEntry('args', value_regex=r"u?\(<.+>, 'baba'\)"), VariableEntry('kwargs', value_regex=r"u?\{\}"), VariableEntry('function', value_regex="u?.*my_method"), @@ -1475,6 +1518,7 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(normalize): LineEntry('return result'), ReturnEntry('return result'), ReturnValueEntry('15'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1531,6 +1575,7 @@ def test_class_with_property(normalize): LineEntry('self._x = 0'), ReturnEntry('self._x = 0'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # Called from getter VariableEntry('self', value_regex="u?.*MyClass object"), @@ -1538,6 +1583,7 @@ def test_class_with_property(normalize): LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # Called from setter VariableEntry('self', value_regex="u?.*MyClass object"), @@ -1545,6 +1591,7 @@ def test_class_with_property(normalize): LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), + ElapsedTimeEntry(), # Called from deleter VariableEntry('self', value_regex="u?.*MyClass object"), @@ -1552,6 +1599,7 @@ def test_class_with_property(normalize): LineEntry('pass'), ReturnEntry('pass'), ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1589,6 +1637,7 @@ def test_snooping_on_class_does_not_cause_base_class_to_be_snooped(normalize): LineEntry('self.method_on_base_class()'), ReturnEntry('self.method_on_base_class()'), ReturnValueEntry('None'), + ElapsedTimeEntry(), ), normalize=normalize, ) @@ -1625,6 +1674,7 @@ def test_normalize(): LineEntry('return res'), ReturnEntry('return res'), ReturnValueEntry('41'), + ElapsedTimeEntry(), ) ) @@ -1661,6 +1711,7 @@ def test_normalize_prefix(): LineEntry('return res', prefix=_prefix), ReturnEntry('return res', prefix=_prefix), ReturnValueEntry('41', prefix=_prefix), + ElapsedTimeEntry(prefix=_prefix), ) ) From ee7be80b449474ca1d3731574a73c006aeba6b89 Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 19:29:21 +0900 Subject: [PATCH 22/89] Add test for relative_time --- tests/test_pysnooper.py | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index b321d95..a4219fc 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -50,6 +50,36 @@ def test_string_io(): ) +def test_relative_time(): + string_io = io.StringIO() + + @pysnooper.snoop(string_io, relative_time=True) + def my_function(foo): + x = 7 + y = 8 + return y + x + + result = my_function('baba') + assert result == 15 + output = string_io.getvalue() + assert_output( + output, + ( + SourcePathEntry(), + VariableEntry('foo', value_regex="u?'baba'"), + CallEntry('def my_function(foo):'), + LineEntry('x = 7'), + VariableEntry('x', '7'), + LineEntry('y = 8'), + VariableEntry('y', '8'), + LineEntry('return y + x'), + ReturnEntry('return y + x'), + ReturnValueEntry('15'), + ElapsedTimeEntry(), + ) + ) + + def test_thread_info(): @pysnooper.snoop(thread_info=True) From 73c2816121470925daf708700ca749d2668a36f3 Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 20:04:18 +0900 Subject: [PATCH 23/89] Add README.md for relative_time --- README.md | 27 ++++++++++++++++++++++++--- 1 file changed, 24 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 12686e8..4f948f6 100644 --- a/README.md +++ b/README.md @@ -72,18 +72,18 @@ Or if you don't want to trace an entire function, you can wrap the relevant part import pysnooper import random -def foo(): +def foo(relative_time=False): lst = [] for i in range(10): lst.append(random.randrange(1, 1000)) - with pysnooper.snoop(): + with pysnooper.snoop(relative_time=relative_time): lower = min(lst) upper = max(lst) mid = (lower + upper) / 2 print(lower, mid, upper) -foo() +foo(False) ``` which outputs something like: @@ -99,6 +99,27 @@ New var:....... upper = 832 74 453.0 832 New var:....... mid = 453.0 09:37:35.882486 line 13 print(lower, mid, upper) +Total elapsed time: 00:00:00.000344 +``` + +If `relative_time` is `True`, print time format will be relative. + +```python +import pysnooper +import random + +def foo(relative_time=False): + lst = [] + for i in range(10): + lst.append(random.randrange(1, 1000)) + + with pysnooper.snoop(relative_time=relative_time): + lower = min(lst) + upper = max(lst) + mid = (lower + upper) / 2 + print(lower, mid, upper) + +foo(True) ``` # Features # From d94b0214f9ffe5e9a2097b85e39b69649f158582 Mon Sep 17 00:00:00 2001 From: iory Date: Fri, 17 Apr 2020 22:04:45 +0900 Subject: [PATCH 24/89] Rename relative_time to elapsed_time --- README.md | 10 +++++----- pysnooper/tracer.py | 10 +++++++--- tests/test_pysnooper.py | 4 ++-- 3 files changed, 14 insertions(+), 10 deletions(-) diff --git a/README.md b/README.md index 4f948f6..a008b56 100644 --- a/README.md +++ b/README.md @@ -72,12 +72,12 @@ Or if you don't want to trace an entire function, you can wrap the relevant part import pysnooper import random -def foo(relative_time=False): +def foo(elapsed_time=False): lst = [] for i in range(10): lst.append(random.randrange(1, 1000)) - with pysnooper.snoop(relative_time=relative_time): + with pysnooper.snoop(elapsed_time=elapsed_time): lower = min(lst) upper = max(lst) mid = (lower + upper) / 2 @@ -102,18 +102,18 @@ New var:....... mid = 453.0 Total elapsed time: 00:00:00.000344 ``` -If `relative_time` is `True`, print time format will be relative. +If `elapsed_time` is `True`, print elapsed time format. ```python import pysnooper import random -def foo(relative_time=False): +def foo(elapsed_time=False): lst = [] for i in range(10): lst.append(random.randrange(1, 1000)) - with pysnooper.snoop(relative_time=relative_time): + with pysnooper.snoop(elapsed_time=elapsed_time): lower = min(lst) upper = max(lst) mid = (lower + upper) / 2 diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index c02153c..8d303ae 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -198,11 +198,15 @@ class Tracer: You can also use `max_variable_length=None` to never truncate them. + Print time in elapsed time format:: + + @pysnooper.snoop(elapsed_time=True) + ''' def __init__(self, output=None, watch=(), watch_explode=(), depth=1, prefix='', overwrite=False, thread_info=False, custom_repr=(), max_variable_length=100, normalize=False, - relative_time=False): + elapsed_time=False): self._write = get_write_function(output, overwrite) self.watch = [ @@ -228,7 +232,7 @@ class Tracer: self.last_source_path = None self.max_variable_length = max_variable_length self.normalize = normalize - self.relative_time = relative_time + self.elapsed_time = elapsed_time def __call__(self, function_or_class): if DISABLED: @@ -359,7 +363,7 @@ class Tracer: # # ### Finished checking whether we should trace this line. ############## - if self.relative_time: + if self.elapsed_time: duration = datetime_module.datetime.now() - self.start_time now_string = pycompat.timedelta_isoformat( duration, timespec='microseconds') if not self.normalize else ' ' * 15 diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index a4219fc..2140ca5 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -50,10 +50,10 @@ def test_string_io(): ) -def test_relative_time(): +def test_elapsed_time(): string_io = io.StringIO() - @pysnooper.snoop(string_io, relative_time=True) + @pysnooper.snoop(string_io, elapsed_time=True) def my_function(foo): x = 7 y = 8 From b886f2b504c4b0ce89df6199e4deb8b3150fe04d Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 09:12:44 +0900 Subject: [PATCH 25/89] Enable multi call --- pysnooper/tracer.py | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 8d303ae..8530589 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -217,6 +217,7 @@ class Tracer: for v in utils.ensure_tuple(watch_explode) ] self.frame_to_local_reprs = {} + self.start_times = {} self.depth = depth self.prefix = prefix self.thread_info = thread_info @@ -302,7 +303,7 @@ class Tracer: 'original_trace_functions', [] ) stack.append(sys.gettrace()) - self.start_time = datetime_module.datetime.now() + self.start_times[id(calling_frame)] = datetime_module.datetime.now() sys.settrace(self.trace) def __exit__(self, exc_type, exc_value, exc_traceback): @@ -314,10 +315,10 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - if thread_global.depth == -1: - duration = datetime_module.datetime.now() - self.start_time - now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') - self.write('Total elapsed time: {now_string}'.format(**locals())) + start_time = self.start_times.pop(id(calling_frame)) + duration = datetime_module.datetime.now() - start_time + now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') + self.write('Total elapsed time: {now_string}'.format(**locals())) def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename @@ -364,7 +365,9 @@ class Tracer: ### Finished checking whether we should trace this line. ############## if self.elapsed_time: - duration = datetime_module.datetime.now() - self.start_time + calling_frame = frame.f_back + duration = datetime_module.datetime.now() - self.start_times[ + id(calling_frame)] now_string = pycompat.timedelta_isoformat( duration, timespec='microseconds') if not self.normalize else ' ' * 15 else: From 4779aebbe45f1326484b7a799ac519d4fd1b5d7e Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 09:28:33 +0900 Subject: [PATCH 26/89] Add indent of elapsed time --- pysnooper/tracer.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 8530589..cf957b7 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -318,7 +318,9 @@ class Tracer: start_time = self.start_times.pop(id(calling_frame)) duration = datetime_module.datetime.now() - start_time now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') - self.write('Total elapsed time: {now_string}'.format(**locals())) + indent = ' ' * 4 * (thread_global.depth + 1) + self.write('{indent}Total elapsed time: {now_string}'.format( + **locals())) def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename From 2ac382f8563452ce982665a39c8abd99106cc9ac Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 09:35:07 +0900 Subject: [PATCH 27/89] Fixed test for elapsed time entry --- tests/samples/indentation.py | 1 + tests/samples/recursion.py | 55 ++++++++++--------- .../test_multiple_files.py | 4 +- tests/test_pysnooper.py | 1 + 4 files changed, 34 insertions(+), 27 deletions(-) diff --git a/tests/samples/indentation.py b/tests/samples/indentation.py index 65cb7b4..60f073b 100644 --- a/tests/samples/indentation.py +++ b/tests/samples/indentation.py @@ -38,6 +38,7 @@ Source path:... Whatever Return value:.. None 21:10:42.299509 return 19 f5() Return value:.. None + Total elapsed time: 00:00:00.000134 21:10:42.299577 return 10 f3() Return value:.. None 21:10:42.299627 return 6 f2() diff --git a/tests/samples/recursion.py b/tests/samples/recursion.py index 7edbaac..f1529ed 100644 --- a/tests/samples/recursion.py +++ b/tests/samples/recursion.py @@ -18,46 +18,49 @@ def main(): expected_output = ''' Source path:... Whatever Starting var:.. x = 4 -20:28:17.875295 call 5 def factorial(x): -20:28:17.875509 line 6 if x <= 1: -20:28:17.875550 line 8 return mul(x, factorial(x - 1)) +09:31:32.691599 call 5 def factorial(x): +09:31:32.691722 line 6 if x <= 1: +09:31:32.691746 line 8 return mul(x, factorial(x - 1)) Starting var:.. x = 3 - 20:28:17.875624 call 5 def factorial(x): - 20:28:17.875668 line 6 if x <= 1: - 20:28:17.875703 line 8 return mul(x, factorial(x - 1)) + 09:31:32.691781 call 5 def factorial(x): + 09:31:32.691806 line 6 if x <= 1: + 09:31:32.691823 line 8 return mul(x, factorial(x - 1)) Starting var:.. x = 2 - 20:28:17.875771 call 5 def factorial(x): - 20:28:17.875813 line 6 if x <= 1: - 20:28:17.875849 line 8 return mul(x, factorial(x - 1)) + 09:31:32.691852 call 5 def factorial(x): + 09:31:32.691875 line 6 if x <= 1: + 09:31:32.691892 line 8 return mul(x, factorial(x - 1)) Starting var:.. x = 1 - 20:28:17.875913 call 5 def factorial(x): - 20:28:17.875953 line 6 if x <= 1: - 20:28:17.875987 line 7 return 1 - 20:28:17.876021 return 7 return 1 + 09:31:32.691918 call 5 def factorial(x): + 09:31:32.691941 line 6 if x <= 1: + 09:31:32.691961 line 7 return 1 + 09:31:32.691978 return 7 return 1 Return value:.. 1 + Total elapsed time: 00:00:00.000092 Starting var:.. a = 2 Starting var:.. b = 1 - 20:28:17.876111 call 11 def mul(a, b): - 20:28:17.876151 line 12 return a * b - 20:28:17.876190 return 12 return a * b + 09:31:32.692025 call 11 def mul(a, b): + 09:31:32.692055 line 12 return a * b + 09:31:32.692075 return 12 return a * b Return value:.. 2 - 20:28:17.876235 return 8 return mul(x, factorial(x - 1)) + 09:31:32.692102 return 8 return mul(x, factorial(x - 1)) Return value:.. 2 + Total elapsed time: 00:00:00.000283 Starting var:.. a = 3 Starting var:.. b = 2 - 20:28:17.876320 call 11 def mul(a, b): - 20:28:17.876359 line 12 return a * b - 20:28:17.876397 return 12 return a * b + 09:31:32.692147 call 11 def mul(a, b): + 09:31:32.692174 line 12 return a * b + 09:31:32.692193 return 12 return a * b Return value:.. 6 - 20:28:17.876442 return 8 return mul(x, factorial(x - 1)) + 09:31:32.692216 return 8 return mul(x, factorial(x - 1)) Return value:.. 6 + Total elapsed time: 00:00:00.000468 Starting var:.. a = 4 Starting var:.. b = 6 - 20:28:17.876525 call 11 def mul(a, b): - 20:28:17.876563 line 12 return a * b - 20:28:17.876601 return 12 return a * b + 09:31:32.692259 call 11 def mul(a, b): + 09:31:32.692285 line 12 return a * b + 09:31:32.692304 return 12 return a * b Return value:.. 24 -20:28:17.876646 return 8 return mul(x, factorial(x - 1)) +09:31:32.692326 return 8 return mul(x, factorial(x - 1)) Return value:.. 24 -Total elapsed time: 00:00:00.000651 +Total elapsed time: 00:00:00.000760 ''' diff --git a/tests/test_multiple_files/test_multiple_files.py b/tests/test_multiple_files/test_multiple_files.py index 5bd233a..e217ce4 100644 --- a/tests/test_multiple_files/test_multiple_files.py +++ b/tests/test_multiple_files/test_multiple_files.py @@ -15,7 +15,8 @@ import pysnooper from pysnooper.variables import needs_parentheses from ..utils import (assert_output, assert_sample_output, VariableEntry, CallEntry, LineEntry, ReturnEntry, OpcodeEntry, - ReturnValueEntry, ExceptionEntry, SourcePathEntry) + ReturnValueEntry, ExceptionEntry, SourcePathEntry, + ElapsedTimeEntry) from .. import mini_toolbox from .multiple_files import foo @@ -45,6 +46,7 @@ def test_multiple_files(): LineEntry(), ReturnEntry(), ReturnValueEntry(), + ElapsedTimeEntry(), ) ) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 2140ca5..d4dd5f4 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -1544,6 +1544,7 @@ def test_class_with_decorated_method_and_snoop_applied_to_method(normalize): LineEntry('return y + self.x'), ReturnEntry('return y + self.x'), ReturnValueEntry('15'), + ElapsedTimeEntry(), VariableEntry('result', '15'), LineEntry('return result'), ReturnEntry('return result'), From 828ffb1d3c6eb7efd58f655d7a221030ff96a889 Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 15:17:40 +0900 Subject: [PATCH 28/89] Add time_fromisoformat --- pysnooper/pycompat.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index c6b1bf7..1899ff8 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -80,6 +80,16 @@ else: return result +if sys.version_info[:2] >= (3, 7): + time_fromisoformat = datetime_module.time.fromisoformat +else: + def time_fromisoformat(isoformat_str): + hour, minute, second, microsecond = map( + int, + isoformat_str.replace('.', ':').split(':')) + return datetime_module.time(hour, minute, second, microsecond) + + def timedelta_isoformat(timedelta, timespec='microseconds'): assert isinstance(timedelta, datetime_module.timedelta) if timespec != 'microseconds': From 0c018d868e60949592b360519e6ca2be2d34883d Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 15:19:38 +0900 Subject: [PATCH 29/89] Fixed elapsed_time --- pysnooper/tracer.py | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index cf957b7..887277e 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -217,7 +217,7 @@ class Tracer: for v in utils.ensure_tuple(watch_explode) ] self.frame_to_local_reprs = {} - self.start_times = {} + self.start_times = [] self.depth = depth self.prefix = prefix self.thread_info = thread_info @@ -303,7 +303,7 @@ class Tracer: 'original_trace_functions', [] ) stack.append(sys.gettrace()) - self.start_times[id(calling_frame)] = datetime_module.datetime.now() + self.start_times.append(datetime_module.datetime.now()) sys.settrace(self.trace) def __exit__(self, exc_type, exc_value, exc_traceback): @@ -315,7 +315,7 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - start_time = self.start_times.pop(id(calling_frame)) + start_time = self.start_times.pop(-1) duration = datetime_module.datetime.now() - start_time now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') indent = ' ' * 4 * (thread_global.depth + 1) @@ -332,7 +332,6 @@ class Tracer: return thread_info.ljust(self.thread_info_padding) def trace(self, frame, event, arg): - ### Checking whether we should trace this line: ####################### # # # We should trace this line either if it's in the decorated function, @@ -367,9 +366,7 @@ class Tracer: ### Finished checking whether we should trace this line. ############## if self.elapsed_time: - calling_frame = frame.f_back - duration = datetime_module.datetime.now() - self.start_times[ - id(calling_frame)] + duration = datetime_module.datetime.now() - self.start_times[-1] now_string = pycompat.timedelta_isoformat( duration, timespec='microseconds') if not self.normalize else ' ' * 15 else: From 612e6ebed710f617d0da006080882c24a5e298dd Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 15:19:55 +0900 Subject: [PATCH 30/89] Add elapsed_time check for test --- tests/test_pysnooper.py | 141 ++++++++++++++++++++++++++++++++++------ tests/utils.py | 15 ++++- 2 files changed, 134 insertions(+), 22 deletions(-) diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index d4dd5f4..4cdbee5 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -4,6 +4,7 @@ import io import textwrap import threading +import time import types import os import sys @@ -51,32 +52,132 @@ def test_string_io(): def test_elapsed_time(): - string_io = io.StringIO() + snoop = pysnooper.snoop(elapsed_time=True) - @pysnooper.snoop(string_io, elapsed_time=True) - def my_function(foo): - x = 7 - y = 8 - return y + x + def foo(x): + if x == 0: + bar1(x) + qux() + return - result = my_function('baba') - assert result == 15 - output = string_io.getvalue() + with snoop: + # There should be line entries for these three lines, + # no line entries for anything else in this function, + # but calls to all bar functions should be traced + foo(x - 1) + bar2(x) + qux() + int(4) + bar3(9) + return x + + @snoop + def bar1(_x): + qux() + + @snoop + def bar2(_x): + qux() + + @snoop + def bar3(_x): + qux() + + def qux(): + time.sleep(0.1) + return 9 # not traced, mustn't show up + + with mini_toolbox.OutputCapturer(stdout=False, + stderr=True) as output_capturer: + result = foo(2) + assert result == 2 + output = output_capturer.string_io.getvalue() assert_output( output, ( + # In first with SourcePathEntry(), - VariableEntry('foo', value_regex="u?'baba'"), - CallEntry('def my_function(foo):'), - LineEntry('x = 7'), - VariableEntry('x', '7'), - LineEntry('y = 8'), - VariableEntry('y', '8'), - LineEntry('return y + x'), - ReturnEntry('return y + x'), - ReturnValueEntry('15'), - ElapsedTimeEntry(), - ) + VariableEntry('x', '2'), + VariableEntry('bar1'), + VariableEntry('bar2'), + VariableEntry('bar3'), + VariableEntry('foo'), + VariableEntry('qux'), + VariableEntry('snoop'), + LineEntry('foo(x - 1)'), + + # In with in recursive call + VariableEntry('x', '1'), + VariableEntry('bar1'), + VariableEntry('bar2'), + VariableEntry('bar3'), + VariableEntry('foo'), + VariableEntry('qux'), + VariableEntry('snoop'), + LineEntry('foo(x - 1)'), + + # Call to bar1 from if block outside with + VariableEntry('_x', '0'), + VariableEntry('qux'), + CallEntry('def bar1(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + + # In with in recursive call + LineEntry('bar2(x)'), + + # Call to bar2 from within with + VariableEntry('_x', '1'), + VariableEntry('qux'), + CallEntry('def bar2(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + + # In with in recursive call + LineEntry('qux()'), + ElapsedTimeEntry(0.4), + + # Call to bar3 from after with + VariableEntry('_x', '9'), + VariableEntry('qux'), + CallEntry('def bar3(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + + # -- Similar to previous few sections, + # -- but from first call to foo + + # In with in first call + LineEntry('bar2(x)'), + + # Call to bar2 from within with + VariableEntry('_x', '2'), + VariableEntry('qux'), + CallEntry('def bar2(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + + # In with in first call + LineEntry('qux()'), + ElapsedTimeEntry(0.7), + + # Call to bar3 from after with + VariableEntry('_x', '9'), + VariableEntry('qux'), + CallEntry('def bar3(_x):'), + LineEntry('qux()'), + ReturnEntry('qux()'), + ReturnValueEntry('None'), + ElapsedTimeEntry(0.1), + ), ) diff --git a/tests/utils.py b/tests/utils.py index 169d184..2b73555 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -221,8 +221,13 @@ class SourcePathEntry(_BaseValueEntry): class ElapsedTimeEntry(_BasePrintEntry): - def __init__(self, prefix=''): + + def __init__(self, elapsed_time_value=None, + tolerance=0.05, + prefix=''): _BasePrintEntry.__init__(self, prefix=prefix) + self.elapsed_time_value = elapsed_time_value + self.tolerance = tolerance _preamble_pattern = re.compile( r"""^Total elapsed time$""" @@ -232,7 +237,13 @@ class ElapsedTimeEntry(_BasePrintEntry): return bool(self._preamble_pattern.match(preamble)) def _check_content(self, content): - return True + if self.elapsed_time_value: + time = pysnooper.pycompat.time_fromisoformat(content) + sec = (time.hour * 60 + time.minute) * 60 + time.second + \ + time.microsecond * (10 ** -6) + return abs(sec - self.elapsed_time_value) <= self.tolerance + else: + return True class _BaseEventEntry(_BaseEntry): From 35d3bc2db165aecbc4fafa1fd3ed6bd0ced30059 Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 18:00:29 +0900 Subject: [PATCH 31/89] Delete default value of timedelta_isoformat --- pysnooper/tracer.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 887277e..c7d6e49 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -317,7 +317,7 @@ class Tracer: start_time = self.start_times.pop(-1) duration = datetime_module.datetime.now() - start_time - now_string = pycompat.timedelta_isoformat(duration, timespec='microseconds') + now_string = pycompat.timedelta_isoformat(duration) indent = ' ' * 4 * (thread_global.depth + 1) self.write('{indent}Total elapsed time: {now_string}'.format( **locals())) From 444ea173147534e8c03b44eaf55c29f7bc026c8c Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 18:24:57 +0900 Subject: [PATCH 32/89] Refactor the timedelta_isoformat --- pysnooper/pycompat.py | 7 ++----- pysnooper/tracer.py | 2 +- 2 files changed, 3 insertions(+), 6 deletions(-) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index 1899ff8..c6b23b3 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -90,9 +90,6 @@ else: return datetime_module.time(hour, minute, second, microsecond) -def timedelta_isoformat(timedelta, timespec='microseconds'): - assert isinstance(timedelta, datetime_module.timedelta) - if timespec != 'microseconds': - raise NotImplementedError +def timedelta_isoformat(timedelta): time = (datetime_module.datetime.min + timedelta).time() - return time_isoformat(time, timespec) + return time_isoformat(time) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index c7d6e49..1c9103b 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -368,7 +368,7 @@ class Tracer: if self.elapsed_time: duration = datetime_module.datetime.now() - self.start_times[-1] now_string = pycompat.timedelta_isoformat( - duration, timespec='microseconds') if not self.normalize else ' ' * 15 + duration) if not self.normalize else ' ' * 15 else: now = datetime_module.datetime.now().time() now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 From 0cb6df1f7b5bab9ca98b6afd5442dd9306328282 Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 23:22:46 +0900 Subject: [PATCH 33/89] Fixed multi thread case of elapsed_time --- pysnooper/tracer.py | 26 +++++++++++++++++--------- 1 file changed, 17 insertions(+), 9 deletions(-) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 1c9103b..e6a4a65 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -217,7 +217,7 @@ class Tracer: for v in utils.ensure_tuple(watch_explode) ] self.frame_to_local_reprs = {} - self.start_times = [] + self.start_times = {} self.depth = depth self.prefix = prefix self.thread_info = thread_info @@ -303,7 +303,7 @@ class Tracer: 'original_trace_functions', [] ) stack.append(sys.gettrace()) - self.start_times.append(datetime_module.datetime.now()) + self.start_times[calling_frame] = datetime_module.datetime.now() sys.settrace(self.trace) def __exit__(self, exc_type, exc_value, exc_traceback): @@ -315,12 +315,14 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - start_time = self.start_times.pop(-1) - duration = datetime_module.datetime.now() - start_time - now_string = pycompat.timedelta_isoformat(duration) - indent = ' ' * 4 * (thread_global.depth + 1) - self.write('{indent}Total elapsed time: {now_string}'.format( - **locals())) + start_time = self.start_times.pop(calling_frame, None) + # TODO(Fix case of start_time is None) + if start_time: + duration = datetime_module.datetime.now() - start_time + now_string = pycompat.timedelta_isoformat(duration) + indent = ' ' * 4 * (thread_global.depth + 1) + self.write('{indent}Total elapsed time: {now_string}'.format( + **locals())) def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename @@ -366,7 +368,11 @@ class Tracer: ### Finished checking whether we should trace this line. ############## if self.elapsed_time: - duration = datetime_module.datetime.now() - self.start_times[-1] + if frame not in self.start_times: + self.start_times[frame] = start_time = datetime_module.datetime.now() + else: + start_time = self.start_times[frame] + duration = datetime_module.datetime.now() - start_time now_string = pycompat.timedelta_isoformat( duration) if not self.normalize else ' ' * 15 else: @@ -458,6 +464,8 @@ class Tracer: if event == 'return': del self.frame_to_local_reprs[frame] + if self.elapsed_time: + del self.start_times[frame] thread_global.depth -= 1 if not ended_by_exception: From 48cc9d94cdb102064fb6b3248c1d2b8f288cb96f Mon Sep 17 00:00:00 2001 From: iory Date: Sat, 18 Apr 2020 23:37:03 +0900 Subject: [PATCH 34/89] Fixed timedelta_isoformat --- pysnooper/pycompat.py | 4 ++-- pysnooper/tracer.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index c6b23b3..fedb3a5 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -90,6 +90,6 @@ else: return datetime_module.time(hour, minute, second, microsecond) -def timedelta_isoformat(timedelta): +def timedelta_isoformat(timedelta, timespec='microseconds'): time = (datetime_module.datetime.min + timedelta).time() - return time_isoformat(time) + return time_isoformat(time, timespec) diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index e6a4a65..7a56d3b 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -374,7 +374,7 @@ class Tracer: start_time = self.start_times[frame] duration = datetime_module.datetime.now() - start_time now_string = pycompat.timedelta_isoformat( - duration) if not self.normalize else ' ' * 15 + duration, timespec='microseconds') if not self.normalize else ' ' * 15 else: now = datetime_module.datetime.now().time() now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 From 43ed249e8cff6c630d5664321cc4f95c06a61998 Mon Sep 17 00:00:00 2001 From: Ram Rachum Date: Tue, 21 Apr 2020 14:17:29 +0300 Subject: [PATCH 35/89] Massaging some code --- ADVANCED_USAGE.md | 5 ++- AUTHORS | 1 + README.md | 29 +++-------------- pysnooper/pycompat.py | 24 +++++++------- pysnooper/tracer.py | 61 +++++++++++++++++++++--------------- tests/samples/exception.py | 2 +- tests/samples/indentation.py | 4 +-- tests/samples/recursion.py | 8 ++--- tests/test_pysnooper.py | 4 +-- tests/utils.py | 55 +++++++++----------------------- 10 files changed, 81 insertions(+), 112 deletions(-) diff --git a/ADVANCED_USAGE.md b/ADVANCED_USAGE.md index 5a95899..aa63618 100644 --- a/ADVANCED_USAGE.md +++ b/ADVANCED_USAGE.md @@ -86,4 +86,7 @@ can customize that: @pysnooper.snoop(max_variable_length=200) ``` -You can also use `max_variable_length=None` to never truncate them. \ No newline at end of file +You can also use `max_variable_length=None` to never truncate them. + +Use `relative_time=True` to show timestamps relative to start time rather than +wall time. \ No newline at end of file diff --git a/AUTHORS b/AUTHORS index 1066728..0035467 100644 --- a/AUTHORS +++ b/AUTHORS @@ -21,3 +21,4 @@ pikez Jonathan Reichelt Gjertsen Guoqiang Ding Itamar.Raviv +iory diff --git a/README.md b/README.md index a008b56..627a757 100644 --- a/README.md +++ b/README.md @@ -64,6 +64,7 @@ Modified var:.. bits = [1, 1, 0] 15:29:11.327032 line 10 return bits 15:29:11.327032 return 10 return bits Return value:.. [1, 1, 0] +Elapsed time: 00:00:00.000001 ``` Or if you don't want to trace an entire function, you can wrap the relevant part in a `with` block: @@ -72,18 +73,18 @@ Or if you don't want to trace an entire function, you can wrap the relevant part import pysnooper import random -def foo(elapsed_time=False): +def foo(): lst = [] for i in range(10): lst.append(random.randrange(1, 1000)) - with pysnooper.snoop(elapsed_time=elapsed_time): + with pysnooper.snoop(): lower = min(lst) upper = max(lst) mid = (lower + upper) / 2 print(lower, mid, upper) -foo(False) +foo() ``` which outputs something like: @@ -99,27 +100,7 @@ New var:....... upper = 832 74 453.0 832 New var:....... mid = 453.0 09:37:35.882486 line 13 print(lower, mid, upper) -Total elapsed time: 00:00:00.000344 -``` - -If `elapsed_time` is `True`, print elapsed time format. - -```python -import pysnooper -import random - -def foo(elapsed_time=False): - lst = [] - for i in range(10): - lst.append(random.randrange(1, 1000)) - - with pysnooper.snoop(elapsed_time=elapsed_time): - lower = min(lst) - upper = max(lst) - mid = (lower + upper) / 2 - print(lower, mid, upper) - -foo(True) +Elapsed time: 00:00:00.000344 ``` # Features # diff --git a/pysnooper/pycompat.py b/pysnooper/pycompat.py index fedb3a5..247dbde 100644 --- a/pysnooper/pycompat.py +++ b/pysnooper/pycompat.py @@ -80,16 +80,16 @@ else: return result -if sys.version_info[:2] >= (3, 7): - time_fromisoformat = datetime_module.time.fromisoformat -else: - def time_fromisoformat(isoformat_str): - hour, minute, second, microsecond = map( - int, - isoformat_str.replace('.', ':').split(':')) - return datetime_module.time(hour, minute, second, microsecond) - - -def timedelta_isoformat(timedelta, timespec='microseconds'): +def timedelta_format(timedelta): time = (datetime_module.datetime.min + timedelta).time() - return time_isoformat(time, timespec) + return time_isoformat(time, timespec='microseconds') + +def timedelta_parse(s): + hours, minutes, seconds, microseconds = map( + int, + s.replace('.', ':').split(':') + ) + return datetime_module.timedelta(hours=hours, minutes=minutes, + seconds=seconds, + microseconds=microseconds) + diff --git a/pysnooper/tracer.py b/pysnooper/tracer.py index 7a56d3b..4b4ac05 100644 --- a/pysnooper/tracer.py +++ b/pysnooper/tracer.py @@ -198,15 +198,14 @@ class Tracer: You can also use `max_variable_length=None` to never truncate them. - Print time in elapsed time format:: + Show timestamps relative to start time rather than wall time:: - @pysnooper.snoop(elapsed_time=True) + @pysnooper.snoop(relative_time=True) ''' def __init__(self, output=None, watch=(), watch_explode=(), depth=1, prefix='', overwrite=False, thread_info=False, custom_repr=(), - max_variable_length=100, normalize=False, - elapsed_time=False): + max_variable_length=100, normalize=False, relative_time=False): self._write = get_write_function(output, overwrite) self.watch = [ @@ -233,7 +232,7 @@ class Tracer: self.last_source_path = None self.max_variable_length = max_variable_length self.normalize = normalize - self.elapsed_time = elapsed_time + self.relative_time = relative_time def __call__(self, function_or_class): if DISABLED: @@ -315,14 +314,17 @@ class Tracer: self.target_frames.discard(calling_frame) self.frame_to_local_reprs.pop(calling_frame, None) - start_time = self.start_times.pop(calling_frame, None) - # TODO(Fix case of start_time is None) - if start_time: - duration = datetime_module.datetime.now() - start_time - now_string = pycompat.timedelta_isoformat(duration) - indent = ' ' * 4 * (thread_global.depth + 1) - self.write('{indent}Total elapsed time: {now_string}'.format( - **locals())) + ### Writing elapsed time: ############################################# + # # + start_time = self.start_times.pop(calling_frame) + duration = datetime_module.datetime.now() - start_time + elapsed_time_string = pycompat.timedelta_format(duration) + indent = ' ' * 4 * (thread_global.depth + 1) + self.write( + '{indent}Elapsed time: {elapsed_time_string}'.format(**locals()) + ) + # # + ### Finished writing elapsed time. #################################### def _is_internal_frame(self, frame): return frame.f_code.co_filename == Tracer.__enter__.__code__.co_filename @@ -334,6 +336,7 @@ class Tracer: return thread_info.ljust(self.thread_info_padding) def trace(self, frame, event, arg): + ### Checking whether we should trace this line: ####################### # # # We should trace this line either if it's in the decorated function, @@ -367,17 +370,26 @@ class Tracer: # # ### Finished checking whether we should trace this line. ############## - if self.elapsed_time: - if frame not in self.start_times: - self.start_times[frame] = start_time = datetime_module.datetime.now() - else: + ### Making timestamp: ################################################# + # # + if self.normalize: + timestamp = ' ' * 15 + elif self.relative_time: + try: start_time = self.start_times[frame] + except KeyError: + start_time = self.start_times[frame] = \ + datetime_module.datetime.now() duration = datetime_module.datetime.now() - start_time - now_string = pycompat.timedelta_isoformat( - duration, timespec='microseconds') if not self.normalize else ' ' * 15 + timestamp = pycompat.timedelta_format(duration) else: - now = datetime_module.datetime.now().time() - now_string = pycompat.time_isoformat(now, timespec='microseconds') if not self.normalize else ' ' * 15 + timestamp = pycompat.time_isoformat( + datetime_module.datetime.now().time(), + timespec='microseconds' + ) + # # + ### Finished making timestamp. ######################################## + line_no = frame.f_lineno source_path, source = get_path_and_source_from_frame(frame) source_path = source_path if not self.normalize else os.path.basename(source_path) @@ -459,13 +471,12 @@ class Tracer: self.write('{indent}Call ended by exception'. format(**locals())) else: - self.write(u'{indent}{now_string} {thread_info}{event:9} ' + self.write(u'{indent}{timestamp} {thread_info}{event:9} ' u'{line_no:4} {source_line}'.format(**locals())) if event == 'return': - del self.frame_to_local_reprs[frame] - if self.elapsed_time: - del self.start_times[frame] + self.frame_to_local_reprs.pop(frame, None) + self.start_times.pop(frame, None) thread_global.depth -= 1 if not ended_by_exception: diff --git a/tests/samples/exception.py b/tests/samples/exception.py index 87642c8..bf6196f 100644 --- a/tests/samples/exception.py +++ b/tests/samples/exception.py @@ -46,5 +46,5 @@ TypeError: bad 12:18:08.018787 line 21 pass 12:18:08.018813 return 21 pass Return value:.. None -Total elapsed time: 00:00:00.000885 +Elapsed time: 00:00:00.000885 ''' diff --git a/tests/samples/indentation.py b/tests/samples/indentation.py index 60f073b..651dfce 100644 --- a/tests/samples/indentation.py +++ b/tests/samples/indentation.py @@ -38,10 +38,10 @@ Source path:... Whatever Return value:.. None 21:10:42.299509 return 19 f5() Return value:.. None - Total elapsed time: 00:00:00.000134 + Elapsed time: 00:00:00.000134 21:10:42.299577 return 10 f3() Return value:.. None 21:10:42.299627 return 6 f2() Return value:.. None -Total elapsed time: 00:00:00.000885 +Elapsed time: 00:00:00.000885 ''' diff --git a/tests/samples/recursion.py b/tests/samples/recursion.py index f1529ed..825f511 100644 --- a/tests/samples/recursion.py +++ b/tests/samples/recursion.py @@ -35,7 +35,7 @@ Starting var:.. x = 4 09:31:32.691961 line 7 return 1 09:31:32.691978 return 7 return 1 Return value:.. 1 - Total elapsed time: 00:00:00.000092 + Elapsed time: 00:00:00.000092 Starting var:.. a = 2 Starting var:.. b = 1 09:31:32.692025 call 11 def mul(a, b): @@ -44,7 +44,7 @@ Starting var:.. x = 4 Return value:.. 2 09:31:32.692102 return 8 return mul(x, factorial(x - 1)) Return value:.. 2 - Total elapsed time: 00:00:00.000283 + Elapsed time: 00:00:00.000283 Starting var:.. a = 3 Starting var:.. b = 2 09:31:32.692147 call 11 def mul(a, b): @@ -53,7 +53,7 @@ Starting var:.. x = 4 Return value:.. 6 09:31:32.692216 return 8 return mul(x, factorial(x - 1)) Return value:.. 6 - Total elapsed time: 00:00:00.000468 + Elapsed time: 00:00:00.000468 Starting var:.. a = 4 Starting var:.. b = 6 09:31:32.692259 call 11 def mul(a, b): @@ -62,5 +62,5 @@ Starting var:.. x = 4 Return value:.. 24 09:31:32.692326 return 8 return mul(x, factorial(x - 1)) Return value:.. 24 -Total elapsed time: 00:00:00.000760 +Elapsed time: 00:00:00.000760 ''' diff --git a/tests/test_pysnooper.py b/tests/test_pysnooper.py index 4cdbee5..2623f35 100644 --- a/tests/test_pysnooper.py +++ b/tests/test_pysnooper.py @@ -51,8 +51,8 @@ def test_string_io(): ) -def test_elapsed_time(): - snoop = pysnooper.snoop(elapsed_time=True) +def test_relative_time(): + snoop = pysnooper.snoop(relative_time=True) def foo(x): if x == 0: diff --git a/tests/utils.py b/tests/utils.py index 2b73555..10fd249 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -77,29 +77,28 @@ class _BaseValueEntry(_BaseEntry): self._check_content(content)) -class _BasePrintEntry(_BaseEntry): - def __init__(self, prefix=''): +class ElapsedTimeEntry(_BaseEntry): + def __init__(self, elapsed_time_value=None, tolerance=0.2, prefix=''): _BaseEntry.__init__(self, prefix=prefix) self.line_pattern = re.compile( - r"""^%s(?P(?: {4})*)(?P[^:]*):""" - r""" (?P.*)$""" % (re.escape(self.prefix),) + r"""^%s(?P(?: {4})*)Elapsed time: (?P