1# Copyright 2014-2016 OpenMarket Ltd
2# Copyright 2021 The Matrix.org Foundation C.I.C.
3#
4# Licensed under the Apache License, Version 2.0 (the "License");
5# you may not use this file except in compliance with the License.
6# You may obtain a copy of the License at
7#
8#     http://www.apache.org/licenses/LICENSE-2.0
9#
10# Unless required by applicable law or agreed to in writing, software
11# distributed under the License is distributed on an "AS IS" BASIS,
12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13# See the License for the specific language governing permissions and
14# limitations under the License.
15import argparse
16import logging
17import logging.config
18import os
19import sys
20import threading
21from string import Template
22from typing import TYPE_CHECKING, Any, Dict, Optional
23
24import yaml
25from zope.interface import implementer
26
27from twisted.logger import (
28    ILogObserver,
29    LogBeginner,
30    STDLibLogObserver,
31    eventAsText,
32    globalLogBeginner,
33)
34
35import synapse
36from synapse.logging._structured import setup_structured_logging
37from synapse.logging.context import LoggingContextFilter
38from synapse.logging.filter import MetadataFilter
39from synapse.util.versionstring import get_version_string
40
41from ._base import Config, ConfigError
42
43if TYPE_CHECKING:
44    from synapse.config.homeserver import HomeServerConfig
45    from synapse.server import HomeServer
46
47DEFAULT_LOG_CONFIG = Template(
48    """\
49# Log configuration for Synapse.
50#
51# This is a YAML file containing a standard Python logging configuration
52# dictionary. See [1] for details on the valid settings.
53#
54# Synapse also supports structured logging for machine readable logs which can
55# be ingested by ELK stacks. See [2] for details.
56#
57# [1]: https://docs.python.org/3.7/library/logging.config.html#configuration-dictionary-schema
58# [2]: https://matrix-org.github.io/synapse/latest/structured_logging.html
59
60version: 1
61
62formatters:
63    precise:
64        format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - \
65%(request)s - %(message)s'
66
67handlers:
68    file:
69        class: logging.handlers.TimedRotatingFileHandler
70        formatter: precise
71        filename: ${log_file}
72        when: midnight
73        backupCount: 3  # Does not include the current log file.
74        encoding: utf8
75
76    # Default to buffering writes to log file for efficiency.
77    # WARNING/ERROR logs will still be flushed immediately, but there will be a
78    # delay (of up to `period` seconds, or until the buffer is full with
79    # `capacity` messages) before INFO/DEBUG logs get written.
80    buffer:
81        class: synapse.logging.handlers.PeriodicallyFlushingMemoryHandler
82        target: file
83
84        # The capacity is the maximum number of log lines that are buffered
85        # before being written to disk. Increasing this will lead to better
86        # performance, at the expensive of it taking longer for log lines to
87        # be written to disk.
88        # This parameter is required.
89        capacity: 10
90
91        # Logs with a level at or above the flush level will cause the buffer to
92        # be flushed immediately.
93        # Default value: 40 (ERROR)
94        # Other values: 50 (CRITICAL), 30 (WARNING), 20 (INFO), 10 (DEBUG)
95        flushLevel: 30  # Flush immediately for WARNING logs and higher
96
97        # The period of time, in seconds, between forced flushes.
98        # Messages will not be delayed for longer than this time.
99        # Default value: 5 seconds
100        period: 5
101
102    # A handler that writes logs to stderr. Unused by default, but can be used
103    # instead of "buffer" and "file" in the logger handlers.
104    console:
105        class: logging.StreamHandler
106        formatter: precise
107
108loggers:
109    synapse.storage.SQL:
110        # beware: increasing this to DEBUG will make synapse log sensitive
111        # information such as access tokens.
112        level: INFO
113
114    twisted:
115        # We send the twisted logging directly to the file handler,
116        # to work around https://github.com/matrix-org/synapse/issues/3471
117        # when using "buffer" logger. Use "console" to log to stderr instead.
118        handlers: [file]
119        propagate: false
120
121root:
122    level: INFO
123
124    # Write logs to the `buffer` handler, which will buffer them together in memory,
125    # then write them to a file.
126    #
127    # Replace "buffer" with "console" to log to stderr instead. (Note that you'll
128    # also need to update the configuration for the `twisted` logger above, in
129    # this case.)
130    #
131    handlers: [buffer]
132
133disable_existing_loggers: false
134"""
135)
136
137LOG_FILE_ERROR = """\
138Support for the log_file configuration option and --log-file command-line option was
139removed in Synapse 1.3.0. You should instead set up a separate log configuration file.
140"""
141
142
143class LoggingConfig(Config):
144    section = "logging"
145
146    def read_config(self, config, **kwargs) -> None:
147        if config.get("log_file"):
148            raise ConfigError(LOG_FILE_ERROR)
149        self.log_config = self.abspath(config.get("log_config"))
150        self.no_redirect_stdio = config.get("no_redirect_stdio", False)
151
152    def generate_config_section(self, config_dir_path, server_name, **kwargs) -> str:
153        log_config = os.path.join(config_dir_path, server_name + ".log.config")
154        return (
155            """\
156        ## Logging ##
157
158        # A yaml python logging config file as described by
159        # https://docs.python.org/3.7/library/logging.config.html#configuration-dictionary-schema
160        #
161        log_config: "%(log_config)s"
162        """
163            % locals()
164        )
165
166    def read_arguments(self, args: argparse.Namespace) -> None:
167        if args.no_redirect_stdio is not None:
168            self.no_redirect_stdio = args.no_redirect_stdio
169        if args.log_file is not None:
170            raise ConfigError(LOG_FILE_ERROR)
171
172    @staticmethod
173    def add_arguments(parser: argparse.ArgumentParser) -> None:
174        logging_group = parser.add_argument_group("logging")
175        logging_group.add_argument(
176            "-n",
177            "--no-redirect-stdio",
178            action="store_true",
179            default=None,
180            help="Do not redirect stdout/stderr to the log",
181        )
182
183        logging_group.add_argument(
184            "-f",
185            "--log-file",
186            dest="log_file",
187            help=argparse.SUPPRESS,
188        )
189
190    def generate_files(self, config: Dict[str, Any], config_dir_path: str) -> None:
191        log_config = config.get("log_config")
192        if log_config and not os.path.exists(log_config):
193            log_file = self.abspath("homeserver.log")
194            print(
195                "Generating log config file %s which will log to %s"
196                % (log_config, log_file)
197            )
198            with open(log_config, "w") as log_config_file:
199                log_config_file.write(DEFAULT_LOG_CONFIG.substitute(log_file=log_file))
200
201
202def _setup_stdlib_logging(
203    config: "HomeServerConfig", log_config_path: Optional[str], logBeginner: LogBeginner
204) -> None:
205    """
206    Set up Python standard library logging.
207    """
208    if log_config_path is None:
209        log_format = (
210            "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s"
211            " - %(message)s"
212        )
213
214        logger = logging.getLogger("")
215        logger.setLevel(logging.INFO)
216        logging.getLogger("synapse.storage.SQL").setLevel(logging.INFO)
217
218        formatter = logging.Formatter(log_format)
219
220        handler = logging.StreamHandler()
221        handler.setFormatter(formatter)
222        logger.addHandler(handler)
223    else:
224        # Load the logging configuration.
225        _load_logging_config(log_config_path)
226
227    # We add a log record factory that runs all messages through the
228    # LoggingContextFilter so that we get the context *at the time we log*
229    # rather than when we write to a handler. This can be done in config using
230    # filter options, but care must when using e.g. MemoryHandler to buffer
231    # writes.
232
233    log_context_filter = LoggingContextFilter()
234    log_metadata_filter = MetadataFilter({"server_name": config.server.server_name})
235    old_factory = logging.getLogRecordFactory()
236
237    def factory(*args: Any, **kwargs: Any) -> logging.LogRecord:
238        record = old_factory(*args, **kwargs)
239        log_context_filter.filter(record)
240        log_metadata_filter.filter(record)
241        return record
242
243    logging.setLogRecordFactory(factory)
244
245    # Route Twisted's native logging through to the standard library logging
246    # system.
247    observer = STDLibLogObserver()
248
249    threadlocal = threading.local()
250
251    @implementer(ILogObserver)
252    def _log(event: dict) -> None:
253        if "log_text" in event:
254            if event["log_text"].startswith("DNSDatagramProtocol starting on "):
255                return
256
257            if event["log_text"].startswith("(UDP Port "):
258                return
259
260            if event["log_text"].startswith("Timing out client"):
261                return
262
263        # this is a workaround to make sure we don't get stack overflows when the
264        # logging system raises an error which is written to stderr which is redirected
265        # to the logging system, etc.
266        if getattr(threadlocal, "active", False):
267            # write the text of the event, if any, to the *real* stderr (which may
268            # be redirected to /dev/null, but there's not much we can do)
269            try:
270                event_text = eventAsText(event)
271                print("logging during logging: %s" % event_text, file=sys.__stderr__)
272            except Exception:
273                # gah.
274                pass
275            return
276
277        try:
278            threadlocal.active = True
279            return observer(event)
280        finally:
281            threadlocal.active = False
282
283    logBeginner.beginLoggingTo([_log], redirectStandardIO=False)
284
285
286def _load_logging_config(log_config_path: str) -> None:
287    """
288    Configure logging from a log config path.
289    """
290    with open(log_config_path, "rb") as f:
291        log_config = yaml.safe_load(f.read())
292
293    if not log_config:
294        logging.warning("Loaded a blank logging config?")
295
296    # If the old structured logging configuration is being used, convert it to
297    # the new style configuration.
298    if "structured" in log_config and log_config.get("structured"):
299        log_config = setup_structured_logging(log_config)
300
301    logging.config.dictConfig(log_config)
302
303
304def _reload_logging_config(log_config_path: Optional[str]) -> None:
305    """
306    Reload the log configuration from the file and apply it.
307    """
308    # If no log config path was given, it cannot be reloaded.
309    if log_config_path is None:
310        return
311
312    _load_logging_config(log_config_path)
313    logging.info("Reloaded log config from %s due to SIGHUP", log_config_path)
314
315
316def setup_logging(
317    hs: "HomeServer",
318    config: "HomeServerConfig",
319    use_worker_options: bool = False,
320    logBeginner: LogBeginner = globalLogBeginner,
321) -> None:
322    """
323    Set up the logging subsystem.
324
325    Args:
326        config (LoggingConfig | synapse.config.worker.WorkerConfig):
327            configuration data
328
329        use_worker_options (bool): True to use the 'worker_log_config' option
330            instead of 'log_config'.
331
332        logBeginner: The Twisted logBeginner to use.
333
334    """
335    log_config_path = (
336        config.worker.worker_log_config
337        if use_worker_options
338        else config.logging.log_config
339    )
340
341    # Perform one-time logging configuration.
342    _setup_stdlib_logging(config, log_config_path, logBeginner=logBeginner)
343    # Add a SIGHUP handler to reload the logging configuration, if one is available.
344    from synapse.app import _base as appbase
345
346    appbase.register_sighup(_reload_logging_config, log_config_path)
347
348    # Log immediately so we can grep backwards.
349    logging.warning("***** STARTING SERVER *****")
350    logging.warning("Server %s version %s", sys.argv[0], get_version_string(synapse))
351    logging.info("Server hostname: %s", config.server.server_name)
352    logging.info("Instance name: %s", hs.get_instance_name())
353