Debugging

How to debug TinyChain code

There is an interactive debugger planned but the current debugging experience relies entirely on naming and logging. Consider this example:

import tinychain as tc

@tc.get_op
def add(a: tc.Int):
    b = tc.Int(2) + tc.Int("foo")
    return a + b

if __name__ == "__main__":
    cxt = tc.Context()
    cxt.op = add
    cxt.result = cxt.op(2)

    host = tc.host.Host("http://demo.tinychain.net")
    print(host.post("/transact/hypothetical", cxt))

Running this produces a BadRequest. This program is small enough that it's easy to search for "foo," but in larger programs the auto-generated names for intermediate variables can be very unhelpful when debugging.

Step 1: assign descriptive names

The first step to take in situations like this is to explicitly assign names in the Op context:

# ...

@tc.get_op
def add(cxt, a: tc.Int):
    cxt.two = tc.Int(2)
    cxt.foo = tc.Int("foo")
    cxt.b = cxt.two + cxt.foo
    return a + cxt.b

# ...

Running this produces a slightly more helpful error message: {'/error/bad_request': 'while resolving result: while resolving b: not a Number: foo'}. Now you can at least tell that the error is happening with TinyChain tries to resolve state b.

Another reason why it's important to assign names to the individual states in an Op is to make sure that each step of your program is only executed once. For example:

# ...

@tc.post_op
def increment(x: tc.tensor.Tensor):
    update = x.write(x + 1)
    return update, update # `x` will be incremented TWICE!

# ...

In the case above updated is a flow control, not a State, so it will be executed again every time it's referenced. Assigning a name solves this problem:

# ...

@tc.post_op
def increment(cxt, x: tc.tensor.Tensor):
    cxt.update = x.write(x + 1)
    return cxt.update, cxt.update # `x` will be incremented ONLY ONCE!

# ...

In this case, we've assigned the result of x.write(x + 1) the name update, so each reference to cxt.update will resolve the result of updating x, not the update op itself.

Step 2: add validation

The simplest way to inspect the state of a running TinyChain program is to add validation checks. For example:

# ...

@tc.post_op
def percentages(x: tc.Tensor) -> tc.Number:
    return x / x.sum()

# ...

In this case you'll get a divide-by-zero error if x is zero-valued, but it may be confusing in the context of a larger program because you won't necessarily know where the error is happening. To get more information, you can add validation checks to your code:

# ...
ERR_ZERO_PERCENT = tc.String("error in percentages: tensor sums to {{sum}}")

@tc.post_op
def percentages(cxt, x: tc.tensor.Tensor) -> tc.Number:
    # assign a name to `x.sum()` to make sure it will only be calculated once
    cxt.sum = x.sum()
    return tc.cond(cxt.sum == 0,
        tc.error.BadRequest(ERR_ZERO_PERCENT.render(sum=cxt.sum)),
        x / cxt.sum)
# ...

Step 3: turn on logging

In larger programs, it may unclear which Op you need to inspect to begin with. To make this determination, you can turn on debug logging:

import logging
import tinychain as tc

@tc.get_op
def add(cxt, a: tc.Int):
    b = tc.Int(2) + tc.Int("foo")
    return a + b

if __name__ == "__main__":
    logging.basicConfig(level=logging.DEBUG) # turn on debug logging
    # ...

With debug logging on, you should see some helpful debug output when you run your test script:

$ python3 test.py 
DEBUG:root:auto-assigning name result_subject_subject to Int(2) in execution context with data []
DEBUG:root:auto-assigning name result_subject to Int(GET Op ref $result_subject_subject/add (Int(foo),)) in execution context with data ['result_subject_subject']
# ...

As long as you have at least a few descriptive names explicitly set, this should give you a good idea where to look for more fine-grained debugging. You can also explicitly use logging.debug in your code to get information about the state of the program at compile-time.

Step 4: inspect program code as JSON

If steps 1-3 don't help, or you suspect you may have found a bug in TinyChain itself, the final step to try on your own is to inspect the compiled JSON that's actually executed by a TinyChain host.

# ...

if __name__ == "__main__":
    cxt = tc.Context()
    cxt.op = add
    cxt.result = cxt.op(2)
    
    # compile `cxt` to a JSON-encodable representation
    json_encodable = tc.to_json(cxt)
    tc.print_json(json_encodable)  # pretty-print JSON to stdout

    host = tc.host.Host("http://demo.tinychain.net")

    # important! make sure to send the same JSON to the host,
    # so the auto-generated names will be the same
    print(host.post("/transact/hypothetical", json_encodable))

When you run this, you'll see the structure of your program represented as JSON printed to stdout:

[
    [
        "op",
        {
            "/state/scalar/op/get": [
                "a",
                [
                    [
                        "Int_7f7ee5844950",
                        2
                    ],
                    [
                        "Int_7f7ee49dec70",
                        {
                            "$Int_7f7ee5844950/add": [
                                "foo"
                            ]
                        }
                    ],
                    [
                        "_return",
                        {
                            "$a/add": [
                                {
                                    "$Int_7f7ee49dec70": []
                                }
                            ]
                        }
                    ]
                ]
            ]
        }
    ],
    [
        "result",
        {
            "$op": [
                2
            ]
        }
    ]
]

See technical details for the specification of the subset of JSON which TinyChain uses as an application language.

Step 5: ask for help

If steps 1-4 didn't solve your problem, please email [e-mail] or open an issue!

Step 6: run the host in debug mode

The TinyChain host supports extensive debug logging, but for performance reasons it must be compiled in debug mode in order to enable this logging. If you're running TinyChain in a Docker container, you'll have to open an interactive terminal:

# the `-it` flag tells Docker to open an interactive terminal
docker run -it <your container ID>

# now, in the container
$ cd host

# optional but recommended: set a filter to specify what debug logs you want
$ export RUST_LOG=tinychain,tc_scalar=debug

# if you're not sure what value to give RUST_LOG, leave it unset
# and watch for module names that you're interested in

# leave `--release` out of the run command to run in debug mode
$ cargo run
# ...
HTTP server listening on 0.0.0.0:8702

Now, whenever you make a request to your local host, you'll see the host's internal debug logs in the terminal.