From 660c8c1415704f0b9c6fe17fe74d40dfefd78f0a Mon Sep 17 00:00:00 2001 From: Sean Quah <8349537+squahtx@users.noreply.github.com> Date: Tue, 5 Oct 2021 12:23:25 +0100 Subject: Log stack traces when a missing opentracing span is detected (#10983) Make it easier to track down where opentracing spans are going missing by including stack traces in the logs. --- synapse/logging/opentracing.py | 1 + 1 file changed, 1 insertion(+) (limited to 'synapse/logging') diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 03d2dd94f6..5276c4bfcc 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -339,6 +339,7 @@ def ensure_active_span(message, ret=None): "There was no active span when trying to %s." " Did you forget to start one or did a context slip?", message, + stack_info=True, ) return ret -- cgit 1.5.1 From bb228f35237879b0cae93e3b5efab468b94a1e5b Mon Sep 17 00:00:00 2001 From: Nick Barrett Date: Fri, 8 Oct 2021 12:08:25 +0100 Subject: Include exception in json logging (#11028) --- changelog.d/11028.feature | 1 + synapse/logging/_terse_json.py | 6 ++++++ tests/logging/test_terse_json.py | 28 ++++++++++++++++++++++++++++ 3 files changed, 35 insertions(+) create mode 100644 changelog.d/11028.feature (limited to 'synapse/logging') diff --git a/changelog.d/11028.feature b/changelog.d/11028.feature new file mode 100644 index 0000000000..48798356b7 --- /dev/null +++ b/changelog.d/11028.feature @@ -0,0 +1 @@ +Include exception information in JSON logging output. Contributed by @Fizzadar at Beeper. diff --git a/synapse/logging/_terse_json.py b/synapse/logging/_terse_json.py index 6e82f7c7f1..b78d6e17c9 100644 --- a/synapse/logging/_terse_json.py +++ b/synapse/logging/_terse_json.py @@ -65,6 +65,12 @@ class JsonFormatter(logging.Formatter): if key not in _IGNORED_LOG_RECORD_ATTRIBUTES: event[key] = value + if record.exc_info: + exc_type, exc_value, _ = record.exc_info + if exc_type: + event["exc_type"] = f"{exc_type.__name__}" + event["exc_value"] = f"{exc_value}" + return _encoder.encode(event) diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index f73fcd684e..96f399b7ab 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -198,3 +198,31 @@ class TerseJsonTestCase(LoggerCleanupMixin, TestCase): self.assertEqual(log["url"], "/_matrix/client/versions") self.assertEqual(log["protocol"], "1.1") self.assertEqual(log["user_agent"], "") + + def test_with_exception(self): + """ + The logging exception type & value should be added to the JSON response. + """ + handler = logging.StreamHandler(self.output) + handler.setFormatter(JsonFormatter()) + logger = self.get_logger(handler) + + try: + raise ValueError("That's wrong, you wally!") + except ValueError: + logger.exception("Hello there, %s!", "wally") + + log = self.get_log_line() + + # The terse logger should give us these keys. + expected_log_keys = [ + "log", + "level", + "namespace", + "exc_type", + "exc_value", + ] + self.assertCountEqual(log.keys(), expected_log_keys) + self.assertEqual(log["log"], "Hello there, wally!") + self.assertEqual(log["exc_type"], "ValueError") + self.assertEqual(log["exc_value"], "That's wrong, you wally!") -- cgit 1.5.1 From 797ee7812db28f6cf130d68e2d10911c826b0be5 Mon Sep 17 00:00:00 2001 From: David Robertson Date: Fri, 8 Oct 2021 14:49:41 +0100 Subject: Relax `ignore-missing-imports` for modules that have stubs now and update mypy (#11006) Updating mypy past version 0.9 means that third-party stubs are no-longer distributed with typeshed. See http://mypy-lang.blogspot.com/2021/06/mypy-0900-released.html for details. We therefore pull in stub packages in setup.py Additionally, some modules that we were previously ignoring import failures for now have stubs. So let's use them. The rest of this change consists of fixups to make the newer mypy + stubs pass CI. Co-authored-by: Patrick Cloke --- changelog.d/11006.misc | 1 + mypy.ini | 69 +++++++++++++-------------- setup.py | 11 ++++- synapse/config/tls.py | 9 ++-- synapse/http/client.py | 2 +- synapse/logging/context.py | 16 +++---- synapse/metrics/background_process_metrics.py | 2 +- synapse/push/mailer.py | 2 +- synapse/rest/media/v1/__init__.py | 38 +++++---------- synapse/rest/media/v1/thumbnailer.py | 21 ++++++-- synapse/storage/prepare_database.py | 4 ++ synapse/util/__init__.py | 5 +- 12 files changed, 100 insertions(+), 80 deletions(-) create mode 100644 changelog.d/11006.misc (limited to 'synapse/logging') diff --git a/changelog.d/11006.misc b/changelog.d/11006.misc new file mode 100644 index 0000000000..7b4abae76a --- /dev/null +++ b/changelog.d/11006.misc @@ -0,0 +1 @@ +Bump mypy version for CI to 0.910, and pull in new type stubs for dependencies. \ No newline at end of file diff --git a/mypy.ini b/mypy.ini index 68437e5ce1..e7cb80b6eb 100644 --- a/mypy.ini +++ b/mypy.ini @@ -198,98 +198,97 @@ disallow_untyped_defs = True [mypy-tests.storage.test_user_directory] disallow_untyped_defs = True -[mypy-pymacaroons.*] -ignore_missing_imports = True +;; Dependencies without annotations +;; Before ignoring a module, check to see if type stubs are available. +;; The `typeshed` project maintains stubs here: +;; https://github.com/python/typeshed/tree/master/stubs +;; and for each package `foo` there's a corresponding `types-foo` package on PyPI, +;; which we can pull in as a dev dependency by adding to `setup.py`'s +;; `CONDITIONAL_REQUIREMENTS["mypy"]` list. -[mypy-zope] +[mypy-authlib.*] ignore_missing_imports = True [mypy-bcrypt] ignore_missing_imports = True -[mypy-constantly] -ignore_missing_imports = True - -[mypy-twisted.*] +[mypy-canonicaljson] ignore_missing_imports = True -[mypy-treq.*] +[mypy-constantly] ignore_missing_imports = True -[mypy-hyperlink] +[mypy-daemonize] ignore_missing_imports = True [mypy-h11] ignore_missing_imports = True -[mypy-msgpack] -ignore_missing_imports = True - -[mypy-opentracing] +[mypy-hiredis] ignore_missing_imports = True -[mypy-OpenSSL.*] +[mypy-hyperlink] ignore_missing_imports = True -[mypy-netaddr] +[mypy-ijson.*] ignore_missing_imports = True -[mypy-saml2.*] +[mypy-jaeger_client.*] ignore_missing_imports = True -[mypy-canonicaljson] +[mypy-josepy.*] ignore_missing_imports = True -[mypy-jaeger_client.*] +[mypy-jwt.*] ignore_missing_imports = True -[mypy-jsonschema] +[mypy-lxml] ignore_missing_imports = True -[mypy-signedjson.*] +[mypy-msgpack] ignore_missing_imports = True -[mypy-prometheus_client.*] +[mypy-nacl.*] ignore_missing_imports = True -[mypy-service_identity.*] +[mypy-netaddr] ignore_missing_imports = True -[mypy-daemonize] +[mypy-opentracing] ignore_missing_imports = True -[mypy-sentry_sdk] +[mypy-phonenumbers.*] ignore_missing_imports = True -[mypy-PIL.*] +[mypy-prometheus_client.*] ignore_missing_imports = True -[mypy-lxml] +[mypy-pymacaroons.*] ignore_missing_imports = True -[mypy-jwt.*] +[mypy-pympler.*] ignore_missing_imports = True -[mypy-authlib.*] +[mypy-rust_python_jaeger_reporter.*] ignore_missing_imports = True -[mypy-rust_python_jaeger_reporter.*] +[mypy-saml2.*] ignore_missing_imports = True -[mypy-nacl.*] +[mypy-sentry_sdk] ignore_missing_imports = True -[mypy-hiredis] +[mypy-service_identity.*] ignore_missing_imports = True -[mypy-josepy.*] +[mypy-signedjson.*] ignore_missing_imports = True -[mypy-pympler.*] +[mypy-treq.*] ignore_missing_imports = True -[mypy-phonenumbers.*] +[mypy-twisted.*] ignore_missing_imports = True -[mypy-ijson.*] +[mypy-zope] ignore_missing_imports = True diff --git a/setup.py b/setup.py index c478563510..f8b4487bc1 100755 --- a/setup.py +++ b/setup.py @@ -112,7 +112,16 @@ CONDITIONAL_REQUIREMENTS["dev"] = CONDITIONAL_REQUIREMENTS["lint"] + [ "pygithub==1.55", ] -CONDITIONAL_REQUIREMENTS["mypy"] = ["mypy==0.812", "mypy-zope==0.2.13"] +CONDITIONAL_REQUIREMENTS["mypy"] = [ + "mypy==0.910", + "mypy-zope==0.3.2", + "types-bleach>=4.1.0", + "types-jsonschema>=3.2.0", + "types-Pillow>=8.3.4", + "types-pyOpenSSL>=20.0.7", + "types-PyYAML>=5.4.10", + "types-setuptools>=57.4.0", +] # Dependencies which are exclusively required by unit test code. This is # NOT a list of all modules that are necessary to run the unit tests. diff --git a/synapse/config/tls.py b/synapse/config/tls.py index 5679f05e42..6227434bac 100644 --- a/synapse/config/tls.py +++ b/synapse/config/tls.py @@ -172,9 +172,12 @@ class TlsConfig(Config): ) # YYYYMMDDhhmmssZ -- in UTC - expires_on = datetime.strptime( - tls_certificate.get_notAfter().decode("ascii"), "%Y%m%d%H%M%SZ" - ) + expiry_data = tls_certificate.get_notAfter() + if expiry_data is None: + raise ValueError( + "TLS Certificate has no expiry date, and this is not permitted" + ) + expires_on = datetime.strptime(expiry_data.decode("ascii"), "%Y%m%d%H%M%SZ") now = datetime.utcnow() days_remaining = (expires_on - now).days return days_remaining diff --git a/synapse/http/client.py b/synapse/http/client.py index 5204c3d08c..b5a2d333a6 100644 --- a/synapse/http/client.py +++ b/synapse/http/client.py @@ -912,7 +912,7 @@ class InsecureInterceptableContextFactory(ssl.ContextFactory): def __init__(self): self._context = SSL.Context(SSL.SSLv23_METHOD) - self._context.set_verify(VERIFY_NONE, lambda *_: None) + self._context.set_verify(VERIFY_NONE, lambda *_: False) def getContext(self, hostname=None, port=None): return self._context diff --git a/synapse/logging/context.py b/synapse/logging/context.py index 02e5ddd2ef..bdc0187743 100644 --- a/synapse/logging/context.py +++ b/synapse/logging/context.py @@ -52,7 +52,7 @@ try: is_thread_resource_usage_supported = True - def get_thread_resource_usage() -> "Optional[resource._RUsage]": + def get_thread_resource_usage() -> "Optional[resource.struct_rusage]": return resource.getrusage(RUSAGE_THREAD) @@ -61,7 +61,7 @@ except Exception: # won't track resource usage. is_thread_resource_usage_supported = False - def get_thread_resource_usage() -> "Optional[resource._RUsage]": + def get_thread_resource_usage() -> "Optional[resource.struct_rusage]": return None @@ -226,10 +226,10 @@ class _Sentinel: def copy_to(self, record): pass - def start(self, rusage: "Optional[resource._RUsage]"): + def start(self, rusage: "Optional[resource.struct_rusage]"): pass - def stop(self, rusage: "Optional[resource._RUsage]"): + def stop(self, rusage: "Optional[resource.struct_rusage]"): pass def add_database_transaction(self, duration_sec): @@ -289,7 +289,7 @@ class LoggingContext: # The thread resource usage when the logcontext became active. None # if the context is not currently active. - self.usage_start: Optional[resource._RUsage] = None + self.usage_start: Optional[resource.struct_rusage] = None self.main_thread = get_thread_id() self.request = None @@ -410,7 +410,7 @@ class LoggingContext: # we also track the current scope: record.scope = self.scope - def start(self, rusage: "Optional[resource._RUsage]") -> None: + def start(self, rusage: "Optional[resource.struct_rusage]") -> None: """ Record that this logcontext is currently running. @@ -435,7 +435,7 @@ class LoggingContext: else: self.usage_start = rusage - def stop(self, rusage: "Optional[resource._RUsage]") -> None: + def stop(self, rusage: "Optional[resource.struct_rusage]") -> None: """ Record that this logcontext is no longer running. @@ -490,7 +490,7 @@ class LoggingContext: return res - def _get_cputime(self, current: "resource._RUsage") -> Tuple[float, float]: + def _get_cputime(self, current: "resource.struct_rusage") -> Tuple[float, float]: """Get the cpu usage time between start() and the given rusage Args: diff --git a/synapse/metrics/background_process_metrics.py b/synapse/metrics/background_process_metrics.py index 3a14260752..2ab599a334 100644 --- a/synapse/metrics/background_process_metrics.py +++ b/synapse/metrics/background_process_metrics.py @@ -265,7 +265,7 @@ class BackgroundProcessLoggingContext(LoggingContext): super().__init__("%s-%s" % (name, instance_id)) self._proc = _BackgroundProcess(name, self) - def start(self, rusage: "Optional[resource._RUsage]"): + def start(self, rusage: "Optional[resource.struct_rusage]"): """Log context has started running (again).""" super().start(rusage) diff --git a/synapse/push/mailer.py b/synapse/push/mailer.py index e38e3c5d44..ce299ba3da 100644 --- a/synapse/push/mailer.py +++ b/synapse/push/mailer.py @@ -892,7 +892,7 @@ def safe_text(raw_text: str) -> jinja2.Markup: A Markup object ready to safely use in a Jinja template. """ return jinja2.Markup( - bleach.linkify(bleach.clean(raw_text, tags=[], attributes={}, strip=False)) + bleach.linkify(bleach.clean(raw_text, tags=[], attributes=[], strip=False)) ) diff --git a/synapse/rest/media/v1/__init__.py b/synapse/rest/media/v1/__init__.py index 3dd16d4bb5..d5b74cddf1 100644 --- a/synapse/rest/media/v1/__init__.py +++ b/synapse/rest/media/v1/__init__.py @@ -12,33 +12,21 @@ # See the License for the specific language governing permissions and # limitations under the License. -import PIL.Image +from PIL.features import check_codec # check for JPEG support. -try: - PIL.Image._getdecoder("rgb", "jpeg", None) -except OSError as e: - if str(e).startswith("decoder jpeg not available"): - raise Exception( - "FATAL: jpeg codec not supported. Install pillow correctly! " - " 'sudo apt-get install libjpeg-dev' then 'pip uninstall pillow &&" - " pip install pillow --user'" - ) -except Exception: - # any other exception is fine - pass +if not check_codec("jpg"): + raise Exception( + "FATAL: jpeg codec not supported. Install pillow correctly! " + " 'sudo apt-get install libjpeg-dev' then 'pip uninstall pillow &&" + " pip install pillow --user'" + ) # check for PNG support. -try: - PIL.Image._getdecoder("rgb", "zip", None) -except OSError as e: - if str(e).startswith("decoder zip not available"): - raise Exception( - "FATAL: zip codec not supported. Install pillow correctly! " - " 'sudo apt-get install libjpeg-dev' then 'pip uninstall pillow &&" - " pip install pillow --user'" - ) -except Exception: - # any other exception is fine - pass +if not check_codec("zlib"): + raise Exception( + "FATAL: zip codec not supported. Install pillow correctly! " + " 'sudo apt-get install libjpeg-dev' then 'pip uninstall pillow &&" + " pip install pillow --user'" + ) diff --git a/synapse/rest/media/v1/thumbnailer.py b/synapse/rest/media/v1/thumbnailer.py index df54a40649..46701a8b83 100644 --- a/synapse/rest/media/v1/thumbnailer.py +++ b/synapse/rest/media/v1/thumbnailer.py @@ -61,9 +61,19 @@ class Thumbnailer: self.transpose_method = None try: # We don't use ImageOps.exif_transpose since it crashes with big EXIF - image_exif = self.image._getexif() + # + # Ignore safety: Pillow seems to acknowledge that this method is + # "private, experimental, but generally widely used". Pillow 6 + # includes a public getexif() method (no underscore) that we might + # consider using instead when we can bump that dependency. + # + # At the time of writing, Debian buster (currently oldstable) + # provides version 5.4.1. It's expected to EOL in mid-2022, see + # https://wiki.debian.org/DebianReleases#Production_Releases + image_exif = self.image._getexif() # type: ignore if image_exif is not None: image_orientation = image_exif.get(EXIF_ORIENTATION_TAG) + assert isinstance(image_orientation, int) self.transpose_method = EXIF_TRANSPOSE_MAPPINGS.get(image_orientation) except Exception as e: # A lot of parsing errors can happen when parsing EXIF @@ -76,7 +86,10 @@ class Thumbnailer: A tuple containing the new image size in pixels as (width, height). """ if self.transpose_method is not None: - self.image = self.image.transpose(self.transpose_method) + # Safety: `transpose` takes an int rather than e.g. an IntEnum. + # self.transpose_method is set above to be a value in + # EXIF_TRANSPOSE_MAPPINGS, and that only contains correct values. + self.image = self.image.transpose(self.transpose_method) # type: ignore[arg-type] self.width, self.height = self.image.size self.transpose_method = None # We don't need EXIF any more @@ -101,7 +114,7 @@ class Thumbnailer: else: return (max_height * self.width) // self.height, max_height - def _resize(self, width: int, height: int) -> Image: + def _resize(self, width: int, height: int) -> Image.Image: # 1-bit or 8-bit color palette images need converting to RGB # otherwise they will be scaled using nearest neighbour which # looks awful. @@ -151,7 +164,7 @@ class Thumbnailer: cropped = scaled_image.crop((crop_left, 0, crop_right, height)) return self._encode_image(cropped, output_type) - def _encode_image(self, output_image: Image, output_type: str) -> BytesIO: + def _encode_image(self, output_image: Image.Image, output_type: str) -> BytesIO: output_bytes_io = BytesIO() fmt = self.FORMATS[output_type] if fmt == "JPEG": diff --git a/synapse/storage/prepare_database.py b/synapse/storage/prepare_database.py index a63eaddfdc..11ca47ea28 100644 --- a/synapse/storage/prepare_database.py +++ b/synapse/storage/prepare_database.py @@ -487,6 +487,10 @@ def _upgrade_existing_database( spec = importlib.util.spec_from_file_location( module_name, absolute_path ) + if spec is None: + raise RuntimeError( + f"Could not build a module spec for {module_name} at {absolute_path}" + ) module = importlib.util.module_from_spec(spec) spec.loader.exec_module(module) # type: ignore diff --git a/synapse/util/__init__.py b/synapse/util/__init__.py index 64daff59df..abf53d149d 100644 --- a/synapse/util/__init__.py +++ b/synapse/util/__init__.py @@ -51,7 +51,10 @@ def _handle_frozendict(obj: Any) -> Dict[Any, Any]: # fishing the protected dict out of the object is a bit nasty, # but we don't really want the overhead of copying the dict. try: - return obj._dict + # Safety: we catch the AttributeError immediately below. + # See https://github.com/matrix-org/python-canonicaljson/issues/36#issuecomment-927816293 + # for discussion on how frozendict's internals have changed over time. + return obj._dict # type: ignore[attr-defined] except AttributeError: # When the C implementation of frozendict is used, # there isn't a `_dict` attribute with a dict -- cgit 1.5.1