Transaction tracing is broken on IPC transport.

[frjnn]

Version
Latest, pulled directly from the master branch of the repository.

Description
I will provide a brief explanation of what I saw from inserting dbg! around the codebase.

It looks to me that the json response format for both trace_transaction and trace_raw_transaction is either one of the following:

Long text

The following occurs, both for trace_transaction and trace_raw_transaction, when the client request is successful.

res = Object({
    "accessList": Array([]),
    "blockHash": Null,
    "blockNumber": Null,
    "chainId": String(
        "0x1",
    ),
    "from": String(
        "0x6ed1cdfe242e653980c37aeb498b997fa0b584fd",
    ),
    "gas": String(
        "0xb493",
    ),
    "gasPrice": String(
        "0x104c533c00",
    ),
    "hash": String(
        "0x31394f7f2e364b2a0a1d14176bfede2ca9e93249e817d5ee8ae9acb4fec4f350",
    ),
    "input": String(
        "0xa22cb46500000000000000000000000003127f766c011ab121f017db093796788a633e890000000000000000000000000000000000000000000000000000000000000001",
    ),
    "maxFeePerGas": String(
        "0x104c533c00",
    ),
    "maxPriorityFeePerGas": String(
        "0x73a20d00",
    ),
    "nonce": String(
        "0xce",
    ),
    "r": String(
        "0x9645c1a24048ed19afac8a4867e1366f264a049ad306b298a7690ad5dc900271",
    ),
    "s": String(
        "0x70cbc2026683cdfc35d535f36dd0ed9e87e33081353a1be09bc14b47b64beaab",
    ),
    "to": String(
        "0x790ca7577efca88dad9ba8eb3865e45b4ce4c7e9",
    ),
    "transactionIndex": Null,
    "type": String(
        "0x2",
    ),
    "v": String(
        "0x1",
    ),
    "value": String(
        "0x0",
    ),
})

EDIT: this one above is the response for eth_getTransactionByHash.

These two occur when it fails. These failure are also suspicious as the same requests issued directly to the node (Geth) doesn't fail.

res = Object({
    "code": Number(
        -32601,
    ),
    "data": Null,
    "message": String(
        "the method trace_transaction does not exist/is not available",
    ),
})

res = Object({
    "code": Number(
        -32601,
    ),
    "data": Null,
    "message": String(
        "the method trace_rawTransaction does not exist/is not available",
    ),
})

As a consequence of this, serde_json is never able to properly deserialise the first object into the types specified in the methods' signatures, namely Vec<Trace> and BlockTrace, and one of these two errors is always returned to the user.

In case of a successful request issued with trace_raw_transaction, this parsing always fails with:

Err(
    JsonRpcClientError(
        JsonError(
            Error("missing field `output`", line: 0, column: 0),
        ),
    ),
)

Conversely, for trace_transaction:

Err(
    JsonRpcClientError(
        JsonError(
            Error("invalid type: map, expected a sequence", line: 0, column: 0),
        ),
    ),
)

To reproduce this results you can use the following code:

#[tokio::test]
async fn test() {
    let client = Provider::connect_ipc(SOCKET).await.unwrap();
    let mut tx_stream = client
        .subscribe_pending_txs()
        .await
        .unwrap()
        .transactions_unordered(256);

    loop {
        if let Some(Ok(tx)) = tx_stream.next().await {
            let _ = dbg!(client.trace_transaction(tx.hash).await);
        }
    }
}

and replace this line with:

Ok(serde_json::from_value(dbg!(res))?)

I was also able to the problem up to here.

[mattsse]

Hmm, isn't the geth trace transaction endpoint called debug_traceTransaction?
By default all rpc namespaces are enabled in geth, I believe.

The rpc name is set here

ethers-rs/ethers-providers/src/provider.rs

Line 777 in dc3ac42

self.request("trace_transaction", vec![hash]).await

you could try to either patching this to debug_traceTransaction and try again? or simpler: add another function that does that like

  async fn trace_transaction<M:Middleware>(provider: &Provider<M>, hash: H256) -> Result<Vec<Trace>, ProviderError> {
        let hash = utils::serialize(&hash);
        provider.request("debug_traceTransaction", vec![hash]).await
    }

[frjnn]

Changed:

ethers-rs/ethers-providers/src/provider.rs

Line 775 in dc3ac42

