Experiment with audit events in bootstrap.
[python_utils.git] / bootstrap.py
1 #!/usr/bin/env python3
2
3 import functools
4 import logging
5 import os
6 from inspect import stack
7 import sys
8
9 # This module is commonly used by others in here and should avoid
10 # taking any unnecessary dependencies back on them.
11
12 from argparse_utils import ActionNoYes
13 import config
14 import logging_utils
15
16 logger = logging.getLogger(__name__)
17
18 args = config.add_commandline_args(
19     f'Bootstrap ({__file__})',
20     'Args related to python program bootstrapper and Swiss army knife')
21 args.add_argument(
22     '--debug_unhandled_exceptions',
23     action=ActionNoYes,
24     default=False,
25     help='Break into pdb on top level unhandled exceptions.'
26 )
27 args.add_argument(
28     '--show_random_seed',
29     action=ActionNoYes,
30     default=False,
31     help='Should we display (and log.debug) the global random seed?'
32 )
33 args.add_argument(
34     '--set_random_seed',
35     type=int,
36     nargs=1,
37     default=None,
38     metavar='SEED_INT',
39     help='Override the global random seed with a particular number.'
40 )
41 args.add_argument(
42     '--dump_all_objects',
43     action=ActionNoYes,
44     default=False,
45     help='Should we dump the Python import tree before main?'
46 )
47 args.add_argument(
48     '--audit_import_events',
49     action=ActionNoYes,
50     default=False,
51     help='Should we audit all import events?',
52 )
53
54
55 original_hook = sys.excepthook
56
57
58 def handle_uncaught_exception(exc_type, exc_value, exc_tb):
59     """
60     Top-level exception handler for exceptions that make it past any exception
61     handlers in the python code being run.  Logs the error and stacktrace then
62     maybe attaches a debugger.
63     """
64     global original_hook
65     msg = f'Unhandled top level exception {exc_type}'
66     logger.exception(msg)
67     print(msg, file=sys.stderr)
68     if issubclass(exc_type, KeyboardInterrupt):
69         sys.__excepthook__(exc_type, exc_value, exc_tb)
70         return
71     else:
72         if (
73                 not sys.stderr.isatty() or
74                 not sys.stdin.isatty()
75         ):
76             # stdin or stderr is redirected, just do the normal thing
77             original_hook(exc_type, exc_value, exc_tb)
78         else:
79             # a terminal is attached and stderr is not redirected, maybe debug.
80             import traceback
81             traceback.print_exception(exc_type, exc_value, exc_tb)
82             if config.config['debug_unhandled_exceptions']:
83                 import pdb
84                 logger.info("Invoking the debugger...")
85                 pdb.pm()
86             else:
87                 original_hook(exc_type, exc_value, exc_tb)
88
89
90 class ImportInterceptor(object):
91     def __init__(self):
92         import collect.trie
93         self.module_by_filename_cache = {}
94         self.repopulate_modules_by_filename()
95         self.tree = collect.trie.Trie()
96         self.tree_node_by_module = {}
97
98     def repopulate_modules_by_filename(self):
99         self.module_by_filename_cache.clear()
100         for mod in sys.modules:
101             if hasattr(sys.modules[mod], '__file__'):
102                 fname = getattr(sys.modules[mod], '__file__')
103             else:
104                 fname = 'unknown'
105             self.module_by_filename_cache[fname] = mod
106
107     def should_ignore_filename(self, filename: str) -> bool:
108         return 'importlib' in filename or 'six.py' in filename
109
110     def find_spec(self, loaded_module, path=None, target=None):
111         s = stack()
112         for x in range(3, len(s)):
113             filename = s[x].filename
114             if self.should_ignore_filename(filename):
115                 continue
116
117             loading_function = s[x].function
118             if filename in self.module_by_filename_cache:
119                 loading_module = self.module_by_filename_cache[filename]
120             else:
121                 self.repopulate_modules_by_filename()
122                 loading_module = self.module_by_filename_cache.get(filename, 'unknown')
123
124             path = self.tree_node_by_module.get(loading_module, [])
125             path.extend([loaded_module])
126             self.tree.insert(path)
127             self.tree_node_by_module[loading_module] = path
128
129             msg = f'*** Import {loaded_module} from {filename}:{s[x].lineno} in {loading_module}::{loading_function}'
130             logger.debug(msg)
131             print(msg)
132             return
133         msg = f'*** Import {loaded_module} from ?????'
134         logger.debug(msg)
135         print(msg)
136
137     def find_importer(self, module: str):
138         if module in self.tree_node_by_module:
139             node = self.tree_node_by_module[module]
140             return node
141         return []
142
143
144 # # TODO: test this with python 3.8+
145 # def audit_import_events(event, args):
146 #     if event == 'import':
147 #         module = args[0]
148 #         filename = args[1]
149 #         sys_path = args[2]
150 #         sys_meta_path = args[3]
151 #         sys_path_hooks = args[4]
152 #         logger.debug(msg)
153 #         print(msg)
154
155
156 # Audit import events?  Note: this runs early in the lifetime of the
157 # process (assuming that import bootstrap happens early); config has
158 # (probably) not yet been loaded or parsed the commandline.  Also,
159 # some things have probably already been imported while we weren't
160 # watching so this information may be incomplete.
161 #
162 # Also note: move bootstrap up in the global import list to catch
163 # more import events and have a more complete record.
164 import_interceptor = None
165 for arg in sys.argv:
166     if arg == '--audit_import_events':
167         import_interceptor = ImportInterceptor()
168         sys.meta_path = [import_interceptor] + sys.meta_path
169         # if not hasattr(sys, 'frozen'):
170         #     if (
171         #             sys.version_info[0] == 3
172         #             and sys.version_info[1] >= 8
173         #     ):
174         #         sys.addaudithook(audit_import_events)
175
176
177 def dump_all_objects() -> None:
178     global import_interceptor
179     messages = {}
180     all_modules = sys.modules
181     for obj in object.__subclasses__():
182         if not hasattr(obj, '__name__'):
183             continue
184         klass = obj.__name__
185         if not hasattr(obj, '__module__'):
186             continue
187         class_mod_name = obj.__module__
188         if class_mod_name in all_modules:
189             mod = all_modules[class_mod_name]
190             if not hasattr(mod, '__name__'):
191                 mod_name = class_mod_name
192             else:
193                 mod_name = mod.__name__
194             if hasattr(mod, '__file__'):
195                 mod_file = mod.__file__
196             else:
197                 mod_file = 'unknown'
198             if import_interceptor is not None:
199                 import_path = import_interceptor.find_importer(mod_name)
200             else:
201                 import_path = 'unknown'
202             msg = f'{class_mod_name}::{klass} ({mod_file})'
203             if import_path != 'unknown' and len(import_path) > 0:
204                 msg += f' imported by {import_path}'
205             messages[f'{class_mod_name}::{klass}'] = msg
206     for x in sorted(messages.keys()):
207         logger.debug(messages[x])
208         print(messages[x])
209
210
211 def initialize(entry_point):
212     """
213     Remember to initialize config, initialize logging, set/log a random
214     seed, etc... before running main.
215
216     """
217     @functools.wraps(entry_point)
218     def initialize_wrapper(*args, **kwargs):
219         # Hook top level unhandled exceptions, maybe invoke debugger.
220         if sys.excepthook == sys.__excepthook__:
221             sys.excepthook = handle_uncaught_exception
222
223         # Try to figure out the name of the program entry point.  Then
224         # parse configuration (based on cmdline flags, environment vars
225         # etc...)
226         if (
227                 '__globals__' in entry_point.__dict__ and
228                 '__file__' in entry_point.__globals__
229         ):
230             config.parse(entry_point.__globals__['__file__'])
231         else:
232             config.parse(None)
233
234         # Initialize logging... and log some remembered messages from
235         # config module.
236         logging_utils.initialize_logging(logging.getLogger())
237         config.late_logging()
238
239         # Allow programs that don't bother to override the random seed
240         # to be replayed via the commandline.
241         import random
242         random_seed = config.config['set_random_seed']
243         if random_seed is not None:
244             random_seed = random_seed[0]
245         else:
246             random_seed = int.from_bytes(os.urandom(4), 'little')
247
248         if config.config['show_random_seed']:
249             msg = f'Global random seed is: {random_seed}'
250             logger.debug(msg)
251             print(msg)
252         random.seed(random_seed)
253
254         # Do it, invoke the user's code.  Pay attention to how long it takes.
255         logger.debug(f'Starting {entry_point.__name__} (program entry point)')
256         ret = None
257         import stopwatch
258         with stopwatch.Timer() as t:
259             ret = entry_point(*args, **kwargs)
260         logger.debug(
261             f'{entry_point.__name__} (program entry point) returned {ret}.'
262         )
263
264         if config.config['dump_all_objects']:
265             dump_all_objects()
266
267         if config.config['audit_import_events']:
268             global import_interceptor
269             if import_interceptor is not None:
270                 print(import_interceptor.tree)
271
272         walltime = t()
273         (utime, stime, cutime, cstime, elapsed_time) = os.times()
274         logger.debug('\n'
275                      f'user: {utime}s\n'
276                      f'system: {stime}s\n'
277                      f'child user: {cutime}s\n'
278                      f'child system: {cstime}s\n'
279                      f'machine uptime: {elapsed_time}s\n'
280                      f'walltime: {walltime}s')
281
282         # If it doesn't return cleanly, call attention to the return value.
283         if ret is not None and ret != 0:
284             logger.error(f'Exit {ret}')
285         else:
286             logger.debug(f'Exit {ret}')
287         sys.exit(ret)
288     return initialize_wrapper