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

retention purge job don't run #6683

Closed
4nd3r opened this issue Jan 12, 2020 · 14 comments
Closed

retention purge job don't run #6683

4nd3r opened this issue Jan 12, 2020 · 14 comments
Assignees
@babolivier
Labels
z-bug (Deprecated Label) z-p2 (Deprecated Label)

Comments

@4nd3r
Copy link
Contributor

4nd3r commented Jan 12, 2020

Steps to reproduce

  • set retention: enabled: true in homeserver config
  • restart synapse
  • send event m.room.retention with content { "max_lifetime": 86400000 }
  • select * from room_retention confirms that message retention is configured for room
  • wait 24 hours and bit more

    synapse/synapse/config/server.py

    Line 368 in c2ba994

    "interval": self.parse_duration("1d"),
  • messages older than 86400000 ms still in the room (even after clear cache and reload)

Version information

  • Homeserver: private
  • Version: 1.8.0
  • Install method: virtual env & pip
  • Platform: debian 9 with postgresql 9.6
@babolivier
Copy link
Contributor

Thanks for the report, I will have a look later next week. FWIW, can you find lines which message start with [purge] in your Synapse logs?

@babolivier babolivier self-assigned this Jan 12, 2020
@4nd3r
Copy link
Contributor Author

4nd3r commented Jan 13, 2020

FWIW, can you find lines which message start with [purge] in your Synapse logs?

no such messages in log (loglevel=INFO).

@babolivier babolivier mentioned this issue Jan 15, 2020
Closed
@babolivier
Copy link
Contributor

Hmm, weird. Even if the purge job doesn't run, Synapse should prevent expired events from being sent to clients:

synapse/synapse/visibility.py

Lines 125 to 135 in ac87ddb

# Don't try to apply the room's retention policy if the event is a state event, as
# MSC1763 states that retention is only considered for non-state events.
if apply_retention_policies and not event.is_state():
retention_policy = retention_policies[event.room_id]
max_lifetime = retention_policy.get("max_lifetime")
if max_lifetime is not None:
oldest_allowed_ts = storage.main.clock.time_msec() - max_lifetime
if event.origin_server_ts < oldest_allowed_ts:
return None

Therefore events shouldn't be visible from Riot after a "Clear cache and reload"...

I've tried to reproduce this in a room with the same settings as yours, with a few messages in there:

Screenshot from 2020-01-13 11-20-34

and then waited a bit more than a day and hit "Clear cache and reload" in Riot, and the messages had disappeared as expected:

Screenshot from 2020-01-14 13-53-43

So it looks to me like Synapse doesn't believe the feature has been enabled on your server, which leaves me puzzled, as it shouldn't happen if you have

retention:
    enable: true

in your homeserver's configuration :/

@babolivier
Copy link
Contributor

At this point the only thing I can think of that might help is restart your homeserver to ensure it registered the configuration change...

@richvdh
Copy link
Member

richvdh commented Jan 15, 2020

@babolivier: would it be worth adding some more logging to help us see what purge jobs are being set up, and when they are running?

@babolivier
Copy link
Contributor

@babolivier: would it be worth adding some more logging to help us see what purge jobs are being set up, and when they are running?

Oh good idea, I'll look at that tomorrow!

