[develop] Error handling background update 'populate_stats_process_rooms'

[turt2live]

2019-05-22 23:12:51,628 - twisted - 242 - ERROR - background_updates-0 - --- Logging error ---
2019-05-22 23:12:51,629 - twisted - 242 - ERROR - background_updates-0 - Traceback (most recent call last):
2019-05-22 23:12:51,629 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2019-05-22 23:12:51,629 - twisted - 242 - ERROR - background_updates-0 -     result = g.send(result)
2019-05-22 23:12:51,629 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/storage/_base.py", line 527, in runWithConnection
2019-05-22 23:12:51,630 - twisted - 242 - ERROR - background_updates-0 -     defer.returnValue(result)
2019-05-22 23:12:51,630 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1362, in returnValue
2019-05-22 23:12:51,630 - twisted - 242 - ERROR - background_updates-0 -     raise _DefGen_Return(val)
2019-05-22 23:12:51,630 - twisted - 242 - ERROR - background_updates-0 - twisted.internet.defer._DefGen_Return: [('!redacted', 7), ... snipped ...]
2019-05-22 23:12:51,633 - twisted - 242 - ERROR - background_updates-0 -
2019-05-22 23:12:51,633 - twisted - 242 - ERROR - background_updates-0 - During handling of the above exception, another exception occurred:
2019-05-22 23:12:51,633 - twisted - 242 - ERROR - background_updates-0 -
2019-05-22 23:12:51,633 - twisted - 242 - ERROR - background_updates-0 - Traceback (most recent call last):
2019-05-22 23:12:51,633 - twisted - 242 - ERROR - background_updates-0 -   File "/usr/lib/python3.6/logging/handlers.py", line 71, in emit
2019-05-22 23:12:51,633 - twisted - 242 - ERROR - background_updates-0 -     if self.shouldRollover(record):
2019-05-22 23:12:51,634 - twisted - 242 - ERROR - background_updates-0 -   File "/usr/lib/python3.6/logging/handlers.py", line 187, in shouldRollover
2019-05-22 23:12:51,634 - twisted - 242 - ERROR - background_updates-0 -     msg = "%s\n" % self.format(record)
2019-05-22 23:12:51,634 - twisted - 242 - ERROR - background_updates-0 -   File "/usr/lib/python3.6/logging/__init__.py", line 840, in format
2019-05-22 23:12:51,634 - twisted - 242 - ERROR - background_updates-0 -     return fmt.format(record)
2019-05-22 23:12:51,634 - twisted - 242 - ERROR - background_updates-0 -   File "/usr/lib/python3.6/logging/__init__.py", line 577, in format
2019-05-22 23:12:51,634 - twisted - 242 - ERROR - background_updates-0 -     record.message = record.getMessage()
2019-05-22 23:12:51,635 - twisted - 242 - ERROR - background_updates-0 -   File "/usr/lib/python3.6/logging/__init__.py", line 338, in getMessage
2019-05-22 23:12:51,635 - twisted - 242 - ERROR - background_updates-0 -     msg = msg % self.args
2019-05-22 23:12:51,635 - twisted - 242 - ERROR - background_updates-0 - TypeError: %d format: a number is required, not tuple
2019-05-22 23:12:51,635 - twisted - 242 - ERROR - background_updates-0 - Call stack:
2019-05-22 23:12:51,635 - twisted - 242 - ERROR - background_updates-0 -   File "/usr/lib/python3.6/runpy.py", line 193, in _run_module_as_main
2019-05-22 23:12:51,636 - twisted - 242 - ERROR - background_updates-0 -     "__main__", mod_spec)
2019-05-22 23:12:51,636 - twisted - 242 - ERROR - background_updates-0 -   File "/usr/lib/python3.6/runpy.py", line 85, in _run_code
2019-05-22 23:12:51,636 - twisted - 242 - ERROR - background_updates-0 -     exec(code, run_globals)
2019-05-22 23:12:51,636 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/app/homeserver.py", line 663, in <module>
2019-05-22 23:12:51,636 - twisted - 242 - ERROR - background_updates-0 -     main()
2019-05-22 23:12:51,636 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/app/homeserver.py", line 659, in main
2019-05-22 23:12:51,637 - twisted - 242 - ERROR - background_updates-0 -     run(hs)
2019-05-22 23:12:51,637 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/app/homeserver.py", line 650, in run
2019-05-22 23:12:51,637 - twisted - 242 - ERROR - background_updates-0 -     logger=logger,
2019-05-22 23:12:51,637 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/app/_base.py", line 144, in start_reactor
2019-05-22 23:12:51,637 - twisted - 242 - ERROR - background_updates-0 -     daemon.start()
2019-05-22 23:12:51,637 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/daemonize.py", line 248, in start
2019-05-22 23:12:51,638 - twisted - 242 - ERROR - background_updates-0 -     self.action(*privileged_action_result)
2019-05-22 23:12:51,638 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/app/_base.py", line 130, in run
2019-05-22 23:12:51,638 - twisted - 242 - ERROR - background_updates-0 -     reactor.run()
2019-05-22 23:12:51,638 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/base.py", line 1267, in run
2019-05-22 23:12:51,638 - twisted - 242 - ERROR - background_updates-0 -     self.mainLoop()
2019-05-22 23:12:51,638 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/base.py", line 1276, in mainLoop
2019-05-22 23:12:51,639 - twisted - 242 - ERROR - background_updates-0 -     self.runUntilCurrent()
2019-05-22 23:12:51,639 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/metrics/__init__.py", line 347, in f
2019-05-22 23:12:51,639 - twisted - 242 - ERROR - background_updates-0 -     ret = func(*args, **kwargs)
2019-05-22 23:12:51,639 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/base.py", line 875, in runUntilCurrent
2019-05-22 23:12:51,639 - twisted - 242 - ERROR - background_updates-0 -     f(*a, **kw)
2019-05-22 23:12:51,639 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 460, in callback
2019-05-22 23:12:51,639 - twisted - 242 - ERROR - background_updates-0 -     self._startRunCallbacks(result)
2019-05-22 23:12:51,640 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2019-05-22 23:12:51,640 - twisted - 242 - ERROR - background_updates-0 -     self._runCallbacks()
2019-05-22 23:12:51,640 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-05-22 23:12:51,640 - twisted - 242 - ERROR - background_updates-0 -     current.result = callback(current.result, *args, **kw)
2019-05-22 23:12:51,640 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2019-05-22 23:12:51,640 - twisted - 242 - ERROR - background_updates-0 -     _inlineCallbacks(r, g, status)
2019-05-22 23:12:51,640 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
2019-05-22 23:12:51,641 - twisted - 242 - ERROR - background_updates-0 -     status.deferred.callback(e.value)
2019-05-22 23:12:51,641 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 460, in callback
2019-05-22 23:12:51,641 - twisted - 242 - ERROR - background_updates-0 -     self._startRunCallbacks(result)
2019-05-22 23:12:51,641 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2019-05-22 23:12:51,641 - twisted - 242 - ERROR - background_updates-0 -     self._runCallbacks()
2019-05-22 23:12:51,641 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-05-22 23:12:51,642 - twisted - 242 - ERROR - background_updates-0 -     current.result = callback(current.result, *args, **kw)
2019-05-22 23:12:51,642 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2019-05-22 23:12:51,642 - twisted - 242 - ERROR - background_updates-0 -     _inlineCallbacks(r, g, status)
2019-05-22 23:12:51,642 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1461, in _inlineCallbacks
2019-05-22 23:12:51,642 - twisted - 242 - ERROR - background_updates-0 -     status.deferred.callback(e.value)
2019-05-22 23:12:51,642 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 460, in callback
2019-05-22 23:12:51,642 - twisted - 242 - ERROR - background_updates-0 -     self._startRunCallbacks(result)
2019-05-22 23:12:51,643 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks
2019-05-22 23:12:51,643 - twisted - 242 - ERROR - background_updates-0 -     self._runCallbacks()
2019-05-22 23:12:51,643 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks
2019-05-22 23:12:51,643 - twisted - 242 - ERROR - background_updates-0 -     current.result = callback(current.result, *args, **kw)
2019-05-22 23:12:51,643 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1475, in gotResult
2019-05-22 23:12:51,643 - twisted - 242 - ERROR - background_updates-0 -     _inlineCallbacks(r, g, status)
2019-05-22 23:12:51,643 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2019-05-22 23:12:51,644 - twisted - 242 - ERROR - background_updates-0 -     result = g.send(result)
2019-05-22 23:12:51,644 - twisted - 242 - ERROR - background_updates-0 -   File "/home/matrix/.synapse/local/lib/python3.6/site-packages/synapse/storage/stats.py", line 172, in _populate_stats_process_rooms
2019-05-22 23:12:51,644 - twisted - 242 - ERROR - background_updates-0 -     (len(rooms_to_work_on), progress["remaining"]),
2019-05-22 23:12:51,644 - twisted - 242 - ERROR - background_updates-0 - Message: 'Processing the next %d rooms of %d remaining'
2019-05-22 23:12:51,644 - twisted - 242 - ERROR - background_updates-0 - Arguments: ((176, 176),)

[neilisfragile]

cc @hawkowl

[richvdh]

Fixed by #5260