event filter.watch sometimes (about 50%) firing twice

[SCBuergel]

my toy contract

pragma solidity ^0.4.5;

contract A {
  event e1(uint u);
  event e2(string s);
  event e3(address a);

  function f1(uint u) {
    e1(u);
  }
  
  function f2(string s) {
    e2(s);
  }
  
  function f3() {
    e3(msg.sender);
  }
}

is being interfaced via the following little NodeJS script:

var w3 = require('web3');
var SolidityCoder = require("web3/lib/solidity/coder.js");

contractAbi = [{"constant": false,"inputs": [{"name": "u","type": "uint256"}],"name": "f1","outputs": [],"payable": false,"type": "function"},{"constant": false,"inputs": [{"name": "u","type": "uint256"}],"name": "f2","outputs": [],"payable": false,"type": "function"},{"constant": false,"inputs": [{"name": "u","type": "uint256"}],"name": "f3","outputs": [],"payable": false,"type": "function"},{"anonymous": false,"inputs": [{"indexed": false,"name": "u","type": "uint256"}],"name": "e1","type": "event"},{"anonymous": false,"inputs": [{"indexed": false,"name": "u","type": "uint256"}],"name": "e2","type": "event"},{"anonymous": false,"inputs": [{"indexed": false,"name": "u","type": "uint256"}],"name": "e3","type": "event"},{"anonymous": false,"inputs": [{"indexed": false,"name": "u","type": "uint256"}],"name": "e4","type": "event"}];

contractAddress = '0x86e0497e32a8e1d79fe38ab87dc80140df5470d9';
var ideUrl = 'https://sbuergel.by.ether.camp:8555/sandbox/';
var sandboxId = 'b287d10ddc';
var sandboxUrl = ideUrl + sandboxId;
var web3 = new w3(new w3.providers.HttpProvider(sandboxUrl));

var contract = web3.eth.contract(contractAbi).at(contractAddress);
var sig1 = 'e1(uint256)';
var top1 = web3.sha3(sig1);
console.log('topic1: ' + top1);

var sig2 = 'e2(string)';
var top2 = web3.sha3(sig2);
console.log('topic2: ' + top2);

var sig3='e3(address)';
var top3 = web3.sha3(sig3);
console.log('topic3: ' + top3);

var filter = web3.eth.filter({fromBlock:0, toBlock: 'latest', address: contractAddress});
filter.watch(function(error, result) {
  console.log('----->>> filter watch, topics: ' + JSON.stringify(result.topics));
  if (error) {
    console.log('error: ' + error);
    return;
  }
  if (result.topics.length != 1) {
    console.log('expected exactly one topic but got: ' + JSON.stringify(result.topics));
    return;
  }
  if (result.topics[0] == top1) {
    console.log('match top1');
    console.log('result: ' + JSON.stringify(result));
    var data = result.data;
    var params = SolidityCoder.decodeParams(["uint"], data.replace("0x", ""));
    console.log('params: ' + JSON.stringify(params));
  }
})

While calling the events all works out well, my event handlers fire once, here the example output:

topic1: 0x3680e78b6fdf571695c81f108d81181ea63f50c100e6375e765b14bd7ac0adbb
topic2: 0xe0d9935fff88c5e5f6d089e6587a79ea3e939e9e799e1f6288408071216fc3b1
topic3: 0x7b64c93018b004886241785dd74cca5f1e57211eb496d814af11ecb26a7beb39
----->>> filter watch, topics: ["0x3680e78b6fdf571695c81f108d81181ea63f50c100e6375e765b14bd7ac0adbb"]
match top1
result: {"logIndex":0,"transactionIndex":1,"transactionHash":"0xc256a9905d90abe8cab06806fcce7a03e829c151d37d59b7ff1a0428de8a5cc9","blockHash":"0xff1235982c72e5ee230cc2b4ea1a04517af50468206b9b8480da8cb875e6b054","blockNumber":6,"address":"0x86e0497e32a8e1d79fe38ab87dc80140df5470d9","data":"0x000000000000000000000000000000000000000000000000000000000000007b","topics":["0x3680e78b6fdf571695c81f108d81181ea63f50c100e6375e765b14bd7ac0adbb"]}
params: ["123"]
----->>> filter watch, topics: ["0xe0d9935fff88c5e5f6d089e6587a79ea3e939e9e799e1f6288408071216fc3b1"]
----->>> filter watch, topics: ["0x7b64c93018b004886241785dd74cca5f1e57211eb496d814af11ecb26a7beb39"]

