## A few hints for debugging SubX programs

Writing programs in SubX is surprisingly pleasant and addictive. Reading
programs is a work in progress, and hopefully the extensive unit tests help.
However, _debugging_ programs is where one really faces up to the low-level
nature of SubX. Even the smallest modifications need testing to make sure they
work. In my experience, there is no modification so small that I get it working
on the first attempt. And when it doesn't work, there are no clear error
messages. Machine code is too simple-minded for that. You can't use a debugger,
since SubX's simplistic ELF binaries contain no debugging information. So
debugging requires returning to basics and practicing with a new, more
rudimentary but hopefully still workable toolkit:

- Start by nailing down a concrete set of steps for reproducibly obtaining the
  error or erroneous behavior.

- If possible, turn the steps into a failing test. It's not always possible,
  but SubX's primary goal is to keep improving the variety of tests one can
  write.

- Start running the single failing test alone. This involves modifying the top
  of the program (or the final `.subx` file passed in to `bootstrap translate`) by
  replacing the call to `run-tests` with a call to the appropriate `test-`
  function.

- Generate a trace for the failing test while running your program in emulated
  mode (`bootstrap run`):

  ```
  $ ./bootstrap translate input.subx -o binary
  $ ./bootstrap --trace run binary arg1 arg2  2>trace
  ```

  The ability to generate a trace is the essential reason for the existence of
  `bootstrap run` mode. It gives far better visibility into program internals than
  running natively.

- As a further refinement, it is possible to render label names in the trace
  by adding a second flag to the `bootstrap translate` command:

  ```
  $ ./bootstrap --debug translate input.subx -o binary
  $ ./bootstrap --trace run binary arg1 arg2  2>trace
  ```

  `bootstrap --debug translate` emits a mapping from label to address in a file
  called `labels`. `bootstrap --trace run` reads in the `labels` file if
  it exists and prints out any matching label name as it traces each instruction
  executed.

  Here's a sample of what a trace looks like, with a few boxes highlighted:

  <img alt='trace example' src='html/trace.png'>

  Each of the green boxes shows the trace emitted for a single instruction.
  It starts with a line of the form `run: inst: ___` followed by the opcode
  for the instruction, the state of registers before the instruction executes,
  and various other facts deduced during execution. Some instructions first
  print a matching label. In the above screenshot, the red boxes show that
  address `0x0900005e` maps to label `$loop` and presumably marks the start of
  some loop. Function names get similar `run: == label` lines.

- One trick when emitting traces with labels:

  ```
  $ grep label trace
  ```

  This is useful for quickly showing you the control flow for the run, and the
  function executing when the error occurred. I find it useful to start with
  this information, only looking at the complete trace after I've gotten
  oriented on the control flow. Did it get to the loop I just modified? How
  many times did it go through the loop?

- Once you have SubX displaying labels in traces, it's a short step to modify
  the program to insert more labels just to gain more insight. For example,
  consider the following function:

  <img alt='control example -- before' src='html/control0.png'>

  This function contains a series of jump instructions. If a trace shows
  `is-hex-lowercase-byte?` being encountered, and then `$is-hex-lowercase-byte?:end`
  being encountered, it's still ambiguous what happened. Did we hit an early
  exit, or did we execute all the way through? To clarify this, add temporary
  labels after each jump:

  <img alt='control example -- after' src='html/control1.png'>

  Now the trace should have a lot more detail on which of these labels was
  reached, and precisely when the exit was taken.

- If you find yourself wondering, "when did the contents of this memory
  address change?", `bootstrap run` has some rudimentary support for _watch
  points_. Just insert a label starting with `$watch-` before an instruction
  that writes to the address, and its value will start getting dumped to the
  trace after every instruction thereafter.

