'Re-starting finished log context handle_presence_timeouts'

[richvdh]

When synapse is busy, we log the following warning:

2020-10-20 11:24:03,215 - synapse.logging.context - 70 - WARNING - handle_presence_timeouts-1- Re-starting finished log context handle_presence_timeouts-1

It looks like the call to FederationSender.send_presence isn't setting up log contexts correctly.

[anoadragon453]

As it's the only function in the codebase to use the @preserve_fn decorator I'm a little suspicious that that may be the cause. Upon investigating the decorator though I don't see anything inherently wrong with it:

synapse/synapse/logging/context.py

Lines 665 to 671 in 5e3ca12

	def preserve_fn(f):
	"""Function decorator which wraps the function with run_in_background"""
	def g(*args, **kwargs):
	return run_in_background(f, *args, **kwargs)
	return g

[richvdh]

yes, it's the use of @preserve_fn that is the problem. It means that we can still be doing work within that function after the handle_presence_timeouts context has finished.

(Apart from the warning, it's bad in that it means that such work isn't making it into the prometheus CPU/database metrics.)

[clokep]

There's a similar-sounding wrap_as_background_task which might do what is wanted? 🤷

[richvdh]

probably. there is a question to be answered over whether this work should run in the background at all, or if the caller should be waiting for it to complete.

[richvdh]

I think this was fixed by #9828.