Peter M. Groen / oletools

Commit 40c14afb6443576ef56c78b8a8eb9bbdb5205c34

Authored by Christian Herdtweck
1 parent 3463905d

limit logging output from open_... and process_file_... functions to info and debug 

no need to do error/exception output here since an error is raised anyway
if opening/processing failed and otherwise the error is not so bad (e.g.
one opening attempt failed but next succeeds for same file)

--> main or other caller can better control the output (e.g. for json/triage mode)

Added a few debug-traces
Inline Side-by-side
Showing 1 changed file with 26 additions and 17 deletions
oletools/olevba.py
  View file @40c14af
@@ -908,7 +908,8 @@ def mso_file_extract(data): @@ -908,7 +908,8 @@ def mso_file_extract(data):
908 log.debug('Parsing MSO file: data offset = 0x%X' % offset) 908 log.debug('Parsing MSO file: data offset = 0x%X' % offset)
909 offsets.insert(0, offset) # insert at beginning of offsets 909 offsets.insert(0, offset) # insert at beginning of offsets
910 except struct.error as exc: 910 except struct.error as exc:
911 - log.exception('Unable to parse MSO/ActiveMime file header (%s)' % exc) 911 + log.info('Unable to parse MSO/ActiveMime file header (%s)' % exc)
  912 + log.debug('Trace:', exc_info=True)
912 raise MsoExtractionError('Unable to parse MSO/ActiveMime file header') 913 raise MsoExtractionError('Unable to parse MSO/ActiveMime file header')
913 # now try offsets 914 # now try offsets
914 for start in offsets: 915 for start in offsets:
@@ -917,8 +918,9 @@ def mso_file_extract(data): @@ -917,8 +918,9 @@ def mso_file_extract(data):
917 extracted_data = zlib.decompress(data[start:]) 918 extracted_data = zlib.decompress(data[start:])
918 return extracted_data 919 return extracted_data
919 except zlib.error as exc: 920 except zlib.error as exc:
920 - log.exception('zlib decompression failed for offset %s (%s)'  
921 - % (start, exc)) 921 + log.info('zlib decompression failed for offset %s (%s)'
  922 + % (start, exc))
  923 + log.debug('Trace:', exc_info=True)
922 # None of the guessed offsets worked, let's try brute-forcing by looking 924 # None of the guessed offsets worked, let's try brute-forcing by looking
923 # for potential zlib-compressed blocks starting with 0x78: 925 # for potential zlib-compressed blocks starting with 0x78:
924 log.debug('Looking for potential zlib-compressed blocks in MSO file') 926 log.debug('Looking for potential zlib-compressed blocks in MSO file')
@@ -929,7 +931,8 @@ def mso_file_extract(data): @@ -929,7 +931,8 @@ def mso_file_extract(data):
929 extracted_data = zlib.decompress(data[start:]) 931 extracted_data = zlib.decompress(data[start:])
930 return extracted_data 932 return extracted_data
931 except zlib.error as exc: 933 except zlib.error as exc:
932 - log.exception('zlib decompression failed (%s)' % exc) 934 + log.info('zlib decompression failed (%s)' % exc)
  935 + log.debug('Trace:', exc_info=True)
933 raise MsoExtractionError('Unable to decompress data from a MSO/ActiveMime file') 936 raise MsoExtractionError('Unable to decompress data from a MSO/ActiveMime file')
934 937
935 938
@@ -2098,7 +2101,7 @@ class VBA_Parser(object): @@ -2098,7 +2101,7 @@ class VBA_Parser(object):
2098 if self.type is None: 2101 if self.type is None:
2099 # At this stage, could not match a known format: 2102 # At this stage, could not match a known format:
2100 msg = '%s is not a supported file type, cannot extract VBA Macros.' % self.filename 2103 msg = '%s is not a supported file type, cannot extract VBA Macros.' % self.filename
2101 - log.error(msg) 2104 + log.info(msg)
2102 raise FileOpenError(msg) 2105 raise FileOpenError(msg)
2103 2106
2104 def open_ole(self, _file): 2107 def open_ole(self, _file):
@@ -2114,9 +2117,10 @@ class VBA_Parser(object): @@ -2114,9 +2117,10 @@ class VBA_Parser(object):
2114 # TODO: raise TypeError if this is a Powerpoint 97 file, since VBA macros cannot be detected yet 2117 # TODO: raise TypeError if this is a Powerpoint 97 file, since VBA macros cannot be detected yet
2115 # set type only if parsing succeeds 2118 # set type only if parsing succeeds
2116 self.type = TYPE_OLE 2119 self.type = TYPE_OLE
2117 - except (IOError, TypeError, ValueError): 2120 + except (IOError, TypeError, ValueError) as exc:
2118 # TODO: handle OLE parsing exceptions 2121 # TODO: handle OLE parsing exceptions
2119 - log.exception('Failed OLE parsing for file %r' % self.filename) 2122 + log.info('Failed OLE parsing for file %r (%s)' % (self.filename, exc))
  2123 + log.debug('Trace:', exc_info=True)
