Skip to content
This repository has been archived by the owner on Feb 26, 2024. It is now read-only.

Add stacktraces to debugger library and print them in CLI #2965

Merged
merged 18 commits into from
Apr 17, 2020

Conversation

haltman-at
Copy link
Contributor

@haltman-at haltman-at commented Apr 16, 2020

This PR adds stacktraces to the debugger! Also some other things.

Stacktraces are done as part of a new submodule, the stacktrace submodule. Did this really need to be a new submodule? Maybe not. But I find it easier to think about this way. And this way it's clear that the stack tracing functions are kind of specialized and should not be confused for keeping track of stack frames for other purposes.

(Keeping track of stack frames the ordinary way is pretty easy -- the difficult thing about stack tracing is not always throwing away returned stack frames!)

Btw: This PR also introduces the "light mode" option to the debugger. This option turns off the data submodule. It's intended for when I integrate the debugger's stack tracing with truffle test, since we won't need the data submodule then, but currently it sits unused (intending to get to that in my next PR, though). Note that, for simplicity, it doesn't strictly speaking turn off everything data, it just prevents the data saga listener from spawning (and tells the trace saga to adjust how many BACKTICKs it expects appropriately). So, the data reducers will still be running, listening to each event (and then doing nothing in response to each one); the data selectors will still exist, although they should never be computed as nothing will ever call any of them; and also reset and unloadTransaction will still send out their appropriate data actions, not that those are performance problems. Still, yeah, that was what was convenient to do.

I've modified the CLI appropriately -- now when a transaction finishes, if it failed, it'll print a stacktrace. You can also manually print a stacktrace at any time with the s command, if that's something you want to do. Also, not really related, but I decided that the "Transaction halted with a runtime error" message could use a nice red color, so I added that. :) (DebugUtils now exports truffleColors to make this possible.)

Note that the debugger itself doesn't produce a text stacktrace; the stacktrace obtained from the selector stacktrace.current.report is a JS object with various stacktrace information. To process it into text, one may use the formatStacktrace function in DebugUtils. (The tests I added, for instance, just use it directly, rather than processing it into text, for obvious reasons.)

The stacktrace object is an array of frames. Each frame has properties name and location, corresponding to a line of the stacktrace; name is the name of the function (may be undefined, which formatStacktrace will process into "unknown function"), and location is the location in the source where that stackframe ends, i.e., where it made the call to the next frame, or, for the final frame, where it returned (or, if you're doing this in the middle rather than at the end so it hasn't yet returned, the current position). The final frame also has an additional property status (well, it will have this once the trace has finished; for intermediate stacktraces it may not), which indicates whether the return from that frame had status false (a revert) or true (a technically-successful return that in this context probably indicates an unexpected selfdestruct).

The implementation is pretty primitive still. For instance, it can give you a function's name... but not the name of the contract it's defined in, which is not really how a stacktrace should go. But, this is what I could do real fast without reworking existing systems. Still, it gives line and column numbers, so, eh.

Also, because it relies on jump markings, it has a number of limitations. For instance:

  1. Modifiers and base constructors don't get a separate stacktrace line, but rather appear as part of the function that calls them
  2. Constructors, fallback functions, receive functions, and getters will all appear as "unknown function"
  3. If you're using a version of Solidity prior to 0.5.1, the first function of each EVM stackframe will appear as "unknown function"

But, hey, it's an initial version. Though fixing these things... uh... not easy... oh well!

Tangential note: I did rework some solidity selectors in the process of writing this because they didn't work in the way I expected and this way less work has to be done in the saga.

OK. The big question: How does it all work, under the hood?

