1# This file is part of Xpra. 2# Copyright (C) 2008, 2009 Nathaniel Smith <njs@pobox.com> 3# Copyright (C) 2012-2021 Antoine Martin <antoine@xpra.org> 4# Xpra is released under the terms of the GNU GPL v2, or, at your option, any 5# later version. See the file COPYING for details. 6 7import os 8import sys 9import logging 10import weakref 11# This module is used by non-GUI programs and thus must not import gtk. 12 13LOG_PREFIX = os.environ.get("XPRA_LOG_PREFIX", "") 14LOG_FORMAT = os.environ.get("XPRA_LOG_FORMAT", "%(asctime)s %(message)s") 15NOPREFIX_FORMAT = "%(message)s" 16 17DEBUG_MODULES = [x for x in os.environ.get("XPRA_DEBUG_MODULES", "").split(",") if x] 18 19logging.basicConfig(format=LOG_FORMAT) 20logging.root.setLevel(logging.INFO) 21 22#so we can keep a reference to all the loggers in use 23#we may have multiple loggers for the same key, so use a dict 24#but we don't want to prevent garbage collection so use a list of weakrefs 25all_loggers = dict() 26def add_logger(categories, logger): 27 global all_loggers 28 categories = list(categories) 29 categories.append("all") 30 l = weakref.ref(logger) 31 for cat in categories: 32 all_loggers.setdefault(cat, set()).add(l) 33 34def get_all_loggers(): 35 global all_loggers 36 a = set() 37 for loggers in all_loggers.values(): 38 for logger in list(loggers): 39 #weakref: 40 instance = logger() 41 if instance: 42 a.add(instance) 43 return a 44 45 46debug_enabled_categories = set() 47debug_disabled_categories = set() 48 49def get_debug_args(): 50 args = [] 51 if debug_enabled_categories: 52 args += list(debug_enabled_categories) 53 if debug_disabled_categories: 54 for x in debug_disabled_categories: 55 args.append("-%s" % x) 56 return args 57 58class FullDebugContext: 59 __slots__ = ("debug_enabled_categories", "enabled") 60 def __enter__(self): 61 global debug_enabled_categories 62 self.debug_enabled_categories = debug_enabled_categories 63 debug_enabled_categories.clear() 64 debug_enabled_categories.add("all") 65 self.enabled = [] 66 for x in get_all_loggers(): 67 if not x.is_debug_enabled(): 68 self.enabled.append(x) 69 x.enable_debug() 70 71 def __exit__(self, *_args): 72 for x in self.enabled: 73 x.disable_debug() 74 global debug_enabled_categories 75 debug_enabled_categories.clear() 76 debug_enabled_categories.add(self.debug_enabled_categories) 77 78 79def add_debug_category(*cat): 80 remove_disabled_category(*cat) 81 for c in cat: 82 debug_enabled_categories.add(c) 83 84def remove_debug_category(*cat): 85 for c in cat: 86 if c in debug_enabled_categories: 87 debug_enabled_categories.remove(c) 88 89def is_debug_enabled(category : str): 90 if "all" in debug_enabled_categories: 91 return True 92 if category in debug_enabled_categories: 93 return True 94 return isenvdebug(category) or isenvdebug("ALL") 95 96 97def add_disabled_category(*cat): 98 remove_debug_category(*cat) 99 for c in cat: 100 debug_disabled_categories.add(c) 101 102def remove_disabled_category(*cat): 103 for c in cat: 104 if c in debug_disabled_categories: 105 debug_disabled_categories.remove(c) 106 107 108def get_loggers_for_categories(*cat): 109 if not cat: 110 return [] 111 if "all" in cat: 112 return get_all_loggers() 113 cset = set(cat) 114 matches = set() 115 for l in get_all_loggers(): 116 if set(l.categories).issuperset(cset): 117 matches.add(l) 118 return list(matches) 119 120def enable_debug_for(*cat): 121 loggers = [] 122 for l in get_loggers_for_categories(*cat): 123 if not l.is_debug_enabled(): 124 l.enable_debug() 125 loggers.append(l) 126 return loggers 127 128def disable_debug_for(*cat): 129 loggers = [] 130 for l in get_loggers_for_categories(*cat): 131 if l.is_debug_enabled(): 132 l.disable_debug() 133 loggers.append(l) 134 return loggers 135 136 137default_level = logging.DEBUG 138def set_default_level(level): 139 global default_level 140 default_level = level 141 142 143def standard_logging(log, level, msg, *args, **kwargs): 144 #this is just the regular logging: 145 log(level, msg, *args, **kwargs) 146 147#this allows us to capture all logging and redirect it: 148#the default 'standard_logging' uses the logger, 149#but the client may inject its own handler here 150global_logging_handler = standard_logging 151 152def set_global_logging_handler(h): 153 assert callable(h) 154 global global_logging_handler 155 saved = global_logging_handler 156 global_logging_handler = h 157 return saved 158 159 160def setloghandler(lh): 161 logging.root.handlers = [] 162 logging.root.addHandler(lh) 163 164def enable_color(to=sys.stdout, format_string=NOPREFIX_FORMAT): 165 if not hasattr(to, "fileno"): 166 #on win32 sys.stdout can be a "Blackhole", 167 #which does not have a fileno 168 return 169 from xpra.colorstreamhandler import ColorStreamHandler 170 csh = ColorStreamHandler(to) 171 csh.setFormatter(logging.Formatter(format_string)) 172 setloghandler(csh) 173 174def enable_format(format_string): 175 try: 176 logging.root.handlers[0].formatter = logging.Formatter(format_string) 177 except (AttributeError, IndexError): 178 pass 179 180 181STRUCT_KNOWN_FILTERS = { 182 "Client" : { 183 "client" : "All client code", 184 "paint" : "Client window paint code", 185 "draw" : "Client draw packets", 186 "cairo" : "Cairo paint code used with the GTK3 client", 187 "opengl" : "Client OpenGL rendering", 188 "info" : "About and Session info dialogs", 189 "launcher" : "The client launcher program", 190 }, 191 "General" : { 192 "clipboard" : "All clipboard operations", 193 "notify" : "Notification forwarding", 194 "tray" : "System Tray forwarding", 195 "printing" : "Printing", 196 "file" : "File transfers", 197 "keyboard" : "Keyboard mapping and key event handling", 198 "screen" : "Screen and workarea dimension", 199 "fps" : "Frames per second", 200 "xsettings" : "XSettings synchronization", 201 "dbus" : "DBUS calls", 202 "rpc" : "Remote Procedure Calls", 203 "menu" : "Menus", 204 "events" : "System and window events", 205 }, 206 "Window" : { 207 "window" : "All window code", 208 "damage" : "Window X11 repaint events", 209 "geometry" : "Window geometry", 210 "shape" : "Window shape forwarding (XShape)", 211 "focus" : "Window focus", 212 "workspace" : "Window workspace synchronization", 213 "metadata" : "Window metadata", 214 "alpha" : "Window Alpha channel (transparency)", 215 "state" : "Window state", 216 "icon" : "Window icons", 217 "frame" : "Window frame", 218 "grab" : "Window grabs (both keyboard and mouse)", 219 "dragndrop" : "Window drag-n-drop events", 220 "filters" : "Window filters", 221 }, 222 "Encoding" : { 223 "codec" : "Codec loader and video helper", 224 "loader" : "Pixel compression codec loader", 225 "video" : "Video encoding", 226 "score" : "Video pipeline scoring and selection", 227 "encoding" : "Server side encoding selection and compression", 228 "scaling" : "Picture scaling", 229 "scroll" : "Scrolling detection and compression", 230 "xor" : "XOR delta pre-compression", 231 "subregion" : "Video subregion processing", 232 "regiondetect" : "Video region detection", 233 "regionrefresh" : "Video region refresh", 234 "refresh" : "Refresh of lossy screen updates", 235 "compress" : "Pixel compression (non video)", 236 }, 237 "Codec" : { 238 #codecs: 239 "csc" : "Colourspace conversion codecs", 240 "cuda" : "CUDA device access (nvenc)", 241 "cython" : "Cython CSC module", 242 "swscale" : "swscale CSC module", 243 "libyuv" : "libyuv CSC module", 244 "decoder" : "All decoders", 245 "encoder" : "All encoders", 246 "avcodec" : "avcodec decoder", 247 "libav" : "libav common code (used by swscale, avcodec and ffmpeg)", 248 "ffmpeg" : "ffmpeg encoder", 249 "pillow" : "Pillow encoder and decoder", 250 "spng" : "spng codec", 251 "jpeg" : "JPEG codec", 252 "vpx" : "libvpx encoder and decoder", 253 "nvjpeg" : "nvidia nvjpeg hardware encoder", 254 "nvenc" : "nvidia nvenc video hardware encoder", 255 "nvfbc" : "nvidia nvfbc screen capture", 256 "x264" : "libx264 encoder", 257 "x265" : "libx265 encoder", 258 "webp" : "libwebp encoder and decoder", 259 "webcam" : "webcam access", 260 }, 261 "Pointer" : { 262 "mouse" : "Mouse motion", 263 "cursor" : "Mouse cursor shape", 264 }, 265 "Misc" : { 266 #libraries 267 "gtk" : "All GTK code: bindings, client, etc", 268 "util" : "All utility functions", 269 "gobject" : "Command line clients", 270 #server bits: 271 "test" : "Test code", 272 "verbose" : "Very verbose flag", 273 #specific applications: 274 }, 275 "Network" : { 276 #internal / network: 277 "network" : "All network code", 278 "bandwidth" : "Bandwidth detection and management", 279 "ssh" : "SSH connections", 280 "ssl" : "SSL connections", 281 "http" : "HTTP requests", 282 "rfb" : "RFB Protocol", 283 "mmap" : "mmap transfers", 284 "protocol" : "Packet input and output (formatting, parsing, sending and receiving)", 285 "websocket" : "WebSocket layer", 286 "named-pipe" : "Named pipe", 287 "crypto" : "Encryption", 288 "auth" : "Authentication", 289 "upnp" : "UPnP", 290 }, 291 "Server" : { 292 #Server: 293 "server" : "All server code", 294 "proxy" : "Proxy server", 295 "shadow" : "Shadow server", 296 "command" : "Server control channel", 297 "timeout" : "Server timeouts", 298 "exec" : "Executing commands", 299 #server features: 300 "mdns" : "mDNS session publishing", 301 #server internals: 302 "stats" : "Server statistics", 303 "xshm" : "XShm pixel capture", 304 }, 305 "Sound" : { 306 "sound" : "All sound", 307 "gstreamer" : "GStreamer internal messages", 308 "av-sync" : "Audio-video sync", 309 }, 310 "X11" : { 311 "x11" : "All X11 code", 312 "xinput" : "XInput bindings", 313 "bindings" : "X11 Cython bindings", 314 "core" : "X11 core bindings", 315 "randr" : "X11 RandR bindings", 316 "ximage" : "X11 XImage bindings", 317 "error" : "X11 errors", 318 }, 319 "Platform" : { 320 "platform" : "All platform support code", 321 "import" : "Platform support import code", 322 "osx" : "Mac OS X platform support code", 323 "win32" : "Microsoft Windows platform support code", 324 "posix" : "Posix platform code", 325 }, 326 } 327 328#flatten it: 329KNOWN_FILTERS = {} 330for d in STRUCT_KNOWN_FILTERS.values(): 331 for k,v in d.items(): 332 KNOWN_FILTERS[k] = v 333 334 335def isenvdebug(category : str) -> bool: 336 return os.environ.get("XPRA_%s_DEBUG" % category.upper().replace("-", "_").replace("+", "_"), "0")=="1" 337 338 339def get_info(): 340 return { 341 "filters" : STRUCT_KNOWN_FILTERS, 342 "categories" : { 343 "enabled" : tuple(debug_enabled_categories), 344 "disabled" : tuple(debug_disabled_categories), 345 }, 346 "handler" : getattr(global_logging_handler, "__name__", "<unknown>"), 347 "prefix" : LOG_PREFIX, 348 "format" : LOG_FORMAT, 349 "debug-modules" : DEBUG_MODULES, 350 #all_loggers 351 } 352 353 354class Logger: 355 """ 356 A wrapper around 'logging' with some convenience stuff. In particular: 357 * You initialize it with a list of categories 358 If unset, the default logging target is set to the name of the module where 359 Logger() was called. 360 * Any of the categories can enable debug logging if the environment 361 variable 'XPRA_${CATEGORY}_DEBUG' is set to "1" 362 * We also keep a list of debug_categories, so these can get enabled 363 programatically too 364 * We keep track of which loggers are associated with each category, 365 so we can enable/disable debug logging by category 366 * You can pass exc_info=True to any method, and sys.exc_info() will be 367 substituted. 368 * __call__ is an alias for debug 369 * we bypass the logging system unless debugging is enabled for the logger, 370 which is much faster than relying on the python logging code 371 """ 372 __slots__ = ("categories", "level_override", "logger", "debug_enabled", "__weakref__") 373 def __init__(self, *categories): 374 global default_level, debug_disabled_categories, KNOWN_FILTERS 375 self.categories = list(categories) 376 try: 377 caller = sys._getframe(1).f_globals["__name__"] #pylint: disable=protected-access 378 except AttributeError: 379 caller = None 380 if caller not in ("__main__", None): 381 self.categories.insert(0, caller) 382 self.level_override = 0 383 self.logger = logging.getLogger(".".join(self.categories)) 384 self.logger.setLevel(default_level) 385 disabled = False 386 enabled = False 387 if caller in DEBUG_MODULES: 388 enabled = True 389 else: 390 for cat in self.categories: 391 if cat in debug_disabled_categories: 392 disabled = True 393 if is_debug_enabled(cat): 394 enabled = True 395 if len(categories)>1: 396 #try all string permutations of those categories: 397 # "keyboard", "events" -> "keyboard+events" or "events+keyboard" 398 import itertools 399 for cats in itertools.permutations(categories): 400 cstr = "+".join(cats) 401 if cstr in debug_disabled_categories: 402 disabled = True 403 if is_debug_enabled(cstr): 404 enabled = True 405 self.debug_enabled = enabled and not disabled 406 #ready, keep track of it: 407 add_logger(self.categories, self) 408 for x in categories: 409 if x not in KNOWN_FILTERS: 410 self.warn("unknown logging category: %s", x) 411 if self.debug_enabled: 412 self.debug("debug enabled for %s / %s", caller, categories) 413 414 def get_info(self) -> dict: 415 return { 416 "categories" : self.categories, 417 "debug" : self.debug_enabled, 418 "level" : self.logger.getEffectiveLevel(), 419 } 420 421 def __repr__(self): 422 return "Logger(%s)" % ", ".join(self.categories) 423 424 def is_debug_enabled(self) -> bool: 425 return self.debug_enabled 426 427 def enable_debug(self): 428 self.debug_enabled = True 429 430 def disable_debug(self): 431 self.debug_enabled = False 432 433 def critical(self, enable=False): 434 self.level_override = logging.CRITICAL if enable else 0 435 436 def log(self, level, msg : str, *args, **kwargs): 437 if kwargs.get("exc_info") is True: 438 ei = sys.exc_info() 439 if ei!=(None, None, None): 440 kwargs["exc_info"] = ei 441 global global_logging_handler 442 if LOG_PREFIX: 443 msg = LOG_PREFIX+msg 444 global_logging_handler(self.logger.log, self.level_override or level, msg, *args, **kwargs) 445 446 def __call__(self, msg : str, *args, **kwargs): 447 if self.debug_enabled: 448 self.log(logging.DEBUG, msg, *args, **kwargs) 449 def debug(self, msg : str, *args, **kwargs): 450 if self.debug_enabled: 451 self.log(logging.DEBUG, msg, *args, **kwargs) 452 def info(self, msg : str, *args, **kwargs): 453 self.log(logging.INFO, msg, *args, **kwargs) 454 def warn(self, msg : str, *args, **kwargs): 455 self.log(logging.WARN, msg, *args, **kwargs) 456 def error(self, msg : str, *args, **kwargs): 457 self.log(logging.ERROR, msg, *args, **kwargs) 458 459 460class CaptureHandler(logging.Handler): 461 def __init__(self): 462 super().__init__(logging.DEBUG) 463 self.records = [] 464 465 def handle(self, record): 466 self.records.append(record) 467 468 def emit(self, record): 469 self.records.append(record) 470 471 def createLock(self): 472 self.lock = None 473 474class SIGPIPEStreamHandler(logging.StreamHandler): 475 def flush(self): 476 try: 477 super().flush() 478 except BrokenPipeError: 479 pass 480 481 def emit(self, record): 482 try: 483 msg = self.format(record) 484 stream = self.stream 485 # issue 35046: merged two stream.writes into one. 486 stream.write(msg + self.terminator) 487 self.flush() 488 except RecursionError: # See issue 36272 489 raise 490 except BrokenPipeError: 491 pass 492 except Exception: 493 self.handleError(record) 494