Introduce subprovider for printing revert stack traces

This commit is contained in:
Alex Browne
2018-06-14 13:58:28 -07:00
parent 4efd28c092
commit 7ab921669b
10 changed files with 416 additions and 50 deletions

View File

@@ -19,6 +19,7 @@
"rebuild_and_test": "run-s build test",
"test:coverage": "SOLIDITY_COVERAGE=true run-s build run_mocha coverage:report:text coverage:report:lcov",
"test:profiler": "SOLIDITY_PROFILER=true run-s build run_mocha profiler:report:html",
"test:trace": "SOLIDITY_REVERT_TRACE=true run-s run_mocha",
"run_mocha": "mocha --require source-map-support/register 'lib/test/**/*.js' --timeout 100000 --bail --exit",
"compile": "sol-compiler",
"clean": "shx rm -rf lib src/generated_contract_wrappers",

View File

@@ -0,0 +1,21 @@
import { devConstants } from '@0xproject/dev-utils';
import { RevertTraceSubprovider, SolCompilerArtifactAdapter } from '@0xproject/sol-cov';
import * as _ from 'lodash';
let revertTraceSubprovider: RevertTraceSubprovider;
export const revertTrace = {
getRevertTraceSubproviderSingleton(): RevertTraceSubprovider {
if (_.isUndefined(revertTraceSubprovider)) {
revertTraceSubprovider = revertTrace._getRevertTraceSubprovider();
}
return revertTraceSubprovider;
},
_getRevertTraceSubprovider(): RevertTraceSubprovider {
const defaultFromAddress = devConstants.TESTRPC_FIRST_ADDRESS;
const solCompilerArtifactAdapter = new SolCompilerArtifactAdapter();
const isVerbose = true;
const subprovider = new RevertTraceSubprovider(solCompilerArtifactAdapter, defaultFromAddress, isVerbose);
return subprovider;
},
};

View File

