Repeated "db txn 'update_presence' from sentinel context" log messages

[zwieberl]

Description

After upgrading my homeserver from 0.33 to 0.34.1.1 (and switching to python3 in a new virtual env, if that is relevant) Synapse writes the following log-entries every minute into the logs:

2019-01-17 19:40:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 19:40:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost

The first hour does not contain anything else:

2019-01-17 13:44:05,223 - root - 211 - WARNING - None - ***** STARTING SERVER *****
2019-01-17 13:44:05,282 - root - 214 - WARNING - None - Server /home/matrix/synapse/env3/lib/python3.5/site-packages/synapse/app/homeserver.py version 0.34.1.1
2019-01-17 13:44:05,596 - synapse.app.homeserver - 223 - WARNING - None - Not enabling webclient resource, as web_client_location is unset.
2019-01-17 13:44:05,672 - synapse.app._base - 194 - WARNING - None - Failed to listen on 0.0.0.0, continuing because listening on [::]
2019-01-17 13:44:05,701 - synapse.app.homeserver - 223 - WARNING - None - Not enabling webclient resource, as web_client_location is unset.
2019-01-17 13:46:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:46:05,582 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:47:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:47:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:48:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:48:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:49:05,576 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:49:05,580 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:50:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:50:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:51:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:51:05,582 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:52:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:52:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:53:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:53:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:54:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:54:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:55:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:55:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:56:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:56:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:57:05,576 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:57:05,580 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:58:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:58:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 13:59:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 13:59:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 14:00:05,576 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 14:00:05,580 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 14:01:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-17 14:01:05,579 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-17 14:02:05,575 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context

After a while, the occasional "Not sending response to request ... client already disconnected"-messages start showing as well.

Before the upgrade I had no such messages in the logs.

Everything seems to work, but I would prefer to get rid of these messages, as they grow the logs very fast.

Version information

• Homeserver: Selfhosted homeserver
• Version: 0.34.1.1
• Install method: pip
• Platform: raspian, rapsberrypi, bare metal

[richvdh]

Thanks for the clear report @zwieberl.

The fact that these are happening reliably at 5 seconds past the minute points to a timer event. So I guess it's this: https://github.com/matrix-org/synapse/blob/v0.34.1.1/synapse/handlers/presence.py#L213

[zwieberl]

I think you are right. Switched to INFO-level and got this:

2019-01-18 09:48:01,593 - synapse.handlers.presence - 350 - INFO -  - Handling presence timeouts
2019-01-18 09:48:01,602 - synapse.handlers.typing - 89 - INFO -  - Checking for typing timeouts
2019-01-18 09:48:06,593 - synapse.handlers.presence - 350 - INFO -  - Handling presence timeouts
2019-01-18 09:48:06,601 - synapse.handlers.presence - 257 - INFO -  - Performing _persist_unpersisted_changes. Persisting 1 unpersisted changes
2019-01-18 09:48:06,603 - synapse.storage._base - 319 - WARNING -  - Starting db txn 'update_presence' from sentinel context
2019-01-18 09:48:06,606 - synapse.storage._base - 355 - WARNING -  - Starting db connection from sentinel context: metrics will be lost
2019-01-18 09:48:06,616 - synapse.handlers.typing - 89 - INFO -  - Checking for typing timeouts
2019-01-18 09:48:06,632 - synapse.handlers.presence - 269 - INFO -  - Finished _persist_unpersisted_changes

So it seems to be indeed the the _persist_unpersisted_changes-handler.
Not sure what that means, though

[richvdh]

fixed by #5275