Now when restarting my NodeJS app (Sandbox kept running, no further calls made), it turns out that all events are firing twice. This does not happen all the time but approximately in half of all times that I try (50% failure rate), I do not see with what this double-firing correlates it seems fairly random. Here some example output:

topic1: 0x3680e78b6fdf571695c81f108d81181ea63f50c100e6375e765b14bd7ac0adbb
topic2: 0xe0d9935fff88c5e5f6d089e6587a79ea3e939e9e799e1f6288408071216fc3b1
topic3: 0x7b64c93018b004886241785dd74cca5f1e57211eb496d814af11ecb26a7beb39
----->>> filter watch, topics: ["0x3680e78b6fdf571695c81f108d81181ea63f50c100e6375e765b14bd7ac0adbb"]
match top1
result: {"logIndex":0,"transactionIndex":1,"transactionHash":"0xc256a9905d90abe8cab06806fcce7a03e829c151d37d59b7ff1a0428de8a5cc9","blockHash":"0xff1235982c72e5ee230cc2b4ea1a04517af50468206b9b8480da8cb875e6b054","blockNumber":6,"address":"0x86e0497e32a8e1d79fe38ab87dc80140df5470d9","data":"0x000000000000000000000000000000000000000000000000000000000000007b","topics":["0x3680e78b6fdf571695c81f108d81181ea63f50c100e6375e765b14bd7ac0adbb"]}
params: ["123"]
----->>> filter watch, topics: ["0xe0d9935fff88c5e5f6d089e6587a79ea3e939e9e799e1f6288408071216fc3b1"]
----->>> filter watch, topics: ["0x7b64c93018b004886241785dd74cca5f1e57211eb496d814af11ecb26a7beb39"]
----->>> filter watch, topics: ["0x3680e78b6fdf571695c81f108d81181ea63f50c100e6375e765b14bd7ac0adbb"]
match top1
result: {"logIndex":0,"transactionIndex":1,"transactionHash":"0xc256a9905d90abe8cab06806fcce7a03e829c151d37d59b7ff1a0428de8a5cc9","blockHash":"0xff1235982c72e5ee230cc2b4ea1a04517af50468206b9b8480da8cb875e6b054","blockNumber":6,"address":"0x86e0497e32a8e1d79fe38ab87dc80140df5470d9","data":"0x000000000000000000000000000000000000000000000000000000000000007b","topics":["0x3680e78b6fdf571695c81f108d81181ea63f50c100e6375e765b14bd7ac0adbb"]}
params: ["123"]
----->>> filter watch, topics: ["0xe0d9935fff88c5e5f6d089e6587a79ea3e939e9e799e1f6288408071216fc3b1"]
----->>> filter watch, topics: ["0x7b64c93018b004886241785dd74cca5f1e57211eb496d814af11ecb26a7beb39"]

[mkalinin]

@SCBuergel this doesn't seem to be a bug. Cause web3 uses eth_getFilterLogs to pick logs. And since you set fromBlock to 0 it shows you info about all the events occurred on the blockchain. If web3 would use eth_getFilterChanges then we'd see behavior expected by you. You, also, can set fromBlock to latest to get an expected behavior.

[SCBuergel]

@mkalinin I would agree if the behavior is consistent. Unfortunately it is not. About 50% of all attempts I get the event handler being called once and the other ~50% of the time I get two my event handler being called twice.

[mkalinin]

@SCBuergel I've made about 10 tries with different action sequences. It hasn't reproduced. can you take a video showing this problem, pls?

[SCBuergel]

@mkalinin you mentioned on Slack that you've been able to reproduce this, any updates?

[mkalinin]

@SCBuergel will investigate in it and keep you updated

[mkalinin]

Caused by web3/web3.js#573