elf: add debug statement aiming to help diagnose problems

Signed-off-by: Waldemar Kozaczuk <jwkozaczuk@gmail.com>

Author: wkozaczuk

core/elf.cc

@@ -30,6 +30,14 @@
 
 #include "arch.hh"
 
+#define ELF_DEBUG_ENABLED 0
+
+#if ELF_DEBUG_ENABLED
+#define elf_debug(format,...) kprintf("ELF [tid:%d, %s]: " format, sched::thread::current()->id(), _pathname.c_str(), ##__VA_ARGS__)
+#else
+#define elf_debug(...)
+#endif
+
 TRACEPOINT(trace_elf_load, "%s", const char *);
 TRACEPOINT(trace_elf_unload, "%s", const char *);
 TRACEPOINT(trace_elf_lookup, "%s", const char *);
@@ -116,10 +124,12 @@ object::object(program& prog, std::string pathname)
     , _is_executable(false)
     , _visibility(nullptr)
 {
+    elf_debug("Instantiated\n");
 }
 
 object::~object()
 {
+    elf_debug("Removed\n");
     _prog.free_dtv(this);
 }
 
@@ -327,6 +337,7 @@ void object::set_base(void* base)
     }
 
     _end = _base + q->p_vaddr + q->p_memsz;
+    elf_debug("The base set to: 0x%016x and end: 0x%016x\n", _base, _end);
 }
 
 void* object::base() const
@@ -367,6 +378,7 @@ void file::load_segment(const Elf64_Phdr& phdr)
             mmu::map_anon(_base + vstart + filesz, memsz - filesz, flag, perm);
         }
     }
+    elf_debug("Loaded and mapped PT_LOAD segment at: 0x%016x of size: 0x%x\n", _base + vstart, filesz); //TODO: Add memory?
 }
 
 bool object::mlocked()
@@ -407,6 +419,7 @@ Elf64_Note::Elf64_Note(void *_base, char *str)
 extern "C" char _pie_static_tls_start, _pie_static_tls_end;
 void object::load_segments()
 {
+    elf_debug("Loading segments\n");
     for (unsigned i = 0; i < _ehdr.e_phnum; ++i) {
         auto &phdr = _phdrs[i];
         switch (phdr.p_type) {
@@ -462,6 +475,7 @@ void object::load_segments()
             _tls_init_size = phdr.p_filesz;
             _tls_uninit_size = phdr.p_memsz - phdr.p_filesz;
             _tls_alignment = phdr.p_align;
+            elf_debug("Found TLS segment at 0x%016x of aligned size: %x\n", _tls_segment, get_aligned_tls_size());
             break;
         default:
             abort("Unknown p_type in executable %s: %d\n", pathname(), phdr.p_type);
@@ -693,6 +707,7 @@ void object::relocate_rela()
             abort();
         }
     }
+    elf_debug("Relocated %d symbols in DT_RELA\n", nb);
 }
 
 extern "C" { void __elf_resolve_pltgot(void); }
@@ -741,6 +756,7 @@ void object::relocate_pltgot()
             *static_cast<u64*>(addr) += reinterpret_cast<u64>(_base);
         }
     }
+    elf_debug("Relocated %d PLT symbols in DT_JMPREL\n", nrel);
 
     // PLTGOT resolution has a special calling convention,
     // for x64 the symbol index and some word is pushed on the stack,
@@ -987,6 +1003,7 @@ void object::load_needed(std::vector<std::shared_ptr<object>>& loaded_objects)
     }
     auto needed = dynamic_str_array(DT_NEEDED);
     for (auto lib : needed) {
+        elf_debug("Loading DT_NEEDED object: %s \n", lib);
         auto obj = _prog.load_object(lib, rpath, loaded_objects);
         if (obj) {
             // Keep a reference to the needed object, so it won't be
@@ -1000,6 +1017,7 @@ void object::load_needed(std::vector<std::shared_ptr<object>>& loaded_objects)
 
 void object::unload_needed()
 {
+    elf_debug("Unloading object dependent objects \n");
     _used_by_resolve_plt_got.clear();
     while (!_needed.empty()) {
         _needed.pop_back();
@@ -1049,15 +1067,19 @@ void object::run_init_funcs(int argc, char** argv)
     if (dynamic_exists(DT_INIT)) {
         auto func = dynamic_ptr<void>(DT_INIT);
         if (func) {
+            elf_debug("Executing DT_INIT function\n");
             reinterpret_cast<void(*)(int, char**)>(func)(argc, argv);
+            elf_debug("Finished executing DT_INIT function\n");
         }
     }
     if (dynamic_exists(DT_INIT_ARRAY)) {
         auto funcs = dynamic_ptr<void(*)(int, char**)>(DT_INIT_ARRAY);
         auto nr = dynamic_val(DT_INIT_ARRAYSZ) / sizeof(*funcs);
+        elf_debug("Executing %d DT_INIT_ARRAYSZ functions\n", nr);
         for (auto i = 0u; i < nr; ++i) {
             funcs[i](argc, argv);
         }
+        elf_debug("Finished executing %d DT_INIT_ARRAYSZ functions\n", nr);
     }
 }
 
@@ -1067,14 +1089,17 @@ void object::run_fini_funcs()
     if (dynamic_exists(DT_FINI_ARRAY)) {
         auto funcs = dynamic_ptr<void (*)()>(DT_FINI_ARRAY);
         auto nr = dynamic_val(DT_FINI_ARRAYSZ) / sizeof(*funcs);
+        elf_debug("Executing %d DT_FINI_ARRAYSZ functions\n", nr);
         // According to the standard, call functions in reverse order.
         for (int i = nr - 1; i >= 0; --i) {
             funcs[i]();
         }
+        elf_debug("Finished executing %d DT_FINI_ARRAYSZ functions\n", nr);
     }
     if (dynamic_exists(DT_FINI)) {
         auto func = dynamic_ptr<void>(DT_FINI);
         if (func) {
+            elf_debug("Executing DT_FINI function\n");
             reinterpret_cast<void(*)()>(func)();
         }
     }
@@ -1096,6 +1121,7 @@ void object::alloc_static_tls()
     if (!_static_tls && tls_size) {
         _static_tls = true;
         _static_tls_offset = _static_tls_alloc.fetch_add(tls_size, std::memory_order_relaxed);
+        elf_debug("Allocated static TLS at 0x%016x of size: 0x%x\n", _static_tls_offset, tls_size);
     }
 }
 
@@ -1131,10 +1157,12 @@ void object::init_static_tls()
         }
         if (obj->is_executable()) {
             obj->prepare_local_tls(_initial_tls_offsets);
+            elf_debug("Initialized local-exec static TLS for %s\n", obj->pathname().c_str());
         }
         else {
             obj->prepare_initial_tls(_initial_tls.get(), _initial_tls_size,
                                      _initial_tls_offsets);
+            elf_debug("Initialized initial-exec static TLS for %s of size: 0x%x\n", obj->pathname().c_str(), _initial_tls_size);
         }
     }
 }
@@ -1712,6 +1740,7 @@ struct module_and_offset {
 
 char *object::setup_tls()
 {
+    elf_debug("Setting up dynamic TLS of %d bytes\n", _tls_init_size + _tls_uninit_size);
     return (char *) sched::thread::current()->setup_tls(
             _module_index, _tls_segment, _tls_init_size, _tls_uninit_size);
 }