Like @zzzeek as suggested these changes display thread infos (identifier and name) on output to help user to track execution on apps who use threading.

Solve #79

Closes #59

Sample usage:

from types import SimpleNamespace

import pysnooper
from pysnooper.variables import Attrs, Indices, Keys, Enumerate


@pysnooper.snoop(variables=(
        Keys('d', exclude='c'),
        Attrs('point'),
        Indices('lst')[-3:],
        Enumerate('s'),
))
def foo():
    d = {'a': 1, 'b': 2, 'c': 'ignore'}
    point = SimpleNamespace(x=3, y=4)
    lst = list(range(1000))
    s = {7, 8, 9}


foo()

Output:

19:01:11.689207 call        13 def foo():
19:01:11.779673 line        14     d = {'a': 1, 'b': 2, 'c': 'ignore'}
New var:....... (d)['a'] = 1
New var:....... (d)['b'] = 2
New var:....... d = {'a': 1, 'b': 2, 'c': 'ignore'}
19:01:11.872593 line        15     point = SimpleNamespace(x=3, y=4)
New var:....... (point).x = 3
New var:....... (point).y = 4
New var:....... point = namespace(x=3, y=4)
19:01:12.000584 line        16     lst = list(range(1000))
New var:....... (lst)[997] = 997
New var:....... (lst)[998] = 998
New var:....... (lst)[999] = 999
New var:....... lst = [0, 1, 2, 3, 4, 5, ...]
19:01:12.128228 line        17     s = {7, 8, 9}
New var:....... (s)<0> = 8
New var:....... (s)<1> = 9
New var:....... (s)<2> = 7
New var:....... s = {7, 8, 9}
19:01:12.260525 return      17     s = {7, 8, 9}
Return value:.. None

I get the following runtime error with the demo code provided in the readme:

Runtime error (MissingMemberException): 'NoneType' object has no attribute 'get'
Traceback:
  line 72, in decorate, "pysnooper.py"
  line 59, in get_source_from_frame, "pysnooper\tracer.py"
  line 209, in trace, "pysnooper\tracer.py"
  line 2, in number_to_bits, "<decorator-gen-10>"
  line 20, in script

(line 20 calls the "number_to_bits" function)

Thank you for your awesome debug tool!

This PR added a printing total elapsed time and elapsed_time format option. The test code is as follows.

import argparse
import time

import pysnooper


def test1(elapsed_time=False):
    with pysnooper.snoop(elapsed_time=elapsed_time):
        time.sleep(1.0)


def test2(elapsed_time=False):
    a = 1
    b = 2
    c = 3
    with pysnooper.snoop(elapsed_time=elapsed_time):
        tmp = a + b
        tmp2 = a - b


test1(elapsed_time=False)
print()
test1(elapsed_time=True)
print()
test2(elapsed_time=False)
print()
test2(elapsed_time=True)

The result is as follows.

Source path:... <ipython-input-14-f06356abdfce>
New var:....... elapsed_time = False
22:14:11.952148 line         9         time.sleep(1.0)
Total elapsed time: 00:00:01.002691

Source path:... <ipython-input-14-f06356abdfce>
New var:....... elapsed_time = True
00:00:00.000007 line         9         time.sleep(1.0)
Total elapsed time: 00:00:01.003509

Source path:... <ipython-input-14-f06356abdfce>
New var:....... elapsed_time = False
New var:....... a = 1
New var:....... b = 2
New var:....... c = 3
22:14:13.959043 line        17         tmp = a + b
New var:....... tmp = 3
22:14:13.959235 line        18         tmp2 = a - b
Total elapsed time: 00:00:00.000334

Source path:... <ipython-input-14-f06356abdfce>
New var:....... elapsed_time = True
New var:....... a = 1
New var:....... b = 2
New var:....... c = 3
00:00:00.000011 line        17         tmp = a + b
New var:....... tmp = 3
00:00:00.000295 line        18         tmp2 = a - b
Total elapsed time: 00:00:00.000409

When I ran a simple script:

import pysnooper
import numpy as np

