eth.getBlock sometimes returns an array

[wbt]

Expected behavior

web3.eth.getBlock "Returns a block matching the block number or block hash."

Actual behavior

In most cases, the expected behavior, but in some cases not. When I call
web3.eth.getBlock(blockNumber, function(error, blockData) {...
where blockNumber is a number (e.g. 2577), blockData typically contains an Object more or less as described in the documentation. However, sometimes, I get back an ARRAY containing Objects, but where the "blockNumber" field does not match the requested block number. These arrays range in length from 0 (empty), including 1, to 17 (probably higher, but this is what I've observed in limited testing).

The object keys also look a little different, containing keys address (40-hex-digit string), topics (an array of a couple 64-hex-digit strings), data (320-hex-digit-string), blockNumber (hex string without leading zeros padding it to a specific length, notably different from number as specified in the Block object), transactionHash (64-hex-digit string), transactionIndex (usually '0x0'), blockHash (64-hex-digit string), logIndex (usually '0x0'), removed (usually false), gasLimit (undefined), gasUsed (undefined), size (undefined), timestamp (undefined), and number (undefined).

There is no nonce, hash, from, to, value, gas, gasPrice or input fields as in a Transaction object.

My inspection of the object is within the callback, and the callback is defined in the call. The call is the primary/only contents of a Promise constructor in a wrapper function, which is called several times in different asynchronous chains kicked off by arrival of an event in the block for which data (specifically, the timestamp) is being requested. In repeated testing, I am getting the arrival of the exact same set of past events on the same contract on the same private chain running on Geth 1.9.1-stable. In these tests, the set of blocks for which an array is returned instead of a Block object seems random, with the probability of an array being returned somewhere around 1.5%.

Steps to reproduce the behavior

Unfortunately, I don't have reliable reproduction steps as the effect appears to be somewhat random.

Environment

npm 6.14.5, node v9.3.0, web3 1.2.7, Windows 10

[cgewecke]

@wbt To summarize, you're seeing eth.getBlock occasionally and non-deterministically return an array of logs?

My inspection of the object is within the callback, and the callback is defined in the call. The call is the primary/only contents of a Promise constructor in a wrapper function, which is called several times in different asynchronous chains kicked off by arrival of an event in the block for which data (specifically, the timestamp) is being requested.

Questions

• What kind of provider are you using? (eg. http | ws | ipc)
• Is it possible that somewhere in the callback nest a variable (ex: "result") is inadvertently shared by both the event handling and block handling contexts?

[wbt]

@cgewecke That seems almost correct, but I hesitate to say it's definitely an array of logs. The objects in the array have all the fields that a Log object should, but also include fields removed, gasLimit, gasUsed, size, timestamp, and number even though the first of those consistently has a value of false and the rest of the ones in that list consistently have a value of undefined. It seems like a strange mashup of objects.

The behavior is occasional and appears non-deterministic, probably to the exact same degree that the order of arrival of past events is non-deterministic. (The program flow is that when an event comes in, it calls getBlock to get the block.timestamp data).

I am using a WebsocketProvider (ws) connected to geth running on localhost.

The core of the revised test setup is:

/**
* Passing in web3 as an object to the function instead of relying on any
* global here was meant to help with debugging by making this more of a
* pure function.
* Having a wrapper with the callback syntax
* (a) helps with code maintainability in light of historic web3 breaking changes,
* (b) allows inspection of the returned data right here, in an attempt to
* eliminate any possible interference from other variables in the context
* where the data will be used.
*/
getBlockInfo = function(web3object, blockNumber) {
    return new Promise(function(resolve, reject) {
        web3object.eth.getBlock(blockNumber, function(error, blockData) {
            if(error) {
                reject(error);
            } else {
                //Omitted: Code for converting blockNumber to hex and
                //comparing that against the contents of blockData if not
                //an array or each element of an array if it is, and rejecting
                //if there is no match.
                //Additional logging statements also omitted.
                if(Array.isArray(blockData)) {
                    console.log("getBlock("+typeof blockNumber+" "+
                    blockNumber+") has an ARRAY return type of length "+
                    blockData.length+":",blockData);
                } else { //not strict, but true for this investigation
                    console.log("getBlock("+typeof blockNumber+" "+
                    blockNumber+") has an object return type as expected.");
                }
                resolve(blockData);
            }
        });
    });
};

The calling context does include this:
getBlockInfo(web3, eventReceived.blockNumber).then(function (blockData) {
but blockData is not otherwise defined or written to in the calling context. According to my (possibly-incorrect!) understanding of JavaScript, blockData as printed out in the conditional log statements above should be only what's coming back from web3, and that is where I am observing the occasional array.

[cgewecke]

@wbt Is it possible to show where/how getPastEvents is positioned in relation to the getBlock code?

[cgewecke]

@wbt What is the mining interval of your private network?

[wbt]

@cgewecke It's a 5 second mining interval. The events being fetched for this test occurred during migrations, generally in the 2500-2800 block range, with no new events being added since, though the code is set up intending to handle any new events if they were to occur (they just aren't, in this testing).

--gcmode "archive" is in effect on geth; there should not be an issue with geth dropping old events as mining continues (and there is no sign of such a dropped-data issue here).

Relevant snippet of where the events are getting fetched:

myContractEvent({fromBlock: '0', toBlock: 'latest'})
.on("data", function (firedEvent) {
    myEventHandlingCallback(undefined, firedEvent);
}).on("error", function(error) {
    myEventHandlingCallback(error, undefined);
});

The call to getBlockInfo is in the if(error === undefined) branch of myEventHandlingCallback(error, eventReceived).

[wbt]

FYI, I did go back and renamed blockData in the calling context so it's
getBlockInfo(web3, eventReceived.blockNumber).then(function (blockInfo) { instead of the getBlockInfo(web3, eventReceived.blockNumber).then(function (blockData) { listed above (with the read references also updated). That did not help.

[wbt]

Here is another clue: As a new first line in myEventHandlingCallback(error, eventReceived), I logged the event name, transaction hash, and block number, all of which is in the eventReceived object.

If I look at the transaction hashes in the blockData printout above, I notice that every one of them correspond to a log of an event which never reaches myEventHandlingCallback, even if a different event triggered by the same transaction in the same block did.

I suspect that at some point in preparing data for the myContractEvent().on("data") callback, web3 is storing information in a variable/location accessed by a different part of web3 preparing data for the getBlock callback, and the sharing of this common variable/memory location is the cause of the bug.

---

I am also observing the following, though I don't know if it's related:

There are 66 unique events in the particular test set I am using at the moment, triggered by a slightly smaller number of unique transactions. If I add a log statement immediately before and immediately after the call to web3's getBlock as shown in the sample code above, I can see that once per run (of 66 events), getBlock never calls its callback function, at all; that Promise never resolves. Previous observations lead me to believe this (rarely) happens more than once per run, but those observations did not have logging to conclude with confidence that the absences were due to getBlock never calling its callback function. Therefore, I cannot yet confidently say it happens only once per run, but it does reliably happen at least once per run. Which block/event this failure-to-return happens on appears to vary randomly from one run to the next.

[wbt]

Also as an FYI, I observe the same issue when using automining Ganche, with events in a different block range, so this makes me think it's less likely to actually be an issue in Geth. However, there's less randomness in Ganache. The array was returned on the same block info request, with the same set of logs (and therefore the same set of missing events), on 10/10 trials.
Re-doing the migration without resetting the Ganache chain, details like the block numbers, contract addresses, and transaction hashes changed as expected, but it was the same event (which is one of two triggered by the same transaction; the other event in that transaction has no problems and there are similar pairs resulting from other calls to the same function without issue) where requesting the block number got back an array of 8 logs, for the same set of transactions as in the earlier migration.

Using Ganache seems to be a step toward reproducibility.

[wbt]

Debugged in #3573.