puts Debugging, and parray

Part I · Module 14 · Chapter 14.9 · puts Debugging, and parray

Tcl inside a vendor tool usually has no debugger, no breakpoints, and no inspector. What it always has is puts. That is not the poor relation it sounds like: for the commonest class of bug — a value that is not what you assumed — a print at the right line beats stepping through forty of them.

What separates effective print debugging from flailing is three decisions: where to put the print, which channel to send it to, and how to get rid of it.

1. Where: at the moment of divergence

The instinct is to print at the failure. The failure is usually the wrong place, because by then the bad value has already propagated. Print where your assumption and reality first part company — which means printing the inputs to the step that produced the wrong output, not the wrong output itself.

A practical bracketing method, applied to a procedure returning a wrong answer:

1. Print the arguments on entry and the value on return. If the arguments are wrong, the bug is in the caller and you are done with this procedure.
2. If the arguments are right and the return is wrong, print once per loop iteration — the state going in and the state coming out.
3. The first iteration where the printed state is not what you predicted is the line.

Step 1 is the one people skip, and it is the one that halves the search.

2. Which channel: stderr, and not as a matter of taste

puts stderr rather than puts. The reason is mechanical, not stylistic:

puts          "  1 report line (stdout)"
puts stderr   "  2 DEBUG line (stderr)"
puts          "  3 report line (stdout)"
puts stderr   "  4 DEBUG line (stderr)"

At a terminal both appear, interleaved in order:

  1 report line (stdout)
  2 DEBUG line (stderr)
  3 report line (stdout)
  4 DEBUG line (stderr)

But redirect them separately — tclsh p4.tcl > f.txt 2>t.txt — and the separation does real work:

  stdout file:
     1 report line (stdout)
     3 report line (stdout)
  stderr file:
     2 DEBUG line (stderr)
     4 DEBUG line (stderr)

The report file contains only the report. That matters because a Tcl script's stdout is very often somebody else's input — a file another tool parses, a list consumed by a downstream script, a report a human reads. A debug line on stdout corrupts it; the same line on stderr is invisible to the consumer and still visible to you.

Two corollaries from Chapter 14.6 §5:

• Stack traces also go to stderr. > log.txt alone captures neither your debug prints nor the error that killed the run. Use > log.txt 2>&1 when you want everything.
• Conversely, when you want the clean artefact, redirect only stdout — and your debug prints cost nothing.

3. parray: the whole array at once

For an array, printing elements one at a time is tedious. parray dumps it:

array set config {
    period     10.0
    clock_name clk
    uncertainty 0.05
    mode       setup
}
parray config

config(clock_name)  = clk
config(mode)        = setup
config(period)      = 10.0
config(uncertainty) = 0.05

Two things it does for you that are worth noticing: the keys come out sorted, and the = signs are column-aligned to the longest key. Both matter when you are comparing two dumps by eye — which is most of what you do with them. Array order is otherwise unspecified, as Chapter 7.10 established, so without the sort two dumps of the same data would not be comparable.

It accepts a glob pattern to narrow a large array:

parray config c*

config(clock_name) = clk

And it is specific about the thing it was given:

set s 5
puts "  parray on a scalar : [catch {parray s} e] / $e"
puts "  parray on nothing  : [catch {parray nosucharray} e] / $e"

  parray on a scalar : 1 / "s" isn't an array
  parray on nothing  : 1 / "nosucharray" isn't an array

Note that a scalar and a non-existent name give the same message, so "x" isn't an array does not tell you which. array exists x separates them.

4. Two things about parray that will catch you

It writes to stdout. Verified by splitting the streams: with stderr captured separately, parray's output is in the stdout file and the stderr file is empty. So parray is the one debug tool in this chapter that contaminates a redirected report — exactly what §2 was avoiding.

Its upvar reaches only one level. parray is an ordinary procedure (info procs parray confirms it) that links to the array by name in its immediate caller. Pass a name down one more level and it fails:

proc inspect_callers {name} {
    puts "  parray \$name where name='$name':"
    catch {parray $name} e
    puts "  -> $e"
}
proc outer {} {
    array set mine {x 9 y 8}
    inspect_callers mine
}
outer

  parray $name where name='mine':
  -> "mine" isn't an array

mine lives in outer, and parray's upvar reached inspect_callers — where no such array exists. The array is fine; the level is wrong.

Both problems are solved by a six-line replacement that goes to stderr and that you control:

