Trace function changed warning when using threads

[nedbat]

Originally reported by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren)

---

When I run coverage.py on the following script I get a message about measurements being wrong:

$ $ coverage run script.py
Hello
Coverage.py warning: Trace function changed, measurement is likely wrong: None

The script:

import threading
import time

class MyThread (threading.Thread):
    def run(self):
        print "Hello"


thr = MyThread()
thr.start()
thr.join()

The script does have full coverage in the report though.

This is using python 2.7.2 on MacOSX 10.7.2 and coverage.py 3.5.1. Python was installed using the binary installer on the python.org website.

---

• Bitbucket: https://bitbucket.org/ned/coveragepy/issue/164

[nedbat]

I'm sorry, I can't reproduce this problem. Is there anything else in your environment that might be interfering with the trace function?

[nedbat]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren)

---

Not that I know of, sys.path and sys.modules look sane when I print them at the point that the warning is generated (no code beyond the std, coverage.py and the test script is loaded)).

I'll try to reproduce the issue on another machine and with a clean install of python in a different sys.prefix.

In the mean time I have another datapoint, although I don't know if it is relevant. I've patched the start and stop methods of the Tracer object to print when they are called including the thread id. The output is then:

<coverage.collector.PyTracer object at 0x1012c6290>: start tracer on [140735149791584 (bb)](https://bitbucket.org/ned/coveragepy/commits/140735149791584)
<coverage.collector.PyTracer object at 0x1012c63d0>: start tracer on [4319088640 (bb)](https://bitbucket.org/ned/coveragepy/commits/4319088640)
Hello
<coverage.collector.PyTracer object at 0x1012c6290>: stop tracer on [140735149791584 (bb)](https://bitbucket.org/ned/coveragepy/commits/140735149791584)
Coverage.py warning: Trace function changed, measurement is likely wrong: <bound method PyTracer._trace of <coverage.collector.PyTracer object at 0x1012c6290>>
<coverage.collector.PyTracer object at 0x1012c63d0>: stop tracer on [140735149791584 (bb)](https://bitbucket.org/ned/coveragepy/commits/140735149791584)
Coverage.py warning: Trace function changed, measurement is likely wrong: None

Bother tracer objects are stopped on the main some thread, which explains the last warning (and explains why the actual data collected seems to be correct regardless of the warning).

[nedbat]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren)

---

The trace above contains a second warning about the trace function, which is likely caused by my tweaks. This output is with a clean install of coverage.py with only changes to the start/stop methods:

coverage run t.py<coverage.collector.PyTracer object at 0x1012cda50>: Start on thread: [140735149791584 (bb)](https://bitbucket.org/ned/coveragepy/commits/140735149791584)
<coverage.collector.PyTracer object at 0x1012cdb90>: Start on thread: [4319088640 (bb)](https://bitbucket.org/ned/coveragepy/commits/4319088640)
Hello
<coverage.collector.PyTracer object at 0x1012cda50>: Stop on thread: [140735149791584 (bb)](https://bitbucket.org/ned/coveragepy/commits/140735149791584)
<coverage.collector.PyTracer object at 0x1012cdb90>: Stop on thread: [140735149791584 (bb)](https://bitbucket.org/ned/coveragepy/commits/140735149791584)
Coverage.py warning: Trace function changed, measurement is likely wrong: None

Both tracers are still stopped on the main thread, but the other warning is now gone.

[nedbat]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren)

---

This seems to be a real bug:

• class Collector adds a settrace function to the threading module
• this settrace function (Collection._installation_trace) sets the sys.tracehook to the _trace method a new PyTracer object and adds that to the list of tracers for the Collector
• Collector.stop() is called when the script stops and that calls the stop method of all PyTracers in the list
• PyTracer.stop checks if the trace function changed, but that code assumes that stop is called on the same thread as where the PyTracer.start method was called, and that is not true for any PyTracer objects for threads other than the main thread.

If I'm correct this is a very minor bug though, it is just a confusing message and does not affect the collection of coverage data.

[nedbat]

An attempt on a Mac didn't show the problem either:

$ cat test.py 
import threading
import time

class MyThread (threading.Thread):
    def run(self):
        print "Hello"


thr = MyThread()
thr.start()
thr.join()
$ coverage run test.py 
Hello
$ coverage report -m
Name    Stmts   Miss  Cover   Missing
-------------------------------------
test        8      0   100%   
$ python -V
Python 2.7.1
$ coverage help
Coverage.py, version 3.5.1
...

$ system_profiler SPSoftwareDataType
Software:

    System Software Overview:

      System Version: Mac OS X 10.6.4
...

[nedbat]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren)

---

I don't get the error in a VM running 10.6, but do get it when running 10.7 even with a clean reinstall of python 2.7.2. Both machines run exactly the same version of python and coverage.py.

The problem does not occur with /usr/bin/python, which is 2.7.1 + patches.

This is likely either a platform bug or an issue in python itself, I'll look into this and will report back when I have more information.

[nedbat]

Original comment by Ben Sizer (Bitbucket: kylotan, GitHub: kylotan)

---

I see this on Windows 7 (64bit OS, but 32 bit Python 2.7.2). I don't think I ever saw it on Windows XP, which I used earlier in the year, but don't hold me to that. I don't think I saw it before 3.5.1 either, but again I can't be positive about that.

It doesn't seem to affect any of the output's accuracy.

[nedbat]

Original comment by Zan Dobersek (Bitbucket: zdobersek, GitHub: zdobersek)

---

I can still confirm this on ToT coveragepy when using PyTracer, i.e. when running coverage run --timid bug.py. This doesn't occur when using CTracer.

Python v2.7.3, Ubuntu Linux.

Looking at the code, it seems all the tracers are being stopped on the main thread while only the first tracer was created there. Stopping of all other tracers produces the warning.

[nedbat]

I think in all of this I somehow missed the fact that you must run the PyTracer, not the CTracer. This is easily reproduced using the --timid flag.

[nedbat]

Original comment by Ronald Oussoren (Bitbucket: ronaldoussoren, GitHub: ronaldoussoren)

---

That explains why I haven't seen the problem for some time. I can confirm that the problem only occurs when I used the --timid option or remove the C tracer extension.

[nedbat]

Fixed in 8649f08abc40 (bb). The check for the trace function was being invoked on a different thread, and the trace function is per-thread, so the check was often incorrect. Now we only make the check if we are stopped on the same thread that started us.