Brought up in bpo-9282: unit tests should be added for the trace module.

Minor naming problem: Lib/test/test_trace.py is currently employed for testing the sys.settrace method.

Suggestion: name the unit tests of the trace module test_trace_module.py

I am adding 2.7. It is ok to add tests to the stable series release AFAIK. Moreover, I believe the unittests should be written for 2.7 first. Since 3.x port of trace was done without the benefit of a test suite, it is likely that there are many differences in behavior that should be eliminated. (See bpo-9317.)

Please start with fine-graned "white-box" API tests. These are easier because you don't need to set up external scripts, capture output, etc. Just create a Trace object in setUp and call its various methods in test cases.

[from pydev discussion] I agree with renaming current test_trace to test_sys_settrace. If sys.settrace does more than line tracing, and the additional actions are not currently tested in the general sys test, then they should be, eventually, by someone, in a different issue.

I see two reasons to start with 2.7. First, the 2.7 code should be better since it will not have errors introduced by the 3.x port. Second, if one file does not work for both 2.7 and 3.1/2, 2to3 is more tested than 3to2. If 2.6 is not to be targeted, you can use any of the new 3.x features backported to 2.7. The main problem for 3.1+ should be any new bugs uncovered, other than the one fixed in bpo-9282. If features are added for 3.2, more tests will be needed for that.

I'm attaching a file with some unit tests for Lib/trace.py module in Python 2.7. Currently the unit tests check the API only, for line counting, func call counting and function caller relationships, because these can be tested through the API, without capturing stdout and resulting coverage files. All in all, these features are given a pretty good coverage.

I've named the file test_trace_module.py because test_trace.py hasn't yet been renamed in 2.7 and I don't want to get into the naming mess.

More tests can (and will) be added, but this is a start.

Lib/test/test_trace.py is now moved to Lib/test/test_sys_settrace.py.

3.2: r83140 r83141
3.1: r83143
2.7: r83142

Eli,

test_trace_module.py is a good start and I would like to commit it soon. I have a few nitpicks and a suggestion.

1. pprint module is not used in the tests so it should not be imported.
2. It is better to do run_unittest(name) in test_main() than list tests explicitly. run_unittest(name) will find all classes that derive from TestCase in the module. Note that not all test runners use test_main().
3. Please don't start docstrings with a space.
4. test_trace is out of the way in 2.7 now, so you can use proper name. If you use SVN, please do svn add Lib/test/test_trace.py with your next revision and post the output of svn diff.
5. A suggestion: since we are doing "white-box" testing of the Trace class, I would recommend calling Trace methods such as globaltrace or localtrace directly from unit tests rather than rely on settrace registrations. That may require faking frames, but I think you can get away with simply passing the current frame with the events. Whether or not sys.settrace is working correctly is tested in the old test_trace (renamed to test_sys_settrace) now.

Thanks for moving this forward.

Alexander,

1. Done

2. Done

3. Done. Made docstrings follow PEP-257, to the best of my understanding

4. Done. Attached patch is made on fresh SVN 2.7 branch, file renamed to test_trace.py and 'svn add' executed

5. I'm not sure I agree with you on this point. IMHO, it's taking the "whiteness" of testing a bit too far. I will explain:

The globaltrace and localtrace methods of Trace are quite thin, taking frame information and shoving it into an internal counts dict. To test them a lot of manual construction is required, which is very implementation dependent. In the future, Trace's implementation may be modified, and such tests will have to be completely re-coded as a result.

At the moment, checking Trace via its 'runfunc' API allows 100%
coverage on the relevant globaltrace and localtrace functions without getting into implementation details too deep. I think that given this there's no real point in getting deeper. Had I not been able to thoroughly examine their inner workings via runfunc, I would indeed consider getting deeper in the unit tests, but now I just don't really see the point.

I will defer to your judgement on the level of "whiteness" that is appropriate.

I have passed your patch through 2to3, replaced test_support with support and it looks like we have a test case for a regression in 3.x:

======================================================================
FAIL: test_loop_caller_importing (main.TestCallers)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "Lib/test/test_trace.py", line 203, in test_loop_caller_importing
    self.assertEqual(self.tr.results().callers, expected)
AssertionError: {(('/Users/sasha/Work/python-svn/py3k-commit/Lib/trace.py', 'trace', 'runfunc'), [truncated]... != {(('Lib/test/test_trace.py', 'test_trace', '_traced_func_importing'), ('fakefile [truncated]...
Diff is 973 characters long. Set self.maxDiff to None to see it.

I am attaching a py3k patch. Let's decide how to proceed. I would like to commit 3.x and 2.x versions at the same time. Ideally together with fixes for 3.x bugs. Another approach would be to temporarily disable failing tests in 3.x, but that would make merging between branches more difficult.

A few more nitpicks:

1. There is no need to use leading or trailing underscores in function or variable names.

2. It would make code more readable if you use longer name for the Trace instance: 'trace' or 'tracer' instead of 'tr'.

3. Your file seems to have white space issues. Please run "make patchcheck".

4. This may be gratuitous, but I would rather see "func" instead of "foo" and testmodule, testfile, etc. instead of fake*.

The test failure of the py3k ports boils down to this: the 'runfunc' method of 'Trace' appears as a caller to '_traced_func_importing_caller'. In 2.7 it appears as 'Trace.runfunc', in py3k as just 'runfunc'.

This raises a question: should method names of classes come after the class names when appearing in a trace? Intuitively yes, but I want to investigate some more, probably by adding a couple more test cases where the traced functions are methods of objects rather than plain functions.

I hope to get to it later today. If not, later this week. In any case, I will address both this issue and your other comments and will submit a new patch.

Thanks for the quick review.

On Mon, Jul 26, 2010 at 12:49 AM, Eli Bendersky <report@bugs.python.org> wrote:
..

This raises a question: should method names of classes come after the class names when appearing
in a trace? Intuitively yes, but I want to investigate some more, probably by adding a couple more test
cases where the traced functions are methods of objects rather than plain functions.

I want to agree, but finding the class name of the method may not be
trivial in 3.x because we don't have unbound methods anymore. Please
bring this up on python-dev.

I am attaching a patch, bpo-9315-trace-fix.diff, that fixes a py3k bug exposed by bpo-9315.1-py3k.patch tests.

One of the 3.x changes that caused the failure was that frames now have a __doc__ attribute and cannot be distinguished from functions. I replaced the hasattr(f, "__doc__") with hasattr(f, "__annotations__"), but I wonder if it would be better to use something like isinstance(f, types.FunctionType) there.

Eli, in order to test the trace module more thoroughly, you need to add generators, list and set comprehensions and instance, class, and static methods to your fake module and test tracing of their execution.

Alexander, it looks like you broke all the 2.7 buildbots. Could you take a look, please?

I am on a train. Can take a look in about an hour, but I did not
commit anything related to this issue recently.

On Jul 28, 2010, at 9:30 AM, Antoine Pitrou <report@bugs.python.org>
wrote:

Antoine Pitrou <pitrou@free.fr> added the comment:

Alexander, it looks like you broke all the 2.7 buildbots. Could you
take a look, please?

----------
nosy: +pitrou

---

Python tracker <report@bugs.python.org>
<http://bugs.python.org/issue9315\>

---

Yep, this looks like me. Will fix shortly. Feel free to revert my
change if it stops you.

On Jul 28, 2010, at 9:39 AM, Antoine Pitrou <report@bugs.python.org>
wrote:

>
> Antoine Pitrou <pitrou@free.fr> added the comment:
>
> test test_sys_setprofile crashed -- <type 'exceptions.ImportError'>:  
> cannot import name support
> Traceback (most recent call last):
>  File "./Lib/test/regrtest.py", line 863, in runtest_inner
>  File "/home/buildbot/slave/py-build/2.7.norwitz-amd64/build/Lib/ 
> test/test_sys_setprofile.py", line 5, in <module>
>    from test import support
> ImportError: cannot import name support
>
> test test_sys_settrace crashed -- <type 'exceptions.SyntaxError'>:  
> unqualified exec is not allowed in function  
> 'test_jump_to_firstlineno' it contains a nested function with free  
> variables (test_sys_settrace.py, line 777)
> Traceback (most recent call last):
>  File "./Lib/test/regrtest.py", line 863, in runtest_inner
> SyntaxError: unqualified exec is not allowed in function  
> 'test_jump_to_firstlineno' it contains a nested function with free  
> variables (test_sys_settrace.py, line 777)
>
> 

---

Python tracker <report@bugs.python.org>
<http://bugs.python.org/issue9315\>

---

test test_sys_setprofile crashed ...

Fixed in r83204 - r83206.

Some more unit tests show that a problem with method names exists in Lib/trace.py even in 2.7 (and probably earlier). When tracing an instance method with runfunc, its name is reported as follows:

ClassName'>.method_name

Instead of:

ClassName.method_name

Alexander, the part of your fix to trace.py in the file_module_function_of method fixes this problem. It should be applied to 2.7 as well, though.

Eli,

Thanks a lot for your continuing effort. I would like to check in
your work before any further enhancement. Please find a reasonable
stop point and post a commit ready patch preferably with a news file
entry describing the bug that is fixed. Note that test additions
don't get a NEWS entry - I'll describe those in the checking log
entry. Unless you think 2.7 backport is tricky, please post only py3k
patch. I'll merge the changes.

Thanks.

Attaching new patch. This patch is for 2.7 (as you suggested earlier, since it's easy to forward-port to py3k with 2to3) and affects Misc/NEWS, Lib/trace.py and Lib/test/test_trace.py (which is added).

In Lib/trace.py:

• Fixed the problem with class names (taken from Alexander's patch for py3k) when tracing methods. Documented this change in Misc/NEWS. Note that I did not include the __annotations__ change because I wasn't sure how it applies to 2.x

Lib/test/test_trace.py:
Added new unit-testing file for the trace module. Changes since the last patch:

• Implemented the changes suggested by Alexander (a few more nitpicks) in http://bugs.python.org/issue9315#msg111592, except changing fake* to test* because I thought test* in this context is confusing with the main purpose of the code (testing), and fake* conveys the meaning pretty well.

• Added tests for tracing instance methods (not yet class methods or static methods because the semantics of tracing these aren't 100% clear to me yet), and for generators and list comprehensions.

Ouch, sorry.... Here it is (bpo-9315.1.patch)

[I wish I could edit/delete my older messages]

I've attached a new file, named bpo-9315.2.patch, with the updated patch. I usually add a numeric prefix before the .patch ending to distinguish consecutive versions of the same patch, and in this case I just submitted the wrong file.

The new one should be correct, though.

Eli,

I was about to commit bpo-9315.3.patch, which is a lightly modified version of bpo-9315.2.patch, but it turned out that test_trace cannot be run by regrtest.py:

$ ./python.exe Lib/test/regrtest.py test_trace
test_trace
test test_trace failed -- multiple errors occurred; run in verbose mode for details
1 test failed:
    test_trace

It looks like your fake module machinery is a little too clever.

Alexander,

Your bpo-9315.3.patch file doesn't contain the new test module at all.

I'm attaching the updated test_trace.py, fixing the problem with running via regrtest. The problem was very simple and not about the fake module - I fixed to runctx with globals() and vars() instead of run on tracer (since the called function is in my module). The fix is on line 218 (with a docstring fix on line 213).

Now py27 regrtest.py -v test_trace passes cleanly. I apologize for not trying it before. I'll learn for the future :-)

I'm attaching a new patch for unit-testing of trace.py. Changes:

1. Fixed the problems that caused failures when run through regrtest
2. Added the test class from bpo-3821
3. Removed the fake module creation, replacing it with a directory named 'tracedmodules' in Lib/test where a test module resides. If you can think of a better name, please let me know.

As far as I see, the tests now run correctly both stand-alone and as part of 'python regrtest.py'. I have also fixed all whitespace issues. The patch was created vs. latest SVN checkout from the 2.7 maintenance branch.

Comments on bpo-9315.27-maint.5.patch:

1. I think you forgot to svn add Lib/test/init.py.

2. Instead of "import tracedmodules.testmod", please use something like "from test.tracedmodules import testmod". There is no need to use implicit relative import and this is different from accepted practice.

def traced_func_importing(aa, bb):
    from tracedmodules.testmod import func

Same comment as in #2 above. No need for implicit relative import here. Also I am not sure it is interesting to test tracing the import statement inside a function. Tests for tracing calls to imported functions are good, but I am not sure import itself generates any interesting events. Just give it a thought - I don't have an informed opinion.

4. Shouldn't all traced functions go to tracedmodules?

5. Please add comments to functions used for line tracing that changing relative or absolute (if matters) line numbers will break the tests.

6. Add comments to testmod.py.

7. You lost changes I made in bpo-9315.4-release27.patch. Specifically, using trailing underscores or double letters to resolve conflicts between variable names is not common style. Trailing underscore convention is for resolving conflicts with python keywords.

8. Please rewrap text in README to fit in 80 columns. In fact, this text belongs to __init__.py docstring and the comment about importance of function location should go next to each (currently one) function for which location is important.

9. fix_pyc_ext(filename) description is misleading. It does not care about incoming filename extension and just whatever extension with '.py'. This is probably good because it works with both '.pyc' and '.pyo', but the name and the docstring suggest otherwise. Note the similar logic in the trace module itself is implemented as follows:

            if filename.endswith((".pyc", ".pyo")):
                filename = filename[:-1]   

I also feel that three functions to just compute ('test_trace.py', 'test_trace') tuple is an overkill. Please look in the inspect module for possible alternatives. Also rather than recomputing these strings in each test case, I would just assign them to module global variables say THIS_FILE_NAME and THIS_MODULE_NAME.

10. A nitpick. I don't think I've ever seen test_main() function called "Driver" in the python test suite. Please try to keep consistency in terminology and coding style between the test modules to the extent it is practical.

11. Similar to bpo-29474: Improve documentation for weakref.WeakValueDictionary #10. I've changed 'ZZZ' to 'XXX' in bpo-9315.4-release27.patch, but you lost that change. See msg112230 above.

[attaching a new patch version]

1. Are you refering to Lib/test/tracedmodules/init.py? I did add it - it appears in the patchfile. What do you mean?

2. Fixed

3. Fixed

4. I'm not sure. Tracing of the current file is also a common use case, and I really only created the tracedmodules package to test tracing throughout module boundaries. Anyway I don't have a strong opinion on this issue, so if you think it's important I can move them.

5. 8. I added a comment above the traced functions. For (8) moved the content of README into __init__.py, which documents this re the tracedmodules files in the tracedmodules/ dir.

6. I've documented this in the __init__.py file, once and globally for all traced modules as I don't want to repeat the same comment for each file that may be created there in the future. If you think this isn't enough, please advise re the comment you'd like to see in there.

7. Fixed

8. Modified the function's name to fix_ext_py and its functionality to what trace and some other modules do. Removed the 'modname' function and folded its functionality into my_file_and_modname. Re the latter, I prefer to leave it as a function because it's more flexible this way (flexible for changes in the trace format, for example), and also I almost always use the pair as a tuple anyway, so the function's returning the tuple is more convenient than always pairing two long constant names. The cost of recomputation is meaningless in the context of this code.

9. Fixed

10. Fixed

Hmm, it looks like patches 5 and 6 lost the fix for the class name issue. I'll check if I can merge in patch 4.

Committed with minor changes in r84777.

Eli, please keep lines under 80 characters.

Leaving the issue open pending py3k port.

Eli, while porting your tests to py3k, I had to change expected output for list comprehension testing. This is not really surprising because 3.x comprehensions differ from 2.x (they don't leak the loop variable anymore).

The difference between versions is most pronounced if a comprehension is spread in several lines:

l = [i for
     i in
     range(10)]

The coverage of the above code in 2.x is

1: l = [i for
        i in

11: range(10)]

but in 3.x, I get

12: l = [i for
10: i in
1: range(10)]

Not surprisingly, 3.x coverage output for generators is the same as for comprehensions:

12: l = list(i for
10: i in
1: range(10))

but in 2.x,

12: l = list(i for
i in
1: range(10))

In any case, I think the counts from the second and third line (10 and 1) are probably correct in 3.x, but I cannot explain 12 in the first line.

Committed in:

py3k: r84780
release31-maint: r84783
release27-maint: r84777

Need a separate issue for the problem highlighted in msg116336.

You probably missed Lib/test/tracedmodules/ in r84780 ;)

You must be right. I thought I did all the svn adds, but may have missed something. I'll take care of this tonight, but I am off the grid for the next 3-4 hours.

On Sep 13, 2010, at 3:13 PM, Florent Xicluna <report@bugs.python.org> wrote:

Florent Xicluna <florent.xicluna@gmail.com> added the comment:

You probably missed Lib/test/tracedmodules/ in r84780 ;)

----------
keywords: +buildbot
nosy: +flox

---

Python tracker <report@bugs.python.org>
<http://bugs.python.org/issue9315\>

---

You probably missed Lib/test/tracedmodules/

fixed in r84794.

Note that if you add new directories under /Lib, you need to make the build system aware of them in several places (I don't remember all of them right now, one is in the Makefile). Otherwise they don't get shipped and/or installed, and tests fail.

On Tue, Sep 14, 2010 at 2:29 AM, Georg Brandl <report@bugs.python.org> wrote:
..

Note that if you add new directories under /Lib, you need to make the build system aware of them in several
places (I don't remember all of them right now, one is in the Makefile).  Otherwise they don't get shipped
and/or installed, and tests fail.

It looks like the right place is the LIBSUBDIRS variable in Makefile.
I guess I need to edit Makefile.pre.in to change it.

Yep. But there are other files to edit for the Windows distribution.

It looks like lots of 3.1 buildbots are unhappy with r84783.
But the test passes on my local 3.1 checkout.

======================================================================
FAIL: test_trace_list_comprehension (test.test_trace.TestLineCounts)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/srv/buildbot/buildarea/3.1.bolen-ubuntu/build/Lib/test/test_trace.py", line 172, in test_trace_list_comprehension
    self.assertEqual(self.tracer.results().counts, expected)
AssertionError: 
  {('/srv/buildbot/buildarea/3.1.bolen-ubuntu/build/Lib/test/test_trace.py', 71): 10,
   ('/srv/buildbot/buildarea/3.1.bolen-ubuntu/build/Lib/test/test_trace.py', 74): 1,
-  ('/srv/buildbot/buildarea/3.1.bolen-ubuntu/build/Lib/test/test_trace.py', 75): 13,
?                                                                                  ^

+ ('/srv/buildbot/buildarea/3.1.bolen-ubuntu/build/Lib/test/test_trace.py', 75): 12,
? ^

('/srv/buildbot/buildarea/3.1.bolen-ubuntu/build/Lib/test/test_trace.py', 76): 1}

----------------------------------------------------------------------
Ran 13 tests in 3.541s

http://www.python.org/dev/buildbot/all/builders/x86%20Ubuntu%203.1/builds/1036

Updated Makefile in r84803 - r84805.

The issue on 3.1 happens when Python is configured --with-computed-gotos.
(this is the case on all 3.1 buildbots)

But this issue does not happen on 3.x branch. On this branch computed-gotos is the default, but the switch --without-computed-gotos does not make a difference.

Antoine suggests to relax the test and only check if the count is within a range (12, 13).

Antoine suggests to relax the test and only check
if the count is within a range (12, 13).

This feels like implementation driven testing. I would prefer to disable the offending test pending further investigation into the core cause.

It is not clear to me that these differences between 2.x and 3.x are not bugs. It seems to me that the 2.x/3.x difference discussed in msg116336 above is simply manifestation of --with-computed-gotos becoming default in 3.x.

It looks like 3.1 with computed gotos produces the yet another different tracing of list comprehensions:

2: l = [i for

10: i in
1: range(10)]

It looks like 3.1 with computed gotos produces the yet another different tracing of list comprehensions:

2: l = [i for

10: i in
1: range(10)]

Well, this kind of thing is going to depend on the exact bytecode, the
way the evaluation loop is written, etc. That's why I would suggest
checking that the number of traced iterations is between, e.g. 10 (since
it's the number of loop iterations) and 15 (to account for any
additional "iterations" due to various inner jumps in the bytecode.

Is it really *interesting* to trace separate parts of list comprehensions
like this? What would one want to do that? The only idea I have in mind of
perhaps for comprehensions containing 'if's, to know how many times the
comprehension was actually executed.

In any case, this indeed depends quite a lot on the internal representation
of comprehensions.

Is it really *interesting* to trace separate parts of list
comprehensions like this?

It may or may not be useful for tracing code in the wild, but it helps to isolate the causes of count mismatches.

I am attaching a file, x.py, that shows differing behavior for 3.1 and 3.2 and with and without computed gotos in each version.

The traced code is

2 def f():
3 return [i
4 for i
5 in range(10)]

and the script prints the disassembly of f including the listcomp object.

The results are (s/g - with/without computed gotos):

3.1s: {('x.py', 3): 2, ('x.py', 5): 1}
3.1g: {('x.py', 4): 10, ('x.py', 3): 2, ('x.py', 5): 1}
3.2s: {('x.py', 3): 12, ('x.py', 5): 1}
3.2g: {('x.py', 4): 10, ('x.py', 3): 12, ('x.py', 5): 1}

Note that the bytecode is the same in all cases:

3 0 LOAD_CONST 1 (<code object <listcomp> at 0x1005250b8, file "x.py", line 3>)
3 MAKE_FUNCTION 0

5 6 LOAD_GLOBAL 0 (range)
9 LOAD_CONST 2 (10)
12 CALL_FUNCTION 1
15 GET_ITER
16 CALL_FUNCTION 1
19 RETURN_VALUE
listcomp:
3 0 BUILD_LIST 0
3 LOAD_FAST 0 (.0)
>> 6 FOR_ITER 12 (to 21)

4 9 STORE_FAST 1 (i)
12 LOAD_FAST 1 (i)
15 LIST_APPEND 2
18 JUMP_ABSOLUTE 6
>> 21 RETURN_VALUE

I am attaching another test file, y.py, which shows that the cause of discrepancy is outside of the trace module. The traced function is the same as in x.py only with 5 iterations instead of 10 for brevity, but instead of using trace module, I am registering a custom trace function like this:

lines =	[]
def tracefunc(frame, what, arg):
    if what == 'line':
	lines.append(frame.f_lineno)
    return tracefunc
sys.settrace(tracefunc)

3.1s: [3, 5, 3]
3.1g: [3, 5, 3, 4, 4, 4, 4, 4]
3.2s: [3, 5, 3, 3, 3, 3, 3, 3]
3.2g: [3, 5, 3, 4, 3, 4, 3, 4, 3, 4, 3, 4, 3]

Interestingly, this shows that effect of computed gotos is the same in 3.1 and 3.2 - adding a line event from "for i" line.

This situation illustrates the reason why I wanted to use synthetic events to test the trace module rather than events generated by settrace machinery. Apparently these differences have nothing to do with trace.py and everything with ceval.c. If it is important to maintain stability of trace events between python versions, tests (with appropriate sensitivity) should be added to test_sys_setrace.

On the other hand, there are a lot of things that can go wrong in trace.py - extracting code information from frame, divining the method and class names etc. Ideally, this logic should be tested without reliance on details of event generation.

Raymond asked on IRC why this work is being back-ported. The answer is that it is being forward-ported rather than back-ported. The trace module had no unittests in either 2.x or 3.x and was very buggy in 3.x. Presumably, 2.x version saw more use and was likely to be more correct than 3.x, so we decided to start with adding unit tests to 2.7 and then port the tests to 3.x while fixing the bugs. See msg111134.

This does not necessarily mean that we need to include 3.1. It may be appropriate to limit what is going to 3.1 to tests that support bug fixes.

If nobody raises an objection, I am going to close this issue by removing list comprehension test from 3.1 and will open a separate "interpreter core" issue for line tracing inconsistencies.

I agree with finishing this and opening a separate issue with respect to list comp behavior. The latter seems peripheral to the purpose of this issue.

See issue bpo-9866 for follow ups on list comprehensions' tracing.

List comprehension test is removed from 3.1 in r84848.