One of the perks of maintaining coverage.py is that you get some really interesting bug reports. Digging into them can be a good way to learn about some obscure corners of Python.

Today's bug was that a piece of product code succeeded when run without coverage.py, and succeeded when run under the C tracer, but failed when run under the Python tracer. I should explain: the heart of coverage.py is the trace function invoked by CPython on every line of exection. Coverage.py has two implementations of its trace function: one in C for speed, and another simpler one in Python for maximum flexibility. The bug report was that one of the implementations caused the product code to fail, and the other did not.

The product code in question looked like this:

def wacky(x, y):
    args = locals()
    args_keys = args.keys()
    #.. do something with args_keys ..

The intent of this code was that args_keys would be the list ['x', 'y']. The code failed because the list was actually ['x', 'y', 'args']. At the moment locals() is called, there are only two local names, x and y, and running under Python gives us the answer we expected. How could running the code under coverage.py cause this change in behavior?

Playing around with it some more, it became clear that it was nothing about coverage.py in particular, it was the presence of a trace function, any trace function, that would cause the change:

import sys

def trace(frame, event, arg):
    return trace

def wacky():
    x = y = 1
    args = locals()
    print(args.keys())

wacky()
sys.settrace(trace)
wacky()
sys.settrace(None)
wacky()

Running this code on any version of Python produces:

['y', 'x']
['y', 'x', 'args']
['y', 'x']

Without the trace function, either before one was registered, or after it was un-registered, the list is ['y', 'x']. But with a trace function, it's ['y', 'x', 'args'].

Thinking it might be a bug in CPython, I searched the bug database, and found ticket 7083, which explained what's going on.

The locals() function is trickier than it appears at first glance. The returned value is a dictionary which is a copy of the local symbol table. This is why changing the dict might not actually change the local variables.

The copy is made when locals() is called, so in our code, the dict has keys 'x' and 'y'. But in fact, the same dict is returned every time you call locals(), but updated to the new contents of the local symbols.

Here's the important (subtle) fact about how CPython works:

When a trace function is in effect, the local symbol table is copied into the locals() dictionary after every statement.

This means that when "args = locals()" is executed, args is simply a reference to the locals() dictionary. Without a trace function, that dictionary is updated only when locals() is called. So the assignment to args isn't reflected in the dictionary.

But with a trace function, after executing "args = locals()", the locals() dict is updated again, copying the name "args" into it. As with all mutable values in Python, when the value is changed in-place, all references see the changed value, so now "args" refers to a dict with the keys, "x", "y", and "args".

The reason the locals are copied after every statement is simple: the trace function is executed after every statement, and to make building debuggers and other tools possible, the locals dict is updated so that the trace function has an accurate view of the current state. But that updating is expensive, and without a trace function, unnecessary. So it's only done when a trace function is registered.

Most Python programs have no trace function registered, but coverage of course uses one to collect data. So the program behaves differently under coverage than without it.

The fix is simple: make a copy of the locals() dict instead of using it directly:

def wacky(x, y):
    args = dict(locals())
    args_keys = args.keys()
    #.. do something with args_keys ..

By copying the dictionary with dict(), we get an independent copy that won't see the changes when the locals dict is updated for the trace function.

BTW: a remaining mystery is why the original bug report said that one trace function worked, but the other didn't. I'm still trying to track that down, but I think perhaps coverage.py wasn't really in effect for the case that worked.

One last question: is there a way to explain this in the docs that makes the point without going into too much detail?

tagged: » 6 reactions

Comments

[gravatar]
Russell Borogove 10:51 PM on 13 Nov 2012

I suggest something like "the presence of a trace function such as that used by coverage.py can affect the behavior of locals(). If this causes problems, it may be possible to work around it by making a copy with dict(locals()). For more information, see http://nedbatchelder.com/blog/201211/tricky_locals.html."

[gravatar]
Kevin Edwards 2:20 AM on 14 Nov 2012

WARNING: coverage.py updates the locals() dict after every statement executed. So if you save a reference to the locals() dict, it will implicitly change after every statement that creates a new local variable.

[gravatar]
Ned Batchelder 5:55 AM on 14 Nov 2012

Those are good suggestions for coverage.py docs. What about the Python docs? Is there something we could put in the description of locals() that would alert people to this?

[gravatar]
Michael Chermside 9:29 AM on 14 Nov 2012

I thought that Russell Borogove's suggestion WAS a suggestion for the documentation of locals(). Perhaps reword it to a minimal form:

The presence of a trace function (sys.settrace) can affect the behavior of locals(). For more information see "http://nedbatchelder.com/blog/201211/tricky_locals.html".

[gravatar]
Titi Ala'ilima 11:20 AM on 14 Nov 2012

Here's what it currently says:


Update and return a dictionary representing the current local symbol table. Free variables are returned by locals() when it is called in function blocks, but not in class blocks.


Note: The contents of this dictionary should not be modified; changes may not affect the values of local and free variables used by the interpreter.


The "update" hints at this behavior, but unless it is clear that locals() is returning the same dictionary, that won't become obvious. So I would add something like "Multiple invocations within the scope update and return the same dictionary instance. When a trace function is in effect, this dictionary is updated after every statement."

[gravatar]
Kevin Edwards 11:44 AM on 14 Nov 2012

It's good that Borogove's text briefly flags that there may be some interference between locals() and coverage.py, but settrace does not actually affect the behavior of locals(). People just don't understand the wacky behavior of locals().

IMHO, locals() should be fixed to always return a LIVE dict interface to the current function's locals, so you'd have to explicitly copy it at some point in code to have a snapshot.

Barring that fix, the description of locals() could be changed to something like:
"""
locals() returns a singleton dict for the duration of a function and that dict is updated whenever locals() is called. Note the wackiness:

  def wacky():
      x = 1
      locals1 = locals()
      print(locals1) # {'x': 1}
      locals2 = locals()
      print(locals1) # {'x': 1, 'locals1': {...}}
      print(locals1 is locals2) # True
NB: when settrace is active, locals() is called implicitly after every statement.
"""

I'd also be happy with Titi's suggestion.

Add a comment:

name
email
Ignore this:
not displayed and no spam.
Leave this empty:
www
not searched.
 
Name and either email or www are required.
Don't put anything here:
Leave this empty:
URLs auto-link and some tags are allowed: <a><b><i><p><br><pre>.