2120 2124
2121 2125
2122 def open_openxml(self, _file): 2126 def open_openxml(self, _file):
@@ -2143,15 +2147,16 @@ class VBA_Parser(object): @@ -2143,15 +2147,16 @@ class VBA_Parser(object):
2143 try: 2147 try:
2144 self.ole_subfiles.append(VBA_Parser(filename=subfile, data=ole_data)) 2148 self.ole_subfiles.append(VBA_Parser(filename=subfile, data=ole_data))
2145 except FileOpenError as exc: 2149 except FileOpenError as exc:
2146 - log.error('%s is not a valid OLE file (%s)' % (subfile, exc)) 2150 + log.info('%s is not a valid OLE file (%s)' % (subfile, exc))
2147 continue 2151 continue
2148 z.close() 2152 z.close()
2149 # set type only if parsing succeeds 2153 # set type only if parsing succeeds
2150 self.type = TYPE_OpenXML 2154 self.type = TYPE_OpenXML
2151 except (RuntimeError, zipfile.BadZipfile, zipfile.LargeZipFile, IOError) as exc: 2155 except (RuntimeError, zipfile.BadZipfile, zipfile.LargeZipFile, IOError) as exc:
2152 # TODO: handle parsing exceptions 2156 # TODO: handle parsing exceptions
2153 - log.exception('Failed Zip/OpenXML parsing for file %r (%s)' 2157 + log.info('Failed Zip/OpenXML parsing for file %r (%s)'
2154 % (self.filename, exc)) 2158 % (self.filename, exc))
  2159 + log.debug('Trace:', exc_info=True)
2155 2160
2156 def open_word2003xml(self, data): 2161 def open_word2003xml(self, data):
2157 """ 2162 """
@@ -2179,19 +2184,21 @@ class VBA_Parser(object): @@ -2179,19 +2184,21 @@ class VBA_Parser(object):
2179 ole_data = mso_file_extract(mso_data) 2184 ole_data = mso_file_extract(mso_data)
2180 self.ole_subfiles.append(VBA_Parser(filename=fname, data=ole_data)) 2185 self.ole_subfiles.append(VBA_Parser(filename=fname, data=ole_data))
2181 except MsoExtractionError: 2186 except MsoExtractionError:
2182 - log.exception('Failed decompressing an MSO container in %r - %s'  
2183 - % (fname, MSG_OLEVBA_ISSUES)) 2187 + log.info('Failed decompressing an MSO container in %r - %s'
  2188 + % (fname, MSG_OLEVBA_ISSUES))
  2189 + log.debug('Trace:', exc_info=True)
2184 except FileOpenError as exc: 2190 except FileOpenError as exc:
2185 log.debug('%s is not a valid OLE sub file (%s)' % (fname, exc)) 2191 log.debug('%s is not a valid OLE sub file (%s)' % (fname, exc))
2186 else: 2192 else:
2187 - log.error('%s is not a valid MSO file' % fname) 2193 + log.info('%s is not a valid MSO file' % fname)
2188 # set type only if parsing succeeds 2194 # set type only if parsing succeeds
2189 self.type = TYPE_Word2003_XML 2195 self.type = TYPE_Word2003_XML
2190 except Exception as exc: 2196 except Exception as exc:
2191 # TODO: differentiate exceptions for each parsing stage 2197 # TODO: differentiate exceptions for each parsing stage
2192 # (but ET is different libs, no good exception description in API) 2198 # (but ET is different libs, no good exception description in API)
2193 # found: XMLSyntaxError 2199 # found: XMLSyntaxError
2194 - log.exception('Failed XML parsing for file %r (%s)' % (self.filename, exc)) 2200 + log.info('Failed XML parsing for file %r (%s)' % (self.filename, exc))
  2201 + log.debug('Trace:', exc_info=True)