- Once we have a sense for precisely which instructions we want to look at,
  it's time to look at the trace as a whole. Key is the state of registers
  before each instruction. If a function is receiving bad arguments it becomes
  natural to inspect what values were pushed on the stack before calling it,
  tracing back further from there, and so on.

  I occasionally want to see the precise state of the stack segment, in which
  case I uncomment a commented-out call to `dump_st
# Helper to print an int32 in decimal.

== code
#   instruction                     effective address                                                   register    displacement    immediate
# . op          subop               mod             rm32          base        index         scale       r32
# . 1-3 bytes   3 bits              2 bits          3 bits        3 bits      3 bits        2 bits      2 bits      0/1/2/4 bytes   0/1/2/4 bytes

write-int32-decimal:  # out: (addr stream byte), n: int32
    # works by generating characters from lowest to highest and pushing them
    # to the stack, before popping them one by one into the stream
    #
    # pseudocode:
    #   push sentinel
    #   eax = abs(n)
    #   while true
    #     sign-extend eax into edx
    #     eax, edx = eax/10, eax%10
    #     edx += '0'
    #     push edx
    #     if (eax == 0) break
    #   if n < 0
    #     push '-'
    #   w = out->write
    #   curr = &out->data[out->write]
    #   max = &out->data[out->size]
    #   while true
    #     pop into eax
    #     if (eax == sentinel) break
    #     if (curr >= max) abort
    #     *curr = AL
    #     ++curr
    #     ++w
    #   out->write = w
    # (based on K&R itoa: https://en.wikibooks.org/wiki/C_Programming/stdlib.h/itoa)
    # (this pseudocode contains registers because operations like division
    # require specific registers in x86)
    #
    # . prologue
    55/push-ebp
    89/copy                         3/mod/direct    5/rm32/ebp    .           .             .           4/r32/esp   .               .                 # copy esp to ebp
    # . save registers
    50/push-eax
    51/push-ecx
    52/push-edx
    53/push-ebx
    57/push-edi
    # const ten/ecx = 10
    b9/copy-to-ecx  0xa/imm32
    # push sentinel
    68/push  0/imm32/sentinel
    # var eax: int = abs(n)
    8b/copy                         1/mod/*+disp8   5/rm32/ebp    .           .             .           0/r32/eax   0xc/disp8       .                 # copy *(ebp+12) to eax
    3d/compare-eax-with  0/imm32
    7d/jump-if->=  $write-int32-decimal:read-loop/disp8
$write-int32-decimal:negative:
    f7          3/subop/negate      3/mod/direct    0/rm32/eax    .           .             .           .           .               .                 # negate eax
$write-int32-decimal:read-loop:
    # eax, edx = eax / 10, eax % 10
    99/sign-extend-eax-into-edx
    f7          7/subop/idiv        3/mod/direct    1/rm32/ecx    .           .             .           .           .               .                 # divide edx:eax by ecx, storing quotient in eax and remainder in edx
    # edx += '0'
    81          0/subop/add         3/mod/direct    2/rm32/edx    .           .             .           .           .               0x30/imm32        # add to edx
    # push edx
    52/push-edx
    # if (eax == 0) break
    3d/compare-eax-and  0/imm32
    7f/jump-if->  $write-int32-decimal:read-loop/disp8
$write-int32-decimal:read-break:
    # if (n < 0) push('-')
    81          7/subop/compare     1/mod/*+disp8   5/rm32/ebp    .           .             .           .           0xc/disp8       0/imm32           # compare *(ebp+12)
    7d/jump-if->=  $write-int32-decimal:write/disp8
$write-int32-decimal:push-negative:
    68/push  0x2d/imm32/-
$write-int32-decimal:write:
    # edi = out
    8b/copy                         1/mod/*+disp8   5/rm32/ebp    .           .             .           7/r32/edi   8/disp8         .                 # copy *(ebp+8) to edi
    # var w/edx: int = out->write
    8b/copy                         0/mod/indirect  7/rm32/edi    .           .             .           2/r32/edx   .               .                 # copy *edi to edx
    # var curr/ecx: (addr byte) = &out->data[out->write]
    8d/copy-address                 1/mod/*+disp8   4/rm32/sib    7/base/edi  2/index/edx   .           1/r32/ecx   0xc/disp8       .                 # copy ebx+edx+12 to ecx
    # var max/ebx: (addr byte) = &out->data[out->size]
    8b/copy                         1/mod/*+disp8   7/rm32/edi    .           .             .           3/r32/ebx   8/disp8         .                 # copy *(edi+8) to ebx
    8d/copy-address                 1/mod/*+disp8   4/rm32/sib    7/base/edi  3/index/ebx   .           3/r32/ebx   0xc/disp8       .                 # copy edi+ebx+12 to ebx
$write-int32-decimal:write-loop:
    # pop into eax
    58/pop-to-eax
    # if (eax == sentinel) break
    3d/compare-eax-and  0/imm32/sentinel
    74/jump-if-=  $write-int32-decimal:write-break/disp8
    # if (curr >= max) abort
    39/compare                      3/mod/direct    1/rm32/ecx    .           .             .           3/r32/ebx   .               .                 # compare ecx with ebx
    73/jump-if-addr>=  $write-int32-decimal:abort/disp8
$write-int32-decimal:write-char:
    # *curr = AL
    88/copy-byte                    0/mod/indirect  1/rm32/ecx    .           .             .           0/r32/AL    .               .                 # copy AL to byte at *ecx
    # ++curr
    41/increment-ecx
    # ++w
    42/increment-edx
    eb/jump  $write-int32-decimal:write-loop/disp8
$write-int32-decimal:write-break:
    # out->write = w
    89/copy                         0/mod/indirect  7/rm32/edi    .           .             .           2/r32/edx   .               .                 # copy edx to *edi
$write-int32-decimal:end:
    # . restore registers
    5f/pop-to-edi
    5b/pop-to-ebx
    5a/pop-to-edx
    59/pop-to-ecx
    58/pop-to-eax
    # . epilogue
    89/copy                         3/mod/direct    4/rm32/esp    .           .             .           5/r32/ebp   .               .                 # copy ebp to esp
    5d/pop-to-ebp
    c3/return

$write-int32-decimal:abort:
    # . _write(2/stderr, error)
    # . . push args
    68/push  "write-int32-decimal: out of space\n"/imm32
    68/push  2/imm32/stderr
    # . . call
    e8/call  _write/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
    # . syscall(exit, 1)
    bb/copy-to-ebx  1/imm32
    e8/call  syscall_exit/disp32
    # never gets here

test-write-int32-decimal:
    # - check that a single-digit number converts correctly
    # setup
    # . clear-stream(_test-stream)
    # . . push args
    68/push  _test-stream/imm32
    # . . call
    e8/call  clear-stream/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # write-int32-decimal(_test-stream, 9)
    # . . push args
    68/push  9/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  write-int32-decimal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
    # check-stream-equal(_test-stream, "9", msg)
    # . . push args
    68/push  "F - test-write-int32-decimal"/imm32
    68/push  "9"/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  check-stream-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    # . end
    c3/return

test-write-int32-decimal-zero:
    # - check that 0 converts correctly
    # setup
    # . clear-stream(_test-stream)
    # . . push args
    68/push  _test-stream/imm32
    # . . call
    e8/call  clear-stream/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # write-int32-decimal(_test-stream, 0)
    # . . push args
    68/push  0/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  write-int32-decimal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
    # check-stream-equal(_test-stream, "0", msg)
    # . . push args
    68/push  "F - test-write-int32-decimal-zero"/imm32
    68/push  "0"/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  check-stream-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    # . end
    c3/return

test-write-int32-decimal-multiple-digits:
    # - check that a multi-digit number converts correctly
    # setup
    # . clear-stream(_test-stream)
    # . . push args
    68/push  _test-stream/imm32
    # . . call
    e8/call  clear-stream/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # write-int32-decimal(_test-stream, 10)
    # . . push args
    68/push  0xa/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  write-int32-decimal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
    # check-stream-equal(_test-stream, "10", msg)
    # . . push args
    68/push  "F - test-write-int32-decimal-multiple-digits"/imm32
    68/push  "10"/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  check-stream-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    # . end
    c3/return

test-write-int32-decimal-negative:
    # - check that a negative single-digit number converts correctly
    # setup
    # . clear-stream(_test-stream)
    # . . push args
    68/push  _test-stream/imm32
    # . . call
    e8/call  clear-stream/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # write-int32-decimal(_test-stream, -9)
    # . . push args
    68/push  -9/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  write-int32-decimal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
#?     # dump _test-stream {{{
#?     # . write(2/stderr, "^")
#?     # . . push args
#?     68/push  "^"/imm32
#?     68/push  2/imm32/stderr
#?     # . . call
#?     e8/call  write/disp32
#?     # . . discard args
#?     81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
#?     # . write-stream(2/stderr, _test-stream)
#?     # . . push args
#?     68/push  _test-stream/imm32
#?     68/push  2/imm32/stderr
#?     # . . call
#?     e8/call  write-stream/disp32
#?     # . . discard args
#?     81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
#?     # . write(2/stderr, "$\n")
#?     # . . push args
#?     68/push  "$\n"/imm32
#?     68/push  2/imm32/stderr
#?     # . . call
#?     e8/call  write/disp32
#?     # . . discard args
#?     81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
#?     # }}}
    # check-stream-equal(_test-stream, "-9", msg)
    # . . push args
    68/push  "F - test-write-int32-decimal-negative"/imm32
    68/push  "-9"/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  check-stream-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    # . end
    c3/return

test-write-int32-decimal-negative-multiple-digits:
    # - check that a multi-digit number converts correctly
    # setup
    # . clear-stream(_test-stream)
    # . . push args
    68/push  _test-stream/imm32
    # . . call
    e8/call  clear-stream/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # write-int32-decimal(_test-stream, -10)
    # . . push args
    68/push  -0xa/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  write-int32-decimal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
    # check-stream-equal(_test-stream, "-10", msg)
    # . . push args
    68/push  "F - test-write-int32-decimal-negative-multiple-digits"/imm32
    68/push  "-10"/imm32
    68/push  _test-stream/imm32
    # . . call
    e8/call  check-stream-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    # . end
    c3/return

is-decimal-digit?:  # c: byte -> result/eax: boolean
    # . prologue
    55/push-ebp
    89/copy                         3/mod/direct    5/rm32/ebp    .           .             .           4/r32/esp   .               .                 # copy esp to ebp
    # . save registers
    51/push-ecx
    # ecx = c
    8b/copy                         1/mod/*+disp8   5/rm32/ebp    .           .             .           1/r32/ecx   8/disp8         .                 # copy *(ebp+8) to ecx
    # result = false
    b8/copy-to-eax  0/imm32/false
    # return false if c < '0'
    81          7/subop/compare     3/mod/direct    1/rm32/ecx    .           .             .           .           .               0x30/imm32        # compare ecx
    7c/jump-if-<  $is-decimal-digit?:end/disp8
    # return (c <= '9')
    81          7/subop/compare     3/mod/direct    1/rm32/ecx    .           .             .           .           .               0x39/imm32        # compare ecx
    7f/jump-if->  $is-decimal-digit?:end/disp8
$is-decimal-digit?:true:
    b8/copy-to-eax  1/imm32/true
$is-decimal-digit?:end:
    # . restore registers
    59/pop-to-ecx
    # . epilogue
    89/copy                         3/mod/direct    4/rm32/esp    .           .             .           5/r32/ebp   .               .                 # copy ebp to esp
    5d/pop-to-ebp
    c3/return

test-is-decimal-digit-below-0:
    # eax = is-decimal-digit?(0x2f)
    # . . push args
    68/push  0x2f/imm32
    # . . call
    e8/call  is-decimal-digit?/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # check-ints-equal(eax, 0, msg)
    # . . push args
    68/push  "F - test-is-decimal-digit-below-0"/imm32
    68/push  0/imm32/false
    50/push-eax
    # . . call
    e8/call  check-ints-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    c3/return

test-is-decimal-digit-0-to-9:
    # eax = is-decimal-digit?(0x30)
    # . . push args
    68/push  0x30/imm32
    # . . call
    e8/call  is-decimal-digit?/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # check-ints-equal(eax, 1, msg)
    # . . push args
    68/push  "F - test-is-decimal-digit-at-0"/imm32
    68/push  1/imm32/true
    50/push-eax
    # . . call
    e8/call  check-ints-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    # eax = is-decimal-digit?(0x39)
    # . . push args
    68/push  0x39/imm32
    # . . call
    e8/call  is-decimal-digit?/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # check-ints-equal(eax, 1, msg)
    # . . push args
    68/push  "F - test-is-decimal-digit-at-9"/imm32
    68/push  1/imm32/true
    50/push-eax
    # . . call
    e8/call  check-ints-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    c3/return

test-is-decimal-digit-above-9:
    # eax = is-decimal-digit?(0x3a)
    # . . push args
    68/push  0x3a/imm32
    # . . call
    e8/call  is-decimal-digit?/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # check-ints-equal(eax, 0, msg)
    # . . push args
    68/push  "F - test-is-decimal-digit-above-9"/imm32
    68/push  0/imm32/false
    50/push-eax
    # . . call
    e8/call  check-ints-equal/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               0xc/imm32         # add to esp
    c3/return

to-decimal-digit:  # in: byte -> out/eax: int
    # . prologue
    55/push-ebp
    89/copy                         3/mod/direct    5/rm32/ebp    .           .             .           4/r32/esp   .               .                 # copy esp to ebp
    # eax = in
    8b/copy                         1/mod/*+disp8   5/rm32/ebp    .           .             .           0/r32/eax   8/disp8         .                 # copy *(ebp+8) to eax
$to-decimal-digit:check0:
    # if (eax < '0') goto abort
    3d/compare-eax-with  0x30/imm32/0
    7c/jump-if-<  $to-decimal-digit:abort/disp8
$to-decimal-digit:check1:
    # if (eax > '9') goto abort
    3d/compare-eax-with  0x39/imm32/f
    7f/jump-if->  $to-decimal-digit:abort/disp8
$to-decimal-digit:digit:
    # return eax - '0'
    2d/subtract-from-eax  0x30/imm32/0
$to-decimal-digit:end:
    # . epilogue
    89/copy                         3/mod/direct    4/rm32/esp    .           .             .           5/r32/ebp   .               .                 # copy ebp to esp
    5d/pop-to-ebp
    c3/return

$to-decimal-digit:abort:
    # . write-buffered(stderr, error)
    # . . push args
    68/push  "to-decimal-digit: not a digit character: "/imm32
    68/push  Stderr/imm32
    # . . call
    e8/call  write-buffered/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
    # . write-byte-buffered(stderr, %eax)
    # . . push args
    50/push-eax
    68/push  Stderr/imm32
    # . . call
#?     e8/call  write-byte-buffered/disp32
    e8/call  write-int32-hex-buffered/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
    # . write-buffered(stderr, "\n")
    # . . push args
    68/push  Newline/imm32
    68/push  Stderr/imm32
    # . . call
    e8/call  write-buffered/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               8/imm32           # add to esp
    # . flush(Stderr)
    # . . push args
    68/push  Stderr/imm32
    # . . call
    e8/call  flush/disp32
    # . . discard args
    81          0/subop/add         3/mod/direct    4/rm32/esp    .           .             .           .           .               4/imm32           # add to esp
    # . syscall(exit, 1)
    bb/copy-to-ebx  1/imm32
    e8/call  syscall_exit/disp32
    # never gets here

# . . vim:nowrap:textwidth=0