Remove `log_function` and its uses (#11761)

I've never found this terribly useful. I think it was added in the early days
of Synapse, without much thought as to what would actually be useful to log,
and has just been cargo-culted ever since.

Rather, it tends to clutter up debug logs with useless information.

changelog.d/11761.misc

@@ -0,0 +1 @@
+Remove `log_function` utility function and its uses.

synapse/federation/federation_client.py

@@ -56,7 +56,6 @@ from synapse.api.room_versions import (
 from synapse.events import EventBase, builder
 from synapse.federation.federation_base import FederationBase, event_from_pdu_json
 from synapse.federation.transport.client import SendJoinResponse
-from synapse.logging.utils import log_function
 from synapse.types import JsonDict, get_domain_from_id
 from synapse.util.async_helpers import concurrently_execute
 from synapse.util.caches.expiringcache import ExpiringCache
@@ -144,7 +143,6 @@ class FederationClient(FederationBase):
             if destination_dict:
                 self.pdu_destination_tried[event_id] = destination_dict
 
-    @log_function
     async def make_query(
         self,
         destination: str,
@@ -178,7 +176,6 @@ class FederationClient(FederationBase):
             ignore_backoff=ignore_backoff,
         )
 
-    @log_function
     async def query_client_keys(
         self, destination: str, content: JsonDict, timeout: int
     ) -> JsonDict:
@@ -196,7 +193,6 @@ class FederationClient(FederationBase):
             destination, content, timeout
         )
 
-    @log_function
     async def query_user_devices(
         self, destination: str, user_id: str, timeout: int = 30000
     ) -> JsonDict:
@@ -208,7 +204,6 @@ class FederationClient(FederationBase):
             destination, user_id, timeout
         )
 
-    @log_function
     async def claim_client_keys(
         self, destination: str, content: JsonDict, timeout: int
     ) -> JsonDict:

synapse/federation/federation_server.py

@@ -58,7 +58,6 @@ from synapse.logging.context import (
     run_in_background,
 )
 from synapse.logging.opentracing import log_kv, start_active_span_from_edu, trace
-from synapse.logging.utils import log_function
 from synapse.metrics.background_process_metrics import wrap_as_background_process
 from synapse.replication.http.federation import (
     ReplicationFederationSendEduRestServlet,
@@ -859,7 +858,6 @@ class FederationServer(FederationBase):
             res = {"auth_chain": [a.get_pdu_json(time_now) for a in auth_pdus]}
         return 200, res
 
-    @log_function
     async def on_query_client_keys(
         self, origin: str, content: Dict[str, str]
     ) -> Tuple[int, Dict[str, Any]]:
@@ -940,7 +938,6 @@ class FederationServer(FederationBase):
 
         return {"events": [ev.get_pdu_json(time_now) for ev in missing_events]}
 
-    @log_function
     async def on_openid_userinfo(self, token: str) -> Optional[str]:
         ts_now_ms = self._clock.time_msec()
         return await self.store.get_user_id_for_open_id_token(token, ts_now_ms)

synapse/federation/persistence.py

@@ -23,7 +23,6 @@ import logging
 from typing import Optional, Tuple
 
 from synapse.federation.units import Transaction
-from synapse.logging.utils import log_function
 from synapse.storage.databases.main import DataStore
 from synapse.types import JsonDict
 
@@ -36,7 +35,6 @@ class TransactionActions:
     def __init__(self, datastore: DataStore):
         self.store = datastore
 
-    @log_function
     async def have_responded(
         self, origin: str, transaction: Transaction
     ) -> Optional[Tuple[int, JsonDict]]:
@@ -53,7 +51,6 @@ class TransactionActions:
 
         return await self.store.get_received_txn_response(transaction_id, origin)
 
-    @log_function
     async def set_response(
         self, origin: str, transaction: Transaction, code: int, response: JsonDict
     ) -> None:

synapse/federation/transport/client.py

@@ -44,7 +44,6 @@ from synapse.api.urls import (
 from synapse.events import EventBase, make_event_from_dict
 from synapse.federation.units import Transaction
 from synapse.http.matrixfederationclient import ByteParser
-from synapse.logging.utils import log_function
 from synapse.types import JsonDict
 
 logger = logging.getLogger(__name__)
@@ -62,7 +61,6 @@ class TransportLayerClient:
         self.server_name = hs.hostname
         self.client = hs.get_federation_http_client()
 
-    @log_function
     async def get_room_state_ids(
         self, destination: str, room_id: str, event_id: str
     ) -> JsonDict:
@@ -88,7 +86,6 @@ class TransportLayerClient:
             try_trailing_slash_on_400=True,
         )
 
-    @log_function
     async def get_event(
         self, destination: str, event_id: str, timeout: Optional[int] = None
     ) -> JsonDict:
@@ -111,7 +108,6 @@ class TransportLayerClient:
             destination, path=path, timeout=timeout, try_trailing_slash_on_400=True
         )
 
-    @log_function
     async def backfill(
         self, destination: str, room_id: str, event_tuples: Collection[str], limit: int
     ) -> Optional[JsonDict]:
@@ -149,7 +145,6 @@ class TransportLayerClient:
             destination, path=path, args=args, try_trailing_slash_on_400=True
         )
 
-    @log_function
     async def timestamp_to_event(
         self, destination: str, room_id: str, timestamp: int, direction: str
     ) -> Union[JsonDict, List]:
@@ -185,7 +180,6 @@ class TransportLayerClient:
 
         return remote_response
 
-    @log_function
     async def send_transaction(
         self,
         transaction: Transaction,
@@ -234,7 +228,6 @@ class TransportLayerClient:
             try_trailing_slash_on_400=True,
         )
 
-    @log_function
     async def make_query(
         self,
         destination: str,
@@ -254,7 +247,6 @@ class TransportLayerClient:
             ignore_backoff=ignore_backoff,
         )
 
-    @log_function
     async def make_membership_event(
         self,
         destination: str,
@@ -317,7 +309,6 @@ class TransportLayerClient:
             ignore_backoff=ignore_backoff,
         )
 
-    @log_function
     async def send_join_v1(
         self,
         room_version: RoomVersion,
@@ -336,7 +327,6 @@ class TransportLayerClient:
             max_response_size=MAX_RESPONSE_SIZE_SEND_JOIN,
         )
 
-    @log_function
     async def send_join_v2(
         self,
         room_version: RoomVersion,
@@ -355,7 +345,6 @@ class TransportLayerClient:
             max_response_size=MAX_RESPONSE_SIZE_SEND_JOIN,
         )
 
-    @log_function
     async def send_leave_v1(
         self, destination: str, room_id: str, event_id: str, content: JsonDict
     ) -> Tuple[int, JsonDict]:
@@ -372,7 +361,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def send_leave_v2(
         self, destination: str, room_id: str, event_id: str, content: JsonDict
     ) -> JsonDict:
@@ -389,7 +377,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def send_knock_v1(
         self,
         destination: str,
@@ -423,7 +410,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=content
         )
 
-    @log_function
     async def send_invite_v1(
         self, destination: str, room_id: str, event_id: str, content: JsonDict
     ) -> Tuple[int, JsonDict]:
@@ -433,7 +419,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=content, ignore_backoff=True
         )
 
-    @log_function
     async def send_invite_v2(
         self, destination: str, room_id: str, event_id: str, content: JsonDict
     ) -> JsonDict:
@@ -443,7 +428,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=content, ignore_backoff=True
         )
 
-    @log_function
     async def get_public_rooms(
         self,
         remote_server: str,
@@ -516,7 +500,6 @@ class TransportLayerClient:
 
         return response
 
-    @log_function
     async def exchange_third_party_invite(
         self, destination: str, room_id: str, event_dict: JsonDict
     ) -> JsonDict:
@@ -526,7 +509,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=event_dict
         )
 
-    @log_function
     async def get_event_auth(
         self, destination: str, room_id: str, event_id: str
     ) -> JsonDict:
@@ -534,7 +516,6 @@ class TransportLayerClient:
 
         return await self.client.get_json(destination=destination, path=path)
 
-    @log_function
     async def query_client_keys(
         self, destination: str, query_content: JsonDict, timeout: int
     ) -> JsonDict:
@@ -576,7 +557,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=query_content, timeout=timeout
         )
 
-    @log_function
     async def query_user_devices(
         self, destination: str, user_id: str, timeout: int
     ) -> JsonDict:
@@ -616,7 +596,6 @@ class TransportLayerClient:
             destination=destination, path=path, timeout=timeout
         )
 
-    @log_function
     async def claim_client_keys(
         self, destination: str, query_content: JsonDict, timeout: int
     ) -> JsonDict:
@@ -655,7 +634,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=query_content, timeout=timeout
         )
 
-    @log_function
     async def get_missing_events(
         self,
         destination: str,
@@ -680,7 +658,6 @@ class TransportLayerClient:
             timeout=timeout,
         )
 
-    @log_function
     async def get_group_profile(
         self, destination: str, group_id: str, requester_user_id: str
     ) -> JsonDict:
@@ -694,7 +671,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def update_group_profile(
         self, destination: str, group_id: str, requester_user_id: str, content: JsonDict
     ) -> JsonDict:
@@ -716,7 +692,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def get_group_summary(
         self, destination: str, group_id: str, requester_user_id: str
     ) -> JsonDict:
@@ -730,7 +705,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def get_rooms_in_group(
         self, destination: str, group_id: str, requester_user_id: str
     ) -> JsonDict:
@@ -798,7 +772,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def get_users_in_group(
         self, destination: str, group_id: str, requester_user_id: str
     ) -> JsonDict:
@@ -812,7 +785,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def get_invited_users_in_group(
         self, destination: str, group_id: str, requester_user_id: str
     ) -> JsonDict:
@@ -826,7 +798,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def accept_group_invite(
         self, destination: str, group_id: str, user_id: str, content: JsonDict
     ) -> JsonDict:
@@ -837,7 +808,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=content, ignore_backoff=True
         )
 
-    @log_function
     def join_group(
         self, destination: str, group_id: str, user_id: str, content: JsonDict
     ) -> Awaitable[JsonDict]:
@@ -848,7 +818,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=content, ignore_backoff=True
         )
 
-    @log_function
     async def invite_to_group(
         self,
         destination: str,
@@ -868,7 +837,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def invite_to_group_notification(
         self, destination: str, group_id: str, user_id: str, content: JsonDict
     ) -> JsonDict:
@@ -882,7 +850,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=content, ignore_backoff=True
         )
 
-    @log_function
     async def remove_user_from_group(
         self,
         destination: str,
@@ -902,7 +869,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def remove_user_from_group_notification(
         self, destination: str, group_id: str, user_id: str, content: JsonDict
     ) -> JsonDict:
@@ -916,7 +882,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=content, ignore_backoff=True
         )
 
-    @log_function
     async def renew_group_attestation(
         self, destination: str, group_id: str, user_id: str, content: JsonDict
     ) -> JsonDict:
@@ -930,7 +895,6 @@ class TransportLayerClient:
             destination=destination, path=path, data=content, ignore_backoff=True
         )
 
-    @log_function
     async def update_group_summary_room(
         self,
         destination: str,
@@ -959,7 +923,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def delete_group_summary_room(
         self,
         destination: str,
@@ -986,7 +949,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def get_group_categories(
         self, destination: str, group_id: str, requester_user_id: str
     ) -> JsonDict:
@@ -1000,7 +962,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def get_group_category(
         self, destination: str, group_id: str, requester_user_id: str, category_id: str
     ) -> JsonDict:
@@ -1014,7 +975,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def update_group_category(
         self,
         destination: str,
@@ -1034,7 +994,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def delete_group_category(
         self, destination: str, group_id: str, requester_user_id: str, category_id: str
     ) -> JsonDict:
@@ -1048,7 +1007,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def get_group_roles(
         self, destination: str, group_id: str, requester_user_id: str
     ) -> JsonDict:
@@ -1062,7 +1020,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def get_group_role(
         self, destination: str, group_id: str, requester_user_id: str, role_id: str
     ) -> JsonDict:
@@ -1076,7 +1033,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def update_group_role(
         self,
         destination: str,
@@ -1096,7 +1052,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def delete_group_role(
         self, destination: str, group_id: str, requester_user_id: str, role_id: str
     ) -> JsonDict:
@@ -1110,7 +1065,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def update_group_summary_user(
         self,
         destination: str,
@@ -1136,7 +1090,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def set_group_join_policy(
         self, destination: str, group_id: str, requester_user_id: str, content: JsonDict
     ) -> JsonDict:
@@ -1151,7 +1104,6 @@ class TransportLayerClient:
             ignore_backoff=True,
         )
 
-    @log_function
     async def delete_group_summary_user(
         self,
         destination: str,

synapse/handlers/events.py

@@ -20,7 +20,6 @@ from synapse.api.constants import EduTypes, EventTypes, Membership
 from synapse.api.errors import AuthError, SynapseError
 from synapse.events import EventBase
 from synapse.handlers.presence import format_user_presence_state
-from synapse.logging.utils import log_function
 from synapse.streams.config import PaginationConfig
 from synapse.types import JsonDict, UserID
 from synapse.visibility import filter_events_for_client
@@ -43,7 +42,6 @@ class EventStreamHandler:
         self._server_notices_sender = hs.get_server_notices_sender()
         self._event_serializer = hs.get_event_client_serializer()
 
-    @log_function
     async def get_stream(
         self,
         auth_user_id: str,

synapse/handlers/federation.py

@@ -51,7 +51,6 @@ from synapse.logging.context import (
     preserve_fn,
     run_in_background,
 )
-from synapse.logging.utils import log_function
 from synapse.replication.http.federation import (
     ReplicationCleanRoomRestServlet,
     ReplicationStoreRoomOnOutlierMembershipRestServlet,
@@ -556,7 +555,6 @@ class FederationHandler:
 
             run_in_background(self._handle_queued_pdus, room_queue)
 
-    @log_function
     async def do_knock(
         self,
         target_hosts: List[str],
@@ -928,7 +926,6 @@ class FederationHandler:
 
         return event
 
-    @log_function
     async def on_make_knock_request(
         self, origin: str, room_id: str, user_id: str
     ) -> EventBase:
@@ -1039,7 +1036,6 @@ class FederationHandler:
         else:
             return []
 
-    @log_function
     async def on_backfill_request(
         self, origin: str, room_id: str, pdu_list: List[str], limit: int
     ) -> List[EventBase]:
@@ -1056,7 +1052,6 @@ class FederationHandler:
 
         return events
 
-    @log_function
     async def get_persisted_pdu(
         self, origin: str, event_id: str
     ) -> Optional[EventBase]:
@@ -1118,7 +1113,6 @@ class FederationHandler:
 
         return missing_events
 
-    @log_function
     async def exchange_third_party_invite(
         self, sender_user_id: str, target_user_id: str, room_id: str, signed: JsonDict
     ) -> None:

synapse/handlers/federation_event.py

@@ -56,7 +56,6 @@ from synapse.events import EventBase
 from synapse.events.snapshot import EventContext
 from synapse.federation.federation_client import InvalidResponseError
 from synapse.logging.context import nested_logging_context, run_in_background
-from synapse.logging.utils import log_function
 from synapse.metrics.background_process_metrics import run_as_background_process
 from synapse.replication.http.devices import ReplicationUserDevicesResyncRestServlet
 from synapse.replication.http.federation import (
@@ -275,7 +274,6 @@ class FederationEventHandler:
 
         await self._process_received_pdu(origin, pdu, state=None)
 
-    @log_function
     async def on_send_membership_event(
         self, origin: str, event: EventBase
     ) -> Tuple[EventBase, EventContext]:
@@ -472,7 +470,6 @@ class FederationEventHandler:
 
             return await self.persist_events_and_notify(room_id, [(event, context)])
 
-    @log_function
     async def backfill(
         self, dest: str, room_id: str, limit: int, extremities: Collection[str]
     ) -> None:

synapse/handlers/presence.py

@@ -55,7 +55,6 @@ from synapse.api.presence import UserPresenceState
 from synapse.appservice import ApplicationService
 from synapse.events.presence_router import PresenceRouter
 from synapse.logging.context import run_in_background
-from synapse.logging.utils import log_function
 from synapse.metrics import LaterGauge
 from synapse.metrics.background_process_metrics import run_as_background_process
 from synapse.replication.http.presence import (
@@ -1542,7 +1541,6 @@ class PresenceEventSource(EventSource[int, UserPresenceState]):
         self.clock = hs.get_clock()
         self.store = hs.get_datastore()
 
-    @log_function
     async def get_new_events(
         self,
         user: UserID,

synapse/logging/utils.py

@@ -1,76 +0,0 @@
-# Copyright 2014-2016 OpenMarket 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
-from functools import wraps
-from inspect import getcallargs
-from typing import Callable, TypeVar, cast
-
-_TIME_FUNC_ID = 0
-
-
-def _log_debug_as_f(f, msg, msg_args):
-    name = f.__module__
-    logger = logging.getLogger(name)
-
-    if logger.isEnabledFor(logging.DEBUG):
-        lineno = f.__code__.co_firstlineno
-        pathname = f.__code__.co_filename
-
-        record = logger.makeRecord(
-            name=name,
-            level=logging.DEBUG,
-            fn=pathname,
-            lno=lineno,
-            msg=msg,
-            args=msg_args,
-            exc_info=None,
-        )
-
-        logger.handle(record)
-
-
-F = TypeVar("F", bound=Callable)
-
-
-def log_function(f: F) -> F:
-    """Function decorator that logs every call to that function."""
-    func_name = f.__name__
-
-    @wraps(f)
-    def wrapped(*args, **kwargs):
-        name = f.__module__
-        logger = logging.getLogger(name)
-        level = logging.DEBUG
-
-        if logger.isEnabledFor(level):
-            bound_args = getcallargs(f, *args, **kwargs)
-
-            def format(value):
-                r = str(value)
-                if len(r) > 50:
-                    r = r[:50] + "..."
-                return r
-
-            func_args = ["%s=%s" % (k, format(v)) for k, v in bound_args.items()]
-
-            msg_args = {"func_name": func_name, "args": ", ".join(func_args)}
-
-            _log_debug_as_f(f, "Invoked '%(func_name)s' with args: %(args)s", msg_args)
-
-        return f(*args, **kwargs)
-
-    wrapped.__name__ = func_name
-    return cast(F, wrapped)

synapse/notifier.py

@@ -40,7 +40,6 @@ from synapse.handlers.presence import format_user_presence_state
 from synapse.logging import issue9533_logger
 from synapse.logging.context import PreserveLoggingContext
 from synapse.logging.opentracing import log_kv, start_active_span
-from synapse.logging.utils import log_function
 from synapse.metrics import LaterGauge
 from synapse.streams.config import PaginationConfig
 from synapse.types import (
@@ -686,7 +685,6 @@ class Notifier:
         else:
             return False
 
-    @log_function
     def remove_expired_streams(self) -> None:
         time_now_ms = self.clock.time_msec()
         expired_streams = []
@@ -700,7 +698,6 @@ class Notifier:
         for expired_stream in expired_streams:
             expired_stream.remove(self)
 
-    @log_function
     def _register_with_keys(self, user_stream: _NotifierUserStream):
         self.user_to_user_stream[user_stream.user_id] = user_stream
 

synapse/state/__init__.py

@@ -45,7 +45,6 @@ from synapse.api.room_versions import KNOWN_ROOM_VERSIONS, StateResolutionVersio
 from synapse.events import EventBase
 from synapse.events.snapshot import EventContext
 from synapse.logging.context import ContextResourceUsage
-from synapse.logging.utils import log_function
 from synapse.state import v1, v2
 from synapse.storage.databases.main.events_worker import EventRedactBehaviour
 from synapse.storage.roommember import ProfileInfo
@@ -512,7 +511,6 @@ class StateResolutionHandler:
 
         self.clock.looping_call(self._report_metrics, 120 * 1000)
 
-    @log_function
     async def resolve_state_groups(
         self,
         room_id: str,

synapse/storage/databases/main/events.py

@@ -39,7 +39,6 @@ from synapse.api.room_versions import RoomVersions
 from synapse.crypto.event_signing import compute_event_reference_hash
 from synapse.events import EventBase  # noqa: F401
 from synapse.events.snapshot import EventContext  # noqa: F401
-from synapse.logging.utils import log_function
 from synapse.storage._base import db_to_json, make_in_list_sql_clause
 from synapse.storage.database import (
     DatabasePool,
@@ -328,7 +327,6 @@ class PersistEventsStore:
 
         return existing_prevs
 
-    @log_function
     def _persist_events_txn(
         self,
         txn: LoggingTransaction,