@@ -5,6 +5,7 @@ import { Web3Wrapper } from '@0xproject/web3-wrapper';
import { coverage } from './coverage';
import { profiler } from './profiler';
import { revertTrace } from './revert_trace';
enum ProviderType {
Ganache = 'ganache',
@@ -48,28 +49,34 @@ const providerConfigs = testProvider === ProviderType.Ganache ? ganacheConfigs :
export const provider = web3Factory.getRpcProvider(providerConfigs);
const isCoverageEnabled = env.parseBoolean(EnvVars.SolidityCoverage);
const isProfilerEnabled = env.parseBoolean(EnvVars.SolidityProfiler);
if (isCoverageEnabled && isProfilerEnabled) {
throw new Error(
`Unfortunately for now you can't enable both coverage and profiler at the same time. They both use coverage.json file and there is no way to configure that.`,
);
}
if (isCoverageEnabled) {
const coverageSubprovider = coverage.getCoverageSubproviderSingleton();
prependSubprovider(provider, coverageSubprovider);
}
if (isProfilerEnabled) {
if (testProvider === ProviderType.Ganache) {
logUtils.warn(
"Gas costs in Ganache traces are incorrect and we don't recommend using it for profiling. Please switch to Geth",
);
process.exit(1);
}
const profilerSubprovider = profiler.getProfilerSubproviderSingleton();
logUtils.log(
"By default profilerSubprovider is stopped so that you don't get noise from setup code. Don't forget to start it before the code you want to profile and stop it afterwards",
);
profilerSubprovider.stop();
prependSubprovider(provider, profilerSubprovider);
const isRevertTraceEnabled = env.parseBoolean(EnvVars.SolidityRevertTrace);
// TODO(albrow): Include revertTrace checks in the warnings below.
// if (isCoverageEnabled && isProfilerEnabled) {
// throw new Error(
// `Unfortunately for now you can't enable both coverage and profiler at the same time. They both use coverage.json file and there is no way to configure that.`,
// );
// }
// if (isCoverageEnabled) {
// const coverageSubprovider = coverage.getCoverageSubproviderSingleton();
// prependSubprovider(provider, coverageSubprovider);
// }
// if (isProfilerEnabled) {
// if (testProvider === ProviderType.Ganache) {
// logUtils.warn(
// "Gas costs in Ganache traces are incorrect and we don't recommend using it for profiling. Please switch to Geth",
// );
// process.exit(1);
// }
// const profilerSubprovider = profiler.getProfilerSubproviderSingleton();
// logUtils.log(
// "By default profilerSubprovider is stopped so that you don't get noise from setup code. Don't forget to start it before the code you want to profile and stop it afterwards",
// );
// profilerSubprovider.stop();
// prependSubprovider(provider, profilerSubprovider);
// }
if (isRevertTraceEnabled) {
const revertTraceSubprovider = revertTrace.getRevertTraceSubproviderSingleton();
prependSubprovider(provider, revertTraceSubprovider);
}
export const web3Wrapper = new Web3Wrapper(provider);

View File

@@ -4,6 +4,7 @@ import * as process from 'process';
export enum EnvVars {
SolidityCoverage = 'SOLIDITY_COVERAGE',
SolidityProfiler = 'SOLIDITY_PROFILER',
SolidityRevertTrace = 'SOLIDITY_REVERT_TRACE',
VerboseGanache = 'VERBOSE_GANACHE',
}

View File

@@ -1,6 +1,7 @@
export { CoverageSubprovider } from './coverage_subprovider';
// HACK: ProfilerSubprovider is a hacky way to do profiling using coverage tools. Not production ready
export { ProfilerSubprovider } from './profiler_subprovider';
export { RevertTraceSubprovider } from './revert_trace_subprovider';
export { SolCompilerArtifactAdapter } from './artifact_adapters/sol_compiler_artifact_adapter';
export { TruffleArtifactAdapter } from './artifact_adapters/truffle_artifact_adapter';
export { AbstractArtifactAdapter } from './artifact_adapters/abstract_artifact_adapter';

View File

@@ -0,0 +1,82 @@
import { logUtils } from '@0xproject/utils';
import { OpCode, StructLog } from 'ethereum-types';
import * as _ from 'lodash';
import { EvmCallStack, EvmCallStackEntry } from './types';
import { utils } from './utils';
export function getRevertTrace(structLogs: StructLog[], startAddress: string): EvmCallStack {
const evmCallStack: EvmCallStack = [];
let currentAddress = startAddress;
if (_.isEmpty(structLogs)) {
return [];
}
const normalizedStructLogs = utils.normalizeStructLogs(structLogs);
// tslint:disable-next-line:prefer-for-of
for (let i = 0; i < normalizedStructLogs.length; i++) {
const structLog = normalizedStructLogs[i];
if (structLog.depth !== evmCallStack.length) {
throw new Error("Malformed trace. Trace depth doesn't match call stack depth");
}
// After that check we have a guarantee that call stack is never empty
// If it would: callStack.length - 1 === structLog.depth === -1
// That means that we can always safely pop from it
// TODO(albrow): split out isCallLike and isEndOpcode
if (utils.isCallLike(structLog.op)) {
const evmCallStackEntry = _.last(evmCallStack) as EvmCallStackEntry;
const prevAddress = _.isUndefined(evmCallStackEntry) ? currentAddress : evmCallStackEntry.address;
const jumpAddressOffset = 1;
currentAddress = utils.getAddressFromStackEntry(
structLog.stack[structLog.stack.length - jumpAddressOffset - 1],
);
if (structLog === _.last(normalizedStructLogs)) {
throw new Error('Malformed trace. CALL-like opcode can not be the last one');
}
// Sometimes calls don't change the execution context (current address). When we do a transfer to an
// externally owned account - it does the call and immediately returns because there is no fallback
// function. We manually check if the call depth had changed to handle that case.
const nextStructLog = normalizedStructLogs[i + 1];
if (nextStructLog.depth !== structLog.depth) {
evmCallStack.push({
address: prevAddress,
structLog,
});
}
} else if (utils.isEndOpcode(structLog.op) && structLog.op !== OpCode.Revert) {
// Just like with calls, sometimes returns/stops don't change the execution context (current address).
const nextStructLog = normalizedStructLogs[i + 1];
if (_.isUndefined(nextStructLog) || nextStructLog.depth !== structLog.depth) {
evmCallStack.pop();
}
if (structLog.op === OpCode.SelfDestruct) {
// After contract execution, we look at all sub-calls to external contracts, and for each one, fetch
// the bytecode and compute the coverage for the call. If the contract is destroyed with a call
// to `selfdestruct`, we are unable to fetch it's bytecode and compute coverage.
// TODO: Refactor this logic to fetch the sub-called contract bytecode before the selfdestruct is called
// in order to handle this edge-case.
logUtils.warn(
"Detected a selfdestruct. Sol-cov currently doesn't support that scenario. We'll just skip the trace part for a destructed contract",
);
}
} else if (structLog.op === OpCode.Revert) {
evmCallStack.push({
address: currentAddress,
structLog,
});
return evmCallStack;
} else if (structLog.op === OpCode.Create) {
// TODO: Extract the new contract address from the stack and handle that scenario
logUtils.warn(
"Detected a contract created from within another contract. Sol-cov currently doesn't support that scenario. We'll just skip that trace",
);
return [];
}
}
if (evmCallStack.length !== 0) {
logUtils.warn('Malformed trace. Call stack non empty at the end. (probably out of gas)');
}
return [];
}

View File

@@ -0,0 +1,237 @@
import { BlockchainLifecycle } from '@0xproject/dev-utils';
import { Callback, ErrorCallback, NextCallback, Subprovider } from '@0xproject/subproviders';
import { Web3Wrapper } from '@0xproject/web3-wrapper';
import { CallData, JSONRPCRequestPayload, Provider, TxData } from 'ethereum-types';
import { stripHexPrefix } from 'ethereumjs-util';
import * as _ from 'lodash';
import { getLogger, levels, Logger } from 'loglevel';
import { Lock } from 'semaphore-async-await';
import { AbstractArtifactAdapter } from './artifact_adapters/abstract_artifact_adapter';
import { constants } from './constants';
import { getRevertTrace } from './revert_trace';
import { parseSourceMap } from './source_maps';
import { BlockParamLiteral, ContractData, EvmCallStack, SourceRange } from './types';
import { utils } from './utils';
interface MaybeFakeTxData extends TxData {
isFakeTransaction?: boolean;
}
const BLOCK_GAS_LIMIT = 6000000;
/**
* This class implements the [web3-provider-engine](https://github.com/MetaMask/provider-engine) subprovider interface.
* It is used to report call stack traces whenever a revert occurs.
*/
export class RevertTraceSubprovider extends Subprovider {
// Lock is used to not accept normal transactions while doing call/snapshot magic because they'll be reverted later otherwise
private _lock = new Lock();
private _defaultFromAddress: string;
private _web3Wrapper!: Web3Wrapper;
private _isEnabled = true;
private _artifactAdapter: AbstractArtifactAdapter;
private _contractsData!: ContractData[];
private _logger: Logger;
/**
* Instantiates a TraceCollectionSubprovider instance
* @param defaultFromAddress default from address to use when sending transactions
*/
constructor(artifactAdapter: AbstractArtifactAdapter, defaultFromAddress: string, isVerbose: boolean) {
super();
this._artifactAdapter = artifactAdapter;
this._defaultFromAddress = defaultFromAddress;
this._logger = getLogger('sol-cov');
this._logger.setLevel(isVerbose ? levels.TRACE : levels.ERROR);
}
/**
* Starts trace collection
*/
public start(): void {
this._isEnabled = true;
}
/**
* Stops trace collection
*/
public stop(): void {
this._isEnabled = false;
}
/**
* This method conforms to the web3-provider-engine interface.
* It is called internally by the ProviderEngine when it is this subproviders
* turn to handle a JSON RPC request.
* @param payload JSON RPC payload
* @param next Callback to call if this subprovider decides not to handle the request
* @param end Callback to call if subprovider handled the request and wants to pass back the request.
*/
// tslint:disable-next-line:prefer-function-over-method async-suffix
public async handleRequest(payload: JSONRPCRequestPayload, next: NextCallback, _end: ErrorCallback): Promise<void> {
if (this._isEnabled) {
switch (payload.method) {
case 'eth_sendTransaction':
const txData = payload.params[0];
next(this._onTransactionSentAsync.bind(this, txData));
return;
case 'eth_call':
const callData = payload.params[0];
next(this._onCallOrGasEstimateExecutedAsync.bind(this, callData));
return;
case 'eth_estimateGas':
const estimateGasData = payload.params[0];
next(this._onCallOrGasEstimateExecutedAsync.bind(this, estimateGasData));
return;
default:
next();
return;
}
} else {
next();
return;
}
}
/**
* Set's the subprovider's engine to the ProviderEngine it is added to.
* This is only called within the ProviderEngine source code, do not call
* directly.
*/
public setEngine(engine: Provider): void {
super.setEngine(engine);
this._web3Wrapper = new Web3Wrapper(engine);
}
private async _onTransactionSentAsync(
txData: MaybeFakeTxData,
err: Error | null,
txHash: string | undefined,
cb: Callback,
): Promise<void> {
if (!txData.isFakeTransaction) {
// This transaction is a usual transaction. Not a call executed as one.
// And we don't want it to be executed within a snapshotting period
await this._lock.acquire();
}
const NULL_ADDRESS = '0x0';
if (_.isNull(err)) {
const toAddress =
_.isUndefined(txData.to) || txData.to === NULL_ADDRESS ? constants.NEW_CONTRACT : txData.to;
await this._recordTxTraceAsync(toAddress, txData.data, txHash as string);
} else {
const latestBlock = await this._web3Wrapper.getBlockWithTransactionDataAsync(BlockParamLiteral.Latest);
const transactions = latestBlock.transactions;
for (const transaction of transactions) {
const toAddress =
_.isUndefined(txData.to) || txData.to === NULL_ADDRESS ? constants.NEW_CONTRACT : txData.to;
await this._recordTxTraceAsync(toAddress, transaction.input, transaction.hash);
}
}
if (!txData.isFakeTransaction) {
// This transaction is a usual transaction. Not a call executed as one.
// And we don't want it to be executed within a snapshotting period
this._lock.release();
}
cb();
}
private async _onCallOrGasEstimateExecutedAsync(
callData: Partial<CallData>,
_err: Error | null,
_callResult: string,
cb: Callback,
): Promise<void> {
await this._recordCallOrGasEstimateTraceAsync(callData);
cb();
}
private async _recordTxTraceAsync(address: string, data: string | undefined, txHash: string): Promise<void> {
await this._web3Wrapper.awaitTransactionMinedAsync(txHash, 0);
const trace = await this._web3Wrapper.getTransactionTraceAsync(txHash, {
disableMemory: true,
disableStack: false,
disableStorage: true,
});
const evmCallStack = getRevertTrace(trace.structLogs, address);
if (evmCallStack.length > 0) {
// if getRevertTrace returns a call stack it means there was a
// revert.
await this._printStackTraceAsync(evmCallStack);
}
}
private async _recordCallOrGasEstimateTraceAsync(callData: Partial<CallData>): Promise<void> {
// We don't want other transactions to be exeucted during snashotting period, that's why we lock the
// transaction execution for all transactions except our fake ones.
await this._lock.acquire();
const blockchainLifecycle = new BlockchainLifecycle(this._web3Wrapper);
await blockchainLifecycle.startAsync();
const fakeTxData: MaybeFakeTxData = {
gas: BLOCK_GAS_LIMIT,
isFakeTransaction: true, // This transaction (and only it) is allowed to come through when the lock is locked
...callData,
from: callData.from || this._defaultFromAddress,
};
try {
const txHash = await this._web3Wrapper.sendTransactionAsync(fakeTxData);
await this._web3Wrapper.awaitTransactionMinedAsync(txHash, 0);
} catch (err) {
// Even if this transaction failed - we've already recorded it's trace.
_.noop();
}
await blockchainLifecycle.revertAsync();
this._lock.release();
}
private async _printStackTraceAsync(evmCallStack: EvmCallStack): Promise<void> {
const sourceRanges: SourceRange[] = [];
if (_.isUndefined(this._contractsData)) {
this._contractsData = await this._artifactAdapter.collectContractsDataAsync();
}
for (const evmCallStackEntry of evmCallStack) {
const isContractCreation = evmCallStackEntry.address === constants.NEW_CONTRACT;
const bytecode = await this._web3Wrapper.getContractCodeAsync(evmCallStackEntry.address);
const contractData = utils.getContractDataIfExists(this._contractsData, bytecode);
if (_.isUndefined(contractData)) {
const errMsg = isContractCreation
? `Unknown contract creation transaction`
: `Transaction to an unknown address: ${evmCallStackEntry.address}`;
this._logger.warn(errMsg);
continue;
}
const bytecodeHex = stripHexPrefix(bytecode);
const sourceMap = isContractCreation ? contractData.sourceMap : contractData.sourceMapRuntime;
const pcToSourceRange = parseSourceMap(
contractData.sourceCodes,
sourceMap,
bytecodeHex,
contractData.sources,
);
// tslint:disable-next-line:no-unnecessary-initializer
let sourceRange: SourceRange | undefined = undefined;
let pc = evmCallStackEntry.structLog.pc;
// Sometimes there is not a mapping for this pc (e.g. if the revert
// actually happens in assembly). In that case, we want to keep
// searching backwards by decrementing the pc until we find a
// mapped source range.
while (_.isUndefined(sourceRange)) {
sourceRange = pcToSourceRange[pc];
pc -= 1;
if (pc <= 0) {
this._logger.warn(
`could not find matching sourceRange for structLog: ${evmCallStackEntry.structLog}`,
);
continue;
}
}
sourceRanges.push(sourceRange);
}
if (sourceRanges.length > 0) {
this._logger.error('\n\nStack trace:\n');
_.forEach(sourceRanges, sourceRange => {
this._logger.error(
`${sourceRange.fileName}:${sourceRange.location.start.line}:${sourceRange.location.start.column}`,
);
});
this._logger.error('\n');
} else {
this._logger.error('Could not determine stack trace');
}
}
}

View File

@@ -1,17 +1,13 @@
import { addressUtils, BigNumber, logUtils } from '@0xproject/utils';
import { logUtils } from '@0xproject/utils';
import { OpCode, StructLog } from 'ethereum-types';
import { addHexPrefix } from 'ethereumjs-util';
import * as _ from 'lodash';
import { utils } from './utils';
export interface TraceByContractAddress {
[contractAddress: string]: StructLog[];
}
function getAddressFromStackEntry(stackEntry: string): string {
const hexBase = 16;
return addressUtils.padZeros(new BigNumber(addHexPrefix(stackEntry)).toString(hexBase));
}
export function getTracesByContractAddress(structLogs: StructLog[], startAddress: string): TraceByContractAddress {
const traceByContractAddress: TraceByContractAddress = {};
let currentTraceSegment = [];
@@ -19,13 +15,10 @@ export function getTracesByContractAddress(structLogs: StructLog[], startAddress
if (_.isEmpty(structLogs)) {
return traceByContractAddress;
}
if (structLogs[0].depth === 1) {
// Geth uses 1-indexed depth counter whilst ganache starts from 0
_.forEach(structLogs, structLog => structLog.depth--);
}
const normalizedStructLogs = utils.normalizeStructLogs(structLogs);
// tslint:disable-next-line:prefer-for-of
for (let i = 0; i < structLogs.length; i++) {
const structLog = structLogs[i];
for (let i = 0; i < normalizedStructLogs.length; i++) {
const structLog = normalizedStructLogs[i];
if (structLog.depth !== callStack.length - 1) {
throw new Error("Malformed trace. Trace depth doesn't match call stack depth");
}
@@ -34,27 +27,19 @@ export function getTracesByContractAddress(structLogs: StructLog[], startAddress
// That means that we can always safely pop from it
currentTraceSegment.push(structLog);
const isCallLike = _.includes(
[OpCode.CallCode, OpCode.StaticCall, OpCode.Call, OpCode.DelegateCall],
structLog.op,
);
const isEndOpcode = _.includes(
[OpCode.Return, OpCode.Stop, OpCode.Revert, OpCode.Invalid, OpCode.SelfDestruct],
structLog.op,
);
if (isCallLike) {
if (utils.isCallLike(structLog.op)) {
const currentAddress = _.last(callStack) as string;
const jumpAddressOffset = 1;
const newAddress = getAddressFromStackEntry(
const newAddress = utils.getAddressFromStackEntry(
structLog.stack[structLog.stack.length - jumpAddressOffset - 1],
);
if (structLog === _.last(structLogs)) {
if (structLog === _.last(normalizedStructLogs)) {
throw new Error('Malformed trace. CALL-like opcode can not be the last one');
}
// Sometimes calls don't change the execution context (current address). When we do a transfer to an
// externally owned account - it does the call and immediately returns because there is no fallback
// function. We manually check if the call depth had changed to handle that case.
const nextStructLog = structLogs[i + 1];
const nextStructLog = normalizedStructLogs[i + 1];
if (nextStructLog.depth !== structLog.depth) {
callStack.push(newAddress);
traceByContractAddress[currentAddress] = (traceByContractAddress[currentAddress] || []).concat(
@@ -62,7 +47,7 @@ export function getTracesByContractAddress(structLogs: StructLog[], startAddress
);
currentTraceSegment = [];
}
} else if (isEndOpcode) {
} else if (utils.isEndOpcode(structLog.op)) {
const currentAddress = callStack.pop() as string;
traceByContractAddress[currentAddress] = (traceByContractAddress[currentAddress] || []).concat(
currentTraceSegment,
@@ -85,8 +70,8 @@ export function getTracesByContractAddress(structLogs: StructLog[], startAddress
);
return traceByContractAddress;
} else {
if (structLog !== _.last(structLogs)) {
const nextStructLog = structLogs[i + 1];
if (structLog !== _.last(normalizedStructLogs)) {
const nextStructLog = normalizedStructLogs[i + 1];
if (nextStructLog.depth === structLog.depth) {
continue;
} else if (nextStructLog.depth === structLog.depth - 1) {

View File

@@ -107,3 +107,10 @@ export type TraceInfo = TraceInfoNewContract | TraceInfoExistingContract;
export enum BlockParamLiteral {
Latest = 'latest',
}
export interface EvmCallStackEntry {
structLog: StructLog;
address: string;
}
export type EvmCallStack = EvmCallStackEntry[];

View File

@@ -1,3 +1,6 @@
import { addressUtils, BigNumber } from '@0xproject/utils';
import { OpCode, StructLog } from 'ethereum-types';
import { addHexPrefix } from 'ethereumjs-util';
import * as _ from 'lodash';
import { ContractData, LineColumn, SingleFileSourceRange } from './types';
@@ -42,4 +45,25 @@ export const utils = {
});
return contractData;
},
isCallLike(op: OpCode): boolean {
return _.includes([OpCode.CallCode, OpCode.StaticCall, OpCode.Call, OpCode.DelegateCall], op);
},
isEndOpcode(op: OpCode): boolean {
return _.includes([OpCode.Return, OpCode.Stop, OpCode.Revert, OpCode.Invalid, OpCode.SelfDestruct], op);
},
getAddressFromStackEntry(stackEntry: string): string {
const hexBase = 16;
return addressUtils.padZeros(new BigNumber(addHexPrefix(stackEntry)).toString(hexBase));
},
normalizeStructLogs(structLogs: StructLog[]): StructLog[] {
if (structLogs[0].depth === 1) {
// Geth uses 1-indexed depth counter whilst ganache starts from 0
const newStructLogs = _.map(structLogs, structLog => ({
...structLog,
depth: structLog.depth - 1,
}));
return newStructLogs;
}
return structLogs;
},
};