CSEP 552: Debugging guide

This guide covers how to debug failing lab tests.

Phase 0: Before you write any code

Read the Common Issues in the dslabs handout.
Make sure you and your partner have a good shared understanding of the design of your protocol. You may find it useful to produce a design document. If you spend more energy on a thoughtful design, you will likely save yourself significant time debugging the implementation.

Phase 1: Before you run any tests

A checklist before you run any tests:

No locking data structures. Your code should not acquire any locks, except in clients by using synchronized on handlers and the client interface methods. In particular, your nodes should allow simultaneous access to their equals and hashCode methods without locking or waiting. All other concurrency is handled by the framework. Locking data structures (e.g. Hashtable) are likely to cause search tests to deadlock.
Use equals instead of == to compare objects. Using == (pointer equality) instead of equals (value equality) on references (non-primitives) is almost always wrong. The test infrastructure clones (serializes and deserializes) your nodes, messages, and timers, which breaks pointer equality.
Avoid static mutable fields in your classes (constants are fine). Your nodes should communicate only through message passing, not through class members.
Remember your Lombok annotations! The messages you send should always be annotated with @Data. Everything contained in a message should be annotated with @Data if it is immutable, or @EqualsAndHashCode if it is mutable.
Go over your design once again, and double check that your implementation is consistent with it. Things to really think about:
- Are nodes properly accepting or ignoring messages?
- Are timers properly being set, reset, or dropped? Think about the conditions for each case.

Phase 2: Debugging test failures

Overview

When you first run your tests, you will likely fail many of them at once, with a variety of errors.

Here is the suggested order to debug tests in:

Make sure there are no SEVERE log outputs, even if a test says it is passing. A SEVERE log output indicates that you have a programming error such as an event handler that throws an exception.
Get a basic run test passing. The first one or two tests usually check basic functionality and are short, so they are easier to debug with log statements. If you don't pass these, you are very unlikely to pass any others.
Debug search tests that fail with an "Invariant violated" error. You can step through these in the visual debugger, and they often capture tricky corner cases.
Debug the remaining run tests, including unreliable ones. These test longer sequences of actions that are hard for the framework to test with search. They can be challenging: you may need to dig through huge logs. See the tips below.
Debug search tests that fail because a state could not be found. These usually fail because of state space explosion: the model checker can't deduplicate certain states and runs out of time before it finds a state matching the goal.

Advice on debugging a single test:

Understand the error. Read the stack trace. What kind of error is it? Which line of the test failed? If the message is not clear, read the test's source code. What was the test checking for? Did it fail in the middle of the test or at the end? A failure partway through often means something went wrong in the test's setup.
Before you make any code changes:
1. Identify the root cause. Follow the rest of this guide for your kind of test and failure. Reason backwards. Why is the client not receiving results in time? Why is the right server not sending a reply? And so on.
2. Understand the root cause. Again, do not change your code until you have a clear idea of where the problem lies. Random changes are very likely to introduce new issues and make debugging harder. Be sure you understand why your current implementation does not have the desired behavior.
3. Plan your change. Talk it over with your partner, or write down how the change will produce the behavior you want. Ideally, reason about how it fits your design: did you miss this case in the design, or did you implement the design incorrectly?
Apply the fix. Start from a clean commit, and keep changes minimal. Then repeat the process.
Once the failed test passes, rerun all tests. Make sure there are no new failures, then commit your code.

The remaining sections give advice for specific kinds of test failures.

	Run	Search
Invariant Violations	Try to see if any Search test finds the same violation instead; or capture a log and work backwards from violation	Visual Debugger: retrace steps that led to the invariant violation
Timeout	Capture a log and look for patterns in log file	Visual Debugger: try to drive system towards goal (under the constraints of the test)

Capturing and reading logs

Logs are useful for debugging run tests but not search tests.

Enable debug logging by passing --log-level (or -g) to run-tests.py. --log-level FINER reports messages received and timers fired, which usually gives enough detail; for tests with unreliable networks you may prefer --log-level FINEST, which also logs message sends and setting timers.
Write your log to a file instead of the screen. Screen output can slow down your tests and even change their behavior, and a file is easier to search. To send standard output and standard error to debug.log:
```
./run-tests.py -g FINER ... > debug.log 2>&1
```
Or use tee to watch the output while also saving it:
```
./run-tests.py -g FINER ... 2>&1 | tee debug.log
```
Read the log backwards. Start at the error and work backward. Look for actions or states that don't match your expectations. If there isn't enough information in the log, see the logging tips.

