2019-03-13 21:02:56 +01:00
|
|
|
# -*- coding: utf-8 -*-
|
|
|
|
# Copyright 2019 New Vector Ltd
|
|
|
|
#
|
|
|
|
# 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.
|
|
|
|
import logging
|
2020-09-03 20:23:07 +02:00
|
|
|
from typing import TYPE_CHECKING, List
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2020-10-01 12:09:12 +02:00
|
|
|
from prometheus_client import Gauge
|
|
|
|
|
2019-03-13 21:02:56 +01:00
|
|
|
from synapse.api.errors import HttpResponseException
|
2020-02-07 14:56:38 +01:00
|
|
|
from synapse.events import EventBase
|
2019-03-13 21:02:56 +01:00
|
|
|
from synapse.federation.persistence import TransactionActions
|
2020-02-07 14:56:38 +01:00
|
|
|
from synapse.federation.units import Edu, Transaction
|
2019-08-22 19:21:10 +02:00
|
|
|
from synapse.logging.opentracing import (
|
|
|
|
extract_text_map,
|
|
|
|
set_tag,
|
|
|
|
start_active_span_follows_from,
|
|
|
|
tags,
|
2019-09-05 15:41:04 +02:00
|
|
|
whitelisted_homeserver,
|
2019-08-22 19:21:10 +02:00
|
|
|
)
|
2020-08-19 13:26:03 +02:00
|
|
|
from synapse.util import json_decoder
|
2019-03-13 21:02:56 +01:00
|
|
|
from synapse.util.metrics import measure_func
|
|
|
|
|
2020-05-05 15:15:57 +02:00
|
|
|
if TYPE_CHECKING:
|
|
|
|
import synapse.server
|
|
|
|
|
2019-03-13 21:02:56 +01:00
|
|
|
logger = logging.getLogger(__name__)
|
|
|
|
|
2021-03-04 17:40:18 +01:00
|
|
|
last_pdu_ts_metric = Gauge(
|
|
|
|
"synapse_federation_last_sent_pdu_time",
|
|
|
|
"The timestamp of the last PDU which was successfully sent to the given domain",
|
2020-10-01 12:09:12 +02:00
|
|
|
labelnames=("server_name",),
|
|
|
|
)
|
|
|
|
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2020-09-04 12:54:56 +02:00
|
|
|
class TransactionManager:
|
2019-03-13 21:02:56 +01:00
|
|
|
"""Helper class which handles building and sending transactions
|
|
|
|
|
|
|
|
shared between PerDestinationQueue objects
|
|
|
|
"""
|
2019-06-20 11:32:02 +02:00
|
|
|
|
2020-02-07 14:56:38 +01:00
|
|
|
def __init__(self, hs: "synapse.server.HomeServer"):
|
2019-03-13 21:02:56 +01:00
|
|
|
self._server_name = hs.hostname
|
2019-06-20 11:32:02 +02:00
|
|
|
self.clock = hs.get_clock() # nb must be called this for @measure_func
|
2019-03-13 21:02:56 +01:00
|
|
|
self._store = hs.get_datastore()
|
|
|
|
self._transaction_actions = TransactionActions(self._store)
|
|
|
|
self._transport_layer = hs.get_federation_transport_client()
|
|
|
|
|
2020-10-01 12:09:12 +02:00
|
|
|
self._federation_metrics_domains = (
|
|
|
|
hs.get_config().federation.federation_metrics_domains
|
|
|
|
)
|
|
|
|
|
2019-03-13 21:02:56 +01:00
|
|
|
# HACK to get unique tx id
|
|
|
|
self._next_txn_id = int(self.clock.time_msec())
|
|
|
|
|
|
|
|
@measure_func("_send_new_transaction")
|
2020-02-07 14:56:38 +01:00
|
|
|
async def send_new_transaction(
|
2021-02-16 23:32:34 +01:00
|
|
|
self,
|
|
|
|
destination: str,
|
|
|
|
pdus: List[EventBase],
|
|
|
|
edus: List[Edu],
|
2021-03-15 15:42:40 +01:00
|
|
|
) -> None:
|
2020-09-03 20:23:07 +02:00
|
|
|
"""
|
|
|
|
Args:
|
|
|
|
destination: The destination to send to (e.g. 'example.org')
|
|
|
|
pdus: In-order list of PDUs to send
|
|
|
|
edus: List of EDUs to send
|
|
|
|
"""
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2019-08-22 19:21:10 +02:00
|
|
|
# Make a transaction-sending opentracing span. This span follows on from
|
|
|
|
# all the edus in that transaction. This needs to be done since there is
|
|
|
|
# no active span here, so if the edus were not received by the remote the
|
|
|
|
# span would have no causality and it would be forgotten.
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2019-09-05 15:41:04 +02:00
|
|
|
span_contexts = []
|
|
|
|
keep_destination = whitelisted_homeserver(destination)
|
|
|
|
|
2020-09-03 20:23:07 +02:00
|
|
|
for edu in edus:
|
2019-09-05 16:07:17 +02:00
|
|
|
context = edu.get_context()
|
|
|
|
if context:
|
2020-08-19 13:26:03 +02:00
|
|
|
span_contexts.append(extract_text_map(json_decoder.decode(context)))
|
2019-09-05 15:41:04 +02:00
|
|
|
if keep_destination:
|
|
|
|
edu.strip_context()
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2019-08-22 19:21:10 +02:00
|
|
|
with start_active_span_follows_from("send_transaction", span_contexts):
|
|
|
|
logger.debug("TX [%s] _attempt_new_transaction", destination)
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2019-08-22 19:21:10 +02:00
|
|
|
txn_id = str(self._next_txn_id)
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2019-08-22 19:21:10 +02:00
|
|
|
logger.debug(
|
2019-11-21 13:00:14 +01:00
|
|
|
"TX [%s] {%s} Attempting new transaction (pdus: %d, edus: %d)",
|
2019-08-22 19:21:10 +02:00
|
|
|
destination,
|
|
|
|
txn_id,
|
|
|
|
len(pdus),
|
|
|
|
len(edus),
|
|
|
|
)
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2019-08-22 19:21:10 +02:00
|
|
|
transaction = Transaction.create_new(
|
|
|
|
origin_server_ts=int(self.clock.time_msec()),
|
|
|
|
transaction_id=txn_id,
|
|
|
|
origin=self._server_name,
|
|
|
|
destination=destination,
|
|
|
|
pdus=pdus,
|
|
|
|
edus=edus,
|
2019-03-13 21:02:56 +01:00
|
|
|
)
|
|
|
|
|
2019-08-22 19:21:10 +02:00
|
|
|
self._next_txn_id += 1
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2019-08-22 19:21:10 +02:00
|
|
|
logger.info(
|
2019-11-21 13:00:14 +01:00
|
|
|
"TX [%s] {%s} Sending transaction [%s], (PDUs: %d, EDUs: %d)",
|
2019-08-22 19:21:10 +02:00
|
|
|
destination,
|
|
|
|
txn_id,
|
|
|
|
transaction.transaction_id,
|
|
|
|
len(pdus),
|
|
|
|
len(edus),
|
|
|
|
)
|
2019-03-13 21:02:56 +01:00
|
|
|
|
2019-08-22 19:21:10 +02:00
|
|
|
# Actually send the transaction
|
|
|
|
|
|
|
|
# FIXME (erikj): This is a bit of a hack to make the Pdu age
|
|
|
|
# keys work
|
2020-10-01 12:09:12 +02:00
|
|
|
# FIXME (richardv): I also believe it no longer works. We (now?) store
|
|
|
|
# "age_ts" in "unsigned" rather than at the top level. See
|
|
|
|
# https://github.com/matrix-org/synapse/issues/8429.
|
2019-08-22 19:21:10 +02:00
|
|
|
def json_data_cb():
|
|
|
|
data = transaction.get_dict()
|
|
|
|
now = int(self.clock.time_msec())
|
|
|
|
if "pdus" in data:
|
|
|
|
for p in data["pdus"]:
|
|
|
|
if "age_ts" in p:
|
|
|
|
unsigned = p.setdefault("unsigned", {})
|
|
|
|
unsigned["age"] = now - int(p["age_ts"])
|
|
|
|
del p["age_ts"]
|
|
|
|
return data
|
|
|
|
|
|
|
|
try:
|
2020-02-07 14:56:38 +01:00
|
|
|
response = await self._transport_layer.send_transaction(
|
2019-08-22 19:21:10 +02:00
|
|
|
transaction, json_data_cb
|
|
|
|
)
|
|
|
|
except HttpResponseException as e:
|
|
|
|
code = e.code
|
|
|
|
response = e.response
|
|
|
|
|
2021-03-15 15:42:40 +01:00
|
|
|
set_tag(tags.ERROR, True)
|
|
|
|
|
|
|
|
logger.info("TX [%s] {%s} got %d response", destination, txn_id, code)
|
|
|
|
raise
|
|
|
|
|
|
|
|
logger.info("TX [%s] {%s} got 200 response", destination, txn_id)
|
|
|
|
|
|
|
|
for e_id, r in response.get("pdus", {}).items():
|
|
|
|
if "error" in r:
|
2019-10-31 11:23:24 +01:00
|
|
|
logger.warning(
|
2021-03-15 15:42:40 +01:00
|
|
|
"TX [%s] {%s} Remote returned error for %s: %s",
|
2019-06-20 11:32:02 +02:00
|
|
|
destination,
|
|
|
|
txn_id,
|
2021-03-15 15:42:40 +01:00
|
|
|
e_id,
|
|
|
|
r,
|
2019-03-13 21:02:56 +01:00
|
|
|
)
|
|
|
|
|
2021-03-15 15:42:40 +01:00
|
|
|
if pdus and destination in self._federation_metrics_domains:
|
2020-10-01 12:09:12 +02:00
|
|
|
last_pdu = pdus[-1]
|
2021-03-04 17:40:18 +01:00
|
|
|
last_pdu_ts_metric.labels(server_name=destination).set(
|
|
|
|
last_pdu.origin_server_ts / 1000
|
2020-10-01 12:09:12 +02:00
|
|
|
)
|