proc dump_array {name} {
    upvar 1 $name arr
    foreach k [lsort [array names arr]] {
        puts stderr [format "  DEBUG %s(%s) = %s" $name $k $arr($k)]
    }
}

proc outer2 {} {
    array set mine {x 9 y 8}
    dump_array mine
}
outer2

  DEBUG mine(x) = 9
  DEBUG mine(y) = 8

Keep the lsort — sorted output is what makes two dumps diffable. If you need to reach further than one level, upvar 2 or an explicit level argument will do it; the point is that now it is your decision rather than a fixed property of a built-in.

5. Switchable: the prints you do not have to delete

The purpose of this chapter names the real problem with print debugging — prints get left behind. The structural fix is to make them inert by default, so there is nothing to remove:

proc dbg {args} {
    if {![info exists ::DEBUG] || !$::DEBUG} { return }
    set where "top"
    if {[info level] > 1} { set where [lindex [info level -1] 0] }
    puts stderr [format "  DEBUG %-12s %s" $where [join $args " "]]
}

Three things that small body is doing:

• ![info exists ::DEBUG] || !$::DEBUG — off unless switched on, and it does not raise when the variable was never set. The order matters: info exists first, so $::DEBUG is never read when absent. This is 14.11's guard pattern in miniature.
• [lindex [info level -1] 0] labels each line with the procedure it came from, so you do not have to write the name into every message. info level -1 is the caller's invocation and element 0 is its command name — the introspection from Chapter 14.10.
• args means dbg takes any number of words without quoting gymnastics at the call site.

In use:

proc worst_slack {rows} {
    dbg "called with [llength $rows] rows"
    set worst 99.0
    foreach row $rows {
        lassign $row pin slack
        dbg "pin=$pin slack=$slack worst=$worst"
        if {$slack < $worst} { set worst $slack }
    }
    dbg "returning $worst"
    return $worst
}

set rows {{clk 0.42} {data -0.11}}
dbg "starting"
puts "  DEBUG off -> worst = [worst_slack $rows]"
set ::DEBUG 1
dbg "starting"
puts "  DEBUG on  -> worst = [worst_slack $rows]"

  DEBUG off -> worst = -0.11
  DEBUG top          starting
  DEBUG worst_slack  called with 2 rows
  DEBUG worst_slack  pin=clk slack=0.42 worst=99.0
  DEBUG worst_slack  pin=data slack=-0.11 worst=0.42
  DEBUG worst_slack  returning -0.11
  DEBUG on  -> worst = -0.11

The first run printed nothing but the answer. The second shows exactly the §1 shape: arguments on entry, state per iteration, value on return — and worst visibly moving from 99.0 to 0.42 to -0.11.

6. Getting them out again

Switchable prints solve the leftovers problem going forward. For prints already written, the removal has to be deliberate, because a debug line left in a delivered script is a real defect: it slows the run, it clutters somebody's output, and on stdout it corrupts a file another tool parses.

The habit that works is to make debug prints findable by shape and then grep for that shape before you ship:

--- grep for bare puts to stdout (candidates for deletion):
   2:    puts "about to open $path"
   13:puts "report complete"
--- grep for the deliberate debug channel:
   6:    puts stderr "DEBUG loaded [llength $rows] rows"
   10:    parray nothing

Read the two lists differently:

• The stdout list is the dangerous one. Line 2 is a leftover; line 13 is intended output. Only you can tell them apart, which is the argument for never debugging on stdout in the first place — then everything in this list is intentional by construction.
• The stderr list is a review list, not a deletion list. A DEBUG line on stderr may be worth keeping permanently. parray nothing on line 10, though, is both a leftover and a latent error: it will raise "nothing" isn't an array the first time that branch runs.

Three conventions that make this work in practice:

1. Prefix every debug message with a fixed token — DEBUG, or a project tag — so one grep finds all of them.
2. Never debug-print to stdout. It makes the grep decidable.
3. Prefer dbg to puts stderr for anything you might want again. Then shipping it switched off is free, and the next person to debug the same procedure inherits your instrumentation instead of re-deriving it.

7. Exercises

Exercise 1. A procedure returns a wrong number. Which two prints do you add first, and why those?

Exercise 2. Why puts stderr rather than puts?

Exercise 3. What two things does parray do to its output that make dumps comparable?

Exercise 4. parray config works at the top level but "cfg" isn't an array inside a helper that was passed the name. Why?

Exercise 5. In dbg, why is the test ![info exists ::DEBUG] || !$::DEBUG rather than just !$::DEBUG?

Exercise 6. Why is a leftover puts on stdout worse than one on stderr?