From 7dc398586c2156a456d9526ac0e42c1fec9f8143 Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Wed, 28 Aug 2019 21:18:53 +1000 Subject: Implement a structured logging output system. (#5680) --- synapse/python_dependencies.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'synapse/python_dependencies.py') diff --git a/synapse/python_dependencies.py b/synapse/python_dependencies.py index c6465c0386..ec0ac547c1 100644 --- a/synapse/python_dependencies.py +++ b/synapse/python_dependencies.py @@ -47,9 +47,9 @@ REQUIREMENTS = [ "idna>=2.5", # validating SSL certs for IP addresses requires service_identity 18.1. "service_identity>=18.1.0", - # our logcontext handling relies on the ability to cancel inlineCallbacks - # (https://twistedmatrix.com/trac/ticket/4632) which landed in Twisted 18.7. - "Twisted>=18.7.0", + # Twisted 18.9 introduces some logger improvements that the structured + # logger utilises + "Twisted>=18.9.0", "treq>=15.1", # Twisted has required pyopenssl 16.0 since about Twisted 16.6. "pyopenssl>=16.0.0", -- cgit 1.5.1 From 6604b64fae970f534d3e2a61f2fbbe51599fa26d Mon Sep 17 00:00:00 2001 From: Jorik Schellekens Date: Wed, 11 Sep 2019 14:00:37 +0100 Subject: Check dependencies on setup in the nicer way. (#5989) --- changelog.d/5989.misc | 1 + synapse/config/metrics.py | 12 +++++------- synapse/config/repository.py | 27 +++++++-------------------- synapse/python_dependencies.py | 8 +++++++- 4 files changed, 20 insertions(+), 28 deletions(-) create mode 100644 changelog.d/5989.misc (limited to 'synapse/python_dependencies.py') diff --git a/changelog.d/5989.misc b/changelog.d/5989.misc new file mode 100644 index 0000000000..9f2525fd3e --- /dev/null +++ b/changelog.d/5989.misc @@ -0,0 +1 @@ +Clean up dependency checking at setup. diff --git a/synapse/config/metrics.py b/synapse/config/metrics.py index 653b990e67..9eb1e55ddb 100644 --- a/synapse/config/metrics.py +++ b/synapse/config/metrics.py @@ -16,11 +16,9 @@ import attr -from ._base import Config, ConfigError +from synapse.python_dependencies import DependencyException, check_requirements -MISSING_SENTRY = """Missing sentry-sdk library. This is required to enable sentry - integration. - """ +from ._base import Config, ConfigError @attr.s @@ -51,9 +49,9 @@ class MetricsConfig(Config): self.sentry_enabled = "sentry" in config if self.sentry_enabled: try: - import sentry_sdk # noqa F401 - except ImportError: - raise ConfigError(MISSING_SENTRY) + check_requirements("sentry") + except DependencyException as e: + raise ConfigError(e.message) self.sentry_dsn = config["sentry"].get("dsn") if not self.sentry_dsn: diff --git a/synapse/config/repository.py b/synapse/config/repository.py index fdb1f246d0..34f1a9a92d 100644 --- a/synapse/config/repository.py +++ b/synapse/config/repository.py @@ -16,6 +16,7 @@ import os from collections import namedtuple +from synapse.python_dependencies import DependencyException, check_requirements from synapse.util.module_loader import load_module from ._base import Config, ConfigError @@ -34,17 +35,6 @@ THUMBNAIL_SIZE_YAML = """\ # method: %(method)s """ -MISSING_NETADDR = "Missing netaddr library. This is required for URL preview API." - -MISSING_LXML = """Missing lxml library. This is required for URL preview API. - - Install by running: - pip install lxml - - Requires libxslt1-dev system package. - """ - - ThumbnailRequirement = namedtuple( "ThumbnailRequirement", ["width", "height", "method", "media_type"] ) @@ -171,16 +161,10 @@ class ContentRepositoryConfig(Config): self.url_preview_enabled = config.get("url_preview_enabled", False) if self.url_preview_enabled: try: - import lxml - - lxml # To stop unused lint. - except ImportError: - raise ConfigError(MISSING_LXML) + check_requirements("url_preview") - try: - from netaddr import IPSet - except ImportError: - raise ConfigError(MISSING_NETADDR) + except DependencyException as e: + raise ConfigError(e.message) if "url_preview_ip_range_blacklist" not in config: raise ConfigError( @@ -189,6 +173,9 @@ class ContentRepositoryConfig(Config): "to work" ) + # netaddr is a dependency for url_preview + from netaddr import IPSet + self.url_preview_ip_range_blacklist = IPSet( config["url_preview_ip_range_blacklist"] ) diff --git a/synapse/python_dependencies.py b/synapse/python_dependencies.py index ec0ac547c1..07345e916a 100644 --- a/synapse/python_dependencies.py +++ b/synapse/python_dependencies.py @@ -147,7 +147,13 @@ def check_requirements(for_feature=None): ) except DistributionNotFound: deps_needed.append(dependency) - errors.append("Needed %s but it was not installed" % (dependency,)) + if for_feature: + errors.append( + "Needed %s for the '%s' feature but it was not installed" + % (dependency, for_feature) + ) + else: + errors.append("Needed %s but it was not installed" % (dependency,)) if not for_feature: # Check the optional dependencies are up to date. We allow them to not be -- cgit 1.5.1 From b617864cd9f81109e818bc5ae95bee317d917b72 Mon Sep 17 00:00:00 2001 From: Amber Brown Date: Fri, 13 Sep 2019 02:29:55 +1000 Subject: Fix for structured logging tests stomping on logs (#6023) --- MANIFEST.in | 12 +++++---- changelog.d/6023.misc | 1 + mypy.ini | 54 ++++++++++++++++++++++++++++++++++++++++ synapse/config/logger.py | 33 ++++++++++++++++++------ synapse/logging/_structured.py | 8 +++--- synapse/logging/_terse_json.py | 8 +++--- synapse/logging/opentracing.py | 4 +-- synapse/metrics/__init__.py | 5 ++-- synapse/metrics/_exposition.py | 4 ++- synapse/python_dependencies.py | 7 +++--- tests/logging/test_structured.py | 25 ++++++++++++++++--- tests/logging/test_terse_json.py | 4 +-- tox.ini | 30 +++++++++++++++++----- 13 files changed, 154 insertions(+), 41 deletions(-) create mode 100644 changelog.d/6023.misc create mode 100644 mypy.ini (limited to 'synapse/python_dependencies.py') diff --git a/MANIFEST.in b/MANIFEST.in index 919cd8a1cd..9c2902b8d2 100644 --- a/MANIFEST.in +++ b/MANIFEST.in @@ -38,14 +38,16 @@ exclude sytest-blacklist include pyproject.toml recursive-include changelog.d * -prune .github -prune demo/etc -prune docker +prune .buildkite prune .circleci +prune .codecov.yml prune .coveragerc +prune .github prune debian -prune .codecov.yml -prune .buildkite +prune demo/etc +prune docker +prune mypy.ini +prune stubs exclude jenkins* recursive-exclude jenkins *.sh diff --git a/changelog.d/6023.misc b/changelog.d/6023.misc new file mode 100644 index 0000000000..d80410c22c --- /dev/null +++ b/changelog.d/6023.misc @@ -0,0 +1 @@ +Fix the structured logging tests stomping on the global log configuration for subsequent tests. diff --git a/mypy.ini b/mypy.ini new file mode 100644 index 0000000000..8788574ee3 --- /dev/null +++ b/mypy.ini @@ -0,0 +1,54 @@ +[mypy] +namespace_packages=True +plugins=mypy_zope:plugin +follow_imports=skip +mypy_path=stubs + +[mypy-synapse.config.homeserver] +# this is a mess because of the metaclass shenanigans +ignore_errors = True + +[mypy-zope] +ignore_missing_imports = True + +[mypy-constantly] +ignore_missing_imports = True + +[mypy-twisted.*] +ignore_missing_imports = True + +[mypy-treq.*] +ignore_missing_imports = True + +[mypy-hyperlink] +ignore_missing_imports = True + +[mypy-h11] +ignore_missing_imports = True + +[mypy-opentracing] +ignore_missing_imports = True + +[mypy-OpenSSL] +ignore_missing_imports = True + +[mypy-netaddr] +ignore_missing_imports = True + +[mypy-saml2.*] +ignore_missing_imports = True + +[mypy-unpaddedbase64] +ignore_missing_imports = True + +[mypy-canonicaljson] +ignore_missing_imports = True + +[mypy-jaeger_client] +ignore_missing_imports = True + +[mypy-jsonschema] +ignore_missing_imports = True + +[mypy-signedjson.*] +ignore_missing_imports = True diff --git a/synapse/config/logger.py b/synapse/config/logger.py index 2704c18720..767ecfdf09 100644 --- a/synapse/config/logger.py +++ b/synapse/config/logger.py @@ -21,7 +21,12 @@ from string import Template import yaml -from twisted.logger import STDLibLogObserver, globalLogBeginner +from twisted.logger import ( + ILogObserver, + LogBeginner, + STDLibLogObserver, + globalLogBeginner, +) import synapse from synapse.app import _base as appbase @@ -124,7 +129,7 @@ class LoggingConfig(Config): log_config_file.write(DEFAULT_LOG_CONFIG.substitute(log_file=log_file)) -def _setup_stdlib_logging(config, log_config): +def _setup_stdlib_logging(config, log_config, logBeginner: LogBeginner): """ Set up Python stdlib logging. """ @@ -165,12 +170,12 @@ def _setup_stdlib_logging(config, log_config): return observer(event) - globalLogBeginner.beginLoggingTo( - [_log], redirectStandardIO=not config.no_redirect_stdio - ) + logBeginner.beginLoggingTo([_log], redirectStandardIO=not config.no_redirect_stdio) if not config.no_redirect_stdio: print("Redirected stdout/stderr to logs") + return observer + def _reload_stdlib_logging(*args, log_config=None): logger = logging.getLogger("") @@ -181,7 +186,9 @@ def _reload_stdlib_logging(*args, log_config=None): logging.config.dictConfig(log_config) -def setup_logging(hs, config, use_worker_options=False): +def setup_logging( + hs, config, use_worker_options=False, logBeginner: LogBeginner = globalLogBeginner +) -> ILogObserver: """ Set up the logging subsystem. @@ -191,6 +198,12 @@ def setup_logging(hs, config, use_worker_options=False): use_worker_options (bool): True to use the 'worker_log_config' option instead of 'log_config'. + + logBeginner: The Twisted logBeginner to use. + + Returns: + The "root" Twisted Logger observer, suitable for sending logs to from a + Logger instance. """ log_config = config.worker_log_config if use_worker_options else config.log_config @@ -210,10 +223,12 @@ def setup_logging(hs, config, use_worker_options=False): log_config_body = read_config() if log_config_body and log_config_body.get("structured") is True: - setup_structured_logging(hs, config, log_config_body) + logger = setup_structured_logging( + hs, config, log_config_body, logBeginner=logBeginner + ) appbase.register_sighup(read_config, callback=reload_structured_logging) else: - _setup_stdlib_logging(config, log_config_body) + logger = _setup_stdlib_logging(config, log_config_body, logBeginner=logBeginner) appbase.register_sighup(read_config, callback=_reload_stdlib_logging) # make sure that the first thing we log is a thing we can grep backwards @@ -221,3 +236,5 @@ def setup_logging(hs, config, use_worker_options=False): logging.warn("***** STARTING SERVER *****") logging.warn("Server %s version %s", sys.argv[0], get_version_string(synapse)) logging.info("Server hostname: %s", config.server_name) + + return logger diff --git a/synapse/logging/_structured.py b/synapse/logging/_structured.py index 0367d6dfc4..3220e985a9 100644 --- a/synapse/logging/_structured.py +++ b/synapse/logging/_structured.py @@ -18,6 +18,7 @@ import os.path import sys import typing import warnings +from typing import List import attr from constantly import NamedConstant, Names, ValueConstant, Values @@ -33,7 +34,6 @@ from twisted.logger import ( LogLevelFilterPredicate, LogPublisher, eventAsText, - globalLogBeginner, jsonFileLogObserver, ) @@ -134,7 +134,7 @@ class PythonStdlibToTwistedLogger(logging.Handler): ) -def SynapseFileLogObserver(outFile: typing.io.TextIO) -> FileLogObserver: +def SynapseFileLogObserver(outFile: typing.IO[str]) -> FileLogObserver: """ A log observer that formats events like the traditional log formatter and sends them to `outFile`. @@ -265,7 +265,7 @@ def setup_structured_logging( hs, config, log_config: dict, - logBeginner: LogBeginner = globalLogBeginner, + logBeginner: LogBeginner, redirect_stdlib_logging: bool = True, ) -> LogPublisher: """ @@ -286,7 +286,7 @@ def setup_structured_logging( if "drains" not in log_config: raise ConfigError("The logging configuration requires a list of drains.") - observers = [] + observers = [] # type: List[ILogObserver] for observer in parse_drain_configs(log_config["drains"]): # Pipe drains diff --git a/synapse/logging/_terse_json.py b/synapse/logging/_terse_json.py index 7f1e8f23fe..0ebbde06f2 100644 --- a/synapse/logging/_terse_json.py +++ b/synapse/logging/_terse_json.py @@ -21,10 +21,11 @@ import sys from collections import deque from ipaddress import IPv4Address, IPv6Address, ip_address from math import floor -from typing.io import TextIO +from typing import IO import attr from simplejson import dumps +from zope.interface import implementer from twisted.application.internet import ClientService from twisted.internet.endpoints import ( @@ -33,7 +34,7 @@ from twisted.internet.endpoints import ( TCP6ClientEndpoint, ) from twisted.internet.protocol import Factory, Protocol -from twisted.logger import FileLogObserver, Logger +from twisted.logger import FileLogObserver, ILogObserver, Logger from twisted.python.failure import Failure @@ -129,7 +130,7 @@ def flatten_event(event: dict, metadata: dict, include_time: bool = False): return new_event -def TerseJSONToConsoleLogObserver(outFile: TextIO, metadata: dict) -> FileLogObserver: +def TerseJSONToConsoleLogObserver(outFile: IO[str], metadata: dict) -> FileLogObserver: """ A log observer that formats events to a flattened JSON representation. @@ -146,6 +147,7 @@ def TerseJSONToConsoleLogObserver(outFile: TextIO, metadata: dict) -> FileLogObs @attr.s +@implementer(ILogObserver) class TerseJSONToTCPLogObserver(object): """ An IObserver that writes JSON logs to a TCP target. diff --git a/synapse/logging/opentracing.py b/synapse/logging/opentracing.py index 7246253018..308a27213b 100644 --- a/synapse/logging/opentracing.py +++ b/synapse/logging/opentracing.py @@ -223,8 +223,8 @@ try: from jaeger_client import Config as JaegerConfig from synapse.logging.scopecontextmanager import LogContextScopeManager except ImportError: - JaegerConfig = None - LogContextScopeManager = None + JaegerConfig = None # type: ignore + LogContextScopeManager = None # type: ignore logger = logging.getLogger(__name__) diff --git a/synapse/metrics/__init__.py b/synapse/metrics/__init__.py index b5c9595cb9..bec3b13397 100644 --- a/synapse/metrics/__init__.py +++ b/synapse/metrics/__init__.py @@ -20,6 +20,7 @@ import os import platform import threading import time +from typing import Dict, Union import six @@ -42,9 +43,7 @@ logger = logging.getLogger(__name__) METRICS_PREFIX = "/_synapse/metrics" running_on_pypy = platform.python_implementation() == "PyPy" -all_metrics = [] -all_collectors = [] -all_gauges = {} +all_gauges = {} # type: Dict[str, Union[LaterGauge, InFlightGauge, BucketCollector]] HAVE_PROC_SELF_STAT = os.path.exists("/proc/self/stat") diff --git a/synapse/metrics/_exposition.py b/synapse/metrics/_exposition.py index 1933ecd3e3..74d9c3ecd3 100644 --- a/synapse/metrics/_exposition.py +++ b/synapse/metrics/_exposition.py @@ -36,7 +36,9 @@ from twisted.web.resource import Resource try: from prometheus_client.samples import Sample except ImportError: - Sample = namedtuple("Sample", ["name", "labels", "value", "timestamp", "exemplar"]) + Sample = namedtuple( + "Sample", ["name", "labels", "value", "timestamp", "exemplar"] + ) # type: ignore CONTENT_TYPE_LATEST = str("text/plain; version=0.0.4; charset=utf-8") diff --git a/synapse/python_dependencies.py b/synapse/python_dependencies.py index 07345e916a..0bd563edc7 100644 --- a/synapse/python_dependencies.py +++ b/synapse/python_dependencies.py @@ -15,6 +15,7 @@ # limitations under the License. import logging +from typing import Set from pkg_resources import ( DistributionNotFound, @@ -97,7 +98,7 @@ CONDITIONAL_REQUIREMENTS = { "jwt": ["pyjwt>=1.6.4"], } -ALL_OPTIONAL_REQUIREMENTS = set() +ALL_OPTIONAL_REQUIREMENTS = set() # type: Set[str] for name, optional_deps in CONDITIONAL_REQUIREMENTS.items(): # Exclude systemd as it's a system-based requirement. @@ -174,8 +175,8 @@ def check_requirements(for_feature=None): pass if deps_needed: - for e in errors: - logging.error(e) + for err in errors: + logging.error(err) raise DependencyException(deps_needed) diff --git a/tests/logging/test_structured.py b/tests/logging/test_structured.py index a786de0233..451d05c0f0 100644 --- a/tests/logging/test_structured.py +++ b/tests/logging/test_structured.py @@ -13,6 +13,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +import logging import os import os.path import shutil @@ -33,7 +34,20 @@ class FakeBeginner(object): self.observers = observers -class StructuredLoggingTestCase(HomeserverTestCase): +class StructuredLoggingTestBase(object): + """ + Test base that registers a cleanup handler to reset the stdlib log handler + to 'unset'. + """ + + def prepare(self, reactor, clock, hs): + def _cleanup(): + logging.getLogger("synapse").setLevel(logging.NOTSET) + + self.addCleanup(_cleanup) + + +class StructuredLoggingTestCase(StructuredLoggingTestBase, HomeserverTestCase): """ Tests for Synapse's structured logging support. """ @@ -139,7 +153,9 @@ class StructuredLoggingTestCase(HomeserverTestCase): self.assertEqual(logs[0]["request"], "somereq") -class StructuredLoggingConfigurationFileTestCase(HomeserverTestCase): +class StructuredLoggingConfigurationFileTestCase( + StructuredLoggingTestBase, HomeserverTestCase +): def make_homeserver(self, reactor, clock): tempdir = self.mktemp() @@ -179,10 +195,11 @@ class StructuredLoggingConfigurationFileTestCase(HomeserverTestCase): """ When a structured logging config is given, Synapse will use it. """ - setup_logging(self.hs, self.hs.config) + beginner = FakeBeginner() + publisher = setup_logging(self.hs, self.hs.config, logBeginner=beginner) # Make a logger and send an event - logger = Logger(namespace="tests.logging.test_structured") + logger = Logger(namespace="tests.logging.test_structured", observer=publisher) with LoggingContext("testcontext", request="somereq"): logger.info("Hello there, {name}!", name="steve") diff --git a/tests/logging/test_terse_json.py b/tests/logging/test_terse_json.py index 514282591d..4cf81f7128 100644 --- a/tests/logging/test_terse_json.py +++ b/tests/logging/test_terse_json.py @@ -23,10 +23,10 @@ from synapse.logging._structured import setup_structured_logging from tests.server import connect_client from tests.unittest import HomeserverTestCase -from .test_structured import FakeBeginner +from .test_structured import FakeBeginner, StructuredLoggingTestBase -class TerseJSONTCPTestCase(HomeserverTestCase): +class TerseJSONTCPTestCase(StructuredLoggingTestBase, HomeserverTestCase): def test_log_output(self): """ The Terse JSON outputter delivers simplified structured logs over TCP. diff --git a/tox.ini b/tox.ini index 7cb40847b5..1bce10a4ce 100644 --- a/tox.ini +++ b/tox.ini @@ -2,6 +2,7 @@ envlist = packaging, py35, py36, py37, check_codestyle, check_isort [base] +basepython = python3.7 deps = mock python-subunit @@ -137,18 +138,35 @@ commands = {toxinidir}/scripts-dev/generate_sample_config --check skip_install = True deps = coverage -whitelist_externals = - bash commands= coverage combine coverage report +[testenv:cov-erase] +skip_install = True +deps = + coverage +commands= + coverage erase + +[testenv:cov-html] +skip_install = True +deps = + coverage +commands= + coverage html + [testenv:mypy] -basepython = python3.5 +basepython = python3.7 +skip_install = True deps = {[base]deps} mypy + mypy-zope + typeshed +env = + MYPYPATH = stubs/ extras = all -commands = mypy --ignore-missing-imports \ - synapse/logging/_structured.py \ - synapse/logging/_terse_json.py +commands = mypy --show-traceback \ + synapse/logging/ \ + synapse/config/ -- cgit 1.5.1