log.py 11 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411
  1. # Copyright (c) Microsoft Corporation. All rights reserved.
  2. # Licensed under the MIT License. See LICENSE in the project root
  3. # for license information.
  4. import atexit
  5. import contextlib
  6. import functools
  7. import inspect
  8. import io
  9. import os
  10. import platform
  11. import sys
  12. import threading
  13. import traceback
  14. import debugpy
  15. from debugpy.common import json, timestamp, util
  16. LEVELS = ("debug", "info", "warning", "error")
  17. """Logging levels, lowest to highest importance.
  18. """
  19. log_dir = os.getenv("DEBUGPY_LOG_DIR")
  20. """If not None, debugger logs its activity to a file named debugpy.*-<pid>.log
  21. in the specified directory, where <pid> is the return value of os.getpid().
  22. """
  23. timestamp_format = "09.3f"
  24. """Format spec used for timestamps. Can be changed to dial precision up or down.
  25. """
  26. _lock = threading.RLock()
  27. _tls = threading.local()
  28. _files = {} # filename -> LogFile
  29. _levels = set() # combined for all log files
  30. def _update_levels():
  31. global _levels
  32. _levels = frozenset(level for file in _files.values() for level in file.levels)
  33. class LogFile(object):
  34. def __init__(self, filename, file, levels=LEVELS, close_file=True):
  35. info("Also logging to {0}.", json.repr(filename))
  36. self.filename = filename
  37. self.file = file
  38. self.close_file = close_file
  39. self._levels = frozenset(levels)
  40. with _lock:
  41. _files[self.filename] = self
  42. _update_levels()
  43. info(
  44. "{0} {1}\n{2} {3} ({4}-bit)\ndebugpy {5}",
  45. platform.platform(),
  46. platform.machine(),
  47. platform.python_implementation(),
  48. platform.python_version(),
  49. 64 if sys.maxsize > 2**32 else 32,
  50. debugpy.__version__,
  51. _to_files=[self],
  52. )
  53. @property
  54. def levels(self):
  55. return self._levels
  56. @levels.setter
  57. def levels(self, value):
  58. with _lock:
  59. self._levels = frozenset(LEVELS if value is all else value)
  60. _update_levels()
  61. def write(self, level, output):
  62. if level in self.levels:
  63. try:
  64. self.file.write(output)
  65. self.file.flush()
  66. except Exception: # pragma: no cover
  67. pass
  68. def close(self):
  69. with _lock:
  70. del _files[self.filename]
  71. _update_levels()
  72. info("Not logging to {0} anymore.", json.repr(self.filename))
  73. if self.close_file:
  74. try:
  75. self.file.close()
  76. except Exception: # pragma: no cover
  77. pass
  78. def __enter__(self):
  79. return self
  80. def __exit__(self, exc_type, exc_val, exc_tb):
  81. self.close()
  82. class NoLog(object):
  83. file = filename = None
  84. __bool__ = __nonzero__ = lambda self: False
  85. def close(self):
  86. pass
  87. def __enter__(self):
  88. return self
  89. def __exit__(self, exc_type, exc_val, exc_tb):
  90. pass
  91. # Used to inject a newline into stderr if logging there, to clean up the output
  92. # when it's intermixed with regular prints from other sources.
  93. def newline(level="info"):
  94. with _lock:
  95. stderr.write(level, "\n")
  96. def write(level, text, _to_files=all):
  97. assert level in LEVELS
  98. t = timestamp.current()
  99. format_string = "{0}+{1:" + timestamp_format + "}: "
  100. prefix = format_string.format(level[0].upper(), t)
  101. text = getattr(_tls, "prefix", "") + text
  102. indent = "\n" + (" " * len(prefix))
  103. output = indent.join(text.split("\n"))
  104. output = prefix + output + "\n\n"
  105. with _lock:
  106. if _to_files is all:
  107. _to_files = _files.values()
  108. for file in _to_files:
  109. file.write(level, output)
  110. return text
  111. def write_format(level, format_string, *args, **kwargs):
  112. # Don't spend cycles doing expensive formatting if we don't have to. Errors are
  113. # always formatted, so that error() can return the text even if it's not logged.
  114. if level != "error" and level not in _levels:
  115. return
  116. try:
  117. text = format_string.format(*args, **kwargs)
  118. except Exception: # pragma: no cover
  119. reraise_exception()
  120. return write(level, text, kwargs.pop("_to_files", all))
  121. debug = functools.partial(write_format, "debug")
  122. info = functools.partial(write_format, "info")
  123. warning = functools.partial(write_format, "warning")
  124. def error(*args, **kwargs):
  125. """Logs an error.
  126. Returns the output wrapped in AssertionError. Thus, the following::
  127. raise log.error(s, ...)
  128. has the same effect as::
  129. log.error(...)
  130. assert False, (s.format(...))
  131. """
  132. return AssertionError(write_format("error", *args, **kwargs))
  133. def _exception(format_string="", *args, **kwargs):
  134. level = kwargs.pop("level", "error")
  135. exc_info = kwargs.pop("exc_info", sys.exc_info())
  136. if format_string:
  137. format_string += "\n\n"
  138. format_string += "{exception}\nStack where logged:\n{stack}"
  139. exception = "".join(traceback.format_exception(*exc_info))
  140. f = inspect.currentframe()
  141. f = f.f_back if f else f # don't log this frame
  142. try:
  143. stack = "".join(traceback.format_stack(f))
  144. finally:
  145. del f # avoid cycles
  146. write_format(
  147. level, format_string, *args, exception=exception, stack=stack, **kwargs
  148. )
  149. def swallow_exception(format_string="", *args, **kwargs):
  150. """Logs an exception with full traceback.
  151. If format_string is specified, it is formatted with format(*args, **kwargs), and
  152. prepended to the exception traceback on a separate line.
  153. If exc_info is specified, the exception it describes will be logged. Otherwise,
  154. sys.exc_info() - i.e. the exception being handled currently - will be logged.
  155. If level is specified, the exception will be logged as a message of that level.
  156. The default is "error".
  157. """
  158. _exception(format_string, *args, **kwargs)
  159. def reraise_exception(format_string="", *args, **kwargs):
  160. """Like swallow_exception(), but re-raises the current exception after logging it."""
  161. assert "exc_info" not in kwargs
  162. _exception(format_string, *args, **kwargs)
  163. raise
  164. def to_file(filename=None, prefix=None, levels=LEVELS):
  165. """Starts logging all messages at the specified levels to the designated file.
  166. Either filename or prefix must be specified, but not both.
  167. If filename is specified, it designates the log file directly.
  168. If prefix is specified, the log file is automatically created in options.log_dir,
  169. with filename computed as prefix + os.getpid(). If log_dir is None, no log file
  170. is created, and the function returns immediately.
  171. If the file with the specified or computed name is already being used as a log
  172. file, it is not overwritten, but its levels are updated as specified.
  173. The function returns an object with a close() method. When the object is closed,
  174. logs are not written into that file anymore. Alternatively, the returned object
  175. can be used in a with-statement:
  176. with log.to_file("some.log"):
  177. # now also logging to some.log
  178. # not logging to some.log anymore
  179. """
  180. assert (filename is not None) ^ (prefix is not None)
  181. if filename is None:
  182. if log_dir is None:
  183. return NoLog()
  184. try:
  185. os.makedirs(log_dir)
  186. except OSError: # pragma: no cover
  187. pass
  188. filename = f"{log_dir}/{prefix}-{os.getpid()}.log"
  189. file = _files.get(filename)
  190. if file is None:
  191. file = LogFile(filename, io.open(filename, "w", encoding="utf-8"), levels)
  192. else:
  193. file.levels = levels
  194. return file
  195. @contextlib.contextmanager
  196. def prefixed(format_string, *args, **kwargs):
  197. """Adds a prefix to all messages logged from the current thread for the duration
  198. of the context manager.
  199. """
  200. prefix = format_string.format(*args, **kwargs)
  201. old_prefix = getattr(_tls, "prefix", "")
  202. _tls.prefix = prefix + old_prefix
  203. try:
  204. yield
  205. finally:
  206. _tls.prefix = old_prefix
  207. def get_environment_description(header):
  208. import sysconfig
  209. import site # noqa
  210. result = [header, "\n\n"]
  211. def report(s, *args, **kwargs):
  212. result.append(s.format(*args, **kwargs))
  213. def report_paths(get_paths, label=None):
  214. prefix = f" {label or get_paths}: "
  215. expr = None
  216. if not callable(get_paths):
  217. expr = get_paths
  218. get_paths = lambda: util.evaluate(expr)
  219. try:
  220. paths = get_paths()
  221. except AttributeError:
  222. report("{0}<missing>\n", prefix)
  223. return
  224. except Exception: # pragma: no cover
  225. swallow_exception(
  226. "Error evaluating {0}",
  227. repr(expr) if expr else util.srcnameof(get_paths),
  228. level="info",
  229. )
  230. return
  231. if not isinstance(paths, (list, tuple)):
  232. paths = [paths]
  233. for p in sorted(paths):
  234. report("{0}{1}", prefix, p)
  235. if p is not None:
  236. rp = os.path.realpath(p)
  237. if p != rp:
  238. report("({0})", rp)
  239. report("\n")
  240. prefix = " " * len(prefix)
  241. report("System paths:\n")
  242. report_paths("sys.executable")
  243. report_paths("sys.prefix")
  244. report_paths("sys.base_prefix")
  245. report_paths("sys.real_prefix")
  246. report_paths("site.getsitepackages()")
  247. report_paths("site.getusersitepackages()")
  248. site_packages = [
  249. p
  250. for p in sys.path
  251. if os.path.exists(p) and os.path.basename(p) == "site-packages"
  252. ]
  253. report_paths(lambda: site_packages, "sys.path (site-packages)")
  254. for name in sysconfig.get_path_names():
  255. expr = "sysconfig.get_path({0!r})".format(name)
  256. report_paths(expr)
  257. report_paths("os.__file__")
  258. report_paths("threading.__file__")
  259. report_paths("debugpy.__file__")
  260. report("\n")
  261. importlib_metadata = None
  262. try:
  263. import importlib_metadata
  264. except ImportError: # pragma: no cover
  265. try:
  266. from importlib import metadata as importlib_metadata
  267. except ImportError:
  268. pass
  269. if importlib_metadata is None: # pragma: no cover
  270. report("Cannot enumerate installed packages - missing importlib_metadata.")
  271. else:
  272. report("Installed packages:\n")
  273. try:
  274. for pkg in importlib_metadata.distributions():
  275. report(" {0}=={1}\n", pkg.name, pkg.version)
  276. except Exception: # pragma: no cover
  277. swallow_exception(
  278. "Error while enumerating installed packages.", level="info"
  279. )
  280. return "".join(result).rstrip("\n")
  281. def describe_environment(header):
  282. info("{0}", get_environment_description(header))
  283. stderr = LogFile(
  284. "<stderr>",
  285. sys.stderr,
  286. levels=os.getenv("DEBUGPY_LOG_STDERR", "warning error").split(),
  287. close_file=False,
  288. )
  289. @atexit.register
  290. def _close_files():
  291. for file in tuple(_files.values()):
  292. file.close()
  293. # The following are helper shortcuts for printf debugging. They must never be used
  294. # in production code.
  295. def _repr(value): # pragma: no cover
  296. warning("$REPR {0!r}", value)
  297. def _vars(*names): # pragma: no cover
  298. locals = inspect.currentframe().f_back.f_locals
  299. if names:
  300. locals = {name: locals[name] for name in names if name in locals}
  301. warning("$VARS {0!r}", locals)
  302. def _stack(): # pragma: no cover
  303. stack = "\n".join(traceback.format_stack())
  304. warning("$STACK:\n\n{0}", stack)
  305. def _threads(): # pragma: no cover
  306. output = "\n".join([str(t) for t in threading.enumerate()])
  307. warning("$THREADS:\n\n{0}", output)