much more verbose logging in hook

CMakeLists.txt

@@ -10,6 +10,10 @@ set(CMAKE_CXX_STANDARD_REQUIRED ON)
 set(CMAKE_SKIP_RPATH ON)
 set(CMAKE_EXPORT_COMPILE_COMMANDS ON)
 
+if(CMAKE_BUILD_TYPE STREQUAL "Release")
+    add_definitions("-DLSFG_NO_DEBUG")
+endif()
+
 # subprojects
 include(cmake/FetchDXVK.cmake)
 include(cmake/FetchPeParse.cmake)

include/utils/log.hpp

@@ -2,35 +2,72 @@
 #define LOG_HPP
 
 #include <format>
+#include <fstream>
 #include <iostream>
+#include <mutex>
+#include <set>
 
 namespace Log {
 
+    namespace Internal {
+        extern bool isSetup;
+
+        extern std::set<std::string> debugModules;
+        extern bool debugAllModules;
+
+        extern std::ofstream logFile;
+        extern std::mutex logMutex;
+
+        void setup();
+    }
+
+    template<typename... Args>
+    void log(std::string_view color, std::string_view module,
+            std::format_string<Args...> fmt, Args&&... args) {
+        Internal::setup();
+
+        std::string prefix = std::format("lsfg-vk({}): ", module);
+        std::string message = std::format(fmt, std::forward<Args>(args)...);
+
+        std::lock_guard<std::mutex> lock(Internal::logMutex);
+        std::cerr << color << prefix << message << "\033[0m" << '\n';
+        if (Internal::logFile.is_open()) {
+            Internal::logFile << prefix << message << '\n';
+            Internal::logFile.flush();
+        }
+    }
+
     const std::string_view WHITE = "\033[1;37m";
     const std::string_view YELLOW = "\033[1;33m";
     const std::string_view RED = "\033[1;31m";
+
+    template<typename... Args>
+    void info(std::string_view module, std::format_string<Args...> fmt, Args&&... args) {
+        log(WHITE, module, fmt, std::forward<Args>(args)...);
+    }
+
+    template<typename... Args>
+    void warn(std::string_view module, std::format_string<Args...> fmt, Args&&... args) {
+        log(YELLOW, module, fmt, std::forward<Args>(args)...);
+    }
+
+    template<typename... Args>
+    void error(std::string_view module, std::format_string<Args...> fmt, Args&&... args) {
+        log(RED, module, fmt, std::forward<Args>(args)...);
+    }
+
     const std::string_view GRAY = "\033[1;90m";
-    const std::string_view RESET = "\033[0m";
 
+#ifdef LSFG_NO_DEBUG
+template<typename... Args>
+void debug(std::string_view, std::format_string<Args...>, Args&&...) {} // NOLINT
+#else
     template<typename... Args>
-    void info(std::format_string<Args...> fmt, Args&&... args) {
+    void debug(std::string_view module, std::format_string<Args...> fmt, Args&&... args) {
-        std::cerr << WHITE << std::format(fmt, std::forward<Args>(args)...) << RESET << '\n';
+        if (Internal::debugAllModules || Internal::debugModules.contains(std::string(module)))
-    }
+            log(GRAY, module, fmt, std::forward<Args>(args)...);
-
-    template<typename... Args>
-    void warn(std::format_string<Args...> fmt, Args&&... args) {
-        std::cerr << YELLOW << std::format(fmt, std::forward<Args>(args)...) << RESET << '\n';
-    }
-
-    template<typename... Args>
-    void error(std::format_string<Args...> fmt, Args&&... args) {
-        std::cerr << RED << std::format(fmt, std::forward<Args>(args)...) << RESET << '\n';
-    }
-
-    template<typename... Args>
-    void debug(std::format_string<Args...> fmt, Args&&... args) {
-        std::cerr << GRAY << std::format(fmt, std::forward<Args>(args)...) << RESET << '\n';
     }
+#endif
 
 }
 

src/context.cpp

@@ -1,5 +1,6 @@
 #include "context.hpp"
 #include "layer.hpp"
+#include "utils/log.hpp"
 #include "utils/utils.hpp"
 
 #include <lsfg.hpp>
@@ -11,7 +12,7 @@ LsContext::LsContext(const Hooks::DeviceInfo& info, VkSwapchainKHR swapchain,
         VkExtent2D extent, const std::vector<VkImage>& swapchainImages)
         : swapchain(swapchain), swapchainImages(swapchainImages),
           extent(extent) {
-    // initialize lsfg
+    // prepare textures for lsfg
     int frame_0_fd{};
     this->frame_0 = Mini::Image(
         info.device, info.physicalDevice,
@@ -19,6 +20,8 @@ LsContext::LsContext(const Hooks::DeviceInfo& info, VkSwapchainKHR swapchain,
         VK_IMAGE_USAGE_TRANSFER_DST_BIT,
         VK_IMAGE_ASPECT_COLOR_BIT,
         &frame_0_fd);
+    Log::info("context", "Created frame_0 image and obtained fd: {}",
+        frame_0_fd);
 
     int frame_1_fd{};
     this->frame_1 = Mini::Image(
@@ -27,27 +30,42 @@ LsContext::LsContext(const Hooks::DeviceInfo& info, VkSwapchainKHR swapchain,
         VK_IMAGE_USAGE_TRANSFER_DST_BIT,
         VK_IMAGE_ASPECT_COLOR_BIT,
         &frame_1_fd);
+    Log::info("context", "Created frame_1 image and obtained fd: {}",
+        frame_1_fd);
 
     std::vector<int> out_n_fds(info.frameGen);
-    for (size_t i = 0; i < info.frameGen; ++i)
+    for (size_t i = 0; i < info.frameGen; ++i) {
         this->out_n.emplace_back(
             info.device, info.physicalDevice,
             extent, VK_FORMAT_R8G8B8A8_UNORM,
             VK_IMAGE_USAGE_TRANSFER_SRC_BIT,
             VK_IMAGE_ASPECT_COLOR_BIT,
             &out_n_fds.at(i));
+        Log::info("context", "Created out_n[{}] image and obtained fd: {}",
+            i, out_n_fds.at(i));
+    }
 
+    // initialize lsfg
+    Log::debug("context", "(entering LSFG initialization)");
     Utils::storeLayerEnv();
     LSFG::initialize();
     Utils::restoreLayerEnv();
+    Log::debug("context", "(exiting LSFG initialization)");
 
+    Log::debug("context", "(entering LSFG context creation)");
     this->lsfgCtxId = std::shared_ptr<int32_t>(
         new int32_t(LSFG::createContext(extent.width, extent.height,
             frame_0_fd, frame_1_fd, out_n_fds)),
         [](const int32_t* id) {
+            Log::info("context",
+                "(entering LSFG context deletion with id: {})", *id);
             LSFG::deleteContext(*id);
+            Log::info("context",
+                "(exiting LSFG context deletion with id: {})", *id);
         }
     );
+    Log::info("context", "(exiting LSFG context creation with id: {})",
+        *this->lsfgCtxId);
 
     // prepare render passes
     this->cmdPool = Mini::CommandPool(info.device, info.queue.first);
@@ -59,6 +77,8 @@ LsContext::LsContext(const Hooks::DeviceInfo& info, VkSwapchainKHR swapchain,
         pass.postCopySemaphores.resize(info.frameGen);
         pass.prevPostCopySemaphores.resize(info.frameGen);
     }
+
+    Log::info("context", "Remaining misc context init finished successfully.");
 }
 
 VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, VkQueue queue,
@@ -66,6 +86,8 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk
     auto& pass = this->passInfos.at(this->frameIdx % 8);
 
     // 1. copy swapchain image to frame_0/frame_1
+    Log::debug("context2", "1. Copying swapchain image {} to frame {}",
+        presentIdx, this->frameIdx % 2 == 0 ? "0" : "1");
     int preCopySemaphoreFd{};
     pass.preCopySemaphores.at(0) = Mini::Semaphore(info.device, &preCopySemaphoreFd);
     pass.preCopySemaphores.at(1) = Mini::Semaphore(info.device);
@@ -91,16 +113,22 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk
           pass.preCopySemaphores.at(1).handle() });
 
     // 2. render intermediary frames
+    Log::debug("context2", "2. Rendering intermediary frames");
     std::vector<int> renderSemaphoreFds(info.frameGen);
     for (size_t i = 0; i < info.frameGen; ++i)
         pass.renderSemaphores.at(i) = Mini::Semaphore(info.device, &renderSemaphoreFds.at(i));
 
+    Log::debug("context2",
+        "(entering LSFG present with id: {})", *this->lsfgCtxId);
     LSFG::presentContext(*this->lsfgCtxId,
         preCopySemaphoreFd,
         renderSemaphoreFds);
+    Log::debug("context2",
+        "(exiting LSFG present with id: {})", *this->lsfgCtxId);
 
     for (size_t i = 0; i < info.frameGen; i++) {
         // 3. acquire next swapchain image
+        Log::debug("context2", "3. Acquiring next swapchain image for frame {}", i);
         pass.acquireSemaphores.at(i) = Mini::Semaphore(info.device);
         uint32_t imageIdx{};
         auto res = Layer::ovkAcquireNextImageKHR(info.device, this->swapchain, UINT64_MAX,
@@ -109,6 +137,7 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk
             throw LSFG::vulkan_error(res, "Failed to acquire next swapchain image");
 
         // 4. copy output image to swapchain image
+        Log::debug("context2", "4. Copying output image to swapchain image for frame {}", i);
         pass.postCopySemaphores.at(i) = Mini::Semaphore(info.device);
         pass.prevPostCopySemaphores.at(i) = Mini::Semaphore(info.device);
         pass.postCopyBufs.at(i) = Mini::CommandBuffer(info.device, this->cmdPool);
@@ -129,6 +158,7 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk
               pass.prevPostCopySemaphores.at(i).handle() });
 
         // 5. present swapchain image
+        Log::debug("context2", "5. Presenting swapchain image for frame {}", i);
         std::vector<VkSemaphore> waitSemaphores{ pass.postCopySemaphores.at(i).handle() };
         if (i != 0) waitSemaphores.emplace_back(pass.prevPostCopySemaphores.at(i - 1).handle());
 
@@ -147,6 +177,7 @@ VkResult LsContext::present(const Hooks::DeviceInfo& info, const void* pNext, Vk
     }
 
     // 6. present actual next frame
+    Log::debug("context2", "6. Presenting actual next frame");
     VkSemaphore lastPrevPostCopySemaphore =
         pass.prevPostCopySemaphores.at(info.frameGen - 1).handle();
     const VkPresentInfoKHR presentInfo{

src/hooks.cpp

@@ -27,18 +27,26 @@ namespace {
                 "VK_KHR_external_memory_capabilities",
                 "VK_KHR_external_semaphore_capabilities"
             });
-
-        Log::info("lsfg-vk: Created Vulkan instance");
         VkInstanceCreateInfo createInfo = *pCreateInfo;
         createInfo.enabledExtensionCount = static_cast<uint32_t>(extensions.size());
         createInfo.ppEnabledExtensionNames = extensions.data();
-        return Layer::ovkCreateInstance(&createInfo, pAllocator, pInstance);
+        auto res = Layer::ovkCreateInstance(&createInfo, pAllocator, pInstance);
+        if (res != VK_SUCCESS) {
+            Log::error("hooks", "Failed to create Vulkan instance: {:x}",
+                static_cast<uint32_t>(res));
+            return res;
+        }
+
+        Log::info("hooks", "Instance created successfully: {:x}",
+            reinterpret_cast<uintptr_t>(*pInstance));
+        return res;
     }
 
     void myvkDestroyInstance(
             VkInstance instance,
             const VkAllocationCallbacks* pAllocator) {
-        Log::info("lsfg-vk: Destroyed Vulkan instance");
+        Log::info("hooks", "Instance destroyed successfully: {:x}",
+            reinterpret_cast<uintptr_t>(instance));
         Layer::ovkDestroyInstance(instance, pAllocator);
     }
 
