trace: Watching a Variable or Command

Part I · Module 14 · Chapter 14.12 · trace: Watching a Variable or Command

Every technique so far has needed you to know roughly where to look. puts goes at a line you chose; info answers a question you knew to ask. This chapter is for the bug where you do not have that: a variable holds the wrong value, several places could have written it, and adding a print to each is both tedious and incomplete — because the writer might be in code you did not write.

trace inverts the problem. Instead of instrumenting the writers, you instrument the variable, and Tcl tells you about every access.

1. A write trace

set count 0

proc on_write {name1 name2 op} {
    upvar #0 $name1 v
    puts "    [format %-6s $op] $name1 -> '$v'   (from [expr {[info level] > 1 ? [lindex [info level -1] 0] : "top level"}])"
}

trace add variable count write on_write

set count 1
incr count
proc bump {} { set ::count 99 }
bump

trace remove variable count write on_write
set count 500
puts "    (trace removed; the last assignment printed nothing)"
puts "    final count = $count"

    write  count -> '1'   (from top level)
    write  count -> '2'   (from top level)
    write  ::count -> '99'   (from bump)
    (trace removed; the last assignment printed nothing)
    final count = 500

The shape is trace add variable <name> <ops> <callback>, and the callback is called with three extra arguments appended. Four things that output establishes:

• incr counts as a write. Any modification fires the trace, not just set.
• The writer is identifiable via [lindex [info level -1] 0] — the 14.10 §5 idiom. bump is named without any instrumentation inside bump.
• name1 arrives as count from the top level and ::count from inside bump — the spelling the writer used, not a canonical form. Do not compare it with eq against a fixed string; this is why the callback uses upvar #0 $name1 to get at the value rather than assuming a name.
• trace remove genuinely detaches it. The assignment to 500 printed nothing.

2. read, write and unset

Three operations, and all three can be watched at once:

proc watch {name1 name2 op} {
    set full $name1
    if {$name2 ne ""} { append full "($name2)" }
    puts "    op=$op  on $full"
}

set v 1
trace add variable v {read write unset} watch
puts "  set v 2:"  ; set v 2
puts "  read \$v:" ; set tmp $v
puts "  unset v:"  ; unset v

  set v 2:
    op=write  on v
  read $v:
    op=read  on v
  unset v:
    op=unset  on v

The op argument tells you which one fired, so one callback can serve all three. A read trace is the rarer and more interesting one: it answers "who is still using this variable", which is what you want before deleting something from a large inherited script.

3. Arrays: that is what name2 is for

For an array, the second argument carries the element name:

array set cfg {a 1}
trace add variable cfg {read write unset} watch
puts "  cfg(b) = 2:"   ; set cfg(b) 2
puts "  read cfg(a):"  ; set tmp $cfg(a)
puts "  unset cfg(a):" ; unset cfg(a)

  cfg(b) = 2:
    op=write  on cfg(b)
  read cfg(a):
    op=read  on cfg(a)
  unset cfg(a):
    op=unset  on cfg(a)

One trace on the array name covers every element, including ones that do not exist yet — cfg(b) was created after the trace was attached and still fired. That makes an array trace the practical way to watch a configuration structure, since you rarely know in advance which key is the problem.

For a scalar, name2 is the empty string, which is what the if {$name2 ne ""} in watch is testing.

4. Inspecting and stacking traces

trace info reports what is attached:

puts "  trace info variable cfg : [trace info variable cfg]"
set z 0
trace add variable z write watch
trace add variable z write {apply {{a b c} {puts "    second handler"}}}
puts "  two handlers on z: [llength [trace info variable z]]"
puts "  setting z:" ; set z 7

  trace info variable cfg : {{read write unset} watch}
  two handlers on z: 2
  setting z:
    second handler
    op=write  on z

Two details:

• The result is a list of {ops callback} pairs, which is also exactly the form trace remove wants — so you can enumerate and detach programmatically.
• Handlers fire in reverse order of addition. second handler printed first, despite being added second. Most-recently-added runs first. If two handlers interact, that ordering is the opposite of the intuitive one.

5. The limit that matters: a write trace cannot veto

This is the most important fact in the chapter, and the one most easily assumed backwards. A write trace fires after the write. So a callback that raises an error does not prevent the assignment:

set x 10
trace add variable x write {apply {{n1 n2 op} {error "no"}}}
catch {set x 99} e
puts "  after a raising trace : x = $x   (the write happened)"
puts "  the error was         : $e"

  after a raising trace : x = 99   (the write happened)
  the error was         : can't set "x": no

If you need a trace to enforce something, it has to write the value back itself:

set y 10
proc clamp_nonneg {n1 n2 op} {
    upvar #0 $n1 v
    if {$v < 0} {
        set old $v
        set v 0
        puts "    clamped $old -> 0"
    }
}
trace add variable y write clamp_nonneg
set y 5  ; puts "  set y 5  -> $y"
set y -3 ; puts "  set y -3 -> $y"

  set y 5  -> 5
    clamped -3 -> 0
  set y -3 -> 0

That works, and note what it did not do: setting v inside a write trace on v did not recurse forever, because Tcl disables a trace while its own callback is running.

But be clear about what this is. The assignment succeeded and then was silently corrected. A caller that wrote -3 and reads back 0 was not told. As a debugging aid — "something keeps setting this negative, clamp it and log it so I can finish the run" — it is excellent. As production validation it is a trap.

6. Execution traces: when did this command run?

The same mechanism applies to commands:

proc compute {a b} { return [expr {$a + $b}] }

proc on_cmd {args} {
    set op [lindex $args end]
    switch -- $op {
        enter  { puts "    ENTER: [lindex $args 0]" }
        leave  { puts "    LEAVE: [lindex $args 0] -> code [lindex $args 1] result '[lindex $args 2]'" }
    }
}

trace add execution compute {enter leave} on_cmd
puts "  calling compute 2 3:"
puts "  result = [compute 2 3]"
trace remove execution compute {enter leave} on_cmd
puts "  after removal: [compute 4 5]"

  calling compute 2 3:
    ENTER: compute 2 3
    LEAVE: compute 2 3 -> code 0 result '5'
  result = 5
  after removal: 9

The callback's argument list differs by operation, which is why on_cmd takes args and reads op from the end:

• enter receives the full command with its arguments, then enter. compute 2 3 — so you see exactly how it was called.
• leave receives the command, the completion code, the result, then leave. code 0 result '5' — and a code of 1 with a message is how you catch a command that fails somewhere you did not expect.

This is the tool for "this procedure is being called more often than it should be", or "something calls this with the wrong argument and I cannot find the call site". It answers both without editing the procedure.

7. The bug this exists for

Four procedures write one global, in sequence, and the final value is wrong:

set ::period 10.0

proc apply_defaults {}  { set ::period 10.0 }
proc apply_user_file {} { set ::period 2.5 }
proc apply_env {}       { if {[info exists ::env(PERIOD)]} { set ::period $::env(PERIOD) } }
proc apply_derate {}    { set ::period [expr {$::period * 0.9}] }

proc run_setup {} {
    apply_defaults
    apply_user_file
    apply_env
    apply_derate
}

run_setup
puts "  final period = $::period"

  final period = 2.25
  (which of the four produced it? unanswerable from this)

2.25 is not any of the literals in the source. Every one of the four could be involved, apply_env depends on the environment, and apply_derate depends on whatever ran before it. Adding a print to each of the four works but is four edits, and in a real script the writers are spread across files you may not own.

One trace answers it:

set ::period 10.0
proc who_wrote {n1 n2 op} {
    set caller "top level"
    if {[info level] > 1} { set caller [lindex [info level -1] 0] }
    puts [format "    %-16s set %s = %s" $caller $n1 [set ::$n1]]
}
trace add variable ::period write who_wrote
run_setup
trace remove variable ::period write who_wrote
puts "  final period = $::period"

    apply_defaults   set ::period = 10.0
    apply_user_file  set ::period = 2.5
    apply_derate     set ::period = 2.25
  final period = 2.25

Three lines, and the whole history is there — including the absence that mattered: apply_env never wrote, because PERIOD was not in the environment. A print statement in each writer would have shown the same three lines, but you would have had to guess that apply_env was worth instrumenting in order to learn that it did nothing.

That is the characteristic strength of a trace: it reports on the variable, so it cannot miss a writer, and silence from a suspect is itself evidence.

8. Where trace fits

Ranked by what to reach for first:

1. Read the error message and the errorInfo trace — 14.6. Free, and usually sufficient.
2. Print the arguments — 14.9. When output is wrong rather than absent.
3. Ask info — 14.10. When you need to know what exists rather than what happened.
4. Trace — this chapter. When you do not know where to put a print, which is a narrow but genuinely unsolvable-otherwise case.
5. Validate at the boundary — 14.11. Not a debugging tool at all; the thing that stops you needing 1–4 next time.

A trace is the right answer about as often as a debugger is in another language: rarely, and decisively when it is.

9. Exercises

Exercise 1. What three arguments does a variable trace callback receive, and what is the second for?

Exercise 2. How does a callback find out which procedure performed the write?

Exercise 3. You set x to 99 with a write trace whose callback raises. What is x afterwards, and what does that rule out?

Exercise 4. Two write handlers on one variable — which runs first?

Exercise 5. Why does a trace on an array name cover a key that does not exist yet?

Exercise 6. A leave execution trace reports code 1. What happened?

Exercise 7. Why should a debugging trace be removed rather than left in place?