@pysnooper.snoop()
def multi_matmul(times):
    x = np.random.rand(2,2)
    w = np.random.rand(2,2)
    
    for i in range(times):
        x = np.matmul(x,w)
    return x

multi_matmul(3)

The error happened:

Starting var:.. times = 3
Traceback (most recent call last):
  File "<tmp 1>", line 14, in <module>
    multi_matmul(3)
  File "</usr/local/lib/python3.6/dist-packages/decorator.py:decorator-gen-121>", line 2, in multi_matmul
  File "/usr/local/lib/python3.6/dist-packages/pysnooper/pysnooper.py", line 72, in decorate
    return function(*args, **kwargs)
  File "<tmp 1>", line 4, in multi_matmul
    @pysnooper.snoop()
  File "/usr/local/lib/python3.6/dist-packages/pysnooper/tracer.py", line 182, in trace
    source_line = get_source_from_frame(frame)[frame.f_lineno - 1]
  File "/usr/local/lib/python3.6/dist-packages/pysnooper/tracer.py", line 75, in get_source_from_frame
    raise NotImplementedError
NotImplementedError

A POC for running pysnooper as an external command (e.g. pysnooper /path/to/script.py)

The script will create sitecustomize.py script and will add it first in PYTHONPATH.

Now the local variables state is examined when the first callback fires. This can be too late, when the variables were created earlier, before the call. For example this code:

import pysnooper
import sys

class C:
    pass

def f():
    pass

a = 1

with pysnooper.snoop(depth=2):
    2 + 2

produces this output

New var:....... __name__ = '__main__'
New var:....... __doc__ = None
New var:....... __package__ = None
New var:....... __loader__ = <_frozen_importlib_external.SourceFileLoader object at 0x7f015d3adfd0>
New var:....... __spec__ = None
New var:....... __annotations__ = {}
New var:....... __builtins__ = <module 'builtins' (built-in)>
New var:....... __file__ = 'q.py'
New var:....... __cached__ = None
New var:....... pysnooper = <module 'pysnooper' from '/home/bay/tmp/249_pysnooper/PySnooper/pysnooper/__init__.py'>
New var:....... sys = <module 'sys' (built-in)>
New var:....... C = <class '__main__.C'>
New var:....... f = <function f at 0x7f015d3e61e0>
New var:....... a = 1
00:51:25.580167 line        14     2 + 2

Here we can see functions, classes, modules, and special variables, declared earlier.

The idea of this one-line patch is to remember the local variables state before the first call, in the __enter__ function:

        self.frame_to_local_reprs[calling_frame] = get_local_reprs(calling_frame)

This adds the symmetry with the __exit__ function, because it contains

        self.frame_to_local_reprs.pop(calling_frame, None)

and also solves the problem:

00:51:43.395931 line        14     2 + 2

Fixes: #218

This is the minimum I had to implement to make the tests compatible with Python 3.10. I also did some improvements in configs for CI and tests.

I'm not sure what is your approach to flake8 and pylint because there are already many errors and it's hard to find the ones possible caused by me here. Also, it's kinda verbose to use the names for keyword arguments instead of **kwargs for the optional ones but I've followed the current codebase.

All unit tests are passing locally so we'll see what CI thinks about it.

normalizing output - removing machine specific data:

absolute paths are replaced with the basename of the path.
time stamps are removed.
default (CPython) reprs of the form <.... at 0x[0-9a-fA-F] > will not contain the 'at 0x...' ending.

tests:

normalization does not affect the original test results so every test now runs with normalize=True
and normalize=False to preserve compatability.
assert_output can now verify the output of a normalized trace.

readme:

• updated accordingly

This implements https://github.com/cool-RR/PySnooper/issues/150 by allowing the same decorator to be applied to a decorator or to a class.

Based on input from @alexmojaki I have added tests to verify that snoop at least does not actively break properties or other methods with decorators. The output is probably suboptimal/confusing in those cases, but I think that should be OK given the warning in README.md.

This separates the concerns of tracing (gathering data), formatting the data, and writing the formatted data. The code is much more organised and easier to read, modify, and test, and the library is easier to externally customise and extend.

The next stage is to remove the use of regexes from tests. Instead, test entries will be compared with the unformatted data directly.