@babolivier babolivier mentioned this issue Jan 16, 2020
Merged
babolivier added a commit that referenced this issue Jan 16, 2020
@babolivier
Add more logging around message retention policies support
3098dfd 
So we can debug issues like #6683 more easily
babolivier added a commit that referenced this issue Jan 17, 2020
@babolivier
Add more logging around message retention policies support (#6717)
a17f643 
So we can debug issues like #6683 more easily
@neilisfragile neilisfragile added z-bug (Deprecated Label) z-p2 (Deprecated Label) labels Jan 22, 2020
@4nd3r
Copy link
Contributor Author

4nd3r commented Jan 23, 2020

upgraded to 1.9.0 and first line in logs was:

Setting up purge job with config: {'longest_max_lifetime': None, 'shortest_max_lifetime': None, 'interval': 86400000}

should I turn loglevel to DEBUG or is INFO enough?

@babolivier
Copy link
Contributor

Hey @4nd3r, debug logs might help.

Though they might contain sensitive data, so please send them to me in PM (@brendan:abolivier.bzh) rather than here.

@4nd3r
Copy link
Contributor Author

4nd3r commented Jan 24, 2020 

# grep -hF '[purge]' homeserver.log*
2020-01-24 17:55:06,975 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 - Message: '[purge] Running purge job for %d < max_lifetime <= %d (include NULLs = %s)'
2020-01-24 17:55:06,994 - synapse.handlers.pagination - 146 - DEBUG - purge_history_for_rooms_in_range-0 - [purge] Rooms to purge: {}

synapse=> select * from room_retention;
           room_id           |          event_id           | min_lifetime | max_lifetime 
-----------------------------+-----------------------------+--------------+--------------
 !XXX:kvlt.ee                | $XXX:kvlt.ee                |              |     86400000
 !YYY:kvlt.ee                | $YYY:kvlt.ee                |              |    604800000
 !ZZZ:kvlt.ee                | $ZZZ:kvlt.ee                |              |    604800000
 !QQQ:kvlt.ee                | $QQQ:kvlt.ee                |              |    604800000
(4 rows)

@4nd3r
Copy link
Contributor Author

4nd3r commented Jan 24, 2020

and some more.

if that's not helpful, then I'll send you full log after some clean up.

2020-01-24 17:55:06,956 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 - --- Logging error ---
2020-01-24 17:55:06,963 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 - Traceback (most recent call last):
2020-01-24 17:55:06,963 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/usr/lib/python3.5/logging/handlers.py", line 71, in emit
2020-01-24 17:55:06,963 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     if self.shouldRollover(record):
2020-01-24 17:55:06,963 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/usr/lib/python3.5/logging/handlers.py", line 187, in shouldRollover
2020-01-24 17:55:06,964 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     msg = "%s\n" % self.format(record)
2020-01-24 17:55:06,964 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/usr/lib/python3.5/logging/__init__.py", line 831, in format
2020-01-24 17:55:06,964 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     return fmt.format(record)
2020-01-24 17:55:06,964 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/usr/lib/python3.5/logging/__init__.py", line 568, in format
2020-01-24 17:55:06,964 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     record.message = record.getMessage()
2020-01-24 17:55:06,964 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/usr/lib/python3.5/logging/__init__.py", line 331, in getMessage
2020-01-24 17:55:06,964 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     msg = msg % self.args
2020-01-24 17:55:06,965 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 - TypeError: %d format: a number is required, not NoneType
2020-01-24 17:55:06,965 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 - Call stack:
2020-01-24 17:55:06,971 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/usr/lib/python3.5/runpy.py", line 193, in _run_module_as_main
2020-01-24 17:55:06,971 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     "__main__", mod_spec)
2020-01-24 17:55:06,971 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/usr/lib/python3.5/runpy.py", line 85, in _run_code
2020-01-24 17:55:06,971 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     exec(code, run_globals)
2020-01-24 17:55:06,971 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/app/homeserver.py", line 639, in <module>
2020-01-24 17:55:06,971 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     main()
2020-01-24 17:55:06,971 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/app/homeserver.py", line 635, in main
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     run(hs)
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/app/homeserver.py", line 626, in run
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     logger=logger,
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/app/_base.py", line 139, in start_reactor
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     run()
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/app/_base.py", line 114, in run
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     run_command()
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/base.py", line 1267, in run
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     self.mainLoop()
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/base.py", line 1276, in mainLoop
2020-01-24 17:55:06,972 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     self.runUntilCurrent()
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/metrics/__init__.py", line 434, in f
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     ret = func(*args, **kwargs)
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/base.py", line 902, in runUntilCurrent
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     call.func(*call.args, **call.kw)
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/task.py", line 239, in __call__
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     d = defer.maybeDeferred(self.f, *self.a, **self.kw)
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/defer.py", line 151, in maybeDeferred
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     result = f(*args, **kw)
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/metrics/background_process_metrics.py", line 222, in run_as_background_process
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     return run()
2020-01-24 17:55:06,973 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/defer.py", line 1613, in unwindGenerator
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     return _cancellableInlineCallbacks(gen)
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/defer.py", line 1529, in _cancellableInlineCallbacks
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     _inlineCallbacks(None, g, status)
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     result = g.send(result)
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/metrics/background_process_metrics.py", line 202, in run
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     result = func(*args, **kwargs)
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/defer.py", line 1613, in unwindGenerator
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     return _cancellableInlineCallbacks(gen)
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/defer.py", line 1529, in _cancellableInlineCallbacks
2020-01-24 17:55:06,974 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     _inlineCallbacks(None, g, status)
2020-01-24 17:55:06,975 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/twisted/internet/defer.py", line 1418, in _inlineCallbacks
2020-01-24 17:55:06,975 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     result = g.send(result)
2020-01-24 17:55:06,975 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -   File "/home/matrix-synapse/synapse/env/lib/python3.5/site-packages/synapse/handlers/pagination.py", line 139, in purge_history_for_rooms_in_range
2020-01-24 17:55:06,975 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 -     include_null,
2020-01-24 17:55:06,975 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 - Message: '[purge] Running purge job for %d < max_lifetime <= %d (include NULLs = %s)'
2020-01-24 17:55:06,975 - twisted - 192 - ERROR - purge_history_for_rooms_in_range-0 - Arguments: (None, None, False)

@4nd3r
Copy link
Contributor Author

4nd3r commented Feb 6, 2020

any update on this?

@babolivier
Copy link
Contributor

any update on this?

Sorry, I've been busy with other things, I'll try to look at this again soon.

@babolivier babolivier mentioned this issue Feb 18, 2020
Merged
@babolivier
Copy link
Contributor

All right, so that error was due to a fail on my part when adding the logs, this has been fixed in #6945. Let's try to debug this further in PM and I'll share the conclusion here.

@babolivier
Copy link
Contributor

We eventually got to the bottom of it, and the issue was that the m.room.retention events weren't sent as state events.

https://github.com/matrix-org/synapse/blob/master/docs/message_retention_policies.md#room-configuration already spells out the requirement for the events to be state events so I don't think any action from me is required, therefore I'm closing the issue.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@babolivier babolivier

Labels
z-bug (Deprecated Label) z-p2 (Deprecated Label)
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@neilisfragile @richvdh @babolivier @4nd3r