Skip to content

bip68-sequence.py failing on master after recent net changes, due to mocktime interaction #9586

@sdaftuar

Description

@sdaftuar

Since 60befa3 in #9441, bip68-sequence.py (one of the extended rpc tests, not run by travis) has been failing:

Initializing test directory /var/folders/pw/k25spdv971g8xhccyx5t3yyr0000gn/T/test5y497icn/9191
Running test disable flag
Running test sequence-lock-confirmed-inputs
Running test sequence-lock-unconfirmed-inputs
Running test BIP68 not consensus before versionbits activation
Verifying nVersion=2 transactions aren't standard
Activating BIP68 (and 112/113)
Assertion failed: Block sync to height 432 timed out:
  {'hash': '05c02af44675851560cb13b1b59f2a7f08ff3bef4e3db19f6a08e79cb51cce62', 'height': 432}
  {'hash': '30f24ff219ac23291d1489710ad467726b7ab202f70923d4bd5707dacfb05051', 'height': 328}
  File "/Users/sdaftuar/projects/ccl-bitcoin/qa/rpc-tests/test_framework/test_framework.py", line 145, in main
    self.run_test()
  File "./bip68-sequence.py", line 58, in run_test
    self.activateCSV()
  File "./bip68-sequence.py", line 409, in activateCSV
    sync_blocks(self.nodes)
  File "/Users/sdaftuar/projects/ccl-bitcoin/qa/rpc-tests/test_framework/util.py", line 147, in sync_blocks
    maxheight, "".join("\n  {!r}".format(tip) for tip in tips)))
Stopping nodes
Not cleaning up dir /var/folders/pw/k25spdv971g8xhccyx5t3yyr0000gn/T/test5y497icn/9191
Failed

I git bisected the problem back to the above commit; the issue seems to be that the inactivity checking at https://github.com/theuni/bitcoin/blob/60befa3997b98d3f913010f2621bec734f643526/src/net.cpp#L1298 is comparing times that are coming from two different places: GetTime() which can use mocktime, and GetTimeMicros() which does not, and the bip68-sequence.py test uses mocktime. (Using GetTimeMicros() for nLastRecv is newly introduced in the commit above.)

Really, it's sort of remarkable/lucky that we didn't have test failures relating to how mocktime interacts with the networking code before. I'm not sure what the right way to fix this is -- I started by trying to narrowly just fix this issue by changing nTimeConnected, nLastSend, and the starting nTime used in the inactivity check to all be based off system clock (eg GetTimeMicros()/1000000), but then that broke some of our other tests that I think must have been relying on mocktime having an effect on some of these things (maxuploadtarget.py, receivedby.py, and listtransactions.py all failed -- I didn't investigate exactly what happened so it's possible my fix just had a simple mistake).

Anyway I think we need a thoughtful approach to how to use GetTime() vs. GetTimeMicros() for the various times we have, especially in net.cpp/net_processing.cpp, and this is a bug that I think we need to fix for 0.14 so we're not shipping broken tests.

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions