Issue #164 resolved

Trace function changed warning when using threads

Ronald Oussoren
created an issue

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

{{{ $ $ coverage run Hello 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 3.5.1. Python was installed using the binary installer on the website.

Comments (11)

  1. Ronald Oussoren reporter

    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, 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
    <coverage.collector.PyTracer object at 0x1012c63d0>: start tracer on 4319088640
    <coverage.collector.PyTracer object at 0x1012c6290>: stop tracer on 140735149791584 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 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).

  2. Ronald Oussoren reporter

    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 with only changes to the start/stop methods:

    coverage run<coverage.collector.PyTracer object at 0x1012cda50>: Start on thread: 140735149791584
    <coverage.collector.PyTracer object at 0x1012cdb90>: Start on thread: 4319088640
    <coverage.collector.PyTracer object at 0x1012cda50>: Stop on thread: 140735149791584
    <coverage.collector.PyTracer object at 0x1012cdb90>: Stop on thread: 140735149791584 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.

  3. Ronald Oussoren reporter

    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.

  4. Ned Batchelder repo owner

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

    $ cat 
    import threading
    import time
    class MyThread (threading.Thread):
        def run(self):
            print "Hello"
    thr = MyThread()
    $ coverage run 
    $ coverage report -m
    Name    Stmts   Miss  Cover   Missing
    test        8      0   100%   
    $ python -V
    Python 2.7.1
    $ coverage help, version 3.5.1
    $ system_profiler SPSoftwareDataType
        System Software Overview:
          System Version: Mac OS X 10.6.4
  5. Ronald Oussoren reporter

    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

    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.

  6. Ben Sizer

    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.

  7. Zan Dobersek

    I can still confirm this on ToT coveragepy when using PyTracer, i.e. when running coverage run --timid 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.

  8. Ned Batchelder repo owner
    • changed status to open

    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.

  9. Ronald Oussoren reporter

    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.

  10. Ned Batchelder repo owner

    Fixed in 8649f08abc40. 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.

  11. Log in to comment