@@ -63,38 +71,59 @@ namespace {
         VkDeviceCreateInfo createInfo = *pCreateInfo;
         createInfo.enabledExtensionCount = static_cast<uint32_t>(extensions.size());
         createInfo.ppEnabledExtensionNames = extensions.data();
-        return Layer::ovkCreateDevice(physicalDevice, &createInfo, pAllocator, pDevice);
+        auto res = Layer::ovkCreateDevice(physicalDevice, &createInfo, pAllocator, pDevice);
+        if (res != VK_SUCCESS) {
+            Log::error("hooks", "Failed to create Vulkan device: {:x}",
+                static_cast<uint32_t>(res));
+            return res;
+        }
+
+        Log::info("hooks", "Device created successfully: {:x}",
+            reinterpret_cast<uintptr_t>(*pDevice));
+        return res;
     }
 
     VkResult myvkCreateDevicePost(
             VkPhysicalDevice physicalDevice,
             VkDeviceCreateInfo* pCreateInfo,
-            const VkAllocationCallbacks* pAllocator,
+            const VkAllocationCallbacks*, // NOLINT
             VkDevice* pDevice) {
         // store device info
+        Log::debug("hooks", "Creating device info for device: {:x}",
+            reinterpret_cast<uintptr_t>(*pDevice));
         try {
-            const char* frameGen = std::getenv("LSFG_MULTIPLIER");
+            const char* frameGenEnv = std::getenv("LSFG_MULTIPLIER");
-            if (!frameGen) frameGen = "2";
+            const uint64_t frameGen = std::max<uint64_t>(1,
+                std::stoul(frameGenEnv ? frameGenEnv : "2") - 1);
+            Log::debug("hooks", "Using {}x frame generation",
+                frameGen + 1);
+
+            auto queue = Utils::findQueue(*pDevice, physicalDevice, pCreateInfo,
+                VK_QUEUE_GRAPHICS_BIT | VK_QUEUE_COMPUTE_BIT);
+            Log::debug("hooks", "Found queue at index {}: {:x}",
+                queue.first, reinterpret_cast<uintptr_t>(queue.second));
+
             devices.emplace(*pDevice, DeviceInfo {
                 .device = *pDevice,
                 .physicalDevice = physicalDevice,
-                .queue = Utils::findQueue(*pDevice, physicalDevice, pCreateInfo,
+                .queue = queue,
-                    VK_QUEUE_GRAPHICS_BIT),
+                .frameGen = frameGen,
-                .frameGen = std::max<size_t>(1, std::stoul(frameGen) - 1)
             });
         } catch (const std::exception& e) {
-            Log::error("Failed to create device info: {}", e.what());
+            Log::error("hooks", "Failed to create device info: {}", e.what());
             return VK_ERROR_INITIALIZATION_FAILED;
         }
 
-        Log::info("lsfg-vk: Created Vulkan device");
+        Log::info("hooks", "Device info created successfully for: {:x}",
+            reinterpret_cast<uintptr_t>(*pDevice));
         return VK_SUCCESS;
     }
 
     void myvkDestroyDevice(VkDevice device, const VkAllocationCallbacks* pAllocator) {
         devices.erase(device); // erase device info
 
-        Log::info("lsfg-vk: Destroyed Vulkan device");
+        Log::info("hooks", "Device & Device info destroyed successfully: {:x}",
+            reinterpret_cast<uintptr_t>(device));
         Layer::ovkDestroyDevice(device, pAllocator);
     }
 
@@ -118,10 +147,25 @@ namespace {
         createInfo.presentMode = VK_PRESENT_MODE_FIFO_KHR; // force vsync
         auto res = Layer::ovkCreateSwapchainKHR(device, &createInfo, pAllocator, pSwapchain);
         if (res != VK_SUCCESS) {
-            Log::error("Failed to create swapchain: {:x}", static_cast<uint32_t>(res));
+            Log::error("hooks", "Failed to create swapchain: {:x}", static_cast<uint32_t>(res));
             return res;
         }
+        Log::info("hooks", "Swapchain created successfully: {:x}",
+            reinterpret_cast<uintptr_t>(*pSwapchain));
 
+        // retire previous swapchain if it exists
+        if (pCreateInfo->oldSwapchain) {
+            Log::debug("hooks", "Retiring previous swapchain context: {:x}",
+                reinterpret_cast<uintptr_t>(pCreateInfo->oldSwapchain));
+            swapchains.erase(pCreateInfo->oldSwapchain);
+            swapchainToDeviceTable.erase(pCreateInfo->oldSwapchain);
+            Log::info("hooks", "Previous swapchain context retired successfully: {:x}",
+                reinterpret_cast<uintptr_t>(pCreateInfo->oldSwapchain));
+        }
+
+        // create swapchain context
+        Log::debug("hooks", "Creating swapchain context for device: {:x}",
+            reinterpret_cast<uintptr_t>(device));
         try {
             // get swapchain images
             uint32_t imageCount{};
@@ -133,24 +177,25 @@ namespace {
             res = Layer::ovkGetSwapchainImagesKHR(device, *pSwapchain, &imageCount, swapchainImages.data());
             if (res != VK_SUCCESS)
                 throw LSFG::vulkan_error(res, "Failed to get swapchain images");
+            Log::debug("hooks", "Swapchain has {} images", swapchainImages.size());
 
             // create swapchain context
             swapchains.emplace(*pSwapchain, LsContext(
                 deviceInfo, *pSwapchain, pCreateInfo->imageExtent,
                 swapchainImages
             ));
-
             swapchainToDeviceTable.emplace(*pSwapchain, device);
         } catch (const LSFG::vulkan_error& e) {
-            Log::error("Encountered Vulkan error {:x} while creating swapchain: {}",
+            Log::error("hooks", "Encountered Vulkan error {:x} while creating swapchain context: {}",
                 static_cast<uint32_t>(e.error()), e.what());
             return e.error();
         } catch (const std::exception& e) {
-            Log::error("Encountered error while creating swapchain: {}", e.what());
+            Log::error("hooks", "Encountered error while creating swapchain context: {}", e.what());
             return VK_ERROR_INITIALIZATION_FAILED;
         }
 
-        Log::info("lsfg-vk: Created swapchain with {} images", pCreateInfo->minImageCount);
+        Log::info("hooks", "Swapchain context created successfully for: {:x}",
+            reinterpret_cast<uintptr_t>(*pSwapchain));
         return res;
     }
 
@@ -160,21 +205,33 @@ namespace {
         auto& deviceInfo = devices.at(swapchainToDeviceTable.at(*pPresentInfo->pSwapchains));
         auto& swapchain = swapchains.at(*pPresentInfo->pSwapchains);
 
+        Log::debug("hooks2", "Presenting swapchain: {:x} on queue: {:x}",
+            reinterpret_cast<uintptr_t>(*pPresentInfo->pSwapchains),
+            reinterpret_cast<uintptr_t>(queue));
+        VkResult res{};
         try {
-            std::vector<VkSemaphore> waitSemaphores(pPresentInfo->waitSemaphoreCount);
+            std::vector<VkSemaphore> semaphores(pPresentInfo->waitSemaphoreCount);
-            std::copy_n(pPresentInfo->pWaitSemaphores, waitSemaphores.size(), waitSemaphores.data());
+            std::copy_n(pPresentInfo->pWaitSemaphores, semaphores.size(), semaphores.data());
+            Log::debug("hooks2", "Waiting on {} semaphores", semaphores.size());
 
             // present the next frame
-            return swapchain.present(deviceInfo, pPresentInfo->pNext,
+            res = swapchain.present(deviceInfo, pPresentInfo->pNext,
-                queue, waitSemaphores, *pPresentInfo->pImageIndices);
+                queue, semaphores, *pPresentInfo->pImageIndices);
         } catch (const LSFG::vulkan_error& e) {
-            Log::error("Encountered Vulkan error {:x} while presenting: {}",
+            Log::error("hooks2", "Encountered Vulkan error {:x} while presenting: {}",
                 static_cast<uint32_t>(e.error()), e.what());
             return e.error();
         } catch (const std::exception& e) {
-            Log::error("Encountered error while creating presenting: {}", e.what());
+            Log::error("hooks2", "Encountered error while creating presenting: {}",
+                e.what());
             return VK_ERROR_INITIALIZATION_FAILED;
         }
+
+        // non VK_SUCCESS or VK_SUBOPTIMAL_KHR doesn't reach here
+        Log::debug("hooks2", "Presented swapchain {:x} on queue {:x} successfully",
+            reinterpret_cast<uintptr_t>(*pPresentInfo->pSwapchains),
+            reinterpret_cast<uintptr_t>(queue));
+        return res;
     }
 
     void myvkDestroySwapchainKHR(
@@ -184,7 +241,8 @@ namespace {
         swapchains.erase(swapchain); // erase swapchain context
         swapchainToDeviceTable.erase(swapchain);
 
-        Log::info("lsfg-vk: Destroyed swapchain");
+        Log::info("hooks", "Swapchain & Swapchain context destroyed successfully: {:x}",
+            reinterpret_cast<uintptr_t>(swapchain));
         Layer::ovkDestroySwapchainKHR(device, swapchain, pAllocator);
     }
 }

src/layer.cpp

@@ -51,7 +51,7 @@ namespace {
     bool initInstanceFunc(VkInstance instance, const char* name, T* func) {
         *func = reinterpret_cast<T>(next_vkGetInstanceProcAddr(instance, name));
         if (!*func) {
-            Log::error("lsfg-vk(layer): Failed to get instance function pointer for {}", name);
+            Log::error("layer", "Failed to get instance function pointer for {}", name);
             return false;
         }
         return true;
@@ -61,7 +61,7 @@ namespace {
     bool initDeviceFunc(VkDevice device, const char* name, T* func) {
         *func = reinterpret_cast<T>(next_vkGetDeviceProcAddr(device, name));
         if (!*func) {
-            Log::error("lsfg-vk(layer): Failed to get device function pointer for {}", name);
+            Log::error("layer", "Failed to get device function pointer for {}", name);
             return false;
         }
         return true;
@@ -74,7 +74,7 @@ namespace {
             const VkInstanceCreateInfo* pCreateInfo,
             const VkAllocationCallbacks* pAllocator,
             VkInstance* pInstance) {
-        Log::debug("lsfg-vk(layer): Initializing lsfg-vk instance layer");
+        Log::debug("layer", "Initializing lsfg-vk instance layer...");
 
         // find layer creation info
         auto* layerDesc = const_cast<VkLayerInstanceCreateInfo*>(
@@ -85,12 +85,15 @@ namespace {
                 reinterpret_cast<const VkLayerInstanceCreateInfo*>(layerDesc->pNext));
         }
         if (!layerDesc) {
-            Log::error("lsfg-vk(layer): No layer creation info found in pNext chain");
+            Log::error("layer", "No layer creation info found in pNext chain");
             return VK_ERROR_INITIALIZATION_FAILED;
         }
 
         // advance link info (i don't really know what this does)
         next_vkGetInstanceProcAddr = layerDesc->u.pLayerInfo->pfnNextGetInstanceProcAddr;
+        Log::debug("layer", "Next instance proc addr: {:x}",
+            reinterpret_cast<uintptr_t>(next_vkGetInstanceProcAddr));
+
         layerDesc->u.pLayerInfo = layerDesc->u.pLayerInfo->pNext;
 
         // create instance
@@ -101,7 +104,7 @@ namespace {
             Hooks::hooks["vkCreateInstance"]);
         auto res = layer_vkCreateInstance2(pCreateInfo, pAllocator, pInstance);
         if (res != VK_SUCCESS) {
-            Log::error("lsfg-vk(layer): Failed to create Vulkan instance: {:x}",
+            Log::error("layer", "Failed to create Vulkan instance: {:x}",
                 static_cast<uint32_t>(res));
             return res;
         }
@@ -112,11 +115,11 @@ namespace {
         success &= initInstanceFunc(*pInstance, "vkGetPhysicalDeviceQueueFamilyProperties", &next_vkGetPhysicalDeviceQueueFamilyProperties);
         success &= initInstanceFunc(*pInstance, "vkGetPhysicalDeviceMemoryProperties", &next_vkGetPhysicalDeviceMemoryProperties);
         if (!success) {
-            Log::error("lsfg-vk(layer): Failed to get instance function pointers");
+            Log::error("layer", "Failed to get instance function pointers");
             return VK_ERROR_INITIALIZATION_FAILED;
         }
 
-        Log::debug("lsfg-vk(layer): Successfully initialized lsfg-vk instance layer");
+        Log::debug("layer", "Successfully initialized lsfg-vk instance layer");
         return res;
     } // NOLINTEND
 
@@ -125,7 +128,7 @@ namespace {
             const VkDeviceCreateInfo* pCreateInfo,
             const VkAllocationCallbacks* pAllocator,
             VkDevice* pDevice) {
-        Log::debug("lsfg-vk(layer): Initializing lsfg-vk device layer");
+        Log::debug("layer", "Initializing lsfg-vk device layer...");
 
         // find layer creation info
         auto* layerDesc = const_cast<VkLayerDeviceCreateInfo*>(
@@ -136,24 +139,26 @@ namespace {
                 reinterpret_cast<const VkLayerDeviceCreateInfo*>(layerDesc->pNext));
         }
         if (!layerDesc) {
-            Log::error("lsfg-vk(layer): No layer creation info found in pNext chain");
+            Log::error("layer", "No layer creation info found in pNext chain");
             return VK_ERROR_INITIALIZATION_FAILED;
         }
 
         // advance link info (i don't really know what this does)
         next_vkGetDeviceProcAddr = layerDesc->u.pLayerInfo->pfnNextGetDeviceProcAddr;
+        Log::debug("layer", "Next device proc addr: {:x}",
+            reinterpret_cast<uintptr_t>(next_vkGetDeviceProcAddr));
+
         layerDesc->u.pLayerInfo = layerDesc->u.pLayerInfo->pNext;
 
         // create device
-        auto success = initInstanceFunc(nullptr, "vkCreateDevice",
+        auto success = initInstanceFunc(nullptr, "vkCreateDevice", &next_vkCreateDevice);
-            &next_vkCreateDevice);
         if (!success) return VK_ERROR_INITIALIZATION_FAILED;
 
         auto* layer_vkCreateDevice2 = reinterpret_cast<PFN_vkCreateDevice>(
             Hooks::hooks["vkCreateDevicePre"]);
         auto res = layer_vkCreateDevice2(physicalDevice, pCreateInfo, pAllocator, pDevice);
         if (res != VK_SUCCESS) {
-            Log::error("lsfg-vk(layer): Failed to create Vulkan device: {:x}",
+            Log::error("layer", "Failed to create Vulkan device: {:x}",
                 static_cast<uint32_t>(res));
             return res;
         }
@@ -187,7 +192,7 @@ namespace {
         success &= initDeviceFunc(*pDevice, "vkCmdCopyImage", &next_vkCmdCopyImage);
         success &= initDeviceFunc(*pDevice, "vkAcquireNextImageKHR", &next_vkAcquireNextImageKHR);
         if (!success) {
-            Log::error("lsfg-vk(layer): Failed to get device function pointers");
+            Log::error("layer", "Failed to get device function pointers");
             return VK_ERROR_INITIALIZATION_FAILED;
         }
 
@@ -195,12 +200,12 @@ namespace {
             Hooks::hooks["vkCreateDevicePost"]);
         res = layer_vkCreateDevice2(physicalDevice, pCreateInfo, pAllocator, pDevice);
         if (res != VK_SUCCESS) {
-            Log::error("lsfg-vk(layer): Failed to create Vulkan device: {:x}",
+            Log::error("layer", "Failed to create Vulkan device: {:x}",
                 static_cast<uint32_t>(res));
             return res;
         }
 
-        Log::debug("lsfg-vk(layer): Successfully initialized lsfg-vk device layer");
+        Log::debug("layer", "Successfully initialized lsfg-vk device layer");
         return res;
     } // NOLINTEND
 }
@@ -217,16 +222,16 @@ const std::unordered_map<std::string, PFN_vkVoidFunction> layerFunctions = {
 };
 
 PFN_vkVoidFunction layer_vkGetInstanceProcAddr(VkInstance instance, const char* pName) {
-    std::string name(pName);
+    const std::string name(pName);
     auto it = layerFunctions.find(name);
     if (it != layerFunctions.end()) {
-        Log::debug("lsfg-vk(layer): Inserted layer function for {}", name);
+        Log::debug("layer", "Inserted layer function for {}", name);
         return it->second;
     }
 
     it = Hooks::hooks.find(name);
     if (it != Hooks::hooks.end()) {
-        Log::debug("lsfg-vk(layer): Inserted hook function for {}", name);
+        Log::debug("layer", "Inserted hook function for {}", name);
         return it->second;
     }
 
@@ -234,16 +239,16 @@ PFN_vkVoidFunction layer_vkGetInstanceProcAddr(VkInstance instance, const char*
 }
 
 PFN_vkVoidFunction layer_vkGetDeviceProcAddr(VkDevice device, const char* pName) {
-    std::string name(pName);
+    const std::string name(pName);
     auto it = layerFunctions.find(name);
     if (it != layerFunctions.end()) {
-        Log::debug("lsfg-vk(layer): Inserted layer function for {}", name);
+        Log::debug("layer", "Inserted layer function for {}", name);
         return it->second;
     }
 
     it = Hooks::hooks.find(name);
     if (it != Hooks::hooks.end()) {
-        Log::debug("lsfg-vk(layer): Inserted hook function for {}", name);
+        Log::debug("layer", "Inserted hook function for {}", name);
         return it->second;
     }
 
@@ -252,15 +257,29 @@ PFN_vkVoidFunction layer_vkGetDeviceProcAddr(VkDevice device, const char* pName)
 
 // original functions
 
+#pragma clang diagnostic push
+#pragma clang diagnostic ignored "-Wunsafe-buffer-usage"
+// NOLINTBEGIN
+
 VkResult Layer::ovkCreateInstance(
         const VkInstanceCreateInfo* pCreateInfo,
         const VkAllocationCallbacks* pAllocator,
         VkInstance* pInstance) {
-    return next_vkCreateInstance(pCreateInfo, pAllocator, pInstance);
+    Log::debug("vulkan", "vkCreateInstance called with {} extensions:",
+        pCreateInfo->enabledExtensionCount);
+    for (uint32_t i = 0; i < pCreateInfo->enabledExtensionCount; ++i)
+        Log::debug("vulkan", "  - {}", pCreateInfo->ppEnabledExtensionNames[i]);
+    auto res = next_vkCreateInstance(pCreateInfo, pAllocator, pInstance);
+    Log::debug("vulkan", "vkCreateInstance({}) returned handle {:x}",
+        static_cast<uint32_t>(res),
+        reinterpret_cast<uintptr_t>(*pInstance));
+    return res;
 }
 void Layer::ovkDestroyInstance(
         VkInstance instance,
         const VkAllocationCallbacks* pAllocator) {
+    Log::debug("vulkan", "vkDestroyInstance called for instance {:x}",
+        reinterpret_cast<uintptr_t>(instance));
     next_vkDestroyInstance(instance, pAllocator);
 }
 
@@ -269,12 +288,24 @@ VkResult Layer::ovkCreateDevice(
         const VkDeviceCreateInfo* pCreateInfo,
         const VkAllocationCallbacks* pAllocator,
         VkDevice* pDevice) {
-    return next_vkCreateDevice(physicalDevice, pCreateInfo, pAllocator, pDevice);
+    Log::debug("vulkan", "vkCreateDevice called with {} extensions:",
+        pCreateInfo->enabledExtensionCount);
+    for (uint32_t i = 0; i < pCreateInfo->enabledExtensionCount; ++i)
+        Log::debug("vulkan", "  - {}", pCreateInfo->ppEnabledExtensionNames[i]);
+    auto res = next_vkCreateDevice(physicalDevice, pCreateInfo, pAllocator, pDevice);
+    Log::debug("vulkan", "vkCreateDevice({}) returned handle {:x}",
+        static_cast<uint32_t>(res),
+        reinterpret_cast<uintptr_t>(*pDevice));
+    return res;
 }
 void Layer::ovkDestroyDevice(
         VkDevice device,
         const VkAllocationCallbacks* pAllocator) {
+    Log::debug("vulkan", "vkDestroyDevice called for device {:x}",
+        reinterpret_cast<uintptr_t>(device));
     next_vkDestroyDevice(device, pAllocator);
+    Log::debug("vulkan", "Device {:x} destroyed successfully",
+        reinterpret_cast<uintptr_t>(device));
 }
 
 PFN_vkVoidFunction Layer::ovkGetInstanceProcAddr(
@@ -293,17 +324,39 @@ VkResult Layer::ovkCreateSwapchainKHR(
         const VkSwapchainCreateInfoKHR* pCreateInfo,
         const VkAllocationCallbacks* pAllocator,
         VkSwapchainKHR* pSwapchain) {
-    return next_vkCreateSwapchainKHR(device, pCreateInfo, pAllocator, pSwapchain);
+    Log::debug("vulkan", "vkCreateSwapchainKHR called with {} images, extent: {}x{}",
+        pCreateInfo->minImageCount, pCreateInfo->imageExtent.width, pCreateInfo->imageExtent.height);
+    auto res = next_vkCreateSwapchainKHR(device, pCreateInfo, pAllocator, pSwapchain);
+    Log::debug("vulkan", "vkCreateSwapchainKHR({}) returned handle {:x}",
+        static_cast<uint32_t>(res),
+        reinterpret_cast<uintptr_t>(*pSwapchain));
+    return res;
 }
 VkResult Layer::ovkQueuePresentKHR(
         VkQueue queue,
         const VkPresentInfoKHR* pPresentInfo) {
-    return next_vkQueuePresentKHR(queue, pPresentInfo);
+    Log::debug("vulkan2", "vkQueuePresentKHR called with {} wait semaphores:",
+        pPresentInfo->waitSemaphoreCount);
+    for (uint32_t i = 0; i < pPresentInfo->waitSemaphoreCount; i++)
+        Log::debug("vulkan2", "  - {:x}", reinterpret_cast<uintptr_t>(pPresentInfo->pWaitSemaphores[i]));
+    Log::debug("vulkan2", "and {} signal semaphores:",
+        pPresentInfo->swapchainCount);
+    for (uint32_t i = 0; i < pPresentInfo->swapchainCount; i++)
+        Log::debug("vulkan2", "  - {:x}", reinterpret_cast<uintptr_t>(pPresentInfo->pSwapchains[i]));
+    Log::debug("vulkan2", "and queue: {:x}, image: {}",
+        reinterpret_cast<uintptr_t>(queue),
+        *pPresentInfo->pImageIndices);
+    auto res = next_vkQueuePresentKHR(queue, pPresentInfo);
+    Log::debug("vulkan2", "vkQueuePresentKHR({}) returned",
+        static_cast<uint32_t>(res));
+    return res;
 }
 void Layer::ovkDestroySwapchainKHR(
         VkDevice device,
         VkSwapchainKHR swapchain,
         const VkAllocationCallbacks* pAllocator) {
+    Log::debug("vulkan", "vkDestroySwapchainKHR called for swapchain {:x}",
+        reinterpret_cast<uintptr_t>(swapchain));
     next_vkDestroySwapchainKHR(device, swapchain, pAllocator);
 }
 
@@ -312,30 +365,48 @@ VkResult Layer::ovkGetSwapchainImagesKHR(
         VkSwapchainKHR swapchain,
         uint32_t* pSwapchainImageCount,
         VkImage* pSwapchainImages) {
-    return next_vkGetSwapchainImagesKHR(device, swapchain, pSwapchainImageCount, pSwapchainImages);
+    Log::debug("vulkan", "vkGetSwapchainImagesKHR called for swapchain {:x}",
+        reinterpret_cast<uintptr_t>(swapchain));
+    auto res = next_vkGetSwapchainImagesKHR(device, swapchain, pSwapchainImageCount, pSwapchainImages);
+    Log::debug("vulkan", "vkGetSwapchainImagesKHR({}) returned {} images",
+        static_cast<uint32_t>(res),
+        *pSwapchainImageCount);
+    return res;
 }
 
 VkResult Layer::ovkAllocateCommandBuffers(
         VkDevice device,
         const VkCommandBufferAllocateInfo* pAllocateInfo,
         VkCommandBuffer* pCommandBuffers) {
-    return next_vkAllocateCommandBuffers(device, pAllocateInfo, pCommandBuffers);
+    Log::debug("vulkan2", "vkAllocateCommandBuffers called for command pool {:x}",
+        reinterpret_cast<uintptr_t>(pAllocateInfo->commandPool));
+    auto res = next_vkAllocateCommandBuffers(device, pAllocateInfo, pCommandBuffers);
+    Log::debug("vulkan2", "vkAllocateCommandBuffers({}) returned command buffer: {}",
+        static_cast<uint32_t>(res),
+        reinterpret_cast<uintptr_t>(*pCommandBuffers));
+    return res;
 }
 void Layer::ovkFreeCommandBuffers(
         VkDevice device,
         VkCommandPool commandPool,
         uint32_t commandBufferCount,
         const VkCommandBuffer* pCommandBuffers) {
+    Log::debug("vulkan2", "vkFreeCommandBuffers called for command buffer: {:x}",
+        reinterpret_cast<uintptr_t>(*pCommandBuffers));
     next_vkFreeCommandBuffers(device, commandPool, commandBufferCount, pCommandBuffers);
 }
 
 VkResult Layer::ovkBeginCommandBuffer(
         VkCommandBuffer commandBuffer,
         const VkCommandBufferBeginInfo* pBeginInfo) {
+    Log::debug("vulkan2", "vkBeginCommandBuffer called for command buffer {:x}",
+        reinterpret_cast<uintptr_t>(commandBuffer));
     return next_vkBeginCommandBuffer(commandBuffer, pBeginInfo);
 }
 VkResult Layer::ovkEndCommandBuffer(
         VkCommandBuffer commandBuffer) {
+    Log::debug("vulkan2", "vkEndCommandBuffer called for command buffer {:x}",
+        reinterpret_cast<uintptr_t>(commandBuffer));
     return next_vkEndCommandBuffer(commandBuffer);
 }
 
@@ -344,12 +415,19 @@ VkResult Layer::ovkCreateCommandPool(
         const VkCommandPoolCreateInfo* pCreateInfo,
         const VkAllocationCallbacks* pAllocator,
         VkCommandPool* pCommandPool) {
-    return next_vkCreateCommandPool(device, pCreateInfo, pAllocator, pCommandPool);
+    Log::debug("vulkan", "vkCreateCommandPool called");
+    auto res = next_vkCreateCommandPool(device, pCreateInfo, pAllocator, pCommandPool);
+    Log::debug("vulkan", "vkCreateCommandPool({}) returned handle {:x}",
+        static_cast<uint32_t>(res),
+        reinterpret_cast<uintptr_t>(*pCommandPool));
+    return res;
 }
 void Layer::ovkDestroyCommandPool(
         VkDevice device,
         VkCommandPool commandPool,
         const VkAllocationCallbacks* pAllocator) {
+    Log::debug("vulkan", "vkDestroyCommandPool called for command pool {:x}",
+        reinterpret_cast<uintptr_t>(commandPool));
     next_vkDestroyCommandPool(device, commandPool, pAllocator);
 }
 
@@ -358,12 +436,22 @@ VkResult Layer::ovkCreateImage(
         const VkImageCreateInfo* pCreateInfo,
         const VkAllocationCallbacks* pAllocator,
         VkImage* pImage) {
-    return next_vkCreateImage(device, pCreateInfo, pAllocator, pImage);
+    Log::debug("vulkan", "vkCreateImage called with format: {}, extent: {}x{}, usage: {}",
+        static_cast<uint32_t>(pCreateInfo->format),
+        pCreateInfo->extent.width, pCreateInfo->extent.height,
+        static_cast<uint32_t>(pCreateInfo->usage));
+    auto res = next_vkCreateImage(device, pCreateInfo, pAllocator, pImage);
+    Log::debug("vulkan", "vkCreateImage({}) returned handle {:x}",
+        static_cast<uint32_t>(res),
+        reinterpret_cast<uintptr_t>(*pImage));
+    return res;
 }
 void Layer::ovkDestroyImage(
         VkDevice device,
         VkImage image,
         const VkAllocationCallbacks* pAllocator) {
+    Log::debug("vulkan", "vkDestroyImage called for image {:x}",
+        reinterpret_cast<uintptr_t>(image));
     next_vkDestroyImage(device, image, pAllocator);
 }
 
@@ -371,6 +459,8 @@ void Layer::ovkGetImageMemoryRequirements(
         VkDevice device,
         VkImage image,
         VkMemoryRequirements* pMemoryRequirements) {
+    Log::debug("vulkan", "vkGetImageMemoryRequirements called for image {:x}",
+        reinterpret_cast<uintptr_t>(image));
     next_vkGetImageMemoryRequirements(device, image, pMemoryRequirements);
 }
 VkResult Layer::ovkBindImageMemory(
@@ -378,7 +468,14 @@ VkResult Layer::ovkBindImageMemory(
         VkImage image,
         VkDeviceMemory memory,
         VkDeviceSize memoryOffset) {
-    return next_vkBindImageMemory(device, image, memory, memoryOffset);
+    Log::debug("vulkan", "vkBindImageMemory called for image {:x}, memory {:x}, offset: {}",
+        reinterpret_cast<uintptr_t>(image),
+        reinterpret_cast<uintptr_t>(memory),
+        memoryOffset);
+    auto res = next_vkBindImageMemory(device, image, memory, memoryOffset);
+    Log::debug("vulkan", "vkBindImageMemory({}) returned",
+        static_cast<uint32_t>(res));
+    return res;
 }
 
 VkResult Layer::ovkAllocateMemory(
@@ -386,12 +483,21 @@ VkResult Layer::ovkAllocateMemory(
         const VkMemoryAllocateInfo* pAllocateInfo,
         const VkAllocationCallbacks* pAllocator,
         VkDeviceMemory* pMemory) {
-    return next_vkAllocateMemory(device, pAllocateInfo, pAllocator, pMemory);
+    Log::debug("vulkan", "vkAllocateMemory called with size: {}, memory type index: {}",
+        pAllocateInfo->allocationSize,
+        pAllocateInfo->memoryTypeIndex);
+    auto res = next_vkAllocateMemory(device, pAllocateInfo, pAllocator, pMemory);
+    Log::debug("vulkan", "vkAllocateMemory({}) returned handle {:x}",
+        static_cast<uint32_t>(res),
+        reinterpret_cast<uintptr_t>(*pMemory));
+    return res;
 }
 void Layer::ovkFreeMemory(
         VkDevice device,
         VkDeviceMemory memory,
         const VkAllocationCallbacks* pAllocator) {
+    Log::debug("vulkan", "vkFreeMemory called for memory {:x}",
+        reinterpret_cast<uintptr_t>(memory));
     next_vkFreeMemory(device, memory, pAllocator);
 }
 
@@ -400,12 +506,20 @@ VkResult Layer::ovkCreateSemaphore(
         const VkSemaphoreCreateInfo* pCreateInfo,
         const VkAllocationCallbacks* pAllocator,
         VkSemaphore* pSemaphore) {
-    return next_vkCreateSemaphore(device, pCreateInfo, pAllocator, pSemaphore);
+    Log::debug("vulkan2", "vkCreateSemaphore called",
+        static_cast<uint32_t>(pCreateInfo->flags));
+    auto res = next_vkCreateSemaphore(device, pCreateInfo, pAllocator, pSemaphore);
+    Log::debug("vulkan2", "vkCreateSemaphore({}) returned handle {:x}",
+        static_cast<uint32_t>(res),
+        reinterpret_cast<uintptr_t>(*pSemaphore));
+    return res;
 }
 void Layer::ovkDestroySemaphore(
         VkDevice device,
         VkSemaphore semaphore,
         const VkAllocationCallbacks* pAllocator) {
+    Log::debug("vulkan2", "vkDestroySemaphore called for semaphore {:x}",
+        reinterpret_cast<uintptr_t>(semaphore));
     next_vkDestroySemaphore(device, semaphore, pAllocator);
 }
 
@@ -413,24 +527,39 @@ VkResult Layer::ovkGetMemoryFdKHR(
         VkDevice device,
         const VkMemoryGetFdInfoKHR* pGetFdInfo,
         int* pFd) {
-    return next_vkGetMemoryFdKHR(device, pGetFdInfo, pFd);
+    Log::debug("vulkan", "vkGetMemoryFdKHR called for memory {:x}, handle type: {}",
+        reinterpret_cast<uintptr_t>(pGetFdInfo->memory),
+        static_cast<uint32_t>(pGetFdInfo->handleType));
+    auto res = next_vkGetMemoryFdKHR(device, pGetFdInfo, pFd);
+    Log::debug("vulkan", "vkGetMemoryFdKHR({}) returned fd: {}",
+        static_cast<uint32_t>(res), *pFd);
+    return res;
 }
 VkResult Layer::ovkGetSemaphoreFdKHR(
         VkDevice device,
         const VkSemaphoreGetFdInfoKHR* pGetFdInfo,
         int* pFd) {
-    return next_vkGetSemaphoreFdKHR(device, pGetFdInfo, pFd);
+    Log::debug("vulkan2", "vkGetSemaphoreFdKHR called for semaphore {:x}",
+        reinterpret_cast<uintptr_t>(pGetFdInfo->semaphore));
+    auto res = next_vkGetSemaphoreFdKHR(device, pGetFdInfo, pFd);
+    Log::debug("vulkan2", "vkGetSemaphoreFdKHR({}) returned fd: {}",
+        static_cast<uint32_t>(res), *pFd);
+    return res;
 }
 
 void Layer::ovkGetPhysicalDeviceQueueFamilyProperties(
         VkPhysicalDevice physicalDevice,
         uint32_t* pQueueFamilyPropertyCount,
         VkQueueFamilyProperties* pQueueFamilyProperties) {
+    Log::debug("vulkan", "vkGetPhysicalDeviceQueueFamilyProperties called for physical device {:x}",
+        reinterpret_cast<uintptr_t>(physicalDevice));
     next_vkGetPhysicalDeviceQueueFamilyProperties(physicalDevice, pQueueFamilyPropertyCount, pQueueFamilyProperties);
 }
 void Layer::ovkGetPhysicalDeviceMemoryProperties(
         VkPhysicalDevice physicalDevice,
         VkPhysicalDeviceMemoryProperties* pMemoryProperties) {
+    Log::debug("vulkan", "vkGetPhysicalDeviceMemoryProperties called for physical device {:x}",
+        reinterpret_cast<uintptr_t>(physicalDevice));
     next_vkGetPhysicalDeviceMemoryProperties(physicalDevice, pMemoryProperties);
 }
 
@@ -439,6 +568,10 @@ void Layer::ovkGetDeviceQueue(
         uint32_t queueFamilyIndex,
         uint32_t queueIndex,
         VkQueue* pQueue) {
+    Log::debug("vulkan", "vkGetDeviceQueue called for device {:x}, queue family index: {}, queue index: {}",
+        reinterpret_cast<uintptr_t>(device),
+        queueFamilyIndex,
+        queueIndex);
     next_vkGetDeviceQueue(device, queueFamilyIndex, queueIndex, pQueue);
 }
 VkResult Layer::ovkQueueSubmit(
@@ -446,7 +579,21 @@ VkResult Layer::ovkQueueSubmit(
         uint32_t submitCount,
         const VkSubmitInfo* pSubmits,
         VkFence fence) {
-    return next_vkQueueSubmit(queue, submitCount, pSubmits, fence);
+    Log::debug("vulkan2", "vkQueueSubmit called for queue {:x}, submitting: {} with wait semaphores:",
+        reinterpret_cast<uintptr_t>(queue),
+        reinterpret_cast<uintptr_t>(*pSubmits->pCommandBuffers));
+    for (uint32_t i = 0; i < pSubmits->waitSemaphoreCount; ++i)
+        Log::debug("vulkan2", "  - {:x}", reinterpret_cast<uintptr_t>(pSubmits->pWaitSemaphores[i]));
+    Log::debug("vulkan2", "and {} signal semaphores:",
+        pSubmits->waitSemaphoreCount);
+    for (uint32_t i = 0; i < submitCount; ++i)
+        Log::debug("vulkan2", "  - {:x}", reinterpret_cast<uintptr_t>(pSubmits[i].pSignalSemaphores));
+    Log::debug("vulkan2", "and fence: {:x}",
+        reinterpret_cast<uintptr_t>(fence));
+    auto res = next_vkQueueSubmit(queue, submitCount, pSubmits, fence);
+    Log::debug("vulkan2", "vkQueueSubmit({}) returned",
+        static_cast<uint32_t>(res));
+    return res;
 }
 
 void Layer::ovkCmdPipelineBarrier(
@@ -460,6 +607,16 @@ void Layer::ovkCmdPipelineBarrier(
         const VkBufferMemoryBarrier* pBufferMemoryBarriers,
         uint32_t imageMemoryBarrierCount,
         const VkImageMemoryBarrier* pImageMemoryBarriers) {
+    Log::debug("vulkan2", "vkCmdPipelineBarrier called for command buffer {:x}, src stage: {}, dst stage: {}, transitioning:",
+        reinterpret_cast<uintptr_t>(commandBuffer),
+        static_cast<uint32_t>(srcStageMask),
+        static_cast<uint32_t>(dstStageMask));
+    for (uint32_t i = 0; i < imageMemoryBarrierCount; ++i) {
+        Log::debug("vulkan2", "  - image {:x}, old layout: {}, new layout: {}",
+            reinterpret_cast<uintptr_t>(pImageMemoryBarriers[i].image),
+            static_cast<uint32_t>(pImageMemoryBarriers[i].oldLayout),
+            static_cast<uint32_t>(pImageMemoryBarriers[i].newLayout));
+    }
     next_vkCmdPipelineBarrier(commandBuffer, srcStageMask, dstStageMask, dependencyFlags,
         memoryBarrierCount, pMemoryBarriers,
         bufferMemoryBarrierCount, pBufferMemoryBarriers,
@@ -473,6 +630,10 @@ void Layer::ovkCmdCopyImage(
         VkImageLayout dstImageLayout,
         uint32_t regionCount,
         const VkImageCopy* pRegions) {
+    Log::debug("vulkan2", "vkCmdCopyImage called for command buffer {:x}, src image {:x}, dst image {:x}",
+        reinterpret_cast<uintptr_t>(commandBuffer),
+        reinterpret_cast<uintptr_t>(srcImage),
+        reinterpret_cast<uintptr_t>(dstImage));
     next_vkCmdCopyImage(commandBuffer, srcImage, srcImageLayout, dstImage, dstImageLayout, regionCount, pRegions);
 }
 
@@ -483,5 +644,17 @@ VkResult Layer::ovkAcquireNextImageKHR(
         VkSemaphore semaphore,
         VkFence fence,
         uint32_t* pImageIndex) {
-    return next_vkAcquireNextImageKHR(device, swapchain, timeout, semaphore, fence, pImageIndex);
+    Log::debug("vulkan", "vkAcquireNextImageKHR called for swapchain {:x}, timeout: {}, semaphore: {:x}, fence: {:x}",
+        reinterpret_cast<uintptr_t>(swapchain),
+        timeout,
+        reinterpret_cast<uintptr_t>(semaphore),
+        reinterpret_cast<uintptr_t>(fence));
+    auto res = next_vkAcquireNextImageKHR(device, swapchain, timeout, semaphore, fence, pImageIndex);
+    Log::debug("vulkan", "vkAcquireNextImageKHR({}) returned image index: {}",
+        static_cast<uint32_t>(res),
+        *pImageIndex);
+    return res;
 }
+
+#pragma clang diagnostic pop
+// NOLINTEND

src/utils/log.cpp

@@ -0,0 +1,43 @@
+#include "utils/log.hpp"
+
+#include <sstream>
+#include <unistd.h>
+
+using namespace Log;
+
+bool Internal::isSetup{};
+
+std::set<std::string> Internal::debugModules;
+bool Internal::debugAllModules{};
+
+std::ofstream Internal::logFile;
+std::mutex Internal::logMutex;
+
+void Internal::setup() {
+     if (isSetup) return;
+     isSetup = true;
+
+     // open log file
+     const char* env_log_file = std::getenv("LSFG_LOG_FILE");
+     if (env_log_file) {
+        std::ostringstream filename;
+        filename << getpid() << "_" << env_log_file;
+        logFile.open(filename.str(), std::ios::app);
+     }
+
+     // parse debug modules
+     const char* env_log_debug = std::getenv("LSFG_LOG_DEBUG");
+     if (!env_log_debug)
+         return;
+     const std::string debugModulesStr(env_log_debug);
+
+     std::stringstream ss(debugModulesStr);
+     std::string item;
+     while (std::getline(ss, item, ',')) {
+         if (item == "all") {
+             debugAllModules = true;
+             return;
+         }
+         debugModules.insert(item);
+     }
+ }

src/utils/utils.cpp

@@ -1,4 +1,5 @@
 #include "utils/utils.hpp"
+#include "utils/log.hpp"
 #include "layer.hpp"
 
 #include <lsfg.hpp>
@@ -44,8 +45,12 @@ std::vector<const char*> Utils::addExtensions(const char* const* extensions, siz
 
     for (const auto& e : requiredExtensions) {
         auto it = std::ranges::find(ext, e);
-        if (it == ext.end())
+        if (it == ext.end()) {
+            Log::debug("hooks-init", "Adding extension: {}", e);
             ext.push_back(e);
+        } else {
+            Log::debug("hooks-init", "Extension {} already present", e);
+        }
     }
 
     return ext;
@@ -148,6 +153,8 @@ namespace {
     std::optional<std::string> layersEnvironment;
 }
 
+// TODO: more environment variables? what about explicit disable?
+
 void Utils::storeLayerEnv() {
     const char* env = std::getenv("VK_INSTANCE_LAYERS");
     if (env)