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