Skip to content
This repository has been archived by the owner on Apr 26, 2024. It is now read-only.

synapse logs drown in logcontext warnings #3518

Closed
ara4n opened this issue Jul 12, 2018 · 10 comments
Closed

synapse logs drown in logcontext warnings #3518

ara4n opened this issue Jul 12, 2018 · 10 comments
Labels
A-Logging Synapse's logs (structured or otherwise). Not metrics. z-minor (Deprecated Label) z-p2 (Deprecated Label)

Comments

@ara4n
Copy link
Member

ara4n commented Jul 12, 2018

even on simple things like /sync
@richvdh
Copy link
Member

richvdh commented Jul 18, 2018

I'm assuming the warnings in question are like these:

2018-07-18 10:48:01,775 - synapse.storage._base - 347 - WARNING - - Running db txn from sentinel context: metrics will be lost

richvdh added a commit that referenced this issue Jul 18, 2018
@richvdh
Resource tracking for background processes
6e3fc65 
This introduces a mechanism for tracking resource usage by background
processes, along with an example of how it will be used.

This will help address #3518, but more importantly will give us better insights
into things which are happening but not being shown up by the request metrics.

We *could* do this with Measure blocks, but:
 - I think having them pulled out as a completely separate metric class will
   make it easier to distinguish top-level processes from those which are
   nested.

 - I want to be able to report on in-flight background processes, and I don't
   think we want to do this for *all* Measure blocks.
@richvdh richvdh mentioned this issue Jul 18, 2018
Merged
@richvdh richvdh mentioned this issue Jul 18, 2018
Merged
@richvdh richvdh mentioned this issue Jul 19, 2018
Closed
@richvdh
Copy link
Member

richvdh commented Jul 19, 2018

(for the record, this was introduced by #3496)

@richvdh richvdh changed the title synapse logs when run by sytest drown in logcontext warnings synapse logs drown in logcontext warnings Jul 19, 2018
richvdh added a commit that referenced this issue Jul 19, 2018
@richvdh
Disable logcontext warning
00bc979 
Temporary workaround to #3518 while we release 0.33.0.
@richvdh richvdh mentioned this issue Jul 19, 2018
Merged
@neilisfragile neilisfragile added z-p2 (Deprecated Label) z-minor (Deprecated Label) labels Jul 23, 2018
@hawkowl hawkowl closed this as completed in 667fba6 Aug 9, 2018
@richvdh
Copy link
Member

richvdh commented Aug 9, 2018

There are actually still a lot of these going on in our production instance. I'm going to reopen this

@richvdh richvdh reopened this Aug 9, 2018
@richvdh richvdh mentioned this issue Aug 23, 2018
Closed
@hawkowl hawkowl added the A-Logging Synapse's logs (structured or otherwise). Not metrics. label Sep 14, 2018
@zwieberl
Copy link

After upgrading from 0.33 to 0.34.1.1 (and switching to python3, if that is relevant), I started getting these log-entries every minute (didn't see them before at all).
The logs are, after the initial startup, empty expect for these messages.

@richvdh
Copy link
Member

richvdh commented Jan 17, 2019

The remaining instances of this on the production server are:

synapse.storage._base - 319 - WARNING -  - Starting db txn '_get_joined_users_from_context' from sentinel context
synapse.storage._base - 319 - WARNING -  - Starting db txn 'get_state_group_delta' from sentinel context
synapse.storage._base - 319 - WARNING -  - Starting db txn '_get_state_groups_from_groups' from sentinel context

we're only getting a handful of them, so this is now a pretty minor issue.

@zwieberl I imagine you have a different problem and it would be better to open a separate issue including the logs you are seeing.

@agherzan
Copy link

On 0.99.3.2 I still get:

2019-05-13 19:58:26,091 - synapse.storage._base - 401 - WARNING - - Starting db txn 'update_presence' from sentinel context
2019-05-13 19:58:26,091 - synapse.storage._base - 437 - WARNING - - Starting db connection from sentinel context: metrics will be lost

@richvdh
Copy link
Member

richvdh commented May 14, 2019

looks like PresenceHandler needs its use of logcontexts cleaning up. In particular, _handle_timeouts and _persist_unpersisted_changes need wrapping with run_as_background_process

@richvdh
Copy link
Member

richvdh commented May 28, 2019

This is being exacerbated by #5271 currently

@richvdh
Copy link
Member

richvdh commented May 28, 2019

and the ones about presence are #4414

@richvdh
Copy link
Member

richvdh commented May 29, 2019

given that #4414 and #5271 are now fixed, I'm going to consider this fixed enough to be closed. We should open more granular bugs for any more that are discovered.

@richvdh richvdh closed this as completed May 29, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
A-Logging Synapse's logs (structured or otherwise). Not metrics. z-minor (Deprecated Label) z-p2 (Deprecated Label)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@neilisfragile @ara4n @richvdh @agherzan @zwieberl @hawkowl