async fn trace_transaction(&self, hash: H256) -> Result<Vec<Trace>, ProviderError> {

into:

    /// Returns all traces of a given transaction
    async fn trace_transaction(&self, hash: H256) -> Result<Vec<Trace>, ProviderError> {
        let hash = utils::serialize(&hash);
        self.request("debug_traceTransaction", vec![hash]).await
    }

It didn't completely solve the issue, as the response format differs from Trace, but the errors complaining about the method non existing are gone.

[mattsse]

Geth's trace type differs from what is currently implemented in struct Trace.
We need geth compliant trace type struct GethTrace and modify the return type accordingly.
The easiest way to do this, get some sample traces from the console as json, then copy that and past it in: https://app.quicktype.io/ this generates rust bindings with serde support,

[frjnn]

This is what QuickType has generated when provided with several outputs of debug.traceTransaction.

extern crate serde_derive;

#[derive(Serialize, Deserialize)]
pub struct GethTrace {
    failed: bool,
    gas: i64,
    #[serde(rename = "returnValue")]
    return_value: String,
    #[serde(rename = "structLogs")]
    struct_logs: Vec<StructLog>,
}

#[derive(Serialize, Deserialize)]
pub struct StructLog {
    depth: i64,
    error: Option<String>,
    gas: i64,
    #[serde(rename = "gasCost")]
    gas_cost: i64,
    memory: Option<Vec<String>>,
    op: String,
    pc: i64,
    stack: Vec<String>,
    storage: Storage,
}

#[derive(Serialize, Deserialize)]
pub struct Storage {
    #[serde(rename = "0000000000000000000000000000000000000000000000000000000000000004")]
    the_0000000000000000000000000000000000000000000000000000000000000004: Option<String>,
    #[serde(rename = "0000000000000000000000000000000000000000000000000000000000000006")]
    the_0000000000000000000000000000000000000000000000000000000000000006: Option<String>,
    #[serde(rename = "f652222313e28459528d920b65115c16c04f3efc82aaedc97be59f3f377c0d3f")]
    f652222313_e28459528_d920_b65115_c16_c04_f3_efc82_aaedc97_be59_f3_f377_c0_d3_f: Option<String>,
    #[serde(rename = "0000000000000000000000000000000000000000000000000000000000000003")]
    the_0000000000000000000000000000000000000000000000000000000000000003: Option<String>,
    #[serde(rename = "0000000000000000000000000000000000000000000000000000000000000005")]
    the_0000000000000000000000000000000000000000000000000000000000000005: Option<String>,
    #[serde(rename = "0000000000000000000000000000000000000000000000000000000000000007")]
    the_0000000000000000000000000000000000000000000000000000000000000007: Option<String>,
    #[serde(rename = "0000000000000000000000000000000000000000000000000000000000000008")]
    the_0000000000000000000000000000000000000000000000000000000000000008: Option<String>,
    #[serde(rename = "000000000000000000000000000000000000000000000000000000000000000c")]
    the_000000000000000000000000000000000000000000000000000000000000000_c: Option<String>,
}

Storage should probably be an HashMap

[mattsse]

since these are storage slots it probably should be

storage: BTreeMap<H256, H256>,

see also https://geth.ethereum.org/docs/rpc/ns-debug#debug_tracetransaction

[frjnn]

I hereby provide a somewhat detailed explanation of what happens when tracing transaction with geth on ipc transport:

1. the debug_traceTransaction request gets sent fine, at that point we begin to read the data from the socket. The data consists in chunks of bytes, and, in the handle_socket function such chunks are put in read_buffer.

   ethers-rs/ethers-providers/src/transports/ipc.rs

   Line 238 in b61adcf

   read_buffer.extend_from_slice(&bytes);

2. inside the loop located in handle_socket, we are trying to deserialise well formed json values from the data contained in read_buffer.

   ethers-rs/ethers-providers/src/transports/ipc.rs

   Line 246 in b61adcf

   while let Some(Ok(value)) = de.next() {

   
   nevertheless, in the case of tracing with Geth, and I believe when dealing with large json rpc responses in general, this attempt at deserialisation always fails, as we are not dealing with multiple well formed json values but rather with chunks of a single big json value, that is the trace returned by geth.

3. as a consequence of this we never successfully deserialise anything, and the size of read_buffer grows after every chunk of bytes is read from the socket.

4. then, at some point, it seems to me that the socket stops sending chunks, and the programs hangs at this line

   ethers-rs/ethers-providers/src/transports/ipc.rs

   Line 176 in b61adcf

   futures_util::select! {

   It's important to note that the last chunk it sends it's not the last chunk to deserialize a well formed response. We are thus left hanging with a in incomplete json value read_buffer.

Related to #562 .

[mattsse]

this seems like a reasonable assumption.
the read_buffer can hang indefinitely if it starts with an illegal json char like , for example.
And we don't truncate this currently.

Could you please dump the read_buffer to a json file after everytime it is extended and look at that?

the way the streamserilizer works is, it skips whitespace and tries to deserialize a value then shift, repeat.

[frjnn]

I produced 2 dump files, namely, dump1.json and dump2.json. The former stores the content of read_buffer after every time that it is extended and accessed, the latter contains the final content of read_buffer immediately before the hang. dump1.json is huge, as expected, so I quickly analysed dump2.json. Its content is truncated, due to the hang, nevertheless I was able to manually complete it into a syntactically correct json file.

Doesn't seem to be an issue of correctness. I have a hunch that it may be socket-related.

[mattsse]

but the read_buffer should then contain the combined content of 1.json + 2.json, right?

[frjnn]

I don't think I understand your question. dump1.json contains snapshots of read_buffer through time instants, i.e. after every chunk read from the socket. The final content of read_buff is stored in dump2.json, which is also equal to dump1.json[t_final]. I sent you the files by email.

[mattsse]

I see,
thanks, you can also simply attach them here FYI :)

so it appears that reading from the socket is exhausted before the trace object was fully read?

[frjnn]

thanks, you can also simply attach them here FYI :)

Yeah! dumps.zip

so it appears that reading from the socket is exhausted before the trace object was fully read?

Exactly.