logger.py 16 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442
  1. """
  2. Emit structured, discrete events when various actions happen.
  3. """
  4. from __future__ import annotations
  5. import asyncio
  6. import copy
  7. import json
  8. import logging
  9. import typing as t
  10. import warnings
  11. from datetime import datetime, timezone
  12. from importlib.metadata import version
  13. from jsonschema import ValidationError
  14. from packaging.version import parse
  15. from traitlets import Dict, Instance, Set, default
  16. from traitlets.config import Config, LoggingConfigurable
  17. from .schema import SchemaType
  18. from .schema_registry import SchemaRegistry
  19. from .traits import Handlers
  20. from .validators import JUPYTER_EVENTS_CORE_VALIDATOR
  21. # Check if the version is greater than 3.1.0
  22. version_info = version("python-json-logger")
  23. if parse(version_info) >= parse("3.1.0"):
  24. from pythonjsonlogger.json import JsonFormatter
  25. else:
  26. from pythonjsonlogger.jsonlogger import JsonFormatter # type: ignore[attr-defined]
  27. # Increment this version when the metadata included with each event
  28. # changes.
  29. EVENTS_METADATA_VERSION = 1
  30. class SchemaNotRegistered(Warning):
  31. """A warning to raise when an event is given to the logger
  32. but its schema has not be registered with the EventLogger
  33. """
  34. class ModifierError(Exception):
  35. """An exception to raise when a modifier does not
  36. show the proper signature.
  37. """
  38. class CoreMetadataError(Exception):
  39. """An exception raised when event core metadata is not valid."""
  40. # Only show this warning on the first instance
  41. # of each event type that fails to emit.
  42. warnings.simplefilter("once", SchemaNotRegistered)
  43. class ListenerError(Exception):
  44. """An exception to raise when a listener does not
  45. show the proper signature.
  46. """
  47. class EventLogger(LoggingConfigurable):
  48. """
  49. An Event logger for emitting structured events.
  50. Event schemas must be registered with the
  51. EventLogger using the `register_schema` or
  52. `register_schema_file` methods. Every schema
  53. will be validated against Jupyter Event's metaschema.
  54. """
  55. handlers = Handlers(
  56. default_value=None,
  57. allow_none=True,
  58. help="""A list of logging.Handler instances to send events to.
  59. When set to None (the default), all events are discarded.
  60. """,
  61. ).tag(config=True)
  62. schemas = Instance(
  63. SchemaRegistry,
  64. help="""The SchemaRegistry for caching validated schemas
  65. and their jsonschema validators.
  66. """,
  67. )
  68. _modifiers = Dict({}, help="A mapping of schemas to their list of modifiers.")
  69. _modified_listeners = Dict({}, help="A mapping of schemas to the listeners of modified events.")
  70. _unmodified_listeners = Dict(
  71. {}, help="A mapping of schemas to the listeners of unmodified/raw events."
  72. )
  73. _active_listeners: set[asyncio.Task[t.Any]] = Set() # type:ignore[assignment]
  74. async def gather_listeners(self) -> list[t.Any]:
  75. """Gather all of the active listeners."""
  76. return await asyncio.gather(*self._active_listeners, return_exceptions=True)
  77. @default("schemas")
  78. def _default_schemas(self) -> SchemaRegistry:
  79. return SchemaRegistry()
  80. def __init__(self, *args: t.Any, **kwargs: t.Any) -> None:
  81. """Initialize the logger."""
  82. # We need to initialize the configurable before
  83. # adding the logging handlers.
  84. super().__init__(*args, **kwargs)
  85. # Use a unique name for the logger so that multiple instances of EventLog do not write
  86. # to each other's handlers.
  87. log_name = __name__ + "." + str(id(self))
  88. self._logger = logging.getLogger(log_name)
  89. # We don't want events to show up in the default logs
  90. self._logger.propagate = False
  91. # We will use log.info to emit
  92. self._logger.setLevel(logging.INFO)
  93. # Add each handler to the logger and format the handlers.
  94. if self.handlers:
  95. for handler in self.handlers:
  96. self.register_handler(handler)
  97. def _load_config(
  98. self,
  99. cfg: Config,
  100. section_names: list[str] | None = None, # noqa: ARG002
  101. traits: list[str] | None = None, # type:ignore[override] # noqa: ARG002
  102. ) -> None:
  103. """Load EventLogger traits from a Config object, patching the
  104. handlers trait in the Config object to avoid deepcopy errors.
  105. """
  106. my_cfg = self._find_my_config(cfg)
  107. handlers: list[logging.Handler] = my_cfg.pop("handlers", [])
  108. # Turn handlers list into a pickeable function
  109. def get_handlers() -> list[logging.Handler]:
  110. return handlers
  111. my_cfg["handlers"] = get_handlers
  112. # Build a new eventlog config object.
  113. eventlogger_cfg = Config({"EventLogger": my_cfg})
  114. super()._load_config(eventlogger_cfg, section_names=None, traits=None)
  115. def register_event_schema(self, schema: SchemaType) -> None:
  116. """Register this schema with the schema registry.
  117. Get this registered schema using the EventLogger.schema.get() method.
  118. """
  119. event_schema = self.schemas.register(schema) # type:ignore[arg-type]
  120. key = event_schema.id
  121. # It's possible that listeners and modifiers have been added for this
  122. # schema before the schema is registered.
  123. if key not in self._modifiers:
  124. self._modifiers[key] = set()
  125. if key not in self._modified_listeners:
  126. self._modified_listeners[key] = set()
  127. if key not in self._unmodified_listeners:
  128. self._unmodified_listeners[key] = set()
  129. def register_handler(self, handler: logging.Handler) -> None:
  130. """Register a new logging handler to the Event Logger.
  131. All outgoing messages will be formatted as a JSON string.
  132. """
  133. def _handle_message_field(record: t.Any, **kwargs: t.Any) -> str:
  134. """Python's logger always emits the "message" field with
  135. the value as "null" unless it's present in the schema/data.
  136. Message happens to be a common field for event logs,
  137. so special case it here and only emit it if "message"
  138. is found the in the schema's property list.
  139. """
  140. schema = self.schemas.get(record["__schema__"])
  141. if "message" not in schema.properties:
  142. del record["message"]
  143. return json.dumps(record, **kwargs)
  144. formatter = JsonFormatter(
  145. json_serializer=_handle_message_field,
  146. )
  147. handler.setFormatter(formatter)
  148. self._logger.addHandler(handler)
  149. if handler not in self.handlers:
  150. self.handlers.append(handler)
  151. def remove_handler(self, handler: logging.Handler) -> None:
  152. """Remove a logging handler from the logger and list of handlers."""
  153. self._logger.removeHandler(handler)
  154. if handler in self.handlers:
  155. self.handlers.remove(handler)
  156. def add_modifier(
  157. self,
  158. *,
  159. schema_id: str | None = None,
  160. modifier: t.Callable[[str, dict[str, t.Any]], dict[str, t.Any]],
  161. ) -> None:
  162. """Add a modifier (callable) to a registered event.
  163. Parameters
  164. ----------
  165. modifier: Callable
  166. A callable function/method that executes when the named event occurs.
  167. This method enforces a string signature for modifiers:
  168. (schema_id: str, data: dict) -> dict:
  169. """
  170. # Ensure that this is a callable function/method
  171. if not callable(modifier):
  172. msg = "`modifier` must be a callable" # type:ignore[unreachable]
  173. raise TypeError(msg)
  174. # If the schema ID and version is given, only add
  175. # this modifier to that schema
  176. if schema_id:
  177. # If the schema hasn't been added yet,
  178. # start a placeholder set.
  179. modifiers = self._modifiers.get(schema_id, set())
  180. modifiers.add(modifier)
  181. self._modifiers[schema_id] = modifiers
  182. return
  183. for id_ in self._modifiers:
  184. if schema_id is None or id_ == schema_id:
  185. self._modifiers[id_].add(modifier)
  186. def remove_modifier(
  187. self,
  188. *,
  189. schema_id: str | None = None,
  190. modifier: t.Callable[[str, dict[str, t.Any]], dict[str, t.Any]],
  191. ) -> None:
  192. """Remove a modifier from an event or all events.
  193. Parameters
  194. ----------
  195. schema_id: str
  196. If given, remove this modifier only for a specific event type.
  197. modifier: Callable[[str, dict], dict]
  198. The modifier to remove.
  199. """
  200. # If schema_id is given remove the modifier from this schema.
  201. if schema_id:
  202. self._modifiers[schema_id].discard(modifier)
  203. # If no schema_id is given, remove the modifier from all events.
  204. else:
  205. for schema_id in self.schemas.schema_ids:
  206. # Remove the modifier if it is found in the list.
  207. self._modifiers[schema_id].discard(modifier)
  208. self._modifiers[schema_id].discard(modifier)
  209. def add_listener(
  210. self,
  211. *,
  212. modified: bool = True,
  213. schema_id: str | None = None,
  214. listener: t.Callable[[EventLogger, str, dict[str, t.Any]], t.Coroutine[t.Any, t.Any, None]],
  215. ) -> None:
  216. """Add a listener (callable) to a registered event.
  217. Parameters
  218. ----------
  219. modified: bool
  220. If True (default), listens to the data after it has been mutated/modified
  221. by the list of modifiers.
  222. schema_id: str
  223. $id of the schema
  224. listener: Callable
  225. A callable function/method that executes when the named event occurs.
  226. """
  227. if not callable(listener):
  228. msg = "`listener` must be a callable" # type:ignore[unreachable]
  229. raise TypeError(msg)
  230. # If the schema ID and version is given, only add
  231. # this modifier to that schema
  232. if schema_id:
  233. if modified:
  234. # If the schema hasn't been added yet,
  235. # start a placeholder set.
  236. listeners = self._modified_listeners.get(schema_id, set())
  237. listeners.add(listener)
  238. self._modified_listeners[schema_id] = listeners
  239. return
  240. listeners = self._unmodified_listeners.get(schema_id, set())
  241. listeners.add(listener)
  242. self._unmodified_listeners[schema_id] = listeners
  243. return
  244. for id_ in self.schemas.schema_ids:
  245. if schema_id is None or id_ == schema_id:
  246. if modified:
  247. self._modified_listeners[id_].add(listener)
  248. else:
  249. self._unmodified_listeners[id_].add(listener)
  250. def remove_listener(
  251. self,
  252. *,
  253. schema_id: str | None = None,
  254. listener: t.Callable[[EventLogger, str, dict[str, t.Any]], t.Coroutine[t.Any, t.Any, None]],
  255. ) -> None:
  256. """Remove a listener from an event or all events.
  257. Parameters
  258. ----------
  259. schema_id: str
  260. If given, remove this modifier only for a specific event type.
  261. listener: Callable[[EventLogger, str, dict], dict]
  262. The modifier to remove.
  263. """
  264. # If schema_id is given remove the listener from this schema.
  265. if schema_id:
  266. self._modified_listeners[schema_id].discard(listener)
  267. self._unmodified_listeners[schema_id].discard(listener)
  268. # If no schema_id is given, remove the listener from all events.
  269. else:
  270. for schema_id in self.schemas.schema_ids:
  271. # Remove the listener if it is found in the list.
  272. self._modified_listeners[schema_id].discard(listener)
  273. self._unmodified_listeners[schema_id].discard(listener)
  274. def emit(
  275. self, *, schema_id: str, data: dict[str, t.Any], timestamp_override: datetime | None = None
  276. ) -> dict[str, t.Any] | None:
  277. """
  278. Record given event with schema has occurred.
  279. Parameters
  280. ----------
  281. schema_id: str
  282. $id of the schema
  283. data: dict
  284. The event to record
  285. timestamp_override: datetime, optional
  286. Optionally override the event timestamp. By default it is set to the current timestamp.
  287. Returns
  288. -------
  289. dict
  290. The recorded event data
  291. """
  292. # If no handlers are routing these events, there's no need to proceed.
  293. if (
  294. not self.handlers
  295. and not self._modified_listeners.get(schema_id)
  296. and not self._unmodified_listeners.get(schema_id)
  297. ):
  298. return None
  299. # If the schema hasn't been registered, raise a warning to make sure
  300. # this was intended.
  301. if schema_id not in self.schemas:
  302. warnings.warn(
  303. f"{schema_id} has not been registered yet. If "
  304. "this was not intentional, please register the schema using the "
  305. "`register_event_schema` method.",
  306. SchemaNotRegistered,
  307. stacklevel=2,
  308. )
  309. return None
  310. schema = self.schemas.get(schema_id)
  311. # Deep copy the data and modify the copy.
  312. modified_data = copy.deepcopy(data)
  313. for modifier in self._modifiers[schema.id]:
  314. modified_data = modifier(schema_id=schema_id, data=modified_data)
  315. if self._unmodified_listeners[schema.id]:
  316. # Process this event, i.e. validate and modify (in place)
  317. self.schemas.validate_event(schema_id, data)
  318. # Validate the modified data.
  319. self.schemas.validate_event(schema_id, modified_data)
  320. # Generate the empty event capsule.
  321. timestamp = (
  322. datetime.now(tz=timezone.utc) if timestamp_override is None else timestamp_override
  323. )
  324. capsule = {
  325. "__timestamp__": timestamp.isoformat() + "Z",
  326. "__schema__": schema_id,
  327. "__schema_version__": schema.version,
  328. "__metadata_version__": EVENTS_METADATA_VERSION,
  329. }
  330. try:
  331. JUPYTER_EVENTS_CORE_VALIDATOR.validate(capsule)
  332. except ValidationError as err:
  333. raise CoreMetadataError from err
  334. capsule.update(modified_data)
  335. self._logger.info(capsule)
  336. # callback for removing from finished listeners
  337. # from active listeners set.
  338. def _listener_task_done(task: asyncio.Task[t.Any]) -> None:
  339. # If an exception happens, log it to the main
  340. # applications logger
  341. err = task.exception()
  342. if err:
  343. self.log.error(err)
  344. self._active_listeners.discard(task)
  345. # Loop over listeners and execute them.
  346. for listener in self._modified_listeners[schema_id]:
  347. # Schedule this listener as a task and add
  348. # it to the list of active listeners
  349. task = asyncio.create_task(
  350. listener(
  351. logger=self,
  352. schema_id=schema_id,
  353. data=modified_data,
  354. )
  355. )
  356. self._active_listeners.add(task)
  357. # Adds the task and cleans it up later if needed.
  358. task.add_done_callback(_listener_task_done)
  359. for listener in self._unmodified_listeners[schema_id]:
  360. task = asyncio.create_task(listener(logger=self, schema_id=schema_id, data=data))
  361. self._active_listeners.add(task)
  362. # Remove task from active listeners once its finished.
  363. def _listener_task_done(task: asyncio.Task[t.Any]) -> None:
  364. # If an exception happens, log it to the main
  365. # applications logger
  366. err = task.exception()
  367. if err:
  368. self.log.error(err)
  369. self._active_listeners.discard(task)
  370. # Adds the task and cleans it up later if needed.
  371. task.add_done_callback(_listener_task_done)
  372. return capsule