| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  | #!/usr/bin/env python | 
					
						
							|  |  |  | """Process a ref debug log
 | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2015-04-17 03:16:59 -04:00
										 |  |  |  This file will process a log file created by enabling | 
					
						
							|  |  |  |  the refdebug config option in asterisk.conf. | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  | 
 | 
					
						
							|  |  |  |  See http://www.asterisk.org for more information about | 
					
						
							|  |  |  |  the Asterisk project. Please do not directly contact | 
					
						
							|  |  |  |  any of the maintainers of this project for assistance; | 
					
						
							|  |  |  |  the project provides a web site, mailing lists and IRC | 
					
						
							|  |  |  |  channels for your use. | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |  This program is free software, distributed under the terms of | 
					
						
							|  |  |  |  the GNU General Public License Version 2. See the LICENSE file | 
					
						
							|  |  |  |  at the top of the source tree. | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |  Copyright (C) 2014, Digium, Inc. | 
					
						
							|  |  |  |  Matt Jordan <mjordan@digium.com> | 
					
						
							|  |  |  | """
 | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  | from __future__ import print_function | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  | import sys | 
					
						
							|  |  |  | import os | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  | from optparse import OptionParser | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  | def parse_line(line): | 
					
						
							|  |  |  |     """Parse out a line into its constituent parts.
 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     Keyword Arguments: | 
					
						
							|  |  |  |     line The line from a ref debug log to parse out | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     Returns: | 
					
						
							|  |  |  |     A dictionary containing the options, or None | 
					
						
							|  |  |  |     """
 | 
					
						
							|  |  |  |     tokens = line.strip().split(',', 7) | 
					
						
							|  |  |  |     if len(tokens) < 8: | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  |         print("ERROR: ref debug line '%s' contains fewer tokens than " | 
					
						
							|  |  |  |               "expected: %d" % (line.strip(), len(tokens))) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |         return None | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     processed_line = {'addr': tokens[0], | 
					
						
							|  |  |  |                       'delta': tokens[1], | 
					
						
							|  |  |  |                       'thread_id': tokens[2], | 
					
						
							|  |  |  |                       'file': tokens[3], | 
					
						
							|  |  |  |                       'line': tokens[4], | 
					
						
							|  |  |  |                       'function': tokens[5], | 
					
						
							|  |  |  |                       'state': tokens[6], | 
					
						
							|  |  |  |                       'tag': tokens[7], | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |                       } | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |     return processed_line | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  | def process_file(options): | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |     """The routine that kicks off processing a ref file
 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     Keyword Arguments: | 
					
						
							|  |  |  |     filename The full path to the file to process | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     Returns: | 
					
						
							|  |  |  |     A tuple containing: | 
					
						
							|  |  |  |         - A list of objects whose lifetimes were completed | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |             (i.e., finished objects) | 
					
						
							|  |  |  |         - A list of objects referenced after destruction | 
					
						
							|  |  |  |             (i.e., invalid objects) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |         - A list of objects whose lifetimes were not completed | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |             (i.e., leaked objects) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |         - A list of objects whose lifetimes are skewed | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |             (i.e., Object history starting with an unusual ref count) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |     """
 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     finished_objects = [] | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |     invalid_objects = [] | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |     leaked_objects = [] | 
					
						
							|  |  |  |     skewed_objects = [] | 
					
						
							|  |  |  |     current_objects = {} | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |     filename = options.filepath | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  | 
 | 
					
						
							|  |  |  |     with open(filename, 'r') as ref_file: | 
					
						
							|  |  |  |         for line in ref_file: | 
					
						
							|  |  |  |             parsed_line = parse_line(line) | 
					
						
							|  |  |  |             if not parsed_line: | 
					
						
							|  |  |  |                 continue | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |             invalid = False | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |             obj = parsed_line['addr'] | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |             if obj not in current_objects: | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |                 current_objects[obj] = {'log': [], 'curcount': 1} | 
					
						
							|  |  |  |                 if 'constructor' in parsed_line['state']: | 
					
						
							|  |  |  |                     # This is the normal expected case | 
					
						
							|  |  |  |                     pass | 
					
						
							|  |  |  |                 elif 'invalid' in parsed_line['state']: | 
					
						
							|  |  |  |                     invalid = True | 
					
						
							|  |  |  |                     current_objects[obj]['curcount'] = 0 | 
					
						
							|  |  |  |                     if options.invalid: | 
					
						
							|  |  |  |                         invalid_objects.append((obj, current_objects[obj])) | 
					
						
							|  |  |  |                 elif 'destructor' in parsed_line['state']: | 
					
						
							|  |  |  |                     current_objects[obj]['curcount'] = 0 | 
					
						
							|  |  |  |                     if options.skewed: | 
					
						
							|  |  |  |                         skewed_objects.append((obj, current_objects[obj])) | 
					
						
							|  |  |  |                 else: | 
					
						
							|  |  |  |                     current_objects[obj]['curcount'] = int( | 
					
						
							|  |  |  |                         parsed_line['state']) | 
					
						
							| 
									
										
										
										
											2014-07-13 21:57:00 +00:00
										 |  |  |                     if options.skewed: | 
					
						
							|  |  |  |                         skewed_objects.append((obj, current_objects[obj])) | 
					
						
							|  |  |  |             else: | 
					
						
							|  |  |  |                 current_objects[obj]['curcount'] += int(parsed_line['delta']) | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2018-10-10 05:37:23 -04:00
										 |  |  |             # Suppress object sizes and lock-state from output logs. | 
					
						
							|  |  |  |             if 'constructor' in parsed_line['state']: | 
					
						
							|  |  |  |                 parsed_line['state'] = '**constructor**' | 
					
						
							|  |  |  |             elif 'destructor' in parsed_line['state']: | 
					
						
							| 
									
										
										
										
											2018-10-01 00:11:44 -04:00
										 |  |  |                 parsed_line['state'] = '**destructor**' | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |             current_objects[obj]['log'].append( | 
					
						
							|  |  |  |                 "[%s] %s:%s %s: %s %s - [%s]" % ( | 
					
						
							|  |  |  |                     parsed_line['thread_id'], | 
					
						
							|  |  |  |                     parsed_line['file'], | 
					
						
							|  |  |  |                     parsed_line['line'], | 
					
						
							|  |  |  |                     parsed_line['function'], | 
					
						
							|  |  |  |                     parsed_line['delta'], | 
					
						
							|  |  |  |                     parsed_line['tag'], | 
					
						
							|  |  |  |                     parsed_line['state'])) | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |             # It is possible for curcount to go below zero if someone | 
					
						
							|  |  |  |             # unrefs an object by two or more when there aren't that | 
					
						
							|  |  |  |             # many refs remaining.  This condition abnormally finishes | 
					
						
							|  |  |  |             # the object. | 
					
						
							|  |  |  |             if current_objects[obj]['curcount'] <= 0: | 
					
						
							|  |  |  |                 if current_objects[obj]['curcount'] < 0: | 
					
						
							|  |  |  |                     current_objects[obj]['log'].append( | 
					
						
							|  |  |  |                         "[%s] %s:%s %s: %s %s - [%s]" % ( | 
					
						
							|  |  |  |                             parsed_line['thread_id'], | 
					
						
							|  |  |  |                             parsed_line['file'], | 
					
						
							|  |  |  |                             parsed_line['line'], | 
					
						
							|  |  |  |                             parsed_line['function'], | 
					
						
							|  |  |  |                             "+0", | 
					
						
							|  |  |  |                             "Object abnormally finalized", | 
					
						
							|  |  |  |                             "**implied destructor**")) | 
					
						
							|  |  |  |                     # Highlight the abnormally finished object in the | 
					
						
							|  |  |  |                     # invalid section as well as reporting it in the normal | 
					
						
							|  |  |  |                     # finished section. | 
					
						
							|  |  |  |                     if options.invalid: | 
					
						
							|  |  |  |                         invalid_objects.append((obj, current_objects[obj])) | 
					
						
							|  |  |  |                 if not invalid and options.normal: | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |                     finished_objects.append((obj, current_objects[obj])) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |                 del current_objects[obj] | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |     if options.leaks: | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  |         for (key, lines) in current_objects.items(): | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |             leaked_objects.append((key, lines)) | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |     return (finished_objects, invalid_objects, leaked_objects, skewed_objects) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  | 
 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  | def print_objects(objects, prefix=""): | 
					
						
							|  |  |  |     """Prints out the objects that were processed
 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     Keyword Arguments: | 
					
						
							|  |  |  |     objects A list of objects to print | 
					
						
							|  |  |  |     prefix  A prefix to print that specifies something about | 
					
						
							|  |  |  |             this object | 
					
						
							|  |  |  |     """
 | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  |     print("======== %s Objects ========" % prefix) | 
					
						
							|  |  |  |     print("\n") | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |     for obj in objects: | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  |         print("==== %s Object %s history ====" % (prefix, obj[0])) | 
					
						
							| 
									
										
										
										
											2014-07-13 21:57:00 +00:00
										 |  |  |         for line in obj[1]['log']: | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  |             print(line) | 
					
						
							|  |  |  |         print("\n") | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  | 
 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  | def main(argv=None): | 
					
						
							|  |  |  |     """Main entry point for the script""" | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     ret_code = 0 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     if argv is None: | 
					
						
							|  |  |  |         argv = sys.argv | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     parser = OptionParser() | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     parser.add_option("-f", "--file", action="store", type="string", | 
					
						
							|  |  |  |                       dest="filepath", default="/var/log/asterisk/refs", | 
					
						
							|  |  |  |                       help="The full path to the refs file to process") | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |     parser.add_option("-i", "--suppress-invalid", action="store_false", | 
					
						
							|  |  |  |                       dest="invalid", default=True, | 
					
						
							|  |  |  |                       help="If specified, don't output invalid object " | 
					
						
							|  |  |  |                            "references") | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |     parser.add_option("-l", "--suppress-leaks", action="store_false", | 
					
						
							|  |  |  |                       dest="leaks", default=True, | 
					
						
							|  |  |  |                       help="If specified, don't output leaked objects") | 
					
						
							|  |  |  |     parser.add_option("-n", "--suppress-normal", action="store_false", | 
					
						
							|  |  |  |                       dest="normal", default=True, | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |                       help="If specified, don't output objects with a " | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |                            "complete lifetime") | 
					
						
							|  |  |  |     parser.add_option("-s", "--suppress-skewed", action="store_false", | 
					
						
							|  |  |  |                       dest="skewed", default=True, | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |                       help="If specified, don't output objects with a " | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |                            "skewed lifetime") | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     (options, args) = parser.parse_args(argv) | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |     if not options.invalid and not options.leaks and not options.normal \ | 
					
						
							|  |  |  |             and not options.skewed: | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  |         print("All options disabled", file=sys.stderr) | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |         return -1 | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |     if not os.path.isfile(options.filepath): | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  |         print("File not found: %s" % options.filepath, file=sys.stderr) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |         return -1 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     try: | 
					
						
							|  |  |  |         (finished_objects, | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |          invalid_objects, | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |          leaked_objects, | 
					
						
							| 
									
										
										
										
											2014-06-27 19:18:32 +00:00
										 |  |  |          skewed_objects) = process_file(options) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-09-18 16:56:40 +00:00
										 |  |  |         if options.invalid and len(invalid_objects): | 
					
						
							|  |  |  |             print_objects(invalid_objects, "Invalid Referenced") | 
					
						
							|  |  |  |             ret_code |= 4 | 
					
						
							|  |  |  | 
 | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |         if options.leaks and len(leaked_objects): | 
					
						
							|  |  |  |             print_objects(leaked_objects, "Leaked") | 
					
						
							|  |  |  |             ret_code |= 1 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |         if options.skewed and len(skewed_objects): | 
					
						
							|  |  |  |             print_objects(skewed_objects, "Skewed") | 
					
						
							|  |  |  |             ret_code |= 2 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |         if options.normal: | 
					
						
							|  |  |  |             print_objects(finished_objects, "Finalized") | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     except (KeyboardInterrupt, SystemExit, IOError): | 
					
						
							| 
									
										
										
										
											2018-03-23 07:49:59 -04:00
										 |  |  |         print("File processing cancelled", file=sys.stderr) | 
					
						
							| 
									
										
										
										
											2014-04-11 02:59:19 +00:00
										 |  |  |         return -1 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  |     return ret_code | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  | 
 | 
					
						
							|  |  |  | if __name__ == "__main__": | 
					
						
							|  |  |  |     sys.exit(main(sys.argv)) |