1. 1. How I Built a Power Debugger Out of the Standard Library and Things I Found on the Internet Doug Hellmann PyOhio 2015
2. 2. I Built a Power Debugger Doug Hellmann PyOhio 2015
3. 3. How I Built a Power Debugger Doug Hellmann PyOhio 2015
4. 4. github.com/dhellmann/smiley smiley.readthedocs.org
5. 5. Features Record calls with data Remote monitoring, local analysis Browse history New tools flickr/Kangrex
6. 6. class Publisher(object): def __init__(self, endpoint, high_water_mark=10000): self.context = zmq.Context() self.pub_socket =self.context.socket(zmq.PUSH) self.pub_socket.bind(endpoint) self.pub_socket.identity = 'publisher' self.pub_socket.hwm = high_water_mark def send(self, msg_type, data): msg = [ msg_type, json.dumps(data, default=self._json_special_types), ] self.pub_socket.send_multipart(msg)
7. 7. class Tracer(object): def __init__(self, publisher): self.publisher = publisher self.run_id = None
8. 8. def trace_calls(self, frame, event, arg): co = frame.f_code filename = co.co_filename if filename in (__file__,): # Ignore ourself return self._send_notice(frame, event, arg) return self.trace_calls
9. 9. def _send_notice(self, frame, event, arg): co = frame.f_code func_name = co.co_name line_no = frame.f_lineno filename = os.path.abspath(co.co_filename) for d in IGNORE_DIRS: if filename.startswith(d): return #
10. 10. # interesting_locals = { n: v for n, v in frame.f_locals.items() if (not inspect.ismodule(v) and not inspect.isfunction(v) and not inspect.ismethod(v) and (n[:2] != '__' and n[-2:] != '__')) } #
11. 11. # self.publisher.send( event, {'func_name': func_name, 'line_no': line_no, 'filename': filename, 'arg': arg, 'locals': interesting_locals, 'timestamp': time.time(), 'run_id': self.run_id, })
12. 12. $ smiley help usage: smiley [--version] [-v] [--log-file LOG_FILE] [-q] [-h] [--debug] smiley spies on your apps as they run optional arguments: --version show program's version number and exit -v, --verbose Increase verbosity of output. --log-file LOG_FILE Specify a file to log output. -q, --quiet suppress output except warnings -h, --help show this help message and exit --debug show tracebacks on errors Commands: complete print bash completion command help print detailed help for another command monitor Listen for running programs and show their progress. run Run another program with monitoring enabled.
13. 13. $ smiley help run usage: smiley run [-h] [--socket SOCKET] command [command ...] Run another program with monitoring enabled. positional arguments: command the command to spy on optional arguments: -h, --help show this help message and exit --socket SOCKET URL for the socket where the listener will be (tcp://127.0.0.1:5556)
14. 14. $ smiley help monitor usage: smiley monitor [-h] [--socket SOCKET] Listen for running programs and show their progress. optional arguments: -h, --help show this help message and exit --socket SOCKET URL for the socket where to monitor on (tcp://127.0.0.1:5556)
15. 15. def _process_message(self, msg): print 'MESSAGE:', msg msg_type, msg_payload = msg if msg_type == 'start_run': print (Starting new run:', msg_payload.get(command_line')) elif msg_type == 'end_run': print 'Finished run' else: line = linecache.getline(msg_payload['filename'], msg_payload['line_no']).rstrip() if msg_type == 'return': print '%s:%4s: return>>> %s' % ( msg_payload['filename'], msg_payload[line_no'], msg_payload['arg']) else: print '%s:%4s: %s' % ( msg_payload['filename'], msg_payload[line_no'], line) if msg_payload.get('locals'): for n, v in sorted(msg_payload['locals'].items()): print '%s %s = %s' % ( ' ' * len(msg_payload['filename']), n, v, ) print
16. 16. def gen(m): for i in xrange(m): yield i def c(input): print 'input =', input data = list(gen(input)) print 'Leaving c()' def b(arg): val = arg * 5 c(val) print 'Leaving b()' return val def a(): print 'args:', sys.argv b(2) print 'Leaving a()' a()
17. 17. u'command_line': [u'simple.py']}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 8: def c(input): command_line = [u'simple.py'] self = MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144169, u'line_no': 14, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'', u'arg': None, u'locals': {u'self': u'', u'command_line': [u'simple.py']}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 14: def b(arg): command_line = [u'simple.py'] self = MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144468, u'line_no': 21, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'', u'arg': None, u'locals': {u'self': u'', u'command_line': [u'simple.py']}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 21: def a(): command_line = [u'simple.py'] self = MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144719, u'line_no': 26, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'', u'arg': None, u'locals': {u'self': u'', u'command_line': [u'simple.py']}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 26: a() command_line = [u'simple.py'] self = MESSAGE: ['call', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144927, u'line_no': 21, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'a', u'arg': None, u'locals': {}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 21: def a(): MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp':
18. 18. u'command_line': [u'simple.py']}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 8: def c(input): command_line = [u'simple.py'] self = MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144169, u'line_no': 14, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'', u'arg': None, u'locals': {u'self': u'', u'command_line': [u'simple.py']}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 14: def b(arg): command_line = [u'simple.py'] self = MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144468, u'line_no': 21, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'', u'arg': None, u'locals': {u'self': u'', u'command_line': [u'simple.py']}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 21: def a(): command_line = [u'simple.py'] self = MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144719, u'line_no': 26, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'', u'arg': None, u'locals': {u'self': u'', u'command_line': [u'simple.py']}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 26: a() command_line = [u'simple.py'] self = MESSAGE: ['call', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144927, u'line_no': 21, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'a', u'arg': None, u'locals': {}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 21: def a(): MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp':
19. 19. MESSAGE: ['call', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144927, u'line_no': 21, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'a', u'arg': None, u'locals': {}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 21: def a(): MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.145128, u'line_no': 22, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'a', u'arg': None, u'locals': {}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 22: print 'args:', sys.argv MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.145343, u'line_no': 23, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'a', u'arg': None, u'locals': {}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 23: b(2)
20. 20. class DB(object): def __init__(self, name): self.conn = sqlite3.connect(name) self.conn.row_factory = sqlite3.Row try: cursor = self.conn.cursor() cursor.execute('select * from run') LOG.debug('database already initialized') except sqlite3.OperationalError: LOG.debug('initializing database') schema = pkgutil.get_data('smiley', 'schema.sql') cursor.executescript(schema)
21. 21. create table run ( id text primary key not null, cwd text, description text, start_time int, end_time int, error_message text, traceback text ); create table trace ( id integer primary key autoincrement not null, run_id text not null references run(id), filename text, line_no int, func_name text, trace_arg text, locals text, time_stamp int );
22. 22. def start_run(self, run_id, cwd, description, start_time): "Record the beginning of a run." with transaction(self.conn) as c: c.execute( """ INSERT INTO run (id, cwd, description, start_time) VALUES (:id, :cwd, :description, :start_time) """, {'id': run_id, 'cwd': cwd, 'description': description, 'start_time': start_time} )
23. 23. def _process_message(self, msg): msg_type, msg_payload = msg if msg_type == 'start_run': command_line = ' .join( msg_payload.get('command_line', [])) self._cwd = msg_payload.get('cwd', '') if self._cwd: self._cwd = (self._cwd.rstrip(os.sep) + os.sep) self.db.start_run( run_id=msg_payload.get('run_id'), cwd=self._cwd, description=command_line, start_time=msg_payload.get('timestamp'), )
24. 24. elif msg_type == 'end_run': self.log.info('Finished run') self.db.end_run( run_id=msg_payload['run_id'], end_time=msg_payload.get('timestamp'), message=msg_payload.get('message'), traceback=msg_payload.get('traceback'), ) else: self.db.trace( run_id=msg_payload['run_id'], event=msg_type, func_name=msg_payload.get('func_name'), line_no=msg_payload.get('line_no'), filename=msg_payload.get('filename'), trace_arg=msg_payload.get('arg'), locals=msg_payload.get('locals'), timestamp=msg_payload.get('timestamp'), )
25. 25. Replay past runs Complex data types flickr/Chris Marquardt
26. 26. import json import traceback import types def _json_special_types(obj): if isinstance(obj, types.TracebackType): return traceback.extract_tb(obj) if isinstance(obj, type): # We don't want to return classes return repr(obj) try: data = dict(vars(obj)) data['__class__'] = obj.__class__.__name__ data['__module__'] = obj.__class__.__module__ except Exception as err: data = repr(obj) return data def dumps(data): return json.dumps(data, default=_json_special_types)
27. 27. ?
28. 28. class EventProcessor(object): __metaclass__ = abc.ABCMeta @abc.abstractmethod def start_run(self, run_id, cwd, description, start_time): """Called when a 'start_run' event is seen. """ @abc.abstractmethod def end_run(self, run_id, end_time, message, traceback): """Called when an 'end_run' event is seen. """ @abc.abstractmethod def trace(self, run_id, event, func_name, line_no, filename, trace_arg, local_vars, timestamp): """Called when any other event type is seen. """
29. 29. def get_runs(self): "Return the runs available to browse." with transaction(self.conn) as c: c.execute( """ SELECT id, cwd, description, start_time, end_time, error_message FROM run """ ) return c.fetchall()
30. 30. def take_action(self, parsed_args): self.out = output.OutputFormatter( linecache.getline) self.db = db.DB(parsed_args.database) run_details = self.db.get_run(parsed_args.run_id) self.out.start_run( run_details.id, run_details.cwd, run_details.description, run_details.start_time, ) for t in self.db.get_trace(parsed_args.run_id): self.out.trace( t.run_id, t.event, t.func_name, t.line_no, t.filename, t.trace_arg, t.local_vars, t.timestamp, ) self.out.end_run( run_details.id, run_details.end_time, run_details.error_message, None) # run_details.traceback
31. 31. MESSAGE: ['call', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.144927, u'line_no': 21, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'a', u'arg': None, u'locals': {}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 21: def a(): MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.145128, u'line_no': 22, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'a', u'arg': None, u'locals': {}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 22: print 'args:', sys.argv MESSAGE: ['line', {u'run_id': u'e87302b2-402a-4243-bb27-69a467d4bd8e', u'timestamp': 1436367235.145343, u'line_no': 23, u'filename': u'/Users/dhellmann/Devel/smiley/scratch/simple.py', u'func_name': u'a', u'arg': None, u'locals': {}}] /Users/dhellmann/Devel/smiley/scratch/simple.py: 23: b(2)