Payment timestamp cannot be from the future

[etam]

Description

Golem Version: current develop (5550f5b0d)

Golem-Messages version: 3.14.1

OS: Linux

Branch: develop

Description of the issue:

2020-01-31 14:49:26 DEBUG    golem.network.transport.message     Deserialization class found. class=<class 'golem_messages.message.tasks.SubtaskResultsAccepted'>
2020-01-31 14:49:26 DEBUG    golem.network.transport.tcpnetwork  SafeProtocol._prepare_msg_to_send('SubtaskResultsAccepted'(header=MessageHeader(type_=2010, timestamp=1580478566, encrypted=False), sig=None, slots=[['payment_ts', 1580478564], ['report_computed_task', (F
2020-01-31 14:49:26 DEBUG    golem.network.transport.tcpnetwork  Sending: <class 'golem_messages.message.tasks.SubtaskResultsAccepted'>, using session: <TaskSession with 10.30.10.100:40109 (LMT: 0.0041120052337646484s)>
2020-01-31 14:49:26 DEBUG    golem.network.transport.message     deserialize_header(): MessageHeader(type_=2010, timestamp=1580478564, encrypted=False)
2020-01-31 14:49:26 DEBUG    golem.network.transport.message     Deserialization class found. class=<class 'golem_messages.message.tasks.SubtaskResultsAccepted'>
2020-01-31 14:49:26 INFO     golem.network.transport.msg_queue   Invalid message in queue. db_model=QueuedMessage node=64dde94b..2deea7ce, version=3.14.1, class=golem_messages.message.tasks.SubtaskResultsAccepted
Traceback (most recent call last):
  File "/home/etam/code/github/golemfactory/golem/develop/golem/network/transport/msg_queue.py", line 45, in get
    msg = db_model.as_message()
  File "/home/etam/code/github/golemfactory/golem/develop/golem/model.py", line 680, in as_message
    check_time=False,
  File "/home/etam/code/github/golemfactory/golem/develop/venv/lib/python3.6/site-packages/golem_messages/shortcuts.py", line 27, in load
    data, decrypt, check_time, sender_public_key=pubkey)
  File "/home/etam/code/github/golemfactory/golem/develop/venv/lib/python3.6/site-packages/golem_messages/message/base.py", line 450, in deserialize
    sender_public_key=sender_public_key,
  File "/home/etam/code/github/golemfactory/golem/develop/venv/lib/python3.6/site-packages/golem_messages/message/tasks.py", line 205, in deserialize_with_header
    instance.is_valid()
  File "/home/etam/code/github/golemfactory/golem/develop/venv/lib/python3.6/site-packages/golem_messages/message/tasks.py", line 586, in is_valid
    "Payment timestamp cannot be from the future!"
golem_messages.exceptions.ValidationError: Payment timestamp cannot be from the future!

In the log fragment above timestamp is equal to time of logs, and payment_ts is 2 seconds earlier. But somehow self.payment_ts > self.header.timestamp in SubtaskResultsAccepted.is_valid became True.

Steps To Reproduce

Run wasm_vbr_single_failure integration test. Reproducible: sometimes.

[etam]

Also happens with test_wasm_vbr_success and test_zero_price.

[etam]

I cannot reproduce it anymore. When reading the code it makes no sense that it could ever happen. Integration tests are now passing. I have no idea.

I'm closing it now. Feel free to reopen if it happens again.

[etam]

happened again in b0.23 branch: https://buildbot.golem.network/buildbot/#/builders/15/builds/979