From 9368996a5bece36f413ff01d1124c13fd1607a72 Mon Sep 17 00:00:00 2001 From: Osma Ahvenlampi Date: Mon, 23 Oct 2023 19:33:55 +0300 Subject: [PATCH] use logging instead of sentry.capture_* (#646) --- activities/models/post.py | 7 +++--- activities/services/post.py | 5 ++-- core/exceptions.py | 31 ------------------------- core/ld.py | 7 +++--- core/signatures.py | 3 ++- stator/management/commands/runstator.py | 7 ++++-- stator/models.py | 8 +++---- stator/runner.py | 25 ++++++++++---------- takahe/settings.py | 4 +++- users/models/domain.py | 10 ++++---- users/models/follow.py | 18 +++++++------- users/models/identity.py | 11 +++++---- users/views/activitypub.py | 28 ++++++++++------------ 13 files changed, 69 insertions(+), 95 deletions(-) diff --git a/activities/models/post.py b/activities/models/post.py index 6cc93fa..92c1b12 100644 --- a/activities/models/post.py +++ b/activities/models/post.py @@ -1,5 +1,6 @@ import datetime import json +import logging import mimetypes import ssl from collections.abc import Iterable @@ -27,7 +28,7 @@ from activities.models.post_types import ( PostTypeDataEncoder, QuestionData, ) -from core.exceptions import ActivityPubFormatError, capture_message +from core.exceptions import ActivityPubFormatError from core.html import ContentRenderer, FediverseHtmlParser from core.ld import ( canonicalise, @@ -896,7 +897,7 @@ class Post(StatorModel): # don't have content, but this shouldn't be a total failure post.content = get_value_or_map(data, "content", "contentMap") except ActivityPubFormatError as err: - capture_message(f"{err} on {post.url}") + logging.warning(f"{err} on {post.url}") post.content = None # Document types have names, not summaries post.summary = data.get("summary") or data.get("name") @@ -992,7 +993,7 @@ class Post(StatorModel): try: cls.ensure_object_uri(post.in_reply_to, reason=post.object_uri) except ValueError: - capture_message( + logging.warning( f"Cannot fetch ancestor of Post={post.pk}, ancestor_uri={post.in_reply_to}" ) else: diff --git a/activities/services/post.py b/activities/services/post.py index 53be357..9f96e53 100644 --- a/activities/services/post.py +++ b/activities/services/post.py @@ -1,3 +1,5 @@ +import logging + from activities.models import ( Post, PostInteraction, @@ -5,7 +7,6 @@ from activities.models import ( PostStates, TimelineEvent, ) -from core.exceptions import capture_message from users.models import Identity @@ -98,7 +99,7 @@ class PostService: try: Post.ensure_object_uri(object_uri, reason=reason) except ValueError: - capture_message( + logging.error( f"Cannot fetch ancestor Post={self.post.pk}, ancestor_uri={object_uri}" ) break diff --git a/core/exceptions.py b/core/exceptions.py index 149fb5d..43a86eb 100644 --- a/core/exceptions.py +++ b/core/exceptions.py @@ -1,8 +1,3 @@ -import traceback - -from django.conf import settings - - class ActivityPubError(BaseException): """ A problem with an ActivityPub message @@ -19,29 +14,3 @@ class ActorMismatchError(ActivityPubError): """ The actor is not authorised to do the action we saw """ - - -def capture_message(message: str, level: str | None = None, scope=None, **scope_args): - """ - Sends the informational message to Sentry if it's configured - """ - if settings.SETUP.SENTRY_DSN and settings.SETUP.SENTRY_CAPTURE_MESSAGES: - from sentry_sdk import capture_message - - capture_message(message, level, scope, **scope_args) - elif settings.DEBUG: - if scope or scope_args: - message += f"; {scope=}, {scope_args=}" - print(message) - - -def capture_exception(exception: BaseException, scope=None, **scope_args): - """ - Sends the exception to Sentry if it's configured - """ - if settings.SETUP.SENTRY_DSN: - from sentry_sdk import capture_exception - - capture_exception(exception, scope, **scope_args) - elif settings.DEBUG: - traceback.print_exc() diff --git a/core/ld.py b/core/ld.py index 4d93314..9a5f7f9 100644 --- a/core/ld.py +++ b/core/ld.py @@ -1,11 +1,12 @@ import datetime +import logging import os import urllib.parse as urllib_parse from dateutil import parser from pyld import jsonld -from core.exceptions import ActivityPubFormatError, capture_message +from core.exceptions import ActivityPubFormatError schemas = { "unknown": { @@ -629,7 +630,7 @@ def builtin_document_loader(url: str, options={}): # Get URL without scheme pieces = urllib_parse.urlparse(url) if pieces.hostname is None: - capture_message(f"No host name for json-ld schema: {url!r}") + logging.info(f"No host name for json-ld schema: {url!r}") return schemas["unknown"] key = pieces.hostname + pieces.path.rstrip("/") try: @@ -640,7 +641,7 @@ def builtin_document_loader(url: str, options={}): return schemas[key] except KeyError: # return an empty context instead of throwing an error - capture_message(f"Ignoring unknown json-ld schema: {url!r}") + logging.info(f"Ignoring unknown json-ld schema: {url!r}") return schemas["unknown"] diff --git a/core/signatures.py b/core/signatures.py index 90b611e..bdc990f 100644 --- a/core/signatures.py +++ b/core/signatures.py @@ -1,5 +1,6 @@ import base64 import json +import logging from ssl import SSLCertVerificationError, SSLError from typing import Literal, TypedDict, cast from urllib.parse import urlparse @@ -258,7 +259,7 @@ class HttpSignature: ) except SSLError as invalid_cert: # Not our problem if the other end doesn't have proper SSL - print(f"{uri} {invalid_cert}") + logging.info(f"{uri} {invalid_cert}") raise SSLCertVerificationError(invalid_cert) from invalid_cert except InvalidCodepoint as ex: # Convert to a more generic error we handle diff --git a/stator/management/commands/runstator.py b/stator/management/commands/runstator.py index acef21b..9eb37ce 100644 --- a/stator/management/commands/runstator.py +++ b/stator/management/commands/runstator.py @@ -1,3 +1,4 @@ +import logging from typing import cast from django.apps import apps @@ -73,7 +74,9 @@ class Command(BaseCommand): if not models: models = StatorModel.subclasses models = [model for model in models if model not in excluded] - print("Running for models: " + " ".join(m._meta.label_lower for m in models)) + logging.info( + "Running for models: " + " ".join(m._meta.label_lower for m in models) + ) # Run a runner runner = StatorRunner( models, @@ -85,4 +88,4 @@ class Command(BaseCommand): try: runner.run() except KeyboardInterrupt: - print("Ctrl-C received") + logging.critical("Ctrl-C received") diff --git a/stator/models.py b/stator/models.py index e17a0c7..0a84938 100644 --- a/stator/models.py +++ b/stator/models.py @@ -1,5 +1,5 @@ import datetime -import traceback +import logging from typing import ClassVar from asgiref.sync import async_to_sync, iscoroutinefunction @@ -8,7 +8,6 @@ from django.db.models.signals import class_prepared from django.utils import timezone from django.utils.functional import classproperty -from core import exceptions from stator.exceptions import TryAgainLater from stator.graph import State, StateGraph @@ -190,7 +189,7 @@ class StatorModel(models.Model): # If it's a manual progression state don't even try # We shouldn't really be here in this case, but it could be a race condition if current_state.externally_progressed: - print( + logging.warning( f"Warning: trying to progress externally progressed state {self.state}!" ) return None @@ -204,8 +203,7 @@ class StatorModel(models.Model): except TryAgainLater: pass except BaseException as e: - exceptions.capture_exception(e) - traceback.print_exc() + logging.exception(e) else: if next_state: # Ensure it's a State object diff --git a/stator/runner.py b/stator/runner.py index 5682d46..90e1f79 100644 --- a/stator/runner.py +++ b/stator/runner.py @@ -1,8 +1,8 @@ import datetime +import logging import os import signal import time -import traceback import uuid from concurrent.futures import Future, ThreadPoolExecutor @@ -10,7 +10,7 @@ from django.conf import settings from django.db import close_old_connections from django.utils import timezone -from core import exceptions, sentry +from core import sentry from core.models import Config from stator.models import StatorModel, Stats @@ -84,7 +84,7 @@ class StatorRunner: self.scheduling_timer = LoopingTimer(self.schedule_interval) self.deletion_timer = LoopingTimer(self.delete_interval) # For the first time period, launch tasks - print("Running main task loop") + logging.info("Running main task loop") try: with sentry.configure_scope() as scope: while True: @@ -137,18 +137,18 @@ class StatorRunner: pass # Wait for tasks to finish - print("Waiting for tasks to complete") + logging.info("Waiting for tasks to complete") self.executor.shutdown() # We're done - print("Complete") + logging.info("Complete") def alarm_handler(self, signum, frame): """ Called when SIGALRM fires, which means we missed a schedule loop. Just exit as we're likely deadlocked. """ - print("Watchdog timeout exceeded") + logging.warning("Watchdog timeout exceeded") os._exit(2) def load_config(self): @@ -165,7 +165,9 @@ class StatorRunner: for model in self.models: num = self.handled.get(model._meta.label_lower, 0) if num or settings.DEBUG: - print(f"{model._meta.label_lower}: Scheduling ({num} handled)") + logging.info( + f"{model._meta.label_lower}: Scheduling ({num} handled)" + ) self.submit_stats(model) model.transition_clean_locks() @@ -237,8 +239,7 @@ class StatorRunner: try: task.result() except BaseException as e: - exceptions.capture_exception(e) - traceback.print_exc() + logging.exception(e) def run_single_cycle(self): """ @@ -268,11 +269,11 @@ def task_transition(instance: StatorModel, in_thread: bool = True): result = instance.transition_attempt() duration = time.monotonic() - started if result: - print( + logging.info( f"{instance._meta.label_lower}: {instance.pk}: {instance.state} -> {result} ({duration:.2f}s)" ) else: - print( + logging.info( f"{instance._meta.label_lower}: {instance.pk}: {instance.state} unchanged ({duration:.2f}s)" ) if in_thread: @@ -288,7 +289,7 @@ def task_deletion(model: type[StatorModel], in_thread: bool = True): deleted = model.transition_delete_due() if not deleted: break - print(f"{model._meta.label_lower}: Deleted {deleted} stale items") + logging.info(f"{model._meta.label_lower}: Deleted {deleted} stale items") time.sleep(1) if in_thread: close_old_connections() diff --git a/takahe/settings.py b/takahe/settings.py index 03c8b2b..c0c45c3 100644 --- a/takahe/settings.py +++ b/takahe/settings.py @@ -11,7 +11,6 @@ import httpx import sentry_sdk from corsheaders.defaults import default_headers from pydantic import AnyUrl, BaseSettings, EmailStr, Field, validator -from sentry_sdk.integrations.django import DjangoIntegration from takahe import __version__ @@ -368,7 +367,9 @@ if SETUP.USE_PROXY_HEADERS: if SETUP.SENTRY_DSN: + from sentry_sdk.integrations.django import DjangoIntegration from sentry_sdk.integrations.httpx import HttpxIntegration + from sentry_sdk.integrations.logging import LoggingIntegration sentry_experiments = {} @@ -382,6 +383,7 @@ if SETUP.SENTRY_DSN: integrations=[ DjangoIntegration(), HttpxIntegration(), + LoggingIntegration(), ], traces_sample_rate=SETUP.SENTRY_TRACES_SAMPLE_RATE, sample_rate=SETUP.SENTRY_SAMPLE_RATE, diff --git a/users/models/domain.py b/users/models/domain.py index ffa41db..4af3cae 100644 --- a/users/models/domain.py +++ b/users/models/domain.py @@ -1,4 +1,5 @@ import json +import logging import ssl from functools import cached_property from typing import Optional @@ -9,7 +10,6 @@ import urlman from django.conf import settings from django.db import models -from core.exceptions import capture_message from core.models import Config from stator.models import State, StateField, StateGraph, StatorModel from users.schemas import NodeInfo @@ -209,9 +209,9 @@ class Domain(StatorModel): and response.status_code < 500 and response.status_code not in [401, 403, 404, 406, 410] ): - capture_message( + logging.warning( f"Client error fetching nodeinfo: {str(ex)}", - extras={ + extra={ "code": response.status_code, "content": response.content, "domain": self.domain, @@ -223,9 +223,9 @@ class Domain(StatorModel): try: info = NodeInfo(**response.json()) except (json.JSONDecodeError, pydantic.ValidationError) as ex: - capture_message( + logging.warning( f"Client error decoding nodeinfo: {str(ex)}", - extras={ + extra={ "domain": self.domain, "nodeinfo20_url": nodeinfo20_url, }, diff --git a/users/models/follow.py b/users/models/follow.py index cd1d0ba..b3118b2 100644 --- a/users/models/follow.py +++ b/users/models/follow.py @@ -1,9 +1,9 @@ +import logging from typing import Optional import httpx from django.db import models, transaction -from core.exceptions import capture_message from core.ld import canonicalise, get_str_or_id from core.snowflake import Snowflake from stator.models import State, StateField, StateGraph, StatorModel @@ -350,8 +350,8 @@ class Follow(StatorModel): try: follow = cls.by_ap(data, create=True) except Identity.DoesNotExist: - capture_message( - "Identity not found for incoming Follow", extras={"data": data} + logging.info( + "Identity not found for incoming Follow", extra={"data": data} ) return if follow.state == FollowStates.accepted: @@ -367,9 +367,9 @@ class Follow(StatorModel): try: follow = cls.by_ap(data["object"]) except (cls.DoesNotExist, Identity.DoesNotExist): - capture_message( + logging.info( "Follow or Identity not found for incoming Accept", - extras={"data": data}, + extra={"data": data}, ) return @@ -389,9 +389,9 @@ class Follow(StatorModel): try: follow = cls.by_ap(data["object"]) except (cls.DoesNotExist, Identity.DoesNotExist): - capture_message( + logging.info( "Follow or Identity not found for incoming Reject", - extras={"data": data}, + extra={"data": data}, ) return @@ -419,8 +419,8 @@ class Follow(StatorModel): try: follow = cls.by_ap(data["object"]) except (cls.DoesNotExist, Identity.DoesNotExist): - capture_message( - "Follow or Identity not found for incoming Undo", extras={"data": data} + logging.info( + "Follow or Identity not found for incoming Undo", extra={"data": data} ) return diff --git a/users/models/identity.py b/users/models/identity.py index b714122..9ba2402 100644 --- a/users/models/identity.py +++ b/users/models/identity.py @@ -1,3 +1,4 @@ +import logging import ssl from functools import cached_property, partial from typing import Literal, Optional @@ -11,7 +12,7 @@ from django.utils import timezone from django.utils.functional import lazy from lxml import etree -from core.exceptions import ActorMismatchError, capture_message +from core.exceptions import ActorMismatchError from core.html import ContentRenderer, FediverseHtmlParser from core.ld import ( canonicalise, @@ -871,9 +872,9 @@ class Identity(StatorModel): # Their account got deleted, so let's do the same. Identity.objects.filter(pk=self.pk).delete() if status_code < 500 and status_code not in [401, 403, 404, 406, 410]: - capture_message( + logging.info( f"Client error fetching actor at {self.actor_uri}: {status_code}", - extras={ + extra={ "identity": self.pk, "domain": self.domain_id, "content": response.content, @@ -884,9 +885,9 @@ class Identity(StatorModel): document = canonicalise(response.json(), include_security=True) except ValueError: # servers with empty or invalid responses are inevitable - capture_message( + logging.info( f"Invalid response fetching actor at {self.actor_uri}", - extras={ + extra={ "identity": self.pk, "domain": self.domain_id, "content": response.content, diff --git a/users/views/activitypub.py b/users/views/activitypub.py index a43301c..726689c 100644 --- a/users/views/activitypub.py +++ b/users/views/activitypub.py @@ -1,4 +1,5 @@ import json +import logging from django.conf import settings from django.http import Http404, HttpResponse, HttpResponseBadRequest, JsonResponse @@ -9,7 +10,6 @@ from django.views.generic import View from activities.models import Post from activities.services import TimelineService -from core import exceptions from core.decorators import cache_page from core.ld import canonicalise from core.models import Config @@ -140,6 +140,10 @@ class Inbox(View): # Find the Identity by the actor on the incoming item # This ensures that the signature used for the headers matches the actor # described in the payload. + if "actor" not in document: + logging.warning("Inbox error: unspecified actor") + return HttpResponseBadRequest("Unspecified actor") + identity = Identity.by_actor_uri(document["actor"], create=True, transient=True) if ( document["type"] == "Delete" @@ -154,23 +158,19 @@ class Inbox(View): try: identity.fetch_actor() except TryAgainLater: - exceptions.capture_message( + logging.warning( f"Inbox error: timed out fetching actor {document['actor']}" ) return HttpResponse(status=504) if not identity.public_key: - exceptions.capture_message( - f"Inbox error: cannot fetch actor {document['actor']}" - ) + logging.warning(f"Inbox error: cannot fetch actor {document['actor']}") return HttpResponseBadRequest("Cannot retrieve actor") # See if it's from a blocked user or domain if identity.blocked or identity.domain.recursively_blocked(): # I love to lie! Throw it away! - exceptions.capture_message( - f"Inbox: Discarded message from {identity.actor_uri}" - ) + logging.warning(f"Inbox: Discarded message from {identity.actor_uri}") return HttpResponse(status=202) # If there's a "signature" payload, verify against that @@ -178,12 +178,10 @@ class Inbox(View): try: LDSignature.verify_signature(document, identity.public_key) except VerificationFormatError as e: - exceptions.capture_message( - f"Inbox error: Bad LD signature format: {e.args[0]}" - ) + logging.warning(f"Inbox error: Bad LD signature format: {e.args[0]}") return HttpResponseBadRequest(e.args[0]) except VerificationError: - exceptions.capture_message("Inbox error: Bad LD signature") + logging.warning("Inbox error: Bad LD signature") return HttpResponseUnauthorized("Bad signature") # Otherwise, verify against the header (assuming it's the same actor) @@ -194,12 +192,10 @@ class Inbox(View): identity.public_key, ) except VerificationFormatError as e: - exceptions.capture_message( - f"Inbox error: Bad HTTP signature format: {e.args[0]}" - ) + logging.warning(f"Inbox error: Bad HTTP signature format: {e.args[0]}") return HttpResponseBadRequest(e.args[0]) except VerificationError: - exceptions.capture_message("Inbox error: Bad HTTP signature") + logging.warning("Inbox error: Bad HTTP signature") return HttpResponseUnauthorized("Bad signature") # Don't allow injection of internal messages