2195 2202
2196 def open_mht(self, data): 2203 def open_mht(self, data):
2197 """ 2204 """
@@ -2239,8 +2246,9 @@ class VBA_Parser(object): @@ -2239,8 +2246,9 @@ class VBA_Parser(object):
2239 # TODO: get the MSO filename from content_location? 2246 # TODO: get the MSO filename from content_location?
2240 self.ole_subfiles.append(VBA_Parser(filename=fname, data=ole_data)) 2247 self.ole_subfiles.append(VBA_Parser(filename=fname, data=ole_data))
2241 except MsoExtractionError: 2248 except MsoExtractionError:
2242 - log.exception('Failed decompressing an MSO container in %r - %s' 2249 + log.info('Failed decompressing an MSO container in %r - %s'
2243 % (fname, MSG_OLEVBA_ISSUES)) 2250 % (fname, MSG_OLEVBA_ISSUES))
  2251 + log.debug('Trace:', exc_info=True)
2244 # TODO: bug here - need to split in smaller functions/classes? 2252 # TODO: bug here - need to split in smaller functions/classes?
2245 except FileOpenError as exc: 2253 except FileOpenError as exc:
2246 log.debug('%s does not contain a valid OLE file (%s)' 2254 log.debug('%s does not contain a valid OLE file (%s)'
@@ -2254,8 +2262,9 @@ class VBA_Parser(object): @@ -2254,8 +2262,9 @@ class VBA_Parser(object):
2254 # set type only if parsing succeeds 2262 # set type only if parsing succeeds
2255 self.type = TYPE_MHTML 2263 self.type = TYPE_MHTML
2256 except Exception: 2264 except Exception:
2257 - log.exception('Failed MIME parsing for file %r - %s' 2265 + log.info('Failed MIME parsing for file %r - %s'
2258 % (self.filename, MSG_OLEVBA_ISSUES)) 2266 % (self.filename, MSG_OLEVBA_ISSUES))
  2267 + log.debug('Trace:', exc_info=True)
2259 2268
2260 2269
2261 def open_text(self, data): 2270 def open_text(self, data):
@@ -2721,7 +2730,7 @@ class VBA_Parser_CLI(VBA_Parser): @@ -2721,7 +2730,7 @@ class VBA_Parser_CLI(VBA_Parser):
2721 print 'No VBA macros found.' 2730 print 'No VBA macros found.'
2722 except Exception as exc: 2731 except Exception as exc:
2723 # display the exception with full stack trace for debugging 2732 # display the exception with full stack trace for debugging
2724 - log.error('Error processing file %s (%s)' % (self.filename, exc)) 2733 + log.info('Error processing file %s (%s)' % (self.filename, exc))
2725 log.debug('Traceback:', exc_info=True) 2734 log.debug('Traceback:', exc_info=True)
2726 raise ProcessingError(self.filename, exc) 2735 raise ProcessingError(self.filename, exc)
2727 print '' 2736 print ''
@@ -2787,7 +2796,7 @@ class VBA_Parser_CLI(VBA_Parser): @@ -2787,7 +2796,7 @@ class VBA_Parser_CLI(VBA_Parser):
2787 result['json_conversion_successful'] = True 2796 result['json_conversion_successful'] = True
2788 except Exception as exc: 2797 except Exception as exc:
2789 # display the exception with full stack trace for debugging 2798 # display the exception with full stack trace for debugging
2790 - log.error('Error processing file %s (%s)' % (self.filename, exc)) 2799 + log.info('Error processing file %s (%s)' % (self.filename, exc))
2791 log.debug('Traceback:', exc_info=True) 2800 log.debug('Traceback:', exc_info=True)
2792 raise ProcessingError(self.filename, exc) 2801 raise ProcessingError(self.filename, exc)
2793 2802