55from logging import Logger
66from typing import Type , Iterable , Any , Optional
77
8- from ..api import Variables , Plugin
8+ from ..api import Variables , Plugin , ext_parse_bool
99from .core import _get_default_vars_instance , get_logger
1010
1111_VAR_ASYNC_LOOP = '=|async_loop|'
1414_NOT_INIT = object ()
1515
1616
17+ def _plugin_logger (v : Variables = None ) -> Logger :
18+ logger = get_logger (v , name = 'plugins' )
19+ if not v .environ ('SAF_DEBUG_PLUGINS' , type_fn = ext_parse_bool , default = False ):
20+ logger .setLevel ('INFO' )
21+ return logger
22+
23+
1724def _plugin_registry (v : Variables = None ) -> Variables :
1825 return v .get_or_set ('=|PR|' , value_fn = Variables )
1926
@@ -64,8 +71,12 @@ def _init_plugin(name, v: Variables = None, _requested_by=None, _now=False, asyn
6471 er = _impl_registry (v )
6572 ext_name = plugin .extension_point_name (v )
6673
74+ # setup logger and announce (debug)
75+ logger = _plugin_logger (v )
76+
6777 # note that this approach means that a plugin cannot simultaneous be single & multi!
6878 if ext_name in er : # return extension point registry result if plugin is marked as initialized
79+ logger .debug ('returning cached extension point result for plugin "%s"' , name )
6980 return er [ext_name ]
7081
7182 is_single = plugin .is_enabled (v )
@@ -74,16 +85,15 @@ def _init_plugin(name, v: Variables = None, _requested_by=None, _now=False, asyn
7485 if not (is_single or is_multi ): # abort init of this plugin if it is disabled
7586 return
7687
88+ logger .debug ('preparing to init plugin "%s" for extension point "%s", single=%s, multi=%s' , name , ext_name , is_single , is_multi )
89+
7790 # maintain expanding set of upstream extension point requests
7891 if _requested_by is None :
7992 _requested_by = {ext_name }
8093 else :
8194 _requested_by = _requested_by .copy ()
8295 _requested_by .add (ext_name )
8396
84- # setup logger and announce (debug)
85- logger = get_logger (v ) # TODO: decide logger context/name (and levels)
86-
8797 # go through dependencies and try to initialize them as needed
8898 deps = plugin .get_dependencies (v )
8999 for dep in deps :
@@ -152,7 +162,7 @@ def shutdown_all_plugins(v: Variables = None, async_enabled: Optional[bool] = No
152162
153163 pr = _plugin_registry (v )
154164 er = _impl_registry (v )
155- logger = get_logger (v )
165+ logger = _plugin_logger (v )
156166 for plugin in reversed (pr .get_or_set ('=|STARTUP_ORDER|' , value_fn = list )): # type: Plugin
157167 if plugin .initialized :
158168 name = plugin .name ()
@@ -212,8 +222,8 @@ def register_plugin(plugin_type: Type[Plugin], v: Variables = None, init=False):
212222 is_single = instance .is_enabled (v )
213223 is_multi = instance .is_multi_extension (v )
214224
215- get_logger (v ).debug ('Registering plugin: "%s" for extension point "%s", single=%s, multi=%s' ,
216- name , ext_name , is_single , is_multi )
225+ _plugin_logger (v ).debug ('Registering plugin: "%s" for extension point "%s", single=%s, multi=%s' ,
226+ name , ext_name , is_single , is_multi )
217227 pr [name ] = instance
218228
219229 # call on_registration hook (only called once, on first registration)
@@ -455,7 +465,7 @@ async def async_plugins_ready(v: Variables = None, *, capture_loop: bool = True)
455465 if capture_loop :
456466 capture_async_loop (v )
457467
458- logger = get_logger (v )
468+ logger = _plugin_logger (v )
459469 pr = _plugin_registry (v )
460470 startup_order = pr .get_or_set ('=|STARTUP_ORDER|' , value_fn = list )
461471
@@ -486,7 +496,7 @@ async def async_plugins_stopping(v: Variables = None):
486496 if v is None :
487497 v = _get_default_vars_instance ()
488498
489- logger = get_logger (v )
499+ logger = _plugin_logger (v )
490500 pr = _plugin_registry (v )
491501 startup_order = pr .get_or_set ('=|STARTUP_ORDER|' , value_fn = list )
492502
@@ -530,8 +540,8 @@ def schedule_async_shutdown(v: Variables = None, timeout: float = 5.0) -> bool:
530540 future .result (timeout = timeout )
531541 return True
532542 except asyncio .TimeoutError :
533- get_logger (v ).warning ('Async shutdown timed out after %.1f seconds' , timeout )
543+ _plugin_logger (v ).warning ('Async shutdown timed out after %.1f seconds' , timeout )
534544 return False
535545 except Exception as e :
536- get_logger (v ).debug ('Could not schedule async shutdown: %s' , e )
546+ _plugin_logger (v ).debug ('Could not schedule async shutdown: %s' , e )
537547 return False
0 commit comments