After that, I'd like to make my own separate library which uses pysnooper at its core while adding additional functionality through dependencies. For example, I'd like to have output colouring including syntax highlighting using pygments and colorama.

In the long term, this will also enable a radically different infrastructure such as writing to a database and then viewing the logs in a web UI.

And then, I'd like to understand how to git.

As requested in #1 , it would be nice to have colored output also for Windows, which should be possible, even though not as easily as in unix.

I don't think I can currently implement it (as I'm also not using PySnooper very often).

Hi,

I would like to trace the http request handling of Django in my development environment.

But I am sure that the bug is in my code, not in the code of Django.

I would like to see every line of my code, excluding Django, standard library and other libraries.

I had a look at the arguments which snoop() accepts, but I think it is not possible up to now.

Would you accept a PR which implements this?

Do you have a hint how to implement this?

See https://github.com/alexmojaki/snoop/pull/34

Basically you need to do this:

https://github.com/alexmojaki/snoop/blob/437956c661184ab458a3f60fcf97c81c31ea2db1/snoop/tracer.py#L213-L217

In particular you need calling_frame.f_trace = previous_trace in addition to the existing sys.settrace(previous_trace).

This is obviously good for restoring the other tracer properly, which I confirmed with the PyCharm debugger. But I stumbled across this because pp stopped working after with snoop: exited. It turns out that if you don't reset f_trace then the frame line number becomes wrong. Here's a demo:

import inspect
import pysnooper

with pysnooper.snoop():
    pass

print(inspect.currentframe().f_trace)
print(inspect.currentframe().f_lineno)  # wrong lineno
1/0  # wrong lineno in traceback

In particular note the weird traceback:

Traceback (most recent call last):
  File "...", line 5, in <module>
    pass
ZeroDivisionError: division by zero

Here's a pure python version of the demo:

import inspect
import sys

frame = inspect.currentframe()

frame.f_trace = lambda *_: print('tracing', frame.f_lineno) or frame.f_trace
sys.settrace(frame.f_trace)

# frame.f_trace = None  # uncomment to fix
sys.settrace(None)

print('after trace', frame.f_lineno)  # wrong lineno
1/0  # wrong lineno in traceback

This is a bug which is apparently fixed in 3.10: https://bugs.python.org/issue42823

I found a bug with relative_time when used with a generator. The times shown seem to be reset at some point. I don't know whether this bug could also happen without generators.

@iory Can you take a look at this bug?

@alexmojaki I suspect that this has something to do with the start_times dict you suggested.

Sample:

import pysnooper
import time

def g():
    time.sleep(0.1)
    yield 8
    time.sleep(0.1)

@pysnooper.snoop(relative_time=True)
def f():
    time.sleep(0.1)
    yield from g()
    time.sleep(0.1)


tuple(f())

Output:

Source path:... C:\Users\Administrator\Desktop\fuck.py
00:00:00.000000 call        10 def f():
00:00:00.000000 line        11     time.sleep(0.1)
00:00:00.100000 line        12     yield from g()
00:00:00.200000 return      12     yield from g()
Return value:.. 8
Elapsed time: 00:00:00.200000
00:00:00.000000 call        12     yield from g()
00:00:00.100000 exception   12     yield from g()
StopIteration
00:00:00.100000 line        13     time.sleep(0.1)
00:00:00.207002 return      13     time.sleep(0.1)
Return value:.. None
Elapsed time: 00:00:00.207002

There is a minor bug at the nesting case. Following is the example.

import time
import pysnooper

snoop = pysnooper.snoop()

def test():
    with snoop:
        a = 10
        with snoop:
            time.sleep(1.0)
        a = 20
        time.sleep(1.0)


test()

The output is the following.

Source path:... <ipython-input-2-9ee7fdb55b80>
22:57:41.232785 line        11         a = 10
New var:....... a = 10
22:57:41.232850 line        12         with snoop:
22:57:41.232936 line        13             time.sleep(1.0)

The debug outputs of the a = 20 and time.sleep(1.0) are vanished. I don't think we'll use it like this, but I'll report it.