I'm failing the basic run tests

The first few tests of each lab mostly check whether your system:

is initialized with the proper state, and
can reach basic states and perform basic operations, such as a single client and server doing single operations.

Failures in these tests almost always point to incorrect initialization or incorrect use or declaration of messages and timers. So first review your code, especially:

Constructors and init() methods. Is every field initialized?
Message definitions and handlers. Is every handler defined? Are all message fields set by the sender and read by the receiver?
Timers. Are you setting and resetting them at the right times?

If a code review doesn't turn up anything obvious, then capture a log and work backwards from the failure to see if you can understand the cause.

I'm failing a search test with an "Invariant violated" error

Start the visual debugger by passing --start-viz to run-tests.py.
The violated invariant is highlighted in the left column. The debugger starts at the first event where the invariant was broken. If you don't see this, you are probably failing the search test because a state could not be found; double-check the original error in the test output!
Identify the root cause. Use the event history on the right to step through individual events; changes in node state are highlighted for each event. Make sure you understand why each node's state changes the way it does. Ideally, you should be able to predict exactly which state will change at each event.

I'm failing the longer run tests, or unreliable run tests

The main errors in these tests are timeouts. Any other error, such as a linearizability violation, is best debugged first with the shorter run tests or the search tests.

A timeout here usually means a deadlock or livelock. It can also mean poor timing of message delivery. Debugging these usually means logging, then reading the log to find the cause.

To check whether it is simply a timing issue (messages not delivered fast enough), run the test with --no-timeouts. If the test then passes, your system may be dropping messages it shouldn't, which suggests an edge case you haven't covered.
Capture a log.
Read the log to find the source of the timeout. These logs are long, so first find the first relevant event, then step through one line at a time to see why progress is not being made. For example:
1. If a client's request was not serviced in time, the stack trace gives the name of the client whose request took too long. Find that request in the log. Your client should be retrying, so find the first time it sent that request. You can mostly ignore what happened before.
2. If the test did not reach some goal in time, work out what state the system should have been in just before the goal. For example, if the test expected a view change, find the last time the view changed in the log.
3. Be on the lookout for suspicious behavior, such as a suspiciously low number of views or leader elections.

To find the right spot in the log faster, you can make your code log events that take too long. For example, to flag a client request that takes too long, change your client like this:

@Log
public class PaxosClient {
    private long startTime;
    // ...

    public synchronized void sendCommand(Command command) {
        startTime = System.currentTimeMillis();
        // ...
    }

    private synchronized void handleReply(Reply m, Address sender) {
        // ... the usual checks that this replies to the latest request ...
        long wait = System.currentTimeMillis() - startTime;
        if (wait >= 2000) {
            LOG.finer(() -> "client " + address() + " waited too long " + wait);
        }
    }
}

The @Log at the top of the class lets you add your own log statements. This is better than System.out.println because it is easy to turn off (by not passing -g FINER).

This prints a special message every time a client waits more than 2 seconds for a response. Then:

Rerun the test to capture a new log with this extra information.
Find the first "waited too long" in the log.
Read upward from there.

You are trying to work out why the client had to wait so long, from the events just before. It may help to add log statements to your server too; don't forget its @Log.

I'm failing a search test because a state could not be found

These failures look like this:

java.lang.AssertionError: Could not find state matching "..."
Search ran out of time.

The search could not reach the goal state before it stopped. There are two possible causes: a logic bug, or state space explosion.

Cause 1: a logic bug

Your implementation fundamentally cannot reach the state. To debug, run the failing search test with --start-viz:

./run-tests.py -l 2 -p 2 -n 17 --start-viz

The debugger starts from the state the failing search started from, which may be the initial state. The goal it was looking for is shown in the left sidebar. This works even when the failure happens while the test is still setting up, before any trace exists.
Walk through the possible next states by hand: deliver messages, fire timers, and so on.
See whether you can reach the goal by hand. If you can't, that's your bug: fix it! If you can, the problem is the other cause, state space explosion.

