2014-11-19 18:20:59 +00:00
|
|
|
# -*- coding: utf-8 -*-
|
2016-01-07 04:26:29 +00:00
|
|
|
# Copyright 2015, 2016 OpenMarket Ltd
|
2014-11-19 18:20:59 +00:00
|
|
|
#
|
|
|
|
# Licensed under the Apache License, Version 2.0 (the "License");
|
|
|
|
# you may not use this file except in compliance with the License.
|
|
|
|
# You may obtain a copy of the License at
|
|
|
|
#
|
|
|
|
# http://www.apache.org/licenses/LICENSE-2.0
|
|
|
|
#
|
|
|
|
# Unless required by applicable law or agreed to in writing, software
|
|
|
|
# distributed under the License is distributed on an "AS IS" BASIS,
|
|
|
|
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
|
|
# See the License for the specific language governing permissions and
|
|
|
|
# limitations under the License.
|
|
|
|
|
|
|
|
from twisted.internet import defer
|
|
|
|
|
|
|
|
from synapse.streams.config import PaginationConfig
|
2016-01-20 15:30:31 +00:00
|
|
|
from synapse.types import StreamToken
|
2016-02-04 10:15:56 +00:00
|
|
|
from synapse.util.logcontext import LoggingContext
|
|
|
|
from synapse.util.metrics import Measure
|
2014-11-19 18:20:59 +00:00
|
|
|
|
|
|
|
import synapse.util.async
|
2015-12-09 15:51:34 +00:00
|
|
|
import push_rule_evaluator as push_rule_evaluator
|
2014-11-19 18:20:59 +00:00
|
|
|
|
|
|
|
import logging
|
2015-06-05 10:40:22 +00:00
|
|
|
import random
|
2014-11-19 18:20:59 +00:00
|
|
|
|
|
|
|
logger = logging.getLogger(__name__)
|
|
|
|
|
2014-12-03 13:37:02 +00:00
|
|
|
|
2016-02-04 10:15:56 +00:00
|
|
|
_NEXT_ID = 1
|
|
|
|
|
|
|
|
|
|
|
|
def _get_next_id():
|
|
|
|
global _NEXT_ID
|
|
|
|
_id = _NEXT_ID
|
|
|
|
_NEXT_ID += 1
|
|
|
|
return _id
|
|
|
|
|
|
|
|
|
2016-01-04 14:05:37 +00:00
|
|
|
# Pushers could now be moved to pull out of the event_push_actions table instead
|
2015-12-22 17:19:22 +00:00
|
|
|
# of listening on the event stream: this would avoid them having to run the
|
|
|
|
# rules again.
|
2014-11-19 18:20:59 +00:00
|
|
|
class Pusher(object):
|
|
|
|
INITIAL_BACKOFF = 1000
|
2014-11-21 12:21:00 +00:00
|
|
|
MAX_BACKOFF = 60 * 60 * 1000
|
|
|
|
GIVE_UP_AFTER = 24 * 60 * 60 * 1000
|
2015-01-30 14:46:03 +00:00
|
|
|
|
2016-01-13 13:08:59 +00:00
|
|
|
def __init__(self, _hs, profile_tag, user_id, app_id,
|
2015-01-13 19:48:37 +00:00
|
|
|
app_display_name, device_display_name, pushkey, pushkey_ts,
|
|
|
|
data, last_token, last_success, failing_since):
|
2014-11-19 18:20:59 +00:00
|
|
|
self.hs = _hs
|
|
|
|
self.evStreamHandler = self.hs.get_handlers().event_stream_handler
|
|
|
|
self.store = self.hs.get_datastore()
|
2014-11-21 12:21:00 +00:00
|
|
|
self.clock = self.hs.get_clock()
|
2015-02-03 16:51:07 +00:00
|
|
|
self.profile_tag = profile_tag
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id = user_id
|
2014-12-03 13:37:02 +00:00
|
|
|
self.app_id = app_id
|
2014-11-19 18:20:59 +00:00
|
|
|
self.app_display_name = app_display_name
|
|
|
|
self.device_display_name = device_display_name
|
|
|
|
self.pushkey = pushkey
|
2015-01-13 19:48:37 +00:00
|
|
|
self.pushkey_ts = pushkey_ts
|
2014-11-19 18:20:59 +00:00
|
|
|
self.data = data
|
|
|
|
self.last_token = last_token
|
2014-12-03 13:37:02 +00:00
|
|
|
self.last_success = last_success # not actually used
|
2014-11-19 18:20:59 +00:00
|
|
|
self.backoff_delay = Pusher.INITIAL_BACKOFF
|
2014-12-03 13:37:02 +00:00
|
|
|
self.failing_since = failing_since
|
2014-12-18 14:49:22 +00:00
|
|
|
self.alive = True
|
2016-01-13 18:55:57 +00:00
|
|
|
self.badge = None
|
2014-11-19 18:20:59 +00:00
|
|
|
|
2016-02-04 10:15:56 +00:00
|
|
|
self.name = "Pusher-%d" % (_get_next_id(),)
|
|
|
|
|
2015-01-28 11:55:49 +00:00
|
|
|
# The last value of last_active_time that we saw
|
|
|
|
self.last_last_active_time = 0
|
2015-01-29 16:10:01 +00:00
|
|
|
self.has_unread = True
|
2015-01-28 11:55:49 +00:00
|
|
|
|
2015-01-15 16:56:18 +00:00
|
|
|
@defer.inlineCallbacks
|
|
|
|
def get_context_for_event(self, ev):
|
|
|
|
name_aliases = yield self.store.get_room_name_and_aliases(
|
|
|
|
ev['room_id']
|
|
|
|
)
|
|
|
|
|
|
|
|
ctx = {'aliases': name_aliases[1]}
|
|
|
|
if name_aliases[0] is not None:
|
|
|
|
ctx['name'] = name_aliases[0]
|
|
|
|
|
2015-01-29 18:51:22 +00:00
|
|
|
their_member_events_for_room = yield self.store.get_current_state(
|
|
|
|
room_id=ev['room_id'],
|
|
|
|
event_type='m.room.member',
|
|
|
|
state_key=ev['user_id']
|
|
|
|
)
|
2015-01-30 23:05:49 +00:00
|
|
|
for mev in their_member_events_for_room:
|
|
|
|
if mev.content['membership'] == 'join' and 'displayname' in mev.content:
|
|
|
|
dn = mev.content['displayname']
|
|
|
|
if dn is not None:
|
|
|
|
ctx['sender_display_name'] = dn
|
2015-01-29 18:51:22 +00:00
|
|
|
|
2015-01-15 16:56:18 +00:00
|
|
|
defer.returnValue(ctx)
|
|
|
|
|
2014-11-19 18:20:59 +00:00
|
|
|
@defer.inlineCallbacks
|
|
|
|
def start(self):
|
2016-02-04 10:15:56 +00:00
|
|
|
with LoggingContext(self.name):
|
|
|
|
if not self.last_token:
|
|
|
|
# First-time setup: get a token to start from (we can't
|
|
|
|
# just start from no token, ie. 'now'
|
|
|
|
# because we need the result to be reproduceable in case
|
|
|
|
# we fail to dispatch the push)
|
|
|
|
config = PaginationConfig(from_token=None, limit='1')
|
|
|
|
chunk = yield self.evStreamHandler.get_stream(
|
|
|
|
self.user_id, config, timeout=0, affect_presence=False
|
2015-06-05 10:40:22 +00:00
|
|
|
)
|
2016-02-04 10:15:56 +00:00
|
|
|
self.last_token = chunk['end']
|
|
|
|
self.store.update_pusher_last_token(
|
|
|
|
self.app_id, self.pushkey, self.user_id, self.last_token
|
|
|
|
)
|
|
|
|
logger.info("New pusher %s for user %s starting from token %s",
|
|
|
|
self.pushkey, self.user_id, self.last_token)
|
|
|
|
|
|
|
|
else:
|
|
|
|
logger.info(
|
|
|
|
"Old pusher %s for user %s starting",
|
|
|
|
self.pushkey, self.user_id,
|
|
|
|
)
|
|
|
|
|
|
|
|
wait = 0
|
|
|
|
while self.alive:
|
|
|
|
try:
|
|
|
|
if wait > 0:
|
|
|
|
yield synapse.util.async.sleep(wait)
|
|
|
|
with Measure(self.clock, "push"):
|
|
|
|
yield self.get_and_dispatch()
|
|
|
|
wait = 0
|
|
|
|
except:
|
|
|
|
if wait == 0:
|
|
|
|
wait = 1
|
|
|
|
else:
|
|
|
|
wait = min(wait * 2, 1800)
|
|
|
|
logger.exception(
|
|
|
|
"Exception in pusher loop for pushkey %s. Pausing for %ds",
|
|
|
|
self.pushkey, wait
|
|
|
|
)
|
2014-11-19 18:20:59 +00:00
|
|
|
|
2015-06-05 10:40:22 +00:00
|
|
|
@defer.inlineCallbacks
|
|
|
|
def get_and_dispatch(self):
|
|
|
|
from_tok = StreamToken.from_string(self.last_token)
|
|
|
|
config = PaginationConfig(from_token=from_tok, limit='1')
|
|
|
|
timeout = (300 + random.randint(-60, 60)) * 1000
|
|
|
|
chunk = yield self.evStreamHandler.get_stream(
|
2016-01-21 16:10:37 +00:00
|
|
|
self.user_id, config, timeout=timeout, affect_presence=False,
|
|
|
|
only_keys=("room", "receipt",),
|
2015-06-05 10:40:22 +00:00
|
|
|
)
|
2014-11-21 12:21:00 +00:00
|
|
|
|
2015-06-05 10:40:22 +00:00
|
|
|
# limiting to 1 may get 1 event plus 1 presence event, so
|
|
|
|
# pick out the actual event
|
|
|
|
single_event = None
|
2016-01-21 14:55:59 +00:00
|
|
|
read_receipt = None
|
2015-06-05 10:40:22 +00:00
|
|
|
for c in chunk['chunk']:
|
|
|
|
if 'event_id' in c: # Hmmm...
|
|
|
|
single_event = c
|
2016-01-21 14:55:59 +00:00
|
|
|
elif c['type'] == 'm.receipt':
|
|
|
|
read_receipt = c
|
|
|
|
|
|
|
|
have_updated_badge = False
|
|
|
|
if read_receipt:
|
|
|
|
for receipt_part in read_receipt['content'].values():
|
|
|
|
if 'm.read' in receipt_part:
|
|
|
|
if self.user_id in receipt_part['m.read'].keys():
|
|
|
|
have_updated_badge = True
|
2016-01-13 18:55:57 +00:00
|
|
|
|
2015-06-05 10:40:22 +00:00
|
|
|
if not single_event:
|
2016-01-21 14:55:59 +00:00
|
|
|
if have_updated_badge:
|
|
|
|
yield self.update_badge()
|
2015-06-05 10:40:22 +00:00
|
|
|
self.last_token = chunk['end']
|
2015-08-19 09:08:31 +00:00
|
|
|
yield self.store.update_pusher_last_token(
|
|
|
|
self.app_id,
|
|
|
|
self.pushkey,
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id,
|
2015-08-19 09:08:31 +00:00
|
|
|
self.last_token
|
|
|
|
)
|
2015-06-05 10:40:22 +00:00
|
|
|
return
|
2014-12-18 14:49:22 +00:00
|
|
|
|
2015-06-05 10:40:22 +00:00
|
|
|
if not self.alive:
|
|
|
|
return
|
2015-01-23 17:07:06 +00:00
|
|
|
|
2015-06-05 10:40:22 +00:00
|
|
|
processed = False
|
2015-12-09 15:51:34 +00:00
|
|
|
|
2015-12-09 15:57:42 +00:00
|
|
|
rule_evaluator = yield \
|
2016-01-13 13:08:59 +00:00
|
|
|
push_rule_evaluator.evaluator_for_user_id_and_profile_tag(
|
|
|
|
self.user_id, self.profile_tag, single_event['room_id'], self.store
|
2015-12-09 15:57:42 +00:00
|
|
|
)
|
2015-12-09 15:51:34 +00:00
|
|
|
|
|
|
|
actions = yield rule_evaluator.actions_for_event(single_event)
|
|
|
|
tweaks = rule_evaluator.tweaks_for_actions(actions)
|
2015-05-21 10:13:19 +00:00
|
|
|
|
2015-12-10 18:40:28 +00:00
|
|
|
if 'notify' in actions:
|
2016-01-13 18:55:57 +00:00
|
|
|
self.badge = yield self._get_badge_count()
|
|
|
|
rejected = yield self.dispatch_push(single_event, tweaks, self.badge)
|
2015-06-05 10:40:22 +00:00
|
|
|
self.has_unread = True
|
|
|
|
if isinstance(rejected, list) or isinstance(rejected, tuple):
|
2015-01-23 17:07:06 +00:00
|
|
|
processed = True
|
2015-06-05 10:40:22 +00:00
|
|
|
for pk in rejected:
|
|
|
|
if pk != self.pushkey:
|
|
|
|
# for sanity, we only remove the pushkey if it
|
|
|
|
# was the one we actually sent...
|
|
|
|
logger.warn(
|
|
|
|
("Ignoring rejected pushkey %s because we"
|
|
|
|
" didn't send it"), pk
|
|
|
|
)
|
|
|
|
else:
|
|
|
|
logger.info(
|
|
|
|
"Pushkey %s was rejected: removing",
|
|
|
|
pk
|
|
|
|
)
|
|
|
|
yield self.hs.get_pusherpool().remove_pusher(
|
2016-01-13 13:08:59 +00:00
|
|
|
self.app_id, pk, self.user_id
|
2015-06-05 10:40:22 +00:00
|
|
|
)
|
2016-01-21 14:55:59 +00:00
|
|
|
else:
|
|
|
|
if have_updated_badge:
|
|
|
|
yield self.update_badge()
|
2015-12-10 18:40:28 +00:00
|
|
|
processed = True
|
2015-06-05 10:40:22 +00:00
|
|
|
|
|
|
|
if not self.alive:
|
|
|
|
return
|
|
|
|
|
|
|
|
if processed:
|
|
|
|
self.backoff_delay = Pusher.INITIAL_BACKOFF
|
|
|
|
self.last_token = chunk['end']
|
2015-08-19 09:08:12 +00:00
|
|
|
yield self.store.update_pusher_last_token_and_success(
|
2015-06-05 10:40:22 +00:00
|
|
|
self.app_id,
|
|
|
|
self.pushkey,
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id,
|
2015-06-05 10:40:22 +00:00
|
|
|
self.last_token,
|
|
|
|
self.clock.time_msec()
|
|
|
|
)
|
|
|
|
if self.failing_since:
|
|
|
|
self.failing_since = None
|
2015-08-19 09:08:12 +00:00
|
|
|
yield self.store.update_pusher_failing_since(
|
2015-06-05 10:40:22 +00:00
|
|
|
self.app_id,
|
|
|
|
self.pushkey,
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id,
|
2015-06-05 10:40:22 +00:00
|
|
|
self.failing_since)
|
|
|
|
else:
|
|
|
|
if not self.failing_since:
|
|
|
|
self.failing_since = self.clock.time_msec()
|
2015-08-19 09:08:12 +00:00
|
|
|
yield self.store.update_pusher_failing_since(
|
2015-06-05 10:40:22 +00:00
|
|
|
self.app_id,
|
|
|
|
self.pushkey,
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id,
|
2015-06-05 10:40:22 +00:00
|
|
|
self.failing_since
|
|
|
|
)
|
2015-01-13 19:48:37 +00:00
|
|
|
|
2015-06-05 10:40:22 +00:00
|
|
|
if (self.failing_since and
|
|
|
|
self.failing_since <
|
|
|
|
self.clock.time_msec() - Pusher.GIVE_UP_AFTER):
|
|
|
|
# we really only give up so that if the URL gets
|
|
|
|
# fixed, we don't suddenly deliver a load
|
|
|
|
# of old notifications.
|
|
|
|
logger.warn("Giving up on a notification to user %s, "
|
|
|
|
"pushkey %s",
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id, self.pushkey)
|
2014-11-19 18:20:59 +00:00
|
|
|
self.backoff_delay = Pusher.INITIAL_BACKOFF
|
|
|
|
self.last_token = chunk['end']
|
2015-08-19 09:08:12 +00:00
|
|
|
yield self.store.update_pusher_last_token(
|
2015-06-05 10:40:22 +00:00
|
|
|
self.app_id,
|
|
|
|
self.pushkey,
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id,
|
2015-06-05 10:40:22 +00:00
|
|
|
self.last_token
|
|
|
|
)
|
|
|
|
|
|
|
|
self.failing_since = None
|
2015-08-19 09:08:12 +00:00
|
|
|
yield self.store.update_pusher_failing_since(
|
2015-02-13 16:16:16 +00:00
|
|
|
self.app_id,
|
2014-12-03 13:37:02 +00:00
|
|
|
self.pushkey,
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id,
|
2015-06-05 10:40:22 +00:00
|
|
|
self.failing_since
|
2014-12-03 13:37:02 +00:00
|
|
|
)
|
2014-11-19 18:20:59 +00:00
|
|
|
else:
|
2015-06-05 10:40:22 +00:00
|
|
|
logger.warn("Failed to dispatch push for user %s "
|
|
|
|
"(failing for %dms)."
|
|
|
|
"Trying again in %dms",
|
2016-01-13 13:08:59 +00:00
|
|
|
self.user_id,
|
2015-06-05 10:40:22 +00:00
|
|
|
self.clock.time_msec() - self.failing_since,
|
|
|
|
self.backoff_delay)
|
|
|
|
yield synapse.util.async.sleep(self.backoff_delay / 1000.0)
|
|
|
|
self.backoff_delay *= 2
|
|
|
|
if self.backoff_delay > Pusher.MAX_BACKOFF:
|
|
|
|
self.backoff_delay = Pusher.MAX_BACKOFF
|
2014-11-19 18:20:59 +00:00
|
|
|
|
2014-12-18 14:49:22 +00:00
|
|
|
def stop(self):
|
|
|
|
self.alive = False
|
|
|
|
|
2016-01-13 18:55:57 +00:00
|
|
|
def dispatch_push(self, p, tweaks, badge):
|
2015-01-13 19:48:37 +00:00
|
|
|
"""
|
|
|
|
Overridden by implementing classes to actually deliver the notification
|
2015-01-28 14:10:46 +00:00
|
|
|
Args:
|
2015-01-28 14:14:49 +00:00
|
|
|
p: The event to notify for as a single event from the event stream
|
2015-01-28 14:10:46 +00:00
|
|
|
Returns: If the notification was delivered, an array containing any
|
2015-01-13 19:48:37 +00:00
|
|
|
pushkeys that were rejected by the push gateway.
|
|
|
|
False if the notification could not be delivered (ie.
|
|
|
|
should be retried).
|
|
|
|
"""
|
2014-12-03 13:37:02 +00:00
|
|
|
pass
|
|
|
|
|
2016-01-13 18:55:57 +00:00
|
|
|
@defer.inlineCallbacks
|
|
|
|
def update_badge(self):
|
|
|
|
new_badge = yield self._get_badge_count()
|
|
|
|
if self.badge != new_badge:
|
|
|
|
self.badge = new_badge
|
|
|
|
yield self.send_badge(self.badge)
|
2015-01-28 11:55:49 +00:00
|
|
|
|
2016-01-13 18:55:57 +00:00
|
|
|
def send_badge(self, badge):
|
2015-01-28 11:55:49 +00:00
|
|
|
"""
|
2016-01-13 18:55:57 +00:00
|
|
|
Overridden by implementing classes to send an updated badge count
|
2015-01-28 11:55:49 +00:00
|
|
|
"""
|
2016-01-13 18:55:57 +00:00
|
|
|
pass
|
|
|
|
|
|
|
|
@defer.inlineCallbacks
|
|
|
|
def _get_badge_count(self):
|
2016-01-25 13:53:05 +00:00
|
|
|
invites, joins = yield defer.gatherResults([
|
|
|
|
self.store.get_invites_for_user(self.user_id),
|
|
|
|
self.store.get_rooms_for_user(self.user_id),
|
|
|
|
], consumeErrors=True)
|
2016-01-13 18:55:57 +00:00
|
|
|
|
2016-01-20 15:30:31 +00:00
|
|
|
my_receipts_by_room = yield self.store.get_receipts_for_user(
|
|
|
|
self.user_id,
|
|
|
|
"m.read",
|
2016-01-13 18:55:57 +00:00
|
|
|
)
|
|
|
|
|
2016-01-25 13:53:05 +00:00
|
|
|
badge = len(invites)
|
2016-01-13 18:55:57 +00:00
|
|
|
|
2016-01-25 13:53:05 +00:00
|
|
|
for r in joins:
|
|
|
|
if r.room_id in my_receipts_by_room:
|
|
|
|
last_unread_event_id = my_receipts_by_room[r.room_id]
|
2016-01-13 18:55:57 +00:00
|
|
|
|
2016-01-25 13:53:05 +00:00
|
|
|
notifs = yield (
|
|
|
|
self.store.get_unread_event_push_actions_by_room_for_user(
|
|
|
|
r.room_id, self.user_id, last_unread_event_id
|
2016-01-13 18:55:57 +00:00
|
|
|
)
|
2016-01-25 13:53:05 +00:00
|
|
|
)
|
2016-02-03 10:50:49 +00:00
|
|
|
badge += notifs["notify_count"]
|
2016-01-13 18:55:57 +00:00
|
|
|
defer.returnValue(badge)
|
2015-01-29 16:10:01 +00:00
|
|
|
|
2015-01-28 11:55:49 +00:00
|
|
|
|
2014-11-19 18:20:59 +00:00
|
|
|
class PusherConfigException(Exception):
|
|
|
|
def __init__(self, msg):
|
2015-01-29 16:10:35 +00:00
|
|
|
super(PusherConfigException, self).__init__(msg)
|