diff --git a/src/smda/common/BinaryInfo.py b/src/smda/common/BinaryInfo.py index 5b0b0fb1..6f9f25d4 100644 --- a/src/smda/common/BinaryInfo.py +++ b/src/smda/common/BinaryInfo.py @@ -99,7 +99,7 @@ def getBinaryData(self): with open(self.file_path, "rb") as fin: data = fin.read() except OSError as e: - LOGGER.debug("Failed to read binary from path %s: %s", self.file_path, e) + LOGGER.warning("Failed to read binary from path %s: %s", self.file_path, e) return None return data diff --git a/src/smda/common/labelprovider/CilSymbolProvider.py b/src/smda/common/labelprovider/CilSymbolProvider.py index 8c4e316c..e1d283d9 100644 --- a/src/smda/common/labelprovider/CilSymbolProvider.py +++ b/src/smda/common/labelprovider/CilSymbolProvider.py @@ -42,7 +42,7 @@ def update(self, binary_info, parsed=None): pe = dnfile.dnPE(data=binary_info.raw_data) if parsed is None else parsed except Exception as exc: reraise_non_operational_exception(exc) - LOGGER.debug("Failed to parse CIL symbols: %s", exc) + LOGGER.warning("Failed to parse CIL symbols: %s", exc) return if not getattr(pe, "net", None) or not getattr(pe.net, "mdtables", None): return diff --git a/src/smda/common/labelprovider/DelphiReSymProvider.py b/src/smda/common/labelprovider/DelphiReSymProvider.py index a19199f6..41056050 100644 --- a/src/smda/common/labelprovider/DelphiReSymProvider.py +++ b/src/smda/common/labelprovider/DelphiReSymProvider.py @@ -252,7 +252,7 @@ def update(self, binary_info): # Determine code areas code_areas = binary_info.code_areas if not code_areas: - LOGGER.debug("No code areas found, skipping DelphiReSym parsing") + LOGGER.warning("No code areas found, skipping DelphiReSym parsing") return # Code areas are virtual addresses - convert to file offsets for scanning @@ -266,7 +266,7 @@ def update(self, binary_info): # Validate the offsets are within binary bounds if self._code_start < 0 or self._code_end > len(self._binary): - LOGGER.debug( + LOGGER.warning( f"Code area offsets out of bounds: {self._code_start}-{self._code_end}, binary size: {len(self._binary)}" ) return diff --git a/src/smda/common/labelprovider/GoLabelProvider.py b/src/smda/common/labelprovider/GoLabelProvider.py index d371f622..a81806fd 100644 --- a/src/smda/common/labelprovider/GoLabelProvider.py +++ b/src/smda/common/labelprovider/GoLabelProvider.py @@ -191,6 +191,7 @@ def update(self, binary_info): self._func_symbols = result except Exception as exc: reraise_non_operational_exception(exc) + LOGGER.warning("Failed to parse Go pclntab at offset 0x%x: %s", pclntab_offset, exc) return def isSymbolProvider(self): diff --git a/src/smda/common/labelprovider/MachoSymbolProvider.py b/src/smda/common/labelprovider/MachoSymbolProvider.py index 8ab1f2d2..944e5e3d 100644 --- a/src/smda/common/labelprovider/MachoSymbolProvider.py +++ b/src/smda/common/labelprovider/MachoSymbolProvider.py @@ -115,8 +115,8 @@ def update(self, binary_info): and adjusted_stub_addr not in self._func_symbols ): self._func_symbols[adjusted_stub_addr] = f"stub_{adjusted_stub_addr:x}" - except Exception: - pass + except Exception as e: + LOGGER.warning("Failed to collect Mach-O symbol stubs: %s", e) self._api_map = self.parseImports(lief_binary) @@ -133,7 +133,7 @@ def parseExports(self, lief_binary): adjusted_val = symbol.value + adjustment exported[adjusted_val] = demangle_macho_symbol(symbol_name) except Exception as e: - LOGGER.debug("Failed to parse Mach-O exports: %s", e) + LOGGER.warning("Failed to parse Mach-O exports: %s", e) return exported def parseSymbols(self, lief_binary): @@ -149,7 +149,7 @@ def parseSymbols(self, lief_binary): adjusted_val = symbol.value + adjustment symbols[adjusted_val] = symbol_name except Exception as e: - LOGGER.debug("Failed to parse Mach-O symbols: %s", e) + LOGGER.warning("Failed to parse Mach-O symbols: %s", e) return symbols def parseImports(self, lief_binary): diff --git a/src/smda/common/labelprovider/RustSymbolProvider.py b/src/smda/common/labelprovider/RustSymbolProvider.py index 7d02a06b..a73b78fb 100644 --- a/src/smda/common/labelprovider/RustSymbolProvider.py +++ b/src/smda/common/labelprovider/RustSymbolProvider.py @@ -44,7 +44,7 @@ def update(self, binary_info): lief_binary = binary_info.getLiefBinary() except Exception as exc: reraise_non_operational_exception(exc) - LOGGER.debug("Failed to parse binary with LIEF: %s", type(exc).__name__) + LOGGER.warning("Failed to parse binary with LIEF: %s", type(exc).__name__) return if not lief_binary or not self.is_rust_binary(binary_info): @@ -124,7 +124,7 @@ def _get_binary_data(self, binary_info): with open(binary_info.file_path, "rb") as fin: data = fin.read() except OSError as e: - LOGGER.debug("Failed to read binary from path %s: %s", binary_info.file_path, e) + LOGGER.warning("Failed to read binary from path %s: %s", binary_info.file_path, e) return None return data diff --git a/src/smda/utility/ElfFileLoader.py b/src/smda/utility/ElfFileLoader.py index 271a84ed..ec7c568d 100644 --- a/src/smda/utility/ElfFileLoader.py +++ b/src/smda/utility/ElfFileLoader.py @@ -271,7 +271,7 @@ def mapBinary(binary, parsed=_NOT_PROVIDED): ) if not max_virtual_address: - LOGGER.debug("ELF: no section or segment data") + LOGGER.warning("ELF: no section or segment data") return b"" # create mapped region. diff --git a/src/smda/utility/FileLoader.py b/src/smda/utility/FileLoader.py index 79275579..465fc787 100644 --- a/src/smda/utility/FileLoader.py +++ b/src/smda/utility/FileLoader.py @@ -1,3 +1,4 @@ +import logging import os from smda.utility.DelphiKbFileLoader import DelphiKbFileLoader @@ -6,6 +7,8 @@ from smda.utility.MachoFileLoader import MachoFileLoader from smda.utility.PeFileLoader import PeFileLoader +LOGGER = logging.getLogger(__name__) + class FileLoader: _file_path = None @@ -61,6 +64,10 @@ def _loadFile(self, buffer=None): # distinguishes "caller did not supply" from # "caller already tried and got None". kw = {"parsed": loader.parseBinary(self._raw_data)} if hasattr(loader, "parseBinary") else {} + # isCompatible() has confirmed the format, so a failed shared parse means + # every accessor below silently yields nothing for a real PE/ELF/Mach-O + if "parsed" in kw and not kw["parsed"]: + LOGGER.warning("%s: failed to parse the binary, no data will be mapped", loader.__name__) self._data = loader.mapBinary(self._raw_data, **kw) self._base_addr = loader.getBaseAddress(self._raw_data, **kw) self._bitness = loader.getBitness(self._raw_data, **kw) diff --git a/src/smda/utility/MachoFileLoader.py b/src/smda/utility/MachoFileLoader.py index e8a63d4c..b1770bdf 100644 --- a/src/smda/utility/MachoFileLoader.py +++ b/src/smda/utility/MachoFileLoader.py @@ -221,7 +221,7 @@ def mapBinary(binary, parsed=_NOT_PROVIDED): max_virtual_address, min_virtual_address, min_raw_offset = _calculate_boundaries(macho_file) if not max_virtual_address: - LOGGER.debug("MachO: no section or segment data") + LOGGER.warning("MachO: no section or segment data") return b"" # create mapped region. diff --git a/src/smda/utility/PeFileLoader.py b/src/smda/utility/PeFileLoader.py index c5e35ccb..198d3f49 100644 --- a/src/smda/utility/PeFileLoader.py +++ b/src/smda/utility/PeFileLoader.py @@ -84,7 +84,7 @@ def mapBinary(binary, parsed=_NOT_PROVIDED): # Mach-O loaders report the same condition, by returning no mapped data, instead # of raising a ValueError that claims the opposite of what happened. if not max_virt_section_offset: - LOGGER.debug("PE: no section data") + LOGGER.warning("PE: no section data") return b"" # support up to 100MB for now. if max_virt_section_offset > SmdaConfig.MAX_IMAGE_SIZE: diff --git a/tests/testCommonModels.py b/tests/testCommonModels.py index 0cb97247..52124085 100644 --- a/tests/testCommonModels.py +++ b/tests/testCommonModels.py @@ -1,6 +1,7 @@ import copy import hashlib import json +import logging import struct import tempfile import unittest @@ -563,6 +564,23 @@ def test_address_one_past_the_image_is_not_inside(self): self.assertFalse(binary_info.isInCodeAreas(0x400100)) +class TestBinaryInfoBinaryData(unittest.TestCase): + def test_an_unreadable_binary_path_is_reported_at_warning(self): + # getBinaryData feeds getLiefBinary and every lief-backed provider through it, so a + # read failure here silently unnames the whole run + binary_info = BinaryInfo(b"") + binary_info.file_path = str(Path(__file__).resolve().parent / "does_not_exist.bin") + # another test module's import-time logging.disable() would hide these records + previous_disable = logging.root.manager.disable + logging.disable(logging.NOTSET) + self.addCleanup(logging.disable, previous_disable) + + with self.assertLogs("smda.common.BinaryInfo", level="WARNING") as logged: + self.assertIsNone(binary_info.getBinaryData()) + + self.assertIn("Failed to read binary", logged.output[0]) + + class TestSmdaFunctionRobustness(unittest.TestCase): def test_escaper_is_declared_for_instances_built_without_a_disassembly(self): self.assertIsNone(SmdaFunction()._escaper) diff --git a/tests/testDelphiPythiaProvider.py b/tests/testDelphiPythiaProvider.py index 0d0cf72f..dc90bc9b 100644 --- a/tests/testDelphiPythiaProvider.py +++ b/tests/testDelphiPythiaProvider.py @@ -1,3 +1,4 @@ +import logging import struct import unittest from types import SimpleNamespace @@ -141,6 +142,43 @@ def test_provider_registered_as_engine_symbol_provider(self): self.assertNotIn(DelphiPythiaProvider, {type(provider) for provider in engine.api_providers}) +class TestDelphiReSymDeadEndLogging(unittest.TestCase): + """Both paths run after the MZ + TObject signature match, so they are real dead ends.""" + + def setUp(self): + # another test module's import-time logging.disable() would hide these records + previous_disable = logging.root.manager.disable + logging.disable(logging.NOTSET) + self.addCleanup(logging.disable, previous_disable) + + @staticmethod + def _delphi_binary_info(code_areas): + binary = bytearray(0x2000) + binary[:2] = b"MZ" + binary[0x100:0x107] = b"TObject" + binary_info = BinaryInfo(bytes(binary)) + binary_info.base_addr = 0x400000 + binary_info.bitness = 32 + binary_info.code_areas = code_areas + return binary_info + + def test_a_binary_without_code_areas_is_reported_at_warning(self): + provider = DelphiReSymProvider(None) + + with self.assertLogs("smda.common.labelprovider.DelphiReSymProvider", level="WARNING") as logged: + provider.update(self._delphi_binary_info([])) + + self.assertIn("No code areas found", logged.output[0]) + + def test_out_of_bounds_code_area_offsets_are_reported_at_warning(self): + provider = DelphiReSymProvider(None) + + with self.assertLogs("smda.common.labelprovider.DelphiReSymProvider", level="WARNING") as logged: + provider.update(self._delphi_binary_info([(0x400000, 0x409000)])) + + self.assertIn("out of bounds", logged.output[0]) + + class TestDelphiReSymNegativeOffsets(unittest.TestCase): def test_method_entry_below_the_image_is_rejected(self): parser = DelphiReSymProvider.__new__(DelphiReSymProvider) diff --git a/tests/testFileFormatParsers.py b/tests/testFileFormatParsers.py index c64ebfbd..e8875e0f 100644 --- a/tests/testFileFormatParsers.py +++ b/tests/testFileFormatParsers.py @@ -46,6 +46,24 @@ def _load_xored_fixture(self, fixture_name): decrypted_binary.append(byte ^ (index % 256)) return bytes(decrypted_binary) + def test_a_confirmed_format_that_fails_to_parse_is_reported_at_warning(self): + # isCompatible() matched the magic, but the shared parse came back empty - every + # accessor below it then yields nothing for what really is a PE/ELF + # another test module's import-time logging.disable() would hide these records + previous_disable = logging.root.manager.disable + logging.disable(logging.NOTSET) + self.addCleanup(logging.disable, previous_disable) + + for name, binary in (("ELF", b"\x7fELF"), ("PE", b"MZ" + b"\x00" * 64)): + with self.subTest(format=name): + loader = FileLoader("/", map_file=True) + + with self.assertLogs("smda.utility.FileLoader", level="WARNING") as logged: + loader._loadFile(binary) + + self.assertEqual(b"", loader.getData()) + self.assertIn("failed to parse the binary", logged.output[0]) + def _create_binary_info(self, binary): loader = FileLoader("/", map_file=True) loader._loadFile(binary) diff --git a/tests/testGoSymbolProvider.py b/tests/testGoSymbolProvider.py index be536c98..2915e4fe 100644 --- a/tests/testGoSymbolProvider.py +++ b/tests/testGoSymbolProvider.py @@ -1,3 +1,4 @@ +import logging import pathlib import random import struct @@ -437,5 +438,23 @@ def test_elf_gopclntab_section_offset_is_preferred_over_the_scan(self): self.assertEqual(_ELF_PCLNTAB_OFFSET, provider.getPcLntabOffset(binary_info)) +class TestPcLntabParseFailureLogging(unittest.TestCase): + def test_a_parse_failure_after_a_validated_header_warns(self): + # the offset is only accepted once the header structure checks out, so recovering no + # symbols from it is a real failure - it used to leave no record at any level + provider = GoSymbolProvider(None) + binary_info = BinaryInfo(b"\xfb\xff\xff\xff\x00\x00\x01\x08") + # another test module's import-time logging.disable() would hide these records + previous_disable = logging.root.manager.disable + logging.disable(logging.NOTSET) + self.addCleanup(logging.disable, previous_disable) + + with self.assertLogs("smda.common.labelprovider.GoLabelProvider", level="WARNING") as logged: + provider.update(binary_info) + + self.assertEqual({}, provider.getFunctionSymbols()) + self.assertIn("pclntab", logged.output[0]) + + if __name__ == "__main__": unittest.main() diff --git a/tests/testMachoSymbolProvider.py b/tests/testMachoSymbolProvider.py index 2d211c91..d9a4d5d2 100644 --- a/tests/testMachoSymbolProvider.py +++ b/tests/testMachoSymbolProvider.py @@ -40,6 +40,20 @@ def __init__(self, symbols): self.sections = [] +class _UnreadableValueSymbol: + name = "_main" + + @property + def value(self): + raise RuntimeError("symbol table unreadable") + + +class _UnreadableAddressStub: + @property + def address(self): + raise RuntimeError("stub table unreadable") + + def _xor_fixture(data): return bytes(byte ^ (index % 256) for index, byte in enumerate(data)) @@ -167,6 +181,56 @@ def test_a_binary_lief_cannot_parse_offers_no_text_start(self): self.assertIsNone(GoSymbolProvider(None).getTextStart(binary_info)) +class TestMachoSymbolProviderFailureLogging(unittest.TestCase): + """Every path here runs only after the isinstance(lief.MachO.Binary) gate has matched.""" + + def setUp(self): + # this module's import-time logging.disable() would hide these records + previous_disable = logging.root.manager.disable + logging.disable(logging.NOTSET) + self.addCleanup(logging.disable, previous_disable) + + def test_a_failing_export_table_is_reported_at_warning(self): + macho = _MockMachoBinary([_UnreadableValueSymbol()]) + provider = MachoSymbolProvider(None) + + with ( + mock.patch("lief.MachO.Binary", _MockMachoBinary), + self.assertLogs("smda.common.labelprovider.MachoSymbolProvider", level="WARNING") as logged, + ): + self.assertEqual({}, provider.parseExports(macho)) + + self.assertIn("exports", logged.output[0]) + + def test_a_failing_symbol_table_is_reported_at_warning(self): + macho = _MockMachoBinary([_UnreadableValueSymbol()]) + provider = MachoSymbolProvider(None) + + with ( + mock.patch("lief.MachO.Binary", _MockMachoBinary), + self.assertLogs("smda.common.labelprovider.MachoSymbolProvider", level="WARNING") as logged, + ): + self.assertEqual({}, provider.parseSymbols(macho)) + + self.assertIn("symbols", logged.output[0]) + + def test_a_failing_stub_table_is_reported_at_warning(self): + macho = _MockMachoBinary([]) + macho.symbol_stubs = [_UnreadableAddressStub()] + binary_info = BinaryInfo(b"not a container") + provider = MachoSymbolProvider(None) + + with ( + mock.patch("lief.MachO.Binary", _MockMachoBinary), + mock.patch.object(binary_info, "getLiefBinary", return_value=macho), + self.assertLogs("smda.common.labelprovider.MachoSymbolProvider", level="WARNING") as logged, + ): + provider.update(binary_info) + + self.assertEqual({}, provider.getFunctionSymbols()) + self.assertIn("stubs", logged.output[0]) + + class TestMachoCorpusIntegration(unittest.TestCase): def test_bluenoroff_symbols_exports_and_imports(self): _, raw, _loader = _load_fixture("objective-see/bluenoroff") diff --git a/tests/testRustSymbolProvider.py b/tests/testRustSymbolProvider.py index d9dffdef..216f8bc2 100644 --- a/tests/testRustSymbolProvider.py +++ b/tests/testRustSymbolProvider.py @@ -1,5 +1,7 @@ +import logging import unittest from concurrent.futures import ThreadPoolExecutor +from pathlib import Path from types import SimpleNamespace from unittest import mock @@ -571,5 +573,35 @@ def test_a_const_backref_reproduces_the_referenced_value(self): self.assertEqual(demangle("_RIC1aKh4_KB4_E"), "a::<4, 4>") +class TestRustProviderFailureLogging(unittest.TestCase): + def setUp(self): + # another test module's import-time logging.disable() would hide these records + previous_disable = logging.root.manager.disable + logging.disable(logging.NOTSET) + self.addCleanup(logging.disable, previous_disable) + + def test_a_lief_parse_failure_is_reported_at_warning(self): + provider = RustSymbolProvider(None) + binary_info = BinaryInfo(b"/rustc/") + + with ( + mock.patch.object(binary_info, "getLiefBinary", side_effect=RuntimeError("boom")), + self.assertLogs("smda.common.labelprovider.RustSymbolProvider", level="WARNING") as logged, + ): + provider.update(binary_info) + + self.assertEqual({}, provider.getFunctionSymbols()) + self.assertIn("RuntimeError", logged.output[0]) + + def test_an_unreadable_binary_path_is_reported_at_warning(self): + provider = RustSymbolProvider(None) + missing = SimpleNamespace(raw_data=b"", file_path=str(Path(__file__).resolve().parent / "does_not_exist.bin")) + + with self.assertLogs("smda.common.labelprovider.RustSymbolProvider", level="WARNING") as logged: + self.assertIsNone(provider._get_binary_data(missing)) + + self.assertIn("Failed to read binary", logged.output[0]) + + if __name__ == "__main__": unittest.main()