Cause 2: state space explosion

There are so many states that the search can't reach the goal in time. This is harder, because it can happen even when your implementation is logically correct. Usually two logically equivalent states look different to the model checker. To fix it, you need fewer distinct states, which often means simplifying your protocol.

Run the test with --checks, and read the output! It catches some errors, but it has both false positives and false negatives. For example, idempotent message handlers are best, but some handlers are inherently not idempotent.
When you reset a timer, do you reuse the same timer (ideal) or always create a new one? A new timer looks like a different state to the model checker.
Walk through each message handler. Can you safely ignore any extra incoming messages? Are you handling messages that should be ignored? Is your protocol sending unnecessary messages?

Other logging tips

Adding your own log statements in the right spots can give you a clearer picture.

Note: remember that logging is not useful during search tests, because events happen in unpredictable order due to the branching nature of the state space.

Add your own log statements. Add import lombok.extern.java.Log; and the @Log annotation to the class, e.g. ViewServer. Inside it, you can write:
```
LOG.finer(() -> String.format("Client has viewNum=%d", viewNum));
```
Avoid WARNING or higher. Use info, fine, finer, finest. To see the message above, run with --log-level FINER.

Think about where to log. For example, log the start and end of an event, such as a state transfer from primary to backup. These may be in different handlers and happen at different times, so logging both helps you follow the whole flow. Some examples:

A simple handler:

private void handleRequest(Request m, Address sender) {
    LOG.fine(() -> "Entering request: " + m);
    // ... your code ...
    send(new Reply(...), sender);
    LOG.fine(() -> "Exiting request: " + m);
}

An asynchronous handler, where one branch forwards the request to another server before replying, and the other replies directly:

private void handleRequest(Request m, Address sender) {
    LOG.fine(() -> "Entering request: " + m);
    if (...) {
        forward(...);
    } else {
        send(new Reply(...), sender);
        LOG.fine(() -> "Exiting request, direct: " + m);
    }
}

private void handleForwardReply(ForwardReply m, Address sender) {
    send(new Reply(...), client);
    LOG.fine(() -> "Exiting request, forwarded: " + m);
}

Use assertions to check your assumptions. Think about correctness in terms of invariants, and assert them. For example, in lab 3 you could assert that a server believes it is the leader before it sends proposals (P2a messages). An assertion makes a test fail early, instead of producing a giant log to walk through. For example:
```
private void assertTrue(boolean cond, String format, Object... args) {
    if (!cond) {
        throw new RuntimeException("Assertion failed: " + String.format(format, args));
    }
}
```
Note: after an assertion fails, the test usually keeps running. So when the test fails, check for SEVERE log messages, then find the first "Assertion failed" stack trace in the log.

Count things. Statistics can show where an issue starts. Do you receive a reasonable number of pings in a window? How many messages go out in a window? This counts the messages received between timer firings:

private int numRequest = 0;
private int numViewReply = 0;

private void handleRequest(Request m, Address sender) {
    numRequest++;
    // ... your code ...
}

private void handleViewReply(ViewReply m, Address sender) {
    numViewReply++;
    // ... your code ...
}

private void onPingTimer(PingTimer t) {
    LOG.fine("numRequest: " + numRequest + ", numViewReply: " + numViewReply);
    numRequest = 0;
    numViewReply = 0;
    // ... your code ...
}

Phase 3: How to make an effective Ed post

If you are stuck on a hard debugging problem, please ask for help! Office hours can be good for debugging synchronously with course staff, but often we will ask you to make an Ed post instead, so that we can debug without time pressure.

A good debugging Ed post should:

List the failing tests and explain what you think the error is. Don't just paste the stack trace. Explain what the error means and why it might happen.
Say what you have tried and what you observed, following Phase 2. For example: what are you logging, and what did the logs show? If a client's request times out, what was the request and when was it first sent? Logs can be long and confusing, but please take the time to read them!
Attach the log. Include what you have learned so far from reading the log. Tell us what line number in the log you are confused about.
If you can guess what part of the protocol the error is related to, say so briefly.
Make sure your latest code is pushed to your repo, and link to it.
Ideally, make the post public, so others with a similar issue can learn from it :)

Happy debugging!