Surface error messages from the DebugSymbols DBGShellCommands external agent; add logging for LC_NOTEs in Mach-O corefiles

[jasonmolenda]

Summary

On Darwin systems, lldb will call into the DebugSymbols framework to find the debug info (and/or binary) for a given UUID. The user may have set a DBGShellCommands preference in com.apple.DebugSymbols to find that binary by UUID. lldb will also try a binary that is set in the env var LLDB_APPLE_DSYMFORUUID_EXECUTABLE (mostly used by the testsuite) and for certain "force a binary load" binaries (e.g. the Darwin kernel binary/symbols, without which kernel debugging is largely useless), we have a special case in source/Symbol/LocateSymbolFileMacOSX.cpp that knows about a binary called /usr/local/bin/dsymForUUID that may be installed.

These DBGShellCommands programs return a plist (xml) output giving lldb the location of the dSYM and/or binary. They can also return an error message in that xml response. Today lldb does not print that error, making it difficult for users to understand why a binary was not successfully loaded.

I also added some simple logging as lldb processes LC_NOTEs in a mach-o corefile binary that can be enabled, to understand what lldb is seeing as it loads one of these.

I have another patch that I'll be uploading soon where I fix the DBGError return from a test case TestMultipleBinaryCorefile.py, although the error message is sent to the Debugger's Stdout channel so I'm not capturing/testing it in the API test right now. (the dsym-for-uuid.sh that this test case creates DOES emit a DBGError right now on an unknown uuid, but it doesn't format it correctly and lldb ignores it).

[JDevlieghere]

lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp

5454–5456

Please use LLDB_LOG(F):

LLDB_LOGF(log, "LC_NOTE 'kern ver str' found with text '%s'", result.c_str());

[jasonmolenda]

Change calls to Log::Printf to use LLDB_LOGF().

[JDevlieghere]

lldb/source/Core/DynamicLoader.cpp

241–243

Shouldn't this be the error stream?

[jasonmolenda]

fix typeo

lldb/source/Core/DynamicLoader.cpp

241–243

Ah good suggestion.

[jasonmolenda]

Update patch to send these error messages to the ErrorStream not OutputStream. Also change LocateSymbolFileMacOSX.cpp so the full command that was used to find the binary is included in the error message, to make it clearer exactly where the error message originated.

[JDevlieghere]

LGTM

lldb/source/Core/DynamicLoader.cpp

241–242

If you don't need the Stream anymore you could do

target.GetDebugger().GetErrorStream() << error.AsCString();

272–276

LLDB_LOG could simplify this a lot ;-)

lldb/source/Core/DynamicLoader.cpp

 //===-- DynamicLoader.cpp -------------------------------------------------===//
 //
 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 // See https://llvm.org/LICENSE.txt for license information.
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 
 #include "lldb/Target/DynamicLoader.h"
 
+#include "lldb/Core/Debugger.h"
 #include "lldb/Core/Module.h"
 #include "lldb/Core/ModuleList.h"
 #include "lldb/Core/ModuleSpec.h"
 #include "lldb/Core/PluginManager.h"
 #include "lldb/Core/Section.h"
 #include "lldb/Symbol/LocateSymbolFile.h"
 #include "lldb/Symbol/ObjectFile.h"
 #include "lldb/Target/MemoryRegionInfo.h"
if (uuid.IsValid()) {
 
     // If we haven't found a binary, or we don't have a SymbolFile, see
     // if there is an external search tool that can find it.
     if (!module_sp || !module_sp->GetSymbolFileFileSpec()) {
       Symbols::DownloadObjectAndSymbolFile(module_spec, error,
                                            force_symbol_search);
       if (FileSystem::Instance().Exists(module_spec.GetFileSpec())) {
         module_sp = std::make_shared<Module>(module_spec);
+      } else if (force_symbol_search && error.AsCString("") &&
+                 error.AsCString("")[0] != '\0') {
+        target.GetDebugger().GetErrorStream() << error.AsCString();
       }
     }
 
     // If we only found the executable, create a Module based on that.
     if (!module_sp && FileSystem::Instance().Exists(module_spec.GetFileSpec()))
       module_sp = std::make_shared<Module>(module_spec);
   }
 
   // If we couldn't find the binary anywhere else, as a last resort,
   // read it out of memory.
if (module_sp.get()) {
     if (!target.GetArchitecture().IsValid())
       target.SetArchitecture(module_sp->GetArchitecture());
     target.GetImages().AppendIfNeeded(module_sp, false);
 
     bool changed = false;
     if (set_address_in_target) {
       if (module_sp->GetObjectFile()) {
         if (value != LLDB_INVALID_ADDRESS) {
           LLDB_LOGF(log,
                     "DynamicLoader::LoadBinaryWithUUIDAndAddress Loading "
-                    "binary UUID %s at %s 0x%" PRIx64,
-                    uuid.GetAsString().c_str(),
+                    "binary %s UUID %s at %s 0x%" PRIx64,
+                    name.str().c_str(), uuid.GetAsString().c_str(),
                     value_is_offset ? "offset" : "address", value);
           module_sp->SetLoadAddress(target, value, value_is_offset, changed);
         } else {
           // No address/offset/slide, load the binary at file address,
           // offset 0.
           LLDB_LOGF(log,
                     "DynamicLoader::LoadBinaryWithUUIDAndAddress Loading "
-                    "binary UUID %s at file address",
-                    uuid.GetAsString().c_str());
+                    "binary %s UUID %s at file address",
+                    name.str().c_str(), uuid.GetAsString().c_str());
           module_sp->SetLoadAddress(target, 0, true /* value_is_slide */,
                                     changed);
         }
       } else {
         // In-memory image, load at its true address, offset 0.
         LLDB_LOGF(log,
                   "DynamicLoader::LoadBinaryWithUUIDAndAddress Loading binary "
-                  "UUID %s from memory at address 0x%" PRIx64,
-                  uuid.GetAsString().c_str(), value);
+                  "%s UUID %s from memory at address 0x%" PRIx64,
+                  name.str().c_str(), uuid.GetAsString().c_str(), value);
         module_sp->SetLoadAddress(target, 0, true /* value_is_slide */,
                                   changed);
       }
     }
 
     if (notify) {
       ModuleList added_module;
       added_module.Append(module_sp, false);
       target.ModulesDidLoad(added_module);
     }
   } else {
-    LLDB_LOGF(log, "Unable to find binary with UUID %s and load it at "
-                  "%s 0x%" PRIx64,
-                  uuid.GetAsString().c_str(),
-                  value_is_offset ? "offset" : "address", value);
+    if (force_symbol_search) {
+      Stream &s = target.GetDebugger().GetErrorStream();
+      s.Printf("Unable to find file");
+      if (!name.empty())
+        s.Printf(" %s", name.str().c_str());
+      if (uuid.IsValid())
+        s.Printf(" with UUID %s", uuid.GetAsString().c_str());
+      if (value != LLDB_INVALID_ADDRESS) {
+        if (value_is_offset)
+          s.Printf(" with slide 0x%" PRIx64, value);
+        else
+          s.Printf(" at address 0x%" PRIx64, value);
+      }
+      s.Printf("\n");
+    }
+    LLDB_LOGF(log,
+              "Unable to find binary %s with UUID %s and load it at "
+              name.str().c_str(), uuid.GetAsString().c_str(),
   }
 
   return module_sp;
 }
 
 int64_t DynamicLoader::ReadUnsignedIntWithSizeInBytes(addr_t addr,
                                                       int size_in_bytes) {
   Status error;

lldb/source/Plugins/DynamicLoader/Darwin-Kernel/DynamicLoaderDarwinKernel.cpp

if (!m_module_sp && m_uuid.IsValid()) {
       ModuleSpec module_spec;
       module_spec.GetUUID() = m_uuid;
       module_spec.GetArchitecture() = target.GetArchitecture();
 
       // For the kernel, we really do need an on-disk file copy of the binary
       // to do anything useful. This will force a call to dsymForUUID if it
       // exists, instead of depending on the DebugSymbols preferences being
       // set.
+      Status kernel_search_error;
       if (IsKernel()) {
-        Status error;
-        if (Symbols::DownloadObjectAndSymbolFile(module_spec, error, true)) {
+        if (Symbols::DownloadObjectAndSymbolFile(module_spec,
+                                                 kernel_search_error, true)) {
           if (FileSystem::Instance().Exists(module_spec.GetFileSpec())) {
             m_module_sp = std::make_shared<Module>(module_spec.GetFileSpec(),
                                                    target.GetArchitecture());
           }
         }
       }
 
       // If the current platform is PlatformDarwinKernel, create a ModuleSpec
if (!m_module_sp && m_uuid.IsValid()) {
       // standard search paths on the system, and on a Mac it will try calling
       // the DebugSymbols framework with the UUID to find the binary via its
       // search methods.
       if (!m_module_sp) {
         m_module_sp = target.GetOrCreateModule(module_spec, true /* notify */);
       }
 
       if (IsKernel() && !m_module_sp) {
-        Stream &s = target.GetDebugger().GetOutputStream();
+        Stream &s = target.GetDebugger().GetErrorStream();
         s.Printf("WARNING: Unable to locate kernel binary on the debugger "
                  "system.\n");
+        if (kernel_search_error.Fail() && kernel_search_error.AsCString("") &&
+            kernel_search_error.AsCString("")[0] != '\0') {
+          s << kernel_search_error.AsCString();
+        }
       }
     }
 
     if (m_module_sp && m_uuid.IsValid() && m_module_sp->GetUUID() == m_uuid &&
         m_module_sp->GetObjectFile()) {
       if (ObjectFileMachO *ondisk_objfile_macho =
               llvm::dyn_cast<ObjectFileMachO>(m_module_sp->GetObjectFile())) {
         if (!IsKernel() && !ondisk_objfile_macho->IsKext()) {

lldb/source/Plugins/ObjectFile/Mach-O/ObjectFileMachO.cpp

if (!m_thread_context_offsets_valid) {
       }
     }
   }
   return m_thread_context_offsets.GetSize();
 }
 
 std::string ObjectFileMachO::GetIdentifierString() {
   std::string result;
+  Log *log(
+      GetLog(LLDBLog::Symbols | LLDBLog::Process | LLDBLog::DynamicLoader));
   ModuleSP module_sp(GetModule());
   if (module_sp) {
     std::lock_guard<std::recursive_mutex> guard(module_sp->GetMutex());
 
     // First, look over the load commands for an LC_NOTE load command with
     // data_owner string "kern ver str" & use that if found.
     lldb::offset_t offset = MachHeaderSizeFromMagic(m_header.magic);
     for (uint32_t i = 0; i < m_header.ncmds; ++i) {
for (uint32_t i = 0; i < m_header.ncmds; ++i) {
               uint32_t strsize = size - sizeof(uint32_t);
               char *buf = (char *)malloc(strsize);
               if (buf) {
                 m_data.CopyData(offset, strsize, buf);
                 buf[strsize - 1] = '\0';
                 result = buf;
                 if (buf)
                   free(buf);
+                LLDB_LOGF(log, "LC_NOTE 'kern ver str' found with text '%s'",
+                          result.c_str());
                 return result;
               }
             }
           }
         }
       }
       offset = cmd_offset + lc.cmdsize;
     }
 
     // Second, make a pass over the load commands looking for an obsolete
     // LC_IDENT load command.
     offset = MachHeaderSizeFromMagic(m_header.magic);
     for (uint32_t i = 0; i < m_header.ncmds; ++i) {
       const uint32_t cmd_offset = offset;
       llvm::MachO::ident_command ident_command;
       if (m_data.GetU32(&offset, &ident_command, 2) == nullptr)
         break;
       if (ident_command.cmd == LC_IDENT && ident_command.cmdsize != 0) {
         char *buf = (char *)malloc(ident_command.cmdsize);
         if (buf != nullptr && m_data.CopyData(offset, ident_command.cmdsize,
                                               buf) == ident_command.cmdsize) {
           buf[ident_command.cmdsize - 1] = '\0';
           result = buf;
+          LLDB_LOGF(log, "LC_IDENT found with text '%s'", result.c_str());
         }
         if (buf)
           free(buf);
       }
       offset = cmd_offset + ident_command.cmdsize;
     }
   }
   return result;
 }
 
 addr_t ObjectFileMachO::GetAddressMask() {
   addr_t mask = 0;
+  Log *log(GetLog(LLDBLog::Process));
   ModuleSP module_sp(GetModule());
   if (module_sp) {
     std::lock_guard<std::recursive_mutex> guard(module_sp->GetMutex());
     lldb::offset_t offset = MachHeaderSizeFromMagic(m_header.magic);
     for (uint32_t i = 0; i < m_header.ncmds; ++i) {
       const uint32_t cmd_offset = offset;
       llvm::MachO::load_command lc = {};
       if (m_data.GetU32(&offset, &lc.cmd, 2) == nullptr)
for (uint32_t i = 0; i < m_header.ncmds; ++i) {
           offset = fileoff;
           uint32_t version;
           if (m_data.GetU32(&offset, &version, 1) != nullptr) {
             if (version == 3) {
               uint32_t num_addr_bits = m_data.GetU32_unchecked(&offset);
               if (num_addr_bits != 0) {
                 mask = ~((1ULL << num_addr_bits) - 1);
               }
+              LLDB_LOGF(log,
+                        "LC_NOTE 'addrable bits' found, value %d bits, "
+                        "mask 0x%" PRIx64,
+                        num_addr_bits, mask);
               break;
             }
           }
         }
       }
       offset = cmd_offset + lc.cmdsize;
     }
   }
   return mask;
 }
 
 bool ObjectFileMachO::GetCorefileMainBinaryInfo(addr_t &value,
                                                 bool &value_is_offset,
                                                 UUID &uuid,
                                                 ObjectFile::BinaryType &type) {
+  Log *log(
+      GetLog(LLDBLog::Symbols | LLDBLog::Process | LLDBLog::DynamicLoader));
   value = LLDB_INVALID_ADDRESS;
   value_is_offset = false;
   uuid.Clear();
   uint32_t log2_pagesize = 0; // not currently passed up to caller
   uint32_t platform = 0;      // not currently passed up to caller
   ModuleSP module_sp(GetModule());
   if (module_sp) {
     std::lock_guard<std::recursive_mutex> guard(module_sp->GetMutex());
for (uint32_t i = 0; i < m_header.ncmds; ++i) {
               value = slide;
               value_is_offset = true;
             }
 
             if (m_data.CopyData(offset, sizeof(uuid_t), raw_uuid) != 0) {
               uuid = UUID(raw_uuid, sizeof(uuid_t));
               // convert the "main bin spec" type into our
               // ObjectFile::BinaryType enum
+              const char *typestr = "unrecognized type";
               switch (binspec_type) {
               case 0:
                 type = eBinaryTypeUnknown;
+                typestr = "uknown";
                 break;
               case 1:
                 type = eBinaryTypeKernel;
+                typestr = "xnu kernel";
                 break;
               case 2:
                 type = eBinaryTypeUser;
+                typestr = "userland dyld";
                 break;
               case 3:
                 type = eBinaryTypeStandalone;
+                typestr = "standalone";
                 break;
               }
+              LLDB_LOGF(log,
+                        "LC_NOTE 'main bin spec' found, version %d type %d "
+                        "(%s), value 0x%" PRIx64 " value-is-slide==%s uuid %s",
+                        version, type, typestr, value,
+                        value_is_offset ? "true" : "false",
+                        uuid.GetAsString().c_str());
               if (!m_data.GetU32(&offset, &log2_pagesize, 1))
                 return false;
               if (version > 1 && !m_data.GetU32(&offset, &platform, 1))
                 return false;
               return true;
             }
           }
         }
return true; // This is the right plug to handle saving core files for
                  // this process
   }
   return false;
 }
 
 ObjectFileMachO::MachOCorefileAllImageInfos
 ObjectFileMachO::GetCorefileAllImageInfos() {
   MachOCorefileAllImageInfos image_infos;
+  Log *log(
+      GetLog(LLDBLog::Symbols | LLDBLog::Process | LLDBLog::DynamicLoader));
 
   // Look for an "all image infos" LC_NOTE.
   lldb::offset_t offset = MachHeaderSizeFromMagic(m_header.magic);
   for (uint32_t i = 0; i < m_header.ncmds; ++i) {
     const uint32_t cmd_offset = offset;
     llvm::MachO::load_command lc = {};
     if (m_data.GetU32(&offset, &lc.cmd, 2) == nullptr)
       break;
if (lc.cmd == LC_NOTE) {
           return image_infos;
         }
         uint32_t imgcount = m_data.GetU32(&offset);
         uint64_t entries_fileoff = m_data.GetU64(&offset);
         // 'entries_size' is not used, nor is the 'unused' entry.
         //  offset += 4; // uint32_t entries_size;
         //  offset += 4; // uint32_t unused;
 
+        LLDB_LOGF(log,
+                  "LC_NOTE 'all image infos' found version %d with %d images",
+                  version, imgcount);
         offset = entries_fileoff;
         for (uint32_t i = 0; i < imgcount; i++) {
           // Read the struct image_entry.
           offset_t filepath_offset = m_data.GetU64(&offset);
           uuid_t uuid;
           memcpy(&uuid, m_data.GetData(&offset, sizeof(uuid_t)),
                  sizeof(uuid_t));
           uint64_t load_address = m_data.GetU64(&offset);
if (lc.cmd == LC_NOTE) {
             seg_vmaddrs_offset += 16;
             uint64_t vmaddr = m_data.GetU64(&seg_vmaddrs_offset);
             seg_vmaddrs_offset += 8; /* unused */
 
             std::tuple<ConstString, addr_t> new_seg{ConstString(segname),
                                                     vmaddr};
             image_entry.segment_load_addresses.push_back(new_seg);
           }
+          LLDB_LOGF(
+              log, "  image entry: %s %s 0x%" PRIx64 " %s",
+              image_entry.filename.c_str(),
+              image_entry.uuid.GetAsString().c_str(), image_entry.load_address,
+              image_entry.currently_executing ? "currently executing"
+                                              : "not currently executing");
           image_infos.all_image_infos.push_back(image_entry);
         }
       } else if (strcmp("load binary", data_owner) == 0) {
         uint32_t version = m_data.GetU32(&fileoff);
         if (version == 1) {
           uuid_t uuid;
           memcpy(&uuid, m_data.GetData(&fileoff, sizeof(uuid_t)),
                  sizeof(uuid_t));
           uint64_t load_address = m_data.GetU64(&fileoff);
           uint64_t slide = m_data.GetU64(&fileoff);
           std::string filename = m_data.GetCStr(&fileoff);
 
           MachOCorefileImageEntry image_entry;
           image_entry.filename = filename;
           image_entry.uuid = UUID(uuid, sizeof(uuid_t));
           image_entry.load_address = load_address;
           image_entry.slide = slide;
           image_entry.currently_executing = true;
           image_infos.all_image_infos.push_back(image_entry);
+          LLDB_LOGF(log,
+                    "LC_NOTE 'load binary' found, filename %s uuid %s load "
+                    "address 0x%" PRIx64 " slide 0x%" PRIx64,
+                    filename.c_str(),
+                    image_entry.uuid.IsValid()
+                        ? image_entry.uuid.GetAsString().c_str()
+                        : "00000000-0000-0000-0000-000000000000",
+                    load_address, slide);
         }
       }
     }
     offset = cmd_offset + lc.cmdsize;
   }
 
   return image_infos;
 }

lldb/source/Symbol/LocateSymbolFileMacOSX.cpp

for (; Iter != End && !EC; Iter.increment(EC)) {
     }
   }
 
   return {};
 }
 
 static bool GetModuleSpecInfoFromUUIDDictionary(CFDictionaryRef uuid_dict,
                                                 ModuleSpec &module_spec,
-                                                Status &error) {
+                                                Status &error,
+                                                const std::string &command) {
   Log *log = GetLog(LLDBLog::Host);
   bool success = false;
   if (uuid_dict != NULL && CFGetTypeID(uuid_dict) == CFDictionaryGetTypeID()) {
     std::string str;
     CFStringRef cf_str;
     CFDictionaryRef cf_dict;
 
     cf_str = (CFStringRef)CFDictionaryGetValue((CFDictionaryRef)uuid_dict,
                                                CFSTR("DBGError"));
     if (cf_str && CFGetTypeID(cf_str) == CFStringGetTypeID()) {
       if (CFCString::FileSystemRepresentation(cf_str, str)) {
-        error.SetErrorString(str);
+        std::string errorstr = command;
+        errorstr += ":\n";
+        errorstr += str;
+        error.SetErrorString(errorstr);
       }
     }
 
     cf_str = (CFStringRef)CFDictionaryGetValue(
         (CFDictionaryRef)uuid_dict, CFSTR("DBGSymbolRichExecutable"));
     if (cf_str && CFGetTypeID(cf_str) == CFStringGetTypeID()) {
       if (CFCString::FileSystemRepresentation(cf_str, str)) {
         module_spec.GetFileSpec().SetFile(str.c_str(), FileSpec::Style::native);
LLDB_LOGF(log, "'%s' failed: output plist is not a valid CFDictionary",
               command.GetData());
     return false;
   }
 
   if (!uuid_str.empty()) {
     CFCString uuid_cfstr(uuid_str.c_str());
     CFDictionaryRef uuid_dict =
         (CFDictionaryRef)CFDictionaryGetValue(plist.get(), uuid_cfstr.get());
-    return GetModuleSpecInfoFromUUIDDictionary(uuid_dict, module_spec, error);
+    return GetModuleSpecInfoFromUUIDDictionary(uuid_dict, module_spec, error,
+                                               command.GetData());
   }
 
   if (const CFIndex num_values = ::CFDictionaryGetCount(plist.get())) {
     std::vector<CFStringRef> keys(num_values, NULL);
     std::vector<CFDictionaryRef> values(num_values, NULL);
     ::CFDictionaryGetKeysAndValues(plist.get(), NULL,
                                    (const void **)&values[0]);
     if (num_values == 1) {
-      return GetModuleSpecInfoFromUUIDDictionary(values[0], module_spec, error);
+      return GetModuleSpecInfoFromUUIDDictionary(values[0], module_spec, error,
+                                                 command.GetData());
     }
 
     for (CFIndex i = 0; i < num_values; ++i) {
       ModuleSpec curr_module_spec;
       if (GetModuleSpecInfoFromUUIDDictionary(values[i], curr_module_spec,
-                                              error)) {
+                                              error, command.GetData())) {
         if (module_spec.GetArchitecture().IsCompatibleMatch(
                 curr_module_spec.GetArchitecture())) {
           module_spec = curr_module_spec;
           return true;
         }
       }
     }
   }
 
   return false;
 }