random 500 failures with exceptions.ValueError: Counters can only be incremented by non-negative amounts.

[richvdh]

from time to time random requests fail with a 500 error. it looks like we're trying to report a negative CPU usage.

2018-07-16 14:09:14,467 - synapse.http.server - 101 - ERROR - POST-2245 - Failed handle request via <function _async_render at 0x7f78a28f5de8>: <SynapseRequest at 0x7f7884056998 method='POST' uri='/_matrix/client/r0/createRoom?access_token=<redacted>' clientproto='HTTP/1.1' site=27060>: Traceback (most recent call last):
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 653, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1442, in gotResult
    _inlineCallbacks(r, g, deferred)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/python/failure.py, line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
--- <exception caught here> ---
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/http/server.py, line 78, in wrapped_request_handler
    yield h(self, request)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/python/failure.py, line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/http/server.py, line 304, in _async_render
    callback_return = yield callback(request, **kwargs)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/python/failure.py, line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/rest/client/v1/room.py, line 73, in on_POST
    requester, self.get_room_config(request)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/python/failure.py, line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/handlers/room.py, line 198, in create_room
    creator_join_profile=creator_join_profile,
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/python/failure.py, line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/handlers/room.py, line 380, in _send_events_for_new_room
    content={history_visibility: config[history_visibility]}
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/python/failure.py, line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/handlers/room.py, line 297, in send
    ratelimit=False
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/python/failure.py, line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/handlers/message.py, line 669, in create_and_send_nonmember_event
    txn_id=txn_id
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1384, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/python/failure.py, line 393, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/handlers/message.py, line 503, in create_event
    prev_events_and_hashes=prev_events_and_hashes,
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/twisted/internet/defer.py, line 1386, in _inlineCallbacks
    result = g.send(result)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/util/metrics.py, line 55, in measured_func
    r = yield func(self, *args, **kwargs)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/synapse/synapse/util/metrics.py, line 108, in __exit__
    block_ru_utime.labels(self.name).inc(usage.ru_utime)
  File /var/lib/jenkins/jobs/Sytest-Postgres-Branches/workspace/.tox/py27/local/lib/python2.7/site-packages/prometheus_client/core.py, line 654, in inc
    raise ValueError('Counters can only be incremented by non-negative amounts.')
exceptions.ValueError: Counters can only be incremented by non-negative amounts.

[richvdh]

This is workarounded by #3563, but it would be good to revisit it and see if we can figure out why it is happening.

[richvdh]

(fwiw we're hitting this a few times a day on matrix.org)

[erikjohnston]

I think the conclusion was that its likely due to calling rusage in quick succession may produce a negative delta due to handwaves floating point errors

[richvdh]

sounds bogus

[richvdh]

This isn't happening any more, so I guess it's fixed.

[richvdh]

(probably by #5609)