OLD | NEW |
1 #!/usr/bin/env python | 1 #!/usr/bin/env python |
2 # coding=utf-8 | 2 # coding=utf-8 |
3 # Copyright (c) 2012 The Chromium Authors. All rights reserved. | 3 # Copyright (c) 2012 The Chromium Authors. All rights reserved. |
4 # Use of this source code is governed by a BSD-style license that can be | 4 # Use of this source code is governed by a BSD-style license that can be |
5 # found in the LICENSE file. | 5 # found in the LICENSE file. |
6 | 6 |
7 """Traces an executable and its child processes and extract the files accessed | 7 """Traces an executable and its child processes and extract the files accessed |
8 by them. | 8 by them. |
9 | 9 |
10 The implementation uses OS-specific API. The native Kernel logger and the ETL | 10 The implementation uses OS-specific API. The native Kernel logger and the ETL |
(...skipping 365 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
376 RE_SIGNAL = re.compile(r'^--- SIG[A-Z]+ .+ ---') | 376 RE_SIGNAL = re.compile(r'^--- SIG[A-Z]+ .+ ---') |
377 # A process didn't handle a signal. | 377 # A process didn't handle a signal. |
378 RE_KILLED = re.compile(r'^\+\+\+ killed by ([A-Z]+) \+\+\+$') | 378 RE_KILLED = re.compile(r'^\+\+\+ killed by ([A-Z]+) \+\+\+$') |
379 # A call was canceled. | 379 # A call was canceled. |
380 RE_UNAVAILABLE = re.compile(r'\)\s+= \? <unavailable>$') | 380 RE_UNAVAILABLE = re.compile(r'\)\s+= \? <unavailable>$') |
381 # Happens when strace fails to even get the function name. | 381 # Happens when strace fails to even get the function name. |
382 UNNAMED_FUNCTION = '????' | 382 UNNAMED_FUNCTION = '????' |
383 | 383 |
384 # Arguments parsing. | 384 # Arguments parsing. |
385 RE_CHDIR = re.compile(r'^\"(.+?)\"$') | 385 RE_CHDIR = re.compile(r'^\"(.+?)\"$') |
386 RE_EXECVE = re.compile(r'^\"(.+?)\", \[.+?\], \[.+?\]$') | 386 RE_EXECVE = re.compile(r'^\"(.+?)\", \[(.+)\], \[\/\* \d\d vars \*\/\]$') |
387 RE_OPEN2 = re.compile(r'^\"(.*?)\", ([A-Z\_\|]+)$') | 387 RE_OPEN2 = re.compile(r'^\"(.*?)\", ([A-Z\_\|]+)$') |
388 RE_OPEN3 = re.compile(r'^\"(.*?)\", ([A-Z\_\|]+), (\d+)$') | 388 RE_OPEN3 = re.compile(r'^\"(.*?)\", ([A-Z\_\|]+), (\d+)$') |
389 RE_RENAME = re.compile(r'^\"(.+?)\", \"(.+?)\"$') | 389 RE_RENAME = re.compile(r'^\"(.+?)\", \"(.+?)\"$') |
390 | 390 |
391 class RelativePath(object): | 391 class RelativePath(object): |
392 """A late-bound relative path.""" | 392 """A late-bound relative path.""" |
393 def __init__(self, parent, value): | 393 def __init__(self, parent, value): |
394 self.parent = parent | 394 self.parent = parent |
395 self.value = value | 395 self.value = value |
396 | 396 |
(...skipping 99 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
496 """Transfers cwd.""" | 496 """Transfers cwd.""" |
497 if result == '? ERESTARTNOINTR (To be restarted)': | 497 if result == '? ERESTARTNOINTR (To be restarted)': |
498 return | 498 return |
499 # Update the other process right away. | 499 # Update the other process right away. |
500 childpid = int(result) | 500 childpid = int(result) |
501 child = self.root().get_or_set_proc(childpid) | 501 child = self.root().get_or_set_proc(childpid) |
502 # Copy the cwd object. | 502 # Copy the cwd object. |
503 child.initial_cwd = self.get_cwd() | 503 child.initial_cwd = self.get_cwd() |
504 assert child.parentid is None | 504 assert child.parentid is None |
505 child.parentid = self.pid | 505 child.parentid = self.pid |
| 506 # It is necessary because the logs are processed out of order. |
| 507 assert childpid not in self.children |
506 self.children.append(childpid) | 508 self.children.append(childpid) |
507 | 509 |
508 def handle_close(self, _function, _args, _result): | 510 def handle_close(self, _function, _args, _result): |
509 pass | 511 pass |
510 | 512 |
511 def handle_execve(self, _function, args, result): | 513 def handle_execve(self, _function, args, result): |
512 self._handle_file(self.RE_EXECVE.match(args).group(1), result) | 514 if result != '0': |
| 515 return |
| 516 m = self.RE_EXECVE.match(args) |
| 517 self._handle_file(m.group(1), result) |
513 | 518 |
514 def handle_exit_group(self, _function, _args, _result): | 519 def handle_exit_group(self, _function, _args, _result): |
515 """Removes cwd.""" | 520 """Removes cwd.""" |
516 self.cwd = None | 521 self.cwd = None |
517 | 522 |
518 @staticmethod | 523 @staticmethod |
519 def handle_fork(_function, args, result): | 524 def handle_fork(_function, args, result): |
520 assert False, (args, result) | 525 assert False, (args, result) |
521 | 526 |
522 def handle_open(self, _function, args, result): | 527 def handle_open(self, _function, args, result): |
(...skipping 235 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
758 syscall::truncate:return, | 763 syscall::truncate:return, |
759 syscall::unlink:return, | 764 syscall::unlink:return, |
760 syscall::utimes:return, | 765 syscall::utimes:return, |
761 */ | 766 */ |
762 """ | 767 """ |
763 | 768 |
764 @classmethod | 769 @classmethod |
765 def code(cls, pid, cwd): | 770 def code(cls, pid, cwd): |
766 """Setups the D code to implement child process tracking. | 771 """Setups the D code to implement child process tracking. |
767 | 772 |
768 Injects a fake chdir() trace to simplify parsing. The reason is that the | 773 Injects the pid and the initial cwd into the trace header for context. |
769 child process is already running at that point so: | 774 The reason is that the child process is already running at that point so: |
770 - no proc_start() is logged for it. | 775 - no proc_start() is logged for it. |
771 - there is no way to figure out the absolute path of cwd in kernel on OSX | 776 - there is no way to figure out the absolute path of cwd in kernel on OSX |
772 | 777 |
773 Since the child process is already started, initialize current_processes to | 778 Since the child process is already started, initialize current_processes to |
774 1. | 779 1. |
775 """ | 780 """ |
776 pid = str(pid) | 781 pid = str(pid) |
777 cwd = os.path.realpath(cwd).replace('\\', '\\\\').replace('%', '%%') | 782 cwd = os.path.realpath(cwd).replace('\\', '\\\\').replace('%', '%%') |
778 return ( | 783 return ( |
779 'dtrace:::BEGIN {\n' | 784 'dtrace:::BEGIN {\n' |
780 ' current_processes = 1;\n' | 785 ' current_processes = 1;\n' |
781 ' logindex = 0;\n' | 786 ' logindex = 0;\n' |
782 ' trackedpid[') + pid + ('] = 1;\n' | 787 ' trackedpid[' + pid + '] = 1;\n' |
783 ' printf("%d %d:%d chdir(\\"' + cwd + '\\") = 0\\n",\n' | 788 ' printf("%d %d:%d %s_%s(\\"' + cwd + '\\") = 0\\n",\n' |
784 ' logindex, 1, ' + pid + ');\n' | 789 ' logindex, ppid, ' + pid + ', probeprov, probename);\n' |
785 ' logindex++;\n' | |
786 ' printf("%d %d:%d %s_%s() = 0\\n",\n' | |
787 ' logindex, ppid, pid, probeprov, probename);\n' | |
788 ' logindex++;\n' | 790 ' logindex++;\n' |
789 '}\n') + cls.D_CODE | 791 '}\n') + cls.D_CODE |
790 | 792 |
791 class Context(ApiBase.Context): | 793 class Context(ApiBase.Context): |
792 # This is the most common format. index pid function(args) = result | 794 # This is the most common format. index pid function(args) = result |
793 RE_HEADER = re.compile(r'^\d+ (\d+):(\d+) ([a-zA-Z_\-]+)\((.*?)\) = (.+)$') | 795 RE_HEADER = re.compile(r'^\d+ (\d+):(\d+) ([a-zA-Z_\-]+)\((.*?)\) = (.+)$') |
794 | 796 |
795 # Arguments parsing. | 797 # Arguments parsing. |
| 798 RE_DTRACE_BEGIN = re.compile(r'^\"(.+?)\"$') |
796 RE_CHDIR = re.compile(r'^\"(.+?)\"$') | 799 RE_CHDIR = re.compile(r'^\"(.+?)\"$') |
797 RE_OPEN = re.compile(r'^\"(.+?)\", (\d+), (-?\d+)$') | 800 RE_OPEN = re.compile(r'^\"(.+?)\", (\d+), (-?\d+)$') |
798 RE_RENAME = re.compile(r'^\"(.+?)\", \"(.+?)\"$') | 801 RE_RENAME = re.compile(r'^\"(.+?)\", \"(.+?)\"$') |
799 | 802 |
800 O_DIRECTORY = 0x100000 | 803 O_DIRECTORY = 0x100000 |
801 | 804 |
802 class Process(ApiBase.Context.Process): | 805 class Process(ApiBase.Context.Process): |
803 pass | 806 pass |
804 | 807 |
| 808 def __init__(self, blacklist): |
| 809 super(Dtrace.Context, self).__init__(blacklist) |
| 810 # Process ID of the trace_child_process.py wrapper script instance. |
| 811 self._tracer_pid = None |
| 812 # First process to be started by self._tracer_pid. |
| 813 self._initial_pid = None |
| 814 self._initial_cwd = None |
| 815 |
805 def on_line(self, line): | 816 def on_line(self, line): |
806 match = self.RE_HEADER.match(line) | 817 match = self.RE_HEADER.match(line) |
807 assert match, line | 818 assert match, line |
808 fn = getattr( | 819 fn = getattr( |
809 self, | 820 self, |
810 'handle_%s' % match.group(3).replace('-', '_'), | 821 'handle_%s' % match.group(3).replace('-', '_'), |
811 self._handle_ignored) | 822 self._handle_ignored) |
812 return fn( | 823 return fn( |
813 int(match.group(1)), | 824 int(match.group(1)), |
814 int(match.group(2)), | 825 int(match.group(2)), |
815 match.group(3), | 826 match.group(3), |
816 match.group(4), | 827 match.group(4), |
817 match.group(5)) | 828 match.group(5)) |
818 | 829 |
819 def handle_dtrace_BEGIN(self, _ppid, _pid, _function, args, _result): | 830 def handle_dtrace_BEGIN(self, _ppid, pid, _function, args, _result): |
820 pass | 831 assert not self._tracer_pid and not self._initial_pid |
| 832 self._tracer_pid = pid |
| 833 self._initial_cwd = self.RE_DTRACE_BEGIN.match(args).group(1) |
821 | 834 |
822 def handle_proc_start(self, ppid, pid, _function, _args, result): | 835 def handle_proc_start(self, ppid, pid, _function, _args, result): |
823 """Transfers cwd.""" | 836 """Transfers cwd. |
| 837 |
| 838 The dtrace script already takes care of only tracing the processes that |
| 839 are child of the traced processes so there is no need to verify the |
| 840 process hierarchy. |
| 841 """ |
824 assert result == '0' | 842 assert result == '0' |
825 cwd = self.processes[ppid].cwd | |
826 assert pid not in self.processes | 843 assert pid not in self.processes |
| 844 assert (ppid == self._tracer_pid) != bool(self._initial_pid) |
| 845 if not self._initial_pid: |
| 846 self._initial_pid = pid |
| 847 ppid = None |
| 848 cwd = self._initial_cwd |
| 849 else: |
| 850 parent = self.processes[ppid] |
| 851 cwd = parent.cwd |
827 proc = self.processes[pid] = self.Process(self, pid, cwd, ppid) | 852 proc = self.processes[pid] = self.Process(self, pid, cwd, ppid) |
828 proc.cwd = cwd | 853 proc.cwd = cwd |
| 854 logging.debug('New child: %s -> %d' % (ppid, pid)) |
829 | 855 |
830 def handle_proc_exit(self, _ppid, pid, _function, _args, _result): | 856 def handle_proc_exit(self, _ppid, pid, _function, _args, _result): |
831 """Removes cwd.""" | 857 """Removes cwd.""" |
832 self.processes[pid].cwd = None | 858 if pid != self._tracer_pid: |
| 859 # self._tracer_pid is not traced itself. |
| 860 self.processes[pid].cwd = None |
833 | 861 |
834 def handle_chdir(self, ppid, pid, _function, args, result): | 862 def handle_chdir(self, _ppid, pid, _function, args, result): |
835 """Updates cwd.""" | 863 """Updates cwd.""" |
| 864 assert self._tracer_pid |
| 865 assert pid in self.processes |
836 if result.startswith('0'): | 866 if result.startswith('0'): |
837 cwd = self.RE_CHDIR.match(args).group(1) | 867 cwd = self.RE_CHDIR.match(args).group(1) |
838 if not cwd.startswith('/'): | 868 if not cwd.startswith('/'): |
839 cwd2 = os.path.join(self.processes[pid].cwd, cwd) | 869 cwd2 = os.path.join(self.processes[pid].cwd, cwd) |
840 logging.debug('handle_chdir(%d, %s) -> %s' % (pid, cwd, cwd2)) | 870 logging.debug('handle_chdir(%d, %s) -> %s' % (pid, cwd, cwd2)) |
841 else: | 871 else: |
842 logging.debug('handle_chdir(%d, %s)' % (pid, cwd)) | 872 logging.debug('handle_chdir(%d, %s)' % (pid, cwd)) |
843 cwd2 = cwd | 873 cwd2 = cwd |
844 proc = self.processes.setdefault( | 874 self.processes[pid].cwd = cwd2 |
845 pid, self.Process(self, pid, cwd2, ppid)) | |
846 proc.cwd = cwd2 | |
847 else: | 875 else: |
848 assert False, 'Unexecpected fail: %s' % result | 876 assert False, 'Unexecpected fail: %s' % result |
849 | 877 |
850 def handle_open_nocancel(self, ppid, pid, function, args, result): | 878 def handle_open_nocancel(self, ppid, pid, function, args, result): |
851 return self.handle_open(ppid, pid, function, args, result) | 879 return self.handle_open(ppid, pid, function, args, result) |
852 | 880 |
853 def handle_open(self, _ppid, pid, function, args, result): | 881 def handle_open(self, _ppid, pid, function, args, result): |
854 match = self.RE_OPEN.match(args) | 882 match = self.RE_OPEN.match(args) |
855 assert match, (pid, function, args, result) | 883 assert match, (pid, function, args, result) |
856 args = match.groups() | 884 args = match.groups() |
(...skipping 132 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
989 with open(logname, 'rb') as logfile: | 1017 with open(logname, 'rb') as logfile: |
990 lines = [f for f in logfile.readlines() if f.strip()] | 1018 lines = [f for f in logfile.readlines() if f.strip()] |
991 lines = sorted(lines, key=lambda l: int(l.split(' ', 1)[0])) | 1019 lines = sorted(lines, key=lambda l: int(l.split(' ', 1)[0])) |
992 with open(logname, 'wb') as logfile: | 1020 with open(logname, 'wb') as logfile: |
993 logfile.write(''.join(lines)) | 1021 logfile.write(''.join(lines)) |
994 | 1022 |
995 | 1023 |
996 class LogmanTrace(ApiBase): | 1024 class LogmanTrace(ApiBase): |
997 """Uses the native Windows ETW based tracing functionality to trace a child | 1025 """Uses the native Windows ETW based tracing functionality to trace a child |
998 process. | 1026 process. |
| 1027 |
| 1028 Caveat: this implementations doesn't track cwd or initial_cwd. |
999 """ | 1029 """ |
1000 class Context(ApiBase.Context): | 1030 class Context(ApiBase.Context): |
1001 """Processes a ETW log line and keeps the list of existent and non | 1031 """Processes a ETW log line and keeps the list of existent and non |
1002 existent files accessed. | 1032 existent files accessed. |
1003 | 1033 |
1004 Ignores directories. | 1034 Ignores directories. |
1005 """ | 1035 """ |
1006 # Only the useful headers common to all entries are listed there. Any column | 1036 # Only the useful headers common to all entries are listed there. Any column |
1007 # at 19 or higher is dependent on the specific event. | 1037 # at 19 or higher is dependent on the specific event. |
1008 EVENT_NAME = 0 | 1038 EVENT_NAME = 0 |
1009 TYPE = 1 | 1039 TYPE = 1 |
1010 PID = 9 | 1040 PID = 9 |
1011 TID = 10 | 1041 TID = 10 |
1012 PROCESSOR_ID = 11 | 1042 PROCESSOR_ID = 11 |
1013 TIMESTAMP = 16 | 1043 TIMESTAMP = 16 |
1014 | 1044 |
1015 class Process(ApiBase.Context.Process): | 1045 class Process(ApiBase.Context.Process): |
1016 pass | 1046 def __init__(self, *args): |
| 1047 super(LogmanTrace.Context.Process, self).__init__(*args) |
| 1048 # Handle file objects that succeeded. |
| 1049 self.file_objects = {} |
1017 | 1050 |
1018 def __init__(self, blacklist): | 1051 def __init__(self, blacklist): |
1019 super(LogmanTrace.Context, self).__init__(blacklist) | 1052 super(LogmanTrace.Context, self).__init__(blacklist) |
1020 self._drive_map = DosDriveMap() | 1053 self._drive_map = DosDriveMap() |
1021 self._first_line = False | |
1022 # Threads mapping to the corresponding process id. | 1054 # Threads mapping to the corresponding process id. |
1023 self._threads_active = {} | 1055 self._threads_active = {} |
| 1056 # Process ID of the tracer, e.g. tracer_inputs.py |
| 1057 self._tracer_pid = None |
| 1058 # First process to be started by self._tracer_pid. |
| 1059 self._initial_pid = None |
| 1060 self._line_number = 0 |
1024 | 1061 |
1025 def on_csv_line(self, line): | 1062 def on_csv_line(self, line): |
1026 """Processes a CSV Event line.""" | 1063 """Processes a CSV Event line.""" |
1027 # So much white space! | 1064 # So much white space! |
1028 line = [i.strip() for i in line] | 1065 line = [i.strip() for i in line] |
1029 if not self._first_line: | 1066 self._line_number += 1 |
| 1067 if self._line_number == 1: |
1030 assert line == [ | 1068 assert line == [ |
1031 u'Event Name', | 1069 u'Event Name', |
1032 u'Type', | 1070 u'Type', |
1033 u'Event ID', | 1071 u'Event ID', |
1034 u'Version', | 1072 u'Version', |
1035 u'Channel', | 1073 u'Channel', |
1036 u'Level', # 5 | 1074 u'Level', # 5 |
1037 u'Opcode', | 1075 u'Opcode', |
1038 u'Task', | 1076 u'Task', |
1039 u'Keyword', | 1077 u'Keyword', |
1040 u'PID', | 1078 u'PID', |
1041 u'TID', # 10 | 1079 u'TID', # 10 |
1042 u'Processor Number', | 1080 u'Processor Number', |
1043 u'Instance ID', | 1081 u'Instance ID', |
1044 u'Parent Instance ID', | 1082 u'Parent Instance ID', |
1045 u'Activity ID', | 1083 u'Activity ID', |
1046 u'Related Activity ID', # 15 | 1084 u'Related Activity ID', # 15 |
1047 u'Clock-Time', | 1085 u'Clock-Time', |
1048 u'Kernel(ms)', # Both have a resolution of ~15ms which makes them | 1086 u'Kernel(ms)', # Both have a resolution of ~15ms which makes them |
1049 u'User(ms)', # pretty much useless. | 1087 u'User(ms)', # pretty much useless. |
1050 u'User Data', | 1088 u'User Data', |
1051 ] | 1089 ] |
1052 self._first_line = True | |
1053 return | 1090 return |
1054 | 1091 |
1055 # As you can see, the CSV is full of useful non-redundant information: | 1092 # As you can see, the CSV is full of useful non-redundant information: |
1056 # Event ID | 1093 # Event ID |
1057 assert line[2] == '0' | 1094 assert line[2] == '0' |
1058 # Version | 1095 # Version |
1059 assert line[3] in ('2', '3'), line[3] | 1096 assert line[3] in ('2', '3'), line[3] |
1060 # Channel | 1097 # Channel |
1061 assert line[4] == '0' | 1098 assert line[4] == '0' |
1062 # Level | 1099 # Level |
(...skipping 24 matching lines...) Expand all Loading... |
1087 'handle_%s_%s' % (line[self.EVENT_NAME], line[self.TYPE]), | 1124 'handle_%s_%s' % (line[self.EVENT_NAME], line[self.TYPE]), |
1088 None) | 1125 None) |
1089 if not handler: | 1126 if not handler: |
1090 # Try to get an universal fallback | 1127 # Try to get an universal fallback |
1091 handler = getattr(self, 'handle_%s_Any' % line[self.EVENT_NAME], None) | 1128 handler = getattr(self, 'handle_%s_Any' % line[self.EVENT_NAME], None) |
1092 if handler: | 1129 if handler: |
1093 handler(line) | 1130 handler(line) |
1094 else: | 1131 else: |
1095 assert False, '%s_%s' % (line[self.EVENT_NAME], line[self.TYPE]) | 1132 assert False, '%s_%s' % (line[self.EVENT_NAME], line[self.TYPE]) |
1096 | 1133 |
| 1134 def _thread_to_process(self, tid): |
| 1135 """Finds the process from the thread id.""" |
| 1136 tid = int(tid, 16) |
| 1137 return self.processes.get(self._threads_active.get(tid)) |
| 1138 |
1097 @staticmethod | 1139 @staticmethod |
1098 def handle_EventTrace_Header(line): | 1140 def handle_EventTrace_Header(line): |
1099 """Verifies no event was dropped, e.g. no buffer overrun occured.""" | 1141 """Verifies no event was dropped, e.g. no buffer overrun occured.""" |
1100 #BUFFER_SIZE = 19 | 1142 #BUFFER_SIZE = 19 |
1101 #VERSION = 20 | 1143 #VERSION = 20 |
1102 #PROVIDER_VERSION = 21 | 1144 #PROVIDER_VERSION = 21 |
1103 #NUMBER_OF_PROCESSORS = 22 | 1145 #NUMBER_OF_PROCESSORS = 22 |
1104 #END_TIME = 23 | 1146 #END_TIME = 23 |
1105 #TIMER_RESOLUTION = 24 | 1147 #TIMER_RESOLUTION = 24 |
1106 #MAX_FILE_SIZE = 25 | 1148 #MAX_FILE_SIZE = 25 |
(...skipping 10 matching lines...) Expand all Loading... |
1117 #START_TIME = 36 | 1159 #START_TIME = 36 |
1118 #RESERVED_FLAGS = 37 | 1160 #RESERVED_FLAGS = 37 |
1119 #BUFFERS_LOST = 38 | 1161 #BUFFERS_LOST = 38 |
1120 #SESSION_NAME_STRING = 39 | 1162 #SESSION_NAME_STRING = 39 |
1121 #LOG_FILE_NAME_STRING = 40 | 1163 #LOG_FILE_NAME_STRING = 40 |
1122 assert line[EVENTS_LOST] == '0' | 1164 assert line[EVENTS_LOST] == '0' |
1123 | 1165 |
1124 def handle_EventTrace_Any(self, line): | 1166 def handle_EventTrace_Any(self, line): |
1125 pass | 1167 pass |
1126 | 1168 |
| 1169 def handle_FileIo_Cleanup(self, line): |
| 1170 """General wisdom: if a file is closed, it's because it was opened. |
| 1171 |
| 1172 Note that FileIo_Close is not used since if a file was opened properly but |
| 1173 not closed before the process exits, only Cleanup will be logged. |
| 1174 """ |
| 1175 #IRP = 19 |
| 1176 TTID = 20 # Thread ID, that's what we want. |
| 1177 FILE_OBJECT = 21 |
| 1178 #FILE_KEY = 22 |
| 1179 proc = self._thread_to_process(line[TTID]) |
| 1180 if not proc: |
| 1181 # Not a process we care about. |
| 1182 return |
| 1183 file_object = line[FILE_OBJECT] |
| 1184 if file_object in proc.file_objects: |
| 1185 proc.add_file(proc.file_objects.pop(file_object)) |
| 1186 |
1127 def handle_FileIo_Create(self, line): | 1187 def handle_FileIo_Create(self, line): |
1128 """Handles a file open. | 1188 """Handles a file open. |
1129 | 1189 |
1130 All FileIo events are described at | 1190 All FileIo events are described at |
1131 http://msdn.microsoft.com/library/windows/desktop/aa363884.aspx | 1191 http://msdn.microsoft.com/library/windows/desktop/aa363884.aspx |
1132 for some value of 'description'. | 1192 for some value of 'description'. |
1133 | 1193 |
1134 " (..) process and thread id values of the IO events (..) are not valid " | 1194 " (..) process and thread id values of the IO events (..) are not valid " |
1135 http://msdn.microsoft.com/magazine/ee358703.aspx | 1195 http://msdn.microsoft.com/magazine/ee358703.aspx |
| 1196 |
| 1197 The FileIo.Create event doesn't return if the CreateFile() call |
| 1198 succeeded, so keep track of the file_object and check that it is |
| 1199 eventually closed with FileIo_Cleanup. |
1136 """ | 1200 """ |
1137 #IRP = 19 | 1201 #IRP = 19 |
1138 TTID = 20 # Thread ID, that's what we want. | 1202 TTID = 20 # Thread ID, that's what we want. |
1139 #FILE_OBJECT = 21 | 1203 FILE_OBJECT = 21 |
1140 #CREATE_OPTIONS = 22 | 1204 #CREATE_OPTIONS = 22 |
1141 #FILE_ATTRIBUTES = 23 | 1205 #FILE_ATTRIBUTES = 23 |
1142 #SHARE_ACCESS = 24 | 1206 #SHARE_ACCESS = 24 |
1143 OPEN_PATH = 25 | 1207 OPEN_PATH = 25 |
1144 | 1208 |
1145 # Find the process from the thread id. | 1209 proc = self._thread_to_process(line[TTID]) |
1146 tid = int(line[TTID], 16) | |
1147 proc = self.processes.get(self._threads_active.get(tid)) | |
1148 if not proc: | 1210 if not proc: |
1149 # Not a process we care about. | 1211 # Not a process we care about. |
1150 return | 1212 return |
1151 | 1213 |
1152 match = re.match(r'^\"(.+)\"$', line[OPEN_PATH]) | 1214 match = re.match(r'^\"(.+)\"$', line[OPEN_PATH]) |
1153 raw_path = match.group(1) | 1215 raw_path = match.group(1) |
1154 # Ignore directories and bare drive right away. | 1216 # Ignore directories and bare drive right away. |
1155 if raw_path.endswith(os.path.sep): | 1217 if raw_path.endswith(os.path.sep): |
1156 return | 1218 return |
1157 filename = self._drive_map.to_dos(raw_path) | 1219 filename = self._drive_map.to_dos(raw_path) |
1158 # Ignore bare drive right away. | 1220 # Ignore bare drive right away. Some may still fall through with format |
1159 if len(raw_path) == 2: | 1221 # like '\\?\X:' |
| 1222 if len(filename) == 2: |
1160 return | 1223 return |
1161 proc.add_file(filename) | 1224 file_object = line[FILE_OBJECT] |
| 1225 # Override any stale file object |
| 1226 proc.file_objects[file_object] = filename |
1162 | 1227 |
1163 def handle_FileIo_Rename(self, line): | 1228 def handle_FileIo_Rename(self, line): |
1164 # TODO(maruel): Handle? | 1229 # TODO(maruel): Handle? |
1165 pass | 1230 pass |
1166 | 1231 |
1167 def handle_FileIo_Any(self, line): | 1232 def handle_FileIo_Any(self, line): |
1168 pass | 1233 pass |
1169 | 1234 |
1170 def handle_Process_Any(self, line): | 1235 def handle_Process_Any(self, line): |
1171 pass | 1236 pass |
(...skipping 11 matching lines...) Expand all Loading... |
1183 #EXIT_STATUS = 23 | 1248 #EXIT_STATUS = 23 |
1184 #DIRECTORY_TABLE_BASE = 24 | 1249 #DIRECTORY_TABLE_BASE = 24 |
1185 #USER_SID = 25 | 1250 #USER_SID = 25 |
1186 IMAGE_FILE_NAME = 26 | 1251 IMAGE_FILE_NAME = 26 |
1187 #COMMAND_LINE = 27 | 1252 #COMMAND_LINE = 27 |
1188 | 1253 |
1189 ppid = int(line[PARENT_PID], 16) | 1254 ppid = int(line[PARENT_PID], 16) |
1190 if line[IMAGE_FILE_NAME] == '"logman.exe"': | 1255 if line[IMAGE_FILE_NAME] == '"logman.exe"': |
1191 # logman's parent is trace_input.py or whatever tool using it as a | 1256 # logman's parent is trace_input.py or whatever tool using it as a |
1192 # library. Trace any other children started by it. | 1257 # library. Trace any other children started by it. |
1193 assert ppid not in self.processes | 1258 assert not self._tracer_pid |
1194 self.processes[ppid] = self.Process(self, ppid, None, None) | 1259 self._tracer_pid = ppid |
1195 logging.info('Found logman\'s parent at %d' % ppid) | 1260 logging.info('Found logman\'s parent at %d' % ppid) |
1196 | 1261 |
1197 def handle_Process_End(self, line): | 1262 def handle_Process_End(self, line): |
1198 # Look if it is logman terminating, if so, grab the parent's process pid | 1263 # Look if it is logman terminating, if so, grab the parent's process pid |
1199 # and inject cwd. | 1264 # and inject cwd. |
1200 pid = line[self.PID] | 1265 pid = line[self.PID] |
1201 if pid in self.processes: | 1266 if pid in self.processes: |
1202 logging.info('Terminated: %d' % pid) | 1267 logging.info('Terminated: %d' % pid) |
1203 self.processes[pid].cwd = None | 1268 self.processes[pid].cwd = None |
1204 | 1269 |
1205 def handle_Process_Start(self, line): | 1270 def handle_Process_Start(self, line): |
1206 """Handles a new child process started by PID.""" | 1271 """Handles a new child process started by PID.""" |
1207 #UNIQUE_PROCESS_KEY = 19 | 1272 #UNIQUE_PROCESS_KEY = 19 |
1208 PROCESS_ID = 20 | 1273 PROCESS_ID = 20 |
1209 #PARENT_PID = 21 | 1274 #PARENT_PID = 21 |
1210 #SESSION_ID = 22 | 1275 #SESSION_ID = 22 |
1211 #EXIT_STATUS = 23 | 1276 #EXIT_STATUS = 23 |
1212 #DIRECTORY_TABLE_BASE = 24 | 1277 #DIRECTORY_TABLE_BASE = 24 |
1213 #USER_SID = 25 | 1278 #USER_SID = 25 |
1214 IMAGE_FILE_NAME = 26 | 1279 IMAGE_FILE_NAME = 26 |
1215 #COMMAND_LINE = 27 | 1280 #COMMAND_LINE = 27 |
1216 | 1281 |
1217 ppid = line[self.PID] | 1282 ppid = line[self.PID] |
1218 pid = int(line[PROCESS_ID], 16) | 1283 pid = int(line[PROCESS_ID], 16) |
1219 if ppid in self.processes: | 1284 if ppid == self._tracer_pid: |
1220 # Need to ignore processes we don't know about because the log is | 1285 # Need to ignore processes we don't know about because the log is |
1221 # system-wide. | 1286 # system-wide. |
1222 if line[IMAGE_FILE_NAME] == '"logman.exe"': | 1287 if line[IMAGE_FILE_NAME] == '"logman.exe"': |
1223 # Skip the shutdown call when "logman.exe stop" is executed. | 1288 # Skip the shutdown call when "logman.exe stop" is executed. |
1224 return | 1289 return |
| 1290 self._initial_pid = self._initial_pid or pid |
| 1291 assert pid not in self.processes |
| 1292 self.processes[pid] = self.Process(self, pid, None, None) |
| 1293 logging.info( |
| 1294 'New child: %d -> %d %s' % (ppid, pid, line[IMAGE_FILE_NAME])) |
| 1295 elif ppid in self.processes: |
| 1296 # Grand-children |
1225 assert pid not in self.processes | 1297 assert pid not in self.processes |
1226 self.processes[pid] = self.Process(self, pid, None, ppid) | 1298 self.processes[pid] = self.Process(self, pid, None, ppid) |
1227 logging.info( | 1299 logging.info( |
1228 'New child: %d -> %d %s' % (ppid, pid, line[IMAGE_FILE_NAME])) | 1300 'New child: %d -> %d %s' % (ppid, pid, line[IMAGE_FILE_NAME])) |
1229 | 1301 |
1230 def handle_Thread_End(self, line): | 1302 def handle_Thread_End(self, line): |
1231 """Has the same parameters as Thread_Start.""" | 1303 """Has the same parameters as Thread_Start.""" |
1232 tid = int(line[self.TID], 16) | 1304 tid = int(line[self.TID], 16) |
1233 self._threads_active.pop(tid, None) | 1305 self._threads_active.pop(tid, None) |
1234 | 1306 |
(...skipping 47 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
1282 'TMP', | 1354 'TMP', |
1283 ) | 1355 ) |
1284 for i in vars_to_ignore: | 1356 for i in vars_to_ignore: |
1285 if os.environ.get(i): | 1357 if os.environ.get(i): |
1286 self.IGNORED.add(os.environ[i]) | 1358 self.IGNORED.add(os.environ[i]) |
1287 | 1359 |
1288 # Also add their short path name equivalents. | 1360 # Also add their short path name equivalents. |
1289 for i in list(self.IGNORED): | 1361 for i in list(self.IGNORED): |
1290 self.IGNORED.add(GetShortPathName(i.replace('/', os.path.sep))) | 1362 self.IGNORED.add(GetShortPathName(i.replace('/', os.path.sep))) |
1291 | 1363 |
1292 # Add this one last since it has no short path name equivalent. | 1364 # Add these last since they have no short path name equivalent. |
1293 self.IGNORED.add('\\SystemRoot') | 1365 self.IGNORED.add('\\SystemRoot') |
| 1366 # All the NTFS metadata is in the form x:\$EXTEND or stuff like that. |
| 1367 for letter in (chr(l) for l in xrange(ord('C'), ord('Z')+1)): |
| 1368 self.IGNORED.add('%s\\\$' % letter) |
| 1369 # TODO(maruel): Remove the need to add these. |
| 1370 self.IGNORED.add('\\\\?\\%s\\$' % letter) |
1294 self.IGNORED = tuple(sorted(self.IGNORED)) | 1371 self.IGNORED = tuple(sorted(self.IGNORED)) |
1295 | 1372 |
1296 @staticmethod | 1373 @staticmethod |
1297 def clean_trace(logname): | 1374 def clean_trace(logname): |
1298 if os.path.isfile(logname): | 1375 if os.path.isfile(logname): |
1299 os.remove(logname) | 1376 os.remove(logname) |
1300 if os.path.isfile(logname + '.etl'): | 1377 if os.path.isfile(logname + '.etl'): |
1301 os.remove(logname + '.etl') | 1378 os.remove(logname + '.etl') |
1302 | 1379 |
1303 @classmethod | 1380 @classmethod |
(...skipping 498 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
1802 os.path.abspath(options.log), | 1879 os.path.abspath(options.log), |
1803 args, | 1880 args, |
1804 options.root_dir, | 1881 options.root_dir, |
1805 options.cwd, | 1882 options.cwd, |
1806 options.product_dir, | 1883 options.product_dir, |
1807 options.force) | 1884 options.force) |
1808 | 1885 |
1809 | 1886 |
1810 if __name__ == '__main__': | 1887 if __name__ == '__main__': |
1811 sys.exit(main()) | 1888 sys.exit(main()) |
OLD | NEW |