Well, first let's answer that question ignoring the hard part. If we ignore the hard part, then the way it works is quite simple. On a jump in you add an internal stackframe, mark the location you jumped into it from, and mark the name of the function you jumped into by looking at the node you're on. (Note that in the state, or in the stacktrace.current.callstack that exposes said state, each frame has the location it was entered from, not the location it was exited from; the stacktrace.current.report selector is responsible for changing things into the latter form.) On a jump out you pop a stackframe (unless the top frame is external, just to be safe). On a call, or on transaction start, you add an external stackframe, marking the location as always (though you can leave out the name here, there won't be anything), and also marking whether it should be skipped in reports -- external stackframes get this marking as long as they were compiled with Solidity 0.5.1 or later. (A stackframe marked as skippable in reports will appear "merged" with the following stackframe in the report in an appropriate manner, unless there is no following stackframe or the following stackframe is external.) And on an EVM halt, you pop stackframes until you've popped an external stackframe. Simple, right?

The problem, of course, is that if you actually popped stackframes on an EVM halt like that, you'd be left with no stacktrace at the end! The point of a stacktrace isn't to show where you currently are, but to show where in the code the revert occurred. If the revert occurred several EVM calls deep, and you go popping the stack when the EVM returns... all that information is going to be lost. (Even if it weren't several EVM calls deep, it'd be lost without a special case to not pop the stack at the end of the transaction, but obviously that's not how we're going to handle this as we aim to be more general.) So, we need to somehow not do that.

So, instead, an EXTERNAL_RETURN action won't cause any stack-popping at all, but will instead merely increment the returnCounter. The key here is that if a call reverts (or unexpectedly self-destructs), and then the call beneath it reverts as a result, the call beneath it will stay in the same place in the code while it does so, rather than moving on. So, we watch for a change in position. (Note that we do not consider entering unmapped code, or exiting it, to be a change in position; we only consider mapped positions.) If a change in position occurs, we then act on the return counter, firing an EXECUTE_RETURN action, popping stack frames until we've popped returnCounter external stackframes, and resetting the return counter to 0. But if we stay in place, and an additional revert happens before we change position, well, then the return counter will simply increment again, waiting to execute until a position change occurs! (Not one from reverting, obviously.) And if we hit the end of the trace before we ever get a chance to do that EXECUTE_RETURN, then, well, we're left with dead stackframes still sitting unpopped on our callstack... which is exactly what we want!

So, that's the basic workings. Before we conclude, though, why don't we take a brief look at all the new state this submodule has added?

The submodule's proc reducers (there are only proc reducers, no info) are as follows:

  1. callstack -- The workings of this have basically already been described. It basically acts like you'd expect a callstack to act, except that instead of popping on EXTERNAL_RETURN, it does nothing, and only pops (to a variable extent) on EXECUTE_RETURN.
  2. returnCounter -- again, this has already been described.
  3. innerReturnPosition -- this is the position that the revert happened at. It's what the report uses for the location for the final frame. (Well, OK, often it'll be null, in which case the report will use lastPosition (coming up) instead, but for the final stacktrace this is what will get used.) It gets stored on EXTERNAL_RETURN (if it's not already set -- we want the innermost return), and cleared on EXECUTE_RETURN.
  4. innerReturnStatus -- similar, except this has the return status of that innermost return. Stored on EXTERNAL_RETURN if it's not already set, cleared on EXECUTE_RETURN. (Note that in this case, by "set" I mean "not null" rather than "true", and by "cleared", I mean "set to null", not "set to false"!)
  5. lastPosition -- Holds the last position we've been to, excluding unmapped code, both for comparison against current position (to determine whether to act on that positive return counter) and for reporting in the final stackframe (if innerReturnPosition isn't set). OK, strictly speaking, this probably didn't need to go in the state, but it was the easiest way. The alternative way would've been to... you know how we have data.nextMapped, in order to look ahead in the trace to the next mapped step for certain data stuff? Notionally we could have a stacktrace.lastMapped, looking backward in the trace. But, I thought it was easier to just put it in the state. So, here it is.

So that's an overview of the new stacktrace submodule! But hopefully this transaction completes successfully. :)

@haltman-at haltman-at requested a review from gnidan April 16, 2020 03:57
Copy link
Contributor

@gnidan gnidan left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good! Just a minor comment about the action naming

packages/debugger/lib/stacktrace/actions/index.js Outdated Show resolved Hide resolved
packages/debugger/lib/stacktrace/actions/index.js Outdated Show resolved Hide resolved
@haltman-at
Copy link
Contributor Author

OK, I added the prefixes, not just to these but to all actions lacking them. (I also deleted an unused action I found in session.) However going to go back and make a few more changes like we discussed.

@haltman-at
Copy link
Contributor Author

OK, this latest commit rejiggers a few things. The selector stacktrace.current.report is now renamed stacktrace.current.finalReport. The name stacktrace.current.report is instead given to a new selector that gives a report based on the current real callstack. (The real callstack is computed by applying the return counter to the current stored callstack.)

Also, now when you press s, the CLI will print the final report if you're at the end of the trace, and the intermediate report otherwise.

@haltman-at
Copy link
Contributor Author

OK, I went back in and added contract names so things look more like a proper stacktrace. I did this in a fairly ad-hoc way, note, using jsonpointer...

Also I renamed the name field to functionName since there's now also contractName. And of course formatStacktrace has been updated to account for all this!

@haltman-at haltman-at requested a review from gnidan April 17, 2020 00:52
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants