classification
Title: trace.py bug with the main file being traced
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.1, Python 3.2, Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: belopolsky Nosy List: belopolsky, eli.bendersky, ezio.melotti, flox
Priority: normal Keywords: patch

Created on 2010-07-21 14:30 by eli.bendersky, last changed 2010-09-13 17:41 by belopolsky. This issue is now closed.

Files
File name Uploaded Description Edit
traceme.py eli.bendersky, 2010-07-21 14:30
issue9323.1.patch eli.bendersky, 2010-07-21 14:32
issue9323_regrtest.diff flox, 2010-09-13 16:05 Patch, apply to 3.x
Messages (10)
msg111066 - (view) Author: Eli Bendersky (eli.bendersky) * (Python committer) Date: 2010-07-21 14:30
[This bug was discovered by Alexander Belopolsky, during the work on Issue 9317]

Bug report
**********

The attached traceme.py file demonstrates the following problem:

With python 2.7:
$ python2 -m trace  -c -s traceme.py
lines   cov%   module   (path)
    1   100%   threading   (Lib/threading.py)
    6   100%   traceme   (traceme.py)

The first entry is clearly spurious, but traceme looks right.  With py3k, however, I get

$ python3 -m trace  -c -s traceme.py
lines   cov%   module   (path)
    1   100%   threading   (Lib/threading.py)

No traceme line at all.

Analysis
********

When trace.py actually runs the script, it uses this code in 3.x:

           t.run('exec(%r)' % (script,))

instead of this code in 2.x:

            t.run('execfile(%r)' % (progname,))

`exec` doesn't have the program name to attach to the code object created, and calls it '<string>' by default. However, this file name is ignored by the trace module.

`execfile` doesn't exist in 3.x, so an alternative approach is needed.

Proposed solution
*****************

Instead of t.run as displayed above, use this code:

            with open(progname) as fp:
                code = compile(fp.read(), progname, 'exec')
                t.run(code)

The code object created by `compile` attaches the program name and is executable by t.run (because t.run actually calls `exec` which can run the result of `compile`).

This solution fixes the problem:

$ py3d -m trace -c -s traceme.py 
lines   cov%   module   (path)
    1   100%   threading   (/home/eliben/python_src/eliben-py3k/Lib/threading.py)
    6   100%   traceme   (traceme.py)

I'll attach a patch file that was creates vs. the latest trunk, with this fix.
msg111074 - (view) Author: Alexander Belopolsky (belopolsky) * (Python committer) Date: 2010-07-21 15:21
[Copying msg111059 from issue9317]

On Wed, Jul 21, 2010 at 9:45 AM, Eli Bendersky <report@bugs.python.org> wrote:
..
> As far as I understand, when you run:
>
>    py3d -m trace -C pickle-trace.d -c -m test_pickle.py
>
> The first -m flag applies to the trace module. Python uses
> runpy.run_module to load it, and then passes it its arguments (-C and
> onwards).
>
When I said "run from command line", I meant something like

$ python Lib/test/test_pickle.py

I am not sure if this uses runpy machinery, but I suspect it does.

 The trace output should not include runpy calls that load the trace
module itself, but

$ python -m trace <flags> Lib/test/test_pickle.py

might show the runpy calls that occur when you run

$ python Lib/test/test_pickle.py

without tracing.   BTW, too bad that '-m' is taken, but I think
trace.py should grow a --run-module option so that you can trace
equivalents of python -m executions:

$ python -m trace <flags> --run-module test.test_pickle

> Moreover, since runpy is only the machinery to execute trace.py, does
> it even make sense to include it in coverage?
>
> What do you think?

I think you should ask python-dev. :-)  Note that most C/C++ coverage
tools do include  pre-main calls in coverage.  In case of C++, a lot
of things may happen before main().

Whatever the solution is, it should be unified between trace, profile,
and pdb modules.
msg111094 - (view) Author: Alexander Belopolsky (belopolsky) * (Python committer) Date: 2010-07-21 17:52
Committed with a minor change.  (There is no need to keep the source file open during the trace run.)  See r83035 (r83037 in release31-maint.)

I will open a separate issue to discuss a possible RFE related to msg111074.
msg113144 - (view) Author: Alexander Belopolsky (belopolsky) * (Python committer) Date: 2010-08-06 23:40
Reopening because I think this fix is responsible for a new problem:

$ ./python.exe -m trace -C. -s -c Lib/test/regrtest.py 
Traceback (most recent call last):
  ...

  File "Lib/test/regrtest.py", line 1458, in <module>
    assert __file__ == os.path.abspath(sys.argv[0])
AssertionError
[98796 refs]
msg113152 - (view) Author: Eli Bendersky (eli.bendersky) * (Python committer) Date: 2010-08-07 06:41
It appears to affect 2.7 as well (probably because of a back-port from py3k to 27-maint in revision 83421).
msg113153 - (view) Author: Eli Bendersky (eli.bendersky) * (Python committer) Date: 2010-08-07 06:50
Looking at Lib/test/regrtest.py:

  if __name__ == '__main__':
      # Simplification for findtestdir().
      assert __file__ == os.path.abspath(sys.argv[0])

I'm not sure regrtest.py is prepared to be run from trace at all. Note that this error also happens when running 'python -m profile regrtest.py', so it's rather regrtest.py specific than trace.py specific.

Anyway, trace.py itself currently passes the cmd-line argument as __file__ and not its full path, which causes the breakage in regrtest.py. The full path *could* be easily passed, but I think we should address this problem from regrtest.py's side.
msg116307 - (view) Author: Alexander Belopolsky (belopolsky) * (Python committer) Date: 2010-09-13 14:12
>  The full path *could* be easily passed, but I think we should
> address this problem from regrtest.py's side.

I disagree.  There may be other scripts that rely on __main__.__file__ being an absolute path and we cannot require everyone to change their assumptions to make their scripts traceable.

It looks like absolute path assumption was added by Florent in r78723 (r78719 in trunk).  Florent, I would like to hear from you before deciding how to proceed.  See also issue #7712.
msg116321 - (view) Author: Florent Xicluna (flox) * (Python committer) Date: 2010-09-13 16:05
I've made the wrong assumption that test.regrtest.__file__ is always absolute.

Here is a patch which should fix it.
msg116333 - (view) Author: Florent Xicluna (flox) * (Python committer) Date: 2010-09-13 17:40
regrtest fixed with r84776 (3.x) and r84779 (2.7)
msg116334 - (view) Author: Alexander Belopolsky (belopolsky) * (Python committer) Date: 2010-09-13 17:41
Thanks, Florent.
History
Date User Action Args
2010-09-13 17:41:50belopolskysetstatus: open -> closed

messages: + msg116334
2010-09-13 17:40:30floxsetmessages: + msg116333
2010-09-13 16:05:43floxsetfiles: + issue9323_regrtest.diff
nosy: + ezio.melotti
messages: + msg116321

2010-09-13 14:12:12belopolskysetnosy: + flox
messages: + msg116307
2010-08-07 06:50:53eli.benderskysetmessages: + msg113153
2010-08-07 06:41:04eli.benderskysetmessages: + msg113152
versions: + Python 2.7
2010-08-06 23:40:21belopolskysetstatus: closed -> open

messages: + msg113144
2010-07-21 17:52:31belopolskysetstatus: open -> closed
resolution: fixed
messages: + msg111094

stage: resolved
2010-07-21 15:21:50belopolskysetassignee: belopolsky

messages: + msg111074
nosy: + belopolsky
2010-07-21 14:32:24eli.benderskysetfiles: + issue9323.1.patch
keywords: + patch
components: + Library (Lib)
2010-07-21 14:30:31eli.benderskycreate