Changed logging to be "Log before execution", Added more error logging, all services should now log on some level

2018-11-26 17:06:13 +11:00
parent 94fce28010
commit a2cc3b10bb
51 changed files with 730 additions and 378 deletions
--- a/src/core/hle/kernel/svc.cpp
+++ b/src/core/hle/kernel/svc.cpp
@@ -69,37 +69,45 @@ bool IsInsideNewMapRegion(const VMManager& vm, VAddr address, u64 size) {
 ResultCode MapUnmapMemorySanityChecks(const VMManager& vm_manager, VAddr dst_addr, VAddr src_addr,
                                      u64 size) {
    if (!Common::Is4KBAligned(dst_addr) || !Common::Is4KBAligned(src_addr)) {
+        LOG_ERROR(Kernel_SVC, "Invalid address");
        return ERR_INVALID_ADDRESS;
    }

    if (size == 0 || !Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Invalid size");
        return ERR_INVALID_SIZE;
    }

    if (!IsValidAddressRange(dst_addr, size)) {
+        LOG_ERROR(Kernel_SVC, "size is out of range");
        return ERR_INVALID_ADDRESS_STATE;
    }

    if (!IsValidAddressRange(src_addr, size)) {
+        LOG_ERROR(Kernel_SVC, "size is out of range");
        return ERR_INVALID_ADDRESS_STATE;
    }

    if (!IsInsideAddressSpace(vm_manager, src_addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is out of the address space");
        return ERR_INVALID_ADDRESS_STATE;
    }

    if (!IsInsideNewMapRegion(vm_manager, dst_addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is out of the address space");
        return ERR_INVALID_MEMORY_RANGE;
    }

    const VAddr dst_end_address = dst_addr + size;
    if (dst_end_address > vm_manager.GetHeapRegionBaseAddress() &&
        vm_manager.GetHeapRegionEndAddress() > dst_addr) {
+        LOG_ERROR(Kernel_SVC, "Region is not in the correct address space");
        return ERR_INVALID_MEMORY_RANGE;
    }

    if (dst_end_address > vm_manager.GetMapRegionBaseAddress() &&
        vm_manager.GetMapRegionEndAddress() > dst_addr) {
+        LOG_ERROR(Kernel_SVC, "Region is not in the correct address space");
        return ERR_INVALID_MEMORY_RANGE;
    }

@@ -113,6 +121,7 @@ static ResultCode SetHeapSize(VAddr* heap_addr, u64 heap_size) {

    // Size must be a multiple of 0x200000 (2MB) and be equal to or less than 4GB.
    if ((heap_size & 0xFFFFFFFE001FFFFF) != 0) {
+        LOG_ERROR(Kernel_SVC, "Invalid heap size");
        return ERR_INVALID_SIZE;
    }

@@ -127,20 +136,24 @@ static ResultCode SetMemoryPermission(VAddr addr, u64 size, u32 prot) {
    LOG_TRACE(Kernel_SVC, "called, addr=0x{:X}, size=0x{:X}, prot=0x{:X}", addr, size, prot);

    if (!Common::Is4KBAligned(addr)) {
+        LOG_ERROR(Kernel_SVC, "Address is not aligned");
        return ERR_INVALID_ADDRESS;
    }

    if (size == 0 || !Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Invalid size");
        return ERR_INVALID_SIZE;
    }

    if (!IsValidAddressRange(addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is out of the address space");
        return ERR_INVALID_ADDRESS_STATE;
    }

    const auto permission = static_cast<MemoryPermission>(prot);
    if (permission != MemoryPermission::None && permission != MemoryPermission::Read &&
        permission != MemoryPermission::ReadWrite) {
+        LOG_ERROR(Kernel_SVC, "Incorrect memory permissions");
        return ERR_INVALID_MEMORY_PERMISSIONS;
    }

@@ -148,11 +161,13 @@ static ResultCode SetMemoryPermission(VAddr addr, u64 size, u32 prot) {
    auto& vm_manager = current_process->VMManager();

    if (!IsInsideAddressSpace(vm_manager, addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is not inside the address space");
        return ERR_INVALID_ADDRESS_STATE;
    }

    const VMManager::VMAHandle iter = vm_manager.FindVMA(addr);
    if (iter == vm_manager.vma_map.end()) {
+        LOG_ERROR(Kernel_SVC, "Unable to find VMA");
        return ERR_INVALID_ADDRESS_STATE;
    }

@@ -182,6 +197,7 @@ static ResultCode MapMemory(VAddr dst_addr, VAddr src_addr, u64 size) {

    const auto result = MapUnmapMemorySanityChecks(vm_manager, dst_addr, src_addr, size);
    if (result != RESULT_SUCCESS) {
+        LOG_ERROR(Kernel_SVC, "Map Memory failed");
        return result;
    }

@@ -198,6 +214,7 @@ static ResultCode UnmapMemory(VAddr dst_addr, VAddr src_addr, u64 size) {

    const auto result = MapUnmapMemorySanityChecks(vm_manager, dst_addr, src_addr, size);
    if (result != RESULT_SUCCESS) {
+        LOG_ERROR(Kernel_SVC, "UnmapMemory failed");
        return result;
    }

@@ -207,6 +224,7 @@ static ResultCode UnmapMemory(VAddr dst_addr, VAddr src_addr, u64 size) {
 /// Connect to an OS service given the port name, returns the handle to the port to out
 static ResultCode ConnectToNamedPort(Handle* out_handle, VAddr port_name_address) {
    if (!Memory::IsValidVirtualAddress(port_name_address)) {
+        LOG_ERROR(Kernel_SVC, "Invalid port name address");
        return ERR_NOT_FOUND;
    }

@@ -214,6 +232,7 @@ static ResultCode ConnectToNamedPort(Handle* out_handle, VAddr port_name_address
    // Read 1 char beyond the max allowed port name to detect names that are too long.
    std::string port_name = Memory::ReadCString(port_name_address, PortNameMaxLength + 1);
    if (port_name.size() > PortNameMaxLength) {
+        LOG_ERROR(Kernel_SVC, "Port name is too long");
        return ERR_OUT_OF_RANGE;
    }

@@ -262,6 +281,7 @@ static ResultCode GetThreadId(u32* thread_id, Handle thread_handle) {
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    const SharedPtr<Thread> thread = handle_table.Get<Thread>(thread_handle);
    if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Invalid thread handle");
        return ERR_INVALID_HANDLE;
    }

@@ -276,6 +296,7 @@ static ResultCode GetProcessId(u32* process_id, Handle process_handle) {
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    const SharedPtr<Process> process = handle_table.Get<Process>(process_handle);
    if (!process) {
+        LOG_ERROR(Kernel_SVC, "Invalid process");
        return ERR_INVALID_HANDLE;
    }

@@ -305,12 +326,15 @@ static ResultCode WaitSynchronization(Handle* index, VAddr handles_address, u64
    LOG_TRACE(Kernel_SVC, "called handles_address=0x{:X}, handle_count={}, nano_seconds={}",
              handles_address, handle_count, nano_seconds);

-    if (!Memory::IsValidVirtualAddress(handles_address))
+    if (!Memory::IsValidVirtualAddress(handles_address)) {
+        LOG_ERROR(Kernel_SVC, "Invalid handle address");
        return ERR_INVALID_POINTER;
+    }

    static constexpr u64 MaxHandles = 0x40;

    if (handle_count > MaxHandles) {
+        LOG_ERROR(Kernel_SVC, "Handle count is too big");
        return ERR_OUT_OF_RANGE;
    }

@@ -325,6 +349,7 @@ static ResultCode WaitSynchronization(Handle* index, VAddr handles_address, u64
        const auto object = handle_table.Get<WaitObject>(handle);

        if (object == nullptr) {
+            LOG_ERROR(Kernel_SVC, "Object is a nullptr");
            return ERR_INVALID_HANDLE;
        }

@@ -348,11 +373,13 @@ static ResultCode WaitSynchronization(Handle* index, VAddr handles_address, u64

    // If a timeout value of 0 was provided, just return the Timeout error code instead of
    // suspending the thread.
-    if (nano_seconds == 0)
+    if (nano_seconds == 0) {
        return RESULT_TIMEOUT;
+    }

-    for (auto& object : objects)
+    for (auto& object : objects) {
        object->AddWaitingThread(thread);
+    }

    thread->SetWaitObjects(std::move(objects));
    thread->SetStatus(ThreadStatus::WaitSynchAny);
@@ -373,6 +400,7 @@ static ResultCode CancelSynchronization(Handle thread_handle) {
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    const SharedPtr<Thread> thread = handle_table.Get<Thread>(thread_handle);
    if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Invalid thread handle");
        return ERR_INVALID_HANDLE;
    }

@@ -391,10 +419,12 @@ static ResultCode ArbitrateLock(Handle holding_thread_handle, VAddr mutex_addr,
              holding_thread_handle, mutex_addr, requesting_thread_handle);

    if (Memory::IsKernelVirtualAddress(mutex_addr)) {
+        LOG_ERROR(Kernel_SVC, "Invalid mutex address");
        return ERR_INVALID_ADDRESS_STATE;
    }

    if (!Common::IsWordAligned(mutex_addr)) {
+        LOG_ERROR(Kernel_SVC, "Mutex address is not aligned");
        return ERR_INVALID_ADDRESS;
    }

@@ -408,10 +438,12 @@ static ResultCode ArbitrateUnlock(VAddr mutex_addr) {
    LOG_TRACE(Kernel_SVC, "called mutex_addr=0x{:X}", mutex_addr);

    if (Memory::IsKernelVirtualAddress(mutex_addr)) {
+        LOG_ERROR(Kernel_SVC, "Invalid size");
        return ERR_INVALID_ADDRESS_STATE;
    }

    if (!Common::IsWordAligned(mutex_addr)) {
+        LOG_ERROR(Kernel_SVC, "Mutex address is not aligned");
        return ERR_INVALID_ADDRESS;
    }

@@ -602,10 +634,12 @@ static ResultCode GetInfo(u64* result, u64 info_id, u64 handle, u64 info_sub_id)
        break;
    case GetInfoType::RandomEntropy:
        if (handle != 0) {
+            LOG_ERROR(Kernel_SVC, "Non zero handle specified");
            return ERR_INVALID_HANDLE;
        }

        if (info_sub_id >= Process::RANDOM_ENTROPY_SIZE) {
+            LOG_ERROR(Kernel_SVC, "Entropy size is too big");
            return ERR_INVALID_COMBINATION;
        }

@@ -643,12 +677,14 @@ static ResultCode GetInfo(u64* result, u64 info_id, u64 handle, u64 info_sub_id)
    case GetInfoType::ThreadTickCount: {
        constexpr u64 num_cpus = 4;
        if (info_sub_id != 0xFFFFFFFFFFFFFFFF && info_sub_id >= num_cpus) {
+            LOG_ERROR(Kernel_SVC, "Incorrect info_sub_id");
            return ERR_INVALID_COMBINATION;
        }

        const auto thread =
            current_process->GetHandleTable().Get<Thread>(static_cast<Handle>(handle));
        if (!thread) {
+            LOG_ERROR(Kernel_SVC, "Thread is not a valid handle");
            return ERR_INVALID_HANDLE;
        }

@@ -691,14 +727,17 @@ static ResultCode GetThreadContext(VAddr thread_context, Handle handle) {
    const auto* current_process = Core::CurrentProcess();
    const SharedPtr<Thread> thread = current_process->GetHandleTable().Get<Thread>(handle);
    if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Thread is not a valid handle");
        return ERR_INVALID_HANDLE;
    }

    if (thread->GetOwnerProcess() != current_process) {
+        LOG_ERROR(Kernel_SVC, "Thread owner process is not the current process");
        return ERR_INVALID_HANDLE;
    }

    if (thread == GetCurrentThread()) {
+        LOG_ERROR(Kernel_SVC, "Thread is already registered");
        return ERR_ALREADY_REGISTERED;
    }

@@ -719,9 +758,12 @@ static ResultCode GetThreadContext(VAddr thread_context, Handle handle) {

 /// Gets the priority for the specified thread
 static ResultCode GetThreadPriority(u32* priority, Handle handle) {
+    LOG_TRACE(Kernel_SVC, "called");
+
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    const SharedPtr<Thread> thread = handle_table.Get<Thread>(handle);
    if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Invalid thread handle");
        return ERR_INVALID_HANDLE;
    }

@@ -731,7 +773,10 @@ static ResultCode GetThreadPriority(u32* priority, Handle handle) {

 /// Sets the priority for the specified thread
 static ResultCode SetThreadPriority(Handle handle, u32 priority) {
+    LOG_TRACE(Kernel_SVC, "called");
+
    if (priority > THREADPRIO_LOWEST) {
+        LOG_ERROR(Kernel_SVC, "Priority is out of range");
        return ERR_INVALID_THREAD_PRIORITY;
    }

@@ -739,6 +784,7 @@ static ResultCode SetThreadPriority(Handle handle, u32 priority) {

    SharedPtr<Thread> thread = current_process->GetHandleTable().Get<Thread>(handle);
    if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Invalid thread handle");
        return ERR_INVALID_HANDLE;
    }

@@ -761,14 +807,17 @@ static ResultCode MapSharedMemory(Handle shared_memory_handle, VAddr addr, u64 s
              shared_memory_handle, addr, size, permissions);

    if (!Common::Is4KBAligned(addr)) {
+        LOG_ERROR(Kernel_SVC, "Address is not aligned");
        return ERR_INVALID_ADDRESS;
    }

    if (size == 0 || !Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Invalid size");
        return ERR_INVALID_SIZE;
    }

    if (!IsValidAddressRange(addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is not in the address space");
        return ERR_INVALID_ADDRESS_STATE;
    }

@@ -782,11 +831,13 @@ static ResultCode MapSharedMemory(Handle shared_memory_handle, VAddr addr, u64 s
    auto* const current_process = Core::CurrentProcess();
    auto shared_memory = current_process->GetHandleTable().Get<SharedMemory>(shared_memory_handle);
    if (!shared_memory) {
+        LOG_ERROR(Kernel_SVC, "Invalid shared memory handle");
        return ERR_INVALID_HANDLE;
    }

    const auto& vm_manager = current_process->VMManager();
    if (!vm_manager.IsWithinASLRRegion(addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is not within the ASLR region");
        return ERR_INVALID_MEMORY_RANGE;
    }

@@ -798,25 +849,30 @@ static ResultCode UnmapSharedMemory(Handle shared_memory_handle, VAddr addr, u64
                shared_memory_handle, addr, size);

    if (!Common::Is4KBAligned(addr)) {
+        LOG_ERROR(Kernel_SVC, "Address is not aligned");
        return ERR_INVALID_ADDRESS;
    }

    if (size == 0 || !Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Size is invalid");
        return ERR_INVALID_SIZE;
    }

    if (!IsValidAddressRange(addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is not in the valid address range");
        return ERR_INVALID_ADDRESS_STATE;
    }

    auto* const current_process = Core::CurrentProcess();
    auto shared_memory = current_process->GetHandleTable().Get<SharedMemory>(shared_memory_handle);
    if (!shared_memory) {
+        LOG_ERROR(Kernel_SVC, "Shared memory is an invalid handle");
        return ERR_INVALID_HANDLE;
    }

    const auto& vm_manager = current_process->VMManager();
    if (!vm_manager.IsWithinASLRRegion(addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is not within the ASLR region");
        return ERR_INVALID_MEMORY_RANGE;
    }

@@ -826,9 +882,11 @@ static ResultCode UnmapSharedMemory(Handle shared_memory_handle, VAddr addr, u64
 /// Query process memory
 static ResultCode QueryProcessMemory(MemoryInfo* memory_info, PageInfo* /*page_info*/,
                                     Handle process_handle, u64 addr) {
+    LOG_TRACE(Kernel_SVC, "called process=0x{:08X} addr={:X}", process_handle, addr);
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    SharedPtr<Process> process = handle_table.Get<Process>(process_handle);
    if (!process) {
+        LOG_ERROR(Kernel_SVC, "Invalid process handle");
        return ERR_INVALID_HANDLE;
    }
    auto vma = process->VMManager().FindVMA(addr);
@@ -844,8 +902,6 @@ static ResultCode QueryProcessMemory(MemoryInfo* memory_info, PageInfo* /*page_i
        memory_info->size = vma->second.size;
        memory_info->type = static_cast<u32>(vma->second.meminfo_state);
    }
-
-    LOG_TRACE(Kernel_SVC, "called process=0x{:08X} addr={:X}", process_handle, addr);
    return RESULT_SUCCESS;
 }

@@ -874,7 +930,13 @@ static void ExitProcess() {
 /// Creates a new thread
 static ResultCode CreateThread(Handle* out_handle, VAddr entry_point, u64 arg, VAddr stack_top,
                               u32 priority, s32 processor_id) {
+    LOG_TRACE(Kernel_SVC,
+              "called entrypoint=0x{:08X} ({}), arg=0x{:08X}, stacktop=0x{:08X}, "
+              "threadpriority=0x{:08X}, processorid=0x{:08X} : created handle=0x{:08X}",
+              entry_point, name, arg, stack_top, priority, processor_id, *out_handle);
+
    if (priority > THREADPRIO_LOWEST) {
+        LOG_ERROR(Kernel_SVC, "Invalid thread priority");
        return ERR_INVALID_THREAD_PRIORITY;
    }

@@ -905,6 +967,8 @@ static ResultCode CreateThread(Handle* out_handle, VAddr entry_point, u64 arg, V

    const auto new_guest_handle = current_process->GetHandleTable().Create(thread);
    if (new_guest_handle.Failed()) {
+        LOG_ERROR(Kernel_SVC, "Failed to create handle with error=0x{:X}",
+                  new_guest_handle.Code().raw);
        return new_guest_handle.Code();
    }
    thread->SetGuestHandle(*new_guest_handle);
@@ -912,11 +976,6 @@ static ResultCode CreateThread(Handle* out_handle, VAddr entry_point, u64 arg, V

    Core::System::GetInstance().CpuCore(thread->GetProcessorID()).PrepareReschedule();

-    LOG_TRACE(Kernel_SVC,
-              "called entrypoint=0x{:08X} ({}), arg=0x{:08X}, stacktop=0x{:08X}, "
-              "threadpriority=0x{:08X}, processorid=0x{:08X} : created handle=0x{:08X}",
-              entry_point, name, arg, stack_top, priority, processor_id, *out_handle);
-
    return RESULT_SUCCESS;
 }

@@ -927,6 +986,7 @@ static ResultCode StartThread(Handle thread_handle) {
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    const SharedPtr<Thread> thread = handle_table.Get<Thread>(thread_handle);
    if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Thread is an invalid handle");
        return ERR_INVALID_HANDLE;
    }

@@ -1106,10 +1166,12 @@ static ResultCode WaitForAddress(VAddr address, u32 type, s32 value, s64 timeout
                address, type, value, timeout);
    // If the passed address is a kernel virtual address, return invalid memory state.
    if (Memory::IsKernelVirtualAddress(address)) {
+        LOG_ERROR(Kernel_SVC, "Address is a kernel virtual address");
        return ERR_INVALID_ADDRESS_STATE;
    }
    // If the address is not properly aligned to 4 bytes, return invalid address.
    if (address % sizeof(u32) != 0) {
+        LOG_ERROR(Kernel_SVC, "Address is not aligned");
        return ERR_INVALID_ADDRESS;
    }

@@ -1121,6 +1183,7 @@ static ResultCode WaitForAddress(VAddr address, u32 type, s32 value, s64 timeout
    case AddressArbiter::ArbitrationType::WaitIfEqual:
        return AddressArbiter::WaitForAddressIfEqual(address, value, timeout);
    default:
+        LOG_ERROR(Kernel_SVC, "Invalid arbitration type");
        return ERR_INVALID_ENUM_VALUE;
    }
 }
@@ -1131,10 +1194,12 @@ static ResultCode SignalToAddress(VAddr address, u32 type, s32 value, s32 num_to
                address, type, value, num_to_wake);
    // If the passed address is a kernel virtual address, return invalid memory state.
    if (Memory::IsKernelVirtualAddress(address)) {
+        LOG_ERROR(Kernel_SVC, "Address is a kernel virtual address");
        return ERR_INVALID_ADDRESS_STATE;
    }
    // If the address is not properly aligned to 4 bytes, return invalid address.
    if (address % sizeof(u32) != 0) {
+        LOG_ERROR(Kernel_SVC, "Address is not aligned");
        return ERR_INVALID_ADDRESS;
    }

@@ -1147,12 +1212,15 @@ static ResultCode SignalToAddress(VAddr address, u32 type, s32 value, s32 num_to
        return AddressArbiter::ModifyByWaitingCountAndSignalToAddressIfEqual(address, value,
                                                                             num_to_wake);
    default:
+        LOG_ERROR(Kernel_SVC, "Invalid arbitration type");
        return ERR_INVALID_ENUM_VALUE;
    }
 }

 /// This returns the total CPU ticks elapsed since the CPU was powered-on
 static u64 GetSystemTick() {
+    LOG_TRACE(Kernel_SVC, "called");
+
    const u64 result{CoreTiming::GetTicks()};

    // Advance time to defeat dumb games that busy-wait for the frame to end.
@@ -1226,6 +1294,7 @@ static ResultCode GetThreadCoreMask(Handle thread_handle, u32* core, u64* mask)
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    const SharedPtr<Thread> thread = handle_table.Get<Thread>(thread_handle);
    if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Thread is an invalid handle");
        return ERR_INVALID_HANDLE;
    }

@@ -1236,12 +1305,13 @@ static ResultCode GetThreadCoreMask(Handle thread_handle, u32* core, u64* mask)
 }

 static ResultCode SetThreadCoreMask(Handle thread_handle, u32 core, u64 mask) {
-    LOG_DEBUG(Kernel_SVC, "called, handle=0x{:08X}, mask=0x{:16X}, core=0x{:X}", thread_handle,
+    LOG_DEBUG(Kernel_SVC, "called, handle=0x{:08X}, mask=0x{:016X}, core=0x{:X}", thread_handle,
              mask, core);

    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    const SharedPtr<Thread> thread = handle_table.Get<Thread>(thread_handle);
    if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Thread is an invalid handle");
        return ERR_INVALID_HANDLE;
    }

@@ -1256,6 +1326,7 @@ static ResultCode SetThreadCoreMask(Handle thread_handle, u32 core, u64 mask) {
    }

    if (mask == 0) {
+        LOG_ERROR(Kernel_SVC, "Mask is 0");
        return ERR_INVALID_COMBINATION;
    }

@@ -1265,11 +1336,13 @@ static ResultCode SetThreadCoreMask(Handle thread_handle, u32 core, u64 mask) {
    if (core == OnlyChangeMask) {
        core = thread->GetIdealCore();
    } else if (core >= Core::NUM_CPU_CORES && core != static_cast<u32>(-1)) {
+        LOG_ERROR(Kernel_SVC, "Invalid processor ID specified");
        return ERR_INVALID_PROCESSOR_ID;
    }

    // Error out if the input core isn't enabled in the input mask.
    if (core < Core::NUM_CPU_CORES && (mask & (1ull << core)) == 0) {
+        LOG_ERROR(Kernel_SVC, "Invalid core and mask");
        return ERR_INVALID_COMBINATION;
    }

@@ -1286,17 +1359,20 @@ static ResultCode CreateSharedMemory(Handle* handle, u64 size, u32 local_permiss
    // Size must be a multiple of 4KB and be less than or equal to
    // approx. 8 GB (actually (1GB - 512B) * 8)
    if (size == 0 || (size & 0xFFFFFFFE00000FFF) != 0) {
+        LOG_ERROR(Kernel_SVC, "Invalid size");
        return ERR_INVALID_SIZE;
    }

    const auto local_perms = static_cast<MemoryPermission>(local_permissions);
    if (local_perms != MemoryPermission::Read && local_perms != MemoryPermission::ReadWrite) {
+        LOG_ERROR(Kernel_SVC, "Invalid memory permissions");
        return ERR_INVALID_MEMORY_PERMISSIONS;
    }

    const auto remote_perms = static_cast<MemoryPermission>(remote_permissions);
    if (remote_perms != MemoryPermission::Read && remote_perms != MemoryPermission::ReadWrite &&
        remote_perms != MemoryPermission::DontCare) {
+        LOG_ERROR(Kernel_SVC, "Invalid memory permissions");
        return ERR_INVALID_MEMORY_PERMISSIONS;
    }

@@ -1316,6 +1392,7 @@ static ResultCode ClearEvent(Handle handle) {
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    SharedPtr<Event> evt = handle_table.Get<Event>(handle);
    if (evt == nullptr) {
+        LOG_ERROR(Kernel_SVC, "Invalid event handle");
        return ERR_INVALID_HANDLE;
    }

@@ -1334,11 +1411,13 @@ static ResultCode GetProcessInfo(u64* out, Handle process_handle, u32 type) {
    const auto& handle_table = Core::CurrentProcess()->GetHandleTable();
    const auto process = handle_table.Get<Process>(process_handle);
    if (!process) {
+        LOG_ERROR(Kernel_SVC, "Invalid process handle");
        return ERR_INVALID_HANDLE;
    }

    const auto info_type = static_cast<InfoType>(type);
    if (info_type != InfoType::Status) {
+        LOG_ERROR(Kernel_SVC, "Info type is not status");
        return ERR_INVALID_ENUM_VALUE;
    }

--- a/src/core/hle/service/acc/acc.cpp
+++ b/src/core/hle/service/acc/acc.cpp
@@ -216,10 +216,11 @@ void Module::Interface::GetLastOpenedUser(Kernel::HLERequestContext& ctx) {
 void Module::Interface::GetProfile(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    UUID user_id = rp.PopRaw<UUID>();
+    LOG_DEBUG(Service_ACC, "called user_id={}", user_id.Format());
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<IProfile>(user_id, *profile_manager);
-    LOG_DEBUG(Service_ACC, "called user_id={}", user_id.Format());
 }

 void Module::Interface::IsUserRegistrationRequestPermitted(Kernel::HLERequestContext& ctx) {
@@ -236,10 +237,10 @@ void Module::Interface::InitializeApplicationInfo(Kernel::HLERequestContext& ctx
 }

 void Module::Interface::GetBaasAccountManagerForApplication(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_ACC, "called");
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<IManagerForApplication>();
-    LOG_DEBUG(Service_ACC, "called");
 }

 void Module::Interface::TrySelectUserWithoutInteraction(Kernel::HLERequestContext& ctx) {
--- a/src/core/hle/service/am/am.cpp
+++ b/src/core/hle/service/am/am.cpp
@@ -217,6 +217,7 @@ ISelfController::~ISelfController() = default;
 void ISelfController::SetFocusHandlingMode(Kernel::HLERequestContext& ctx) {
    // Takes 3 input u8s with each field located immediately after the previous
    // u8, these are bool flags. No output.
+    LOG_WARNING(Service_AM, "(STUBBED) called");

    IPC::RequestParser rp{ctx};

@@ -229,44 +230,40 @@ void ISelfController::SetFocusHandlingMode(Kernel::HLERequestContext& ctx) {

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::SetRestartMessageEnabled(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::SetPerformanceModeChangedNotification(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};

    bool flag = rp.Pop<bool>();
+    LOG_WARNING(Service_AM, "(STUBBED) called flag={}", flag);

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called flag={}", flag);
 }

 void ISelfController::SetScreenShotPermission(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::SetOperationModeChangedNotification(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};

    bool flag = rp.Pop<bool>();
+    LOG_WARNING(Service_AM, "(STUBBED) called flag={}", flag);

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called flag={}", flag);
 }

 void ISelfController::SetOutOfFocusSuspendingEnabled(Kernel::HLERequestContext& ctx) {
@@ -275,45 +272,45 @@ void ISelfController::SetOutOfFocusSuspendingEnabled(Kernel::HLERequestContext&
    IPC::RequestParser rp{ctx};

    bool enabled = rp.Pop<bool>();
+    LOG_WARNING(Service_AM, "(STUBBED) called enabled={}", enabled);

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called enabled={}", enabled);
 }

 void ISelfController::LockExit(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::UnlockExit(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::GetLibraryAppletLaunchableEvent(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    launchable_event->Signal();

    IPC::ResponseBuilder rb{ctx, 2, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushCopyObjects(launchable_event);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::SetScreenShotImageOrientation(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::CreateManagedDisplayLayer(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
    // TODO(Subv): Find out how AM determines the display to use, for now just
    // create the layer in the Default display.
    u64 display_id = nvflinger->OpenDisplay("Default");
@@ -322,32 +319,31 @@ void ISelfController::CreateManagedDisplayLayer(Kernel::HLERequestContext& ctx)
    IPC::ResponseBuilder rb{ctx, 4};
    rb.Push(RESULT_SUCCESS);
    rb.Push(layer_id);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::SetHandlesRequestToDisplay(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::SetIdleTimeDetectionExtension(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    idle_time_detection_extension = rp.Pop<u32>();
+    LOG_WARNING(Service_AM, "(STUBBED) called idle_time_detection_extension={}",
+                idle_time_detection_extension);
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ISelfController::GetIdleTimeDetectionExtension(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u32>(idle_time_detection_extension);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 AppletMessageQueue::AppletMessageQueue() {
@@ -438,47 +434,49 @@ ICommonStateGetter::ICommonStateGetter(std::shared_ptr<AppletMessageQueue> msg_q
 ICommonStateGetter::~ICommonStateGetter() = default;

 void ICommonStateGetter::GetBootMode(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);

    rb.Push<u8>(static_cast<u8>(Service::PM::SystemBootMode::Normal)); // Normal boot mode
-
-    LOG_DEBUG(Service_AM, "called");
 }

 void ICommonStateGetter::GetEventHandle(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushCopyObjects(msg_queue->GetMesssageRecieveEvent());
-
-    LOG_DEBUG(Service_AM, "called");
 }

 void ICommonStateGetter::ReceiveMessage(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.PushEnum<AppletMessageQueue::AppletMessage>(msg_queue->PopMessage());
-
-    LOG_DEBUG(Service_AM, "called");
 }

 void ICommonStateGetter::GetCurrentFocusState(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push(static_cast<u8>(FocusState::InFocus));
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void ICommonStateGetter::GetDefaultDisplayResolutionChangeEvent(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushCopyObjects(msg_queue->GetOperationModeChangedEvent());
-
-    LOG_DEBUG(Service_AM, "called");
 }

 void ICommonStateGetter::GetDefaultDisplayResolution(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 4};
    rb.Push(RESULT_SUCCESS);

@@ -493,8 +491,6 @@ void ICommonStateGetter::GetDefaultDisplayResolution(Kernel::HLERequestContext&
        rb.Push(static_cast<u32>(Service::VI::DisplayResolution::UndockedHeight) *
                static_cast<u32>(Settings::values.resolution_factor));
    }
-
-    LOG_DEBUG(Service_AM, "called");
 }

 IStorage::IStorage(std::vector<u8> buffer)
@@ -517,21 +513,21 @@ const std::vector<u8>& IStorage::GetData() const {

 void ICommonStateGetter::GetOperationMode(Kernel::HLERequestContext& ctx) {
    const bool use_docked_mode{Settings::values.use_docked_mode};
+    LOG_DEBUG(Service_AM, "called, use_docked_mode={}", use_docked_mode);
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push(static_cast<u8>(use_docked_mode ? OperationMode::Docked : OperationMode::Handheld));
-
-    LOG_DEBUG(Service_AM, "called");
 }

 void ICommonStateGetter::GetPerformanceMode(Kernel::HLERequestContext& ctx) {
    const bool use_docked_mode{Settings::values.use_docked_mode};
+    LOG_DEBUG(Service_AM, "called, use_docked_mode={}", use_docked_mode);
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push(static_cast<u32>(use_docked_mode ? APM::PerformanceMode::Docked
                                             : APM::PerformanceMode::Handheld));
-
-    LOG_DEBUG(Service_AM, "called");
 }

 class ILibraryAppletAccessor final : public ServiceFramework<ILibraryAppletAccessor> {
@@ -566,32 +562,34 @@ public:

 private:
    void GetAppletStateChangedEvent(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        const auto event = applet->GetBroker().GetStateChangedEvent();
        event->Signal();

        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(event);
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void IsCompleted(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(applet->TransactionComplete());
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetResult(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(applet->GetStatus());
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void Start(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        ASSERT(applet != nullptr);

        applet->Initialize();
@@ -599,36 +597,38 @@ private:

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void PushInData(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::RequestParser rp{ctx};
        applet->GetBroker().PushNormalDataFromGame(*rp.PopIpcInterface<IStorage>());

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void PopOutData(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};

        const auto storage = applet->GetBroker().PopNormalDataToGame();
        if (storage == nullptr) {
+            LOG_ERROR(Service_AM, "storage is a nullptr");
+
            rb.Push(ERR_NO_DATA_IN_CHANNEL);
            return;
        }

        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IStorage>(std::move(*storage));
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void PushInteractiveInData(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::RequestParser rp{ctx};
        applet->GetBroker().PushInteractiveDataFromGame(*rp.PopIpcInterface<IStorage>());

@@ -638,51 +638,51 @@ private:

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void PopInteractiveOutData(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};

        const auto storage = applet->GetBroker().PopInteractiveDataToGame();
        if (storage == nullptr) {
+            LOG_ERROR(Service_AM, "storage is a nullptr");
+
            rb.Push(ERR_NO_DATA_IN_CHANNEL);
            return;
        }

        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IStorage>(std::move(*storage));
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetPopOutDataEvent(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(applet->GetBroker().GetNormalDataEvent());
-
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetPopInteractiveOutDataEvent(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(applet->GetBroker().GetInteractiveDataEvent());
-
-        LOG_DEBUG(Service_AM, "called");
    }

    std::shared_ptr<Applets::Applet> applet;
 };

 void IStorage::Open(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};

    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<IStorageAccessor>(*this);
-
-    LOG_DEBUG(Service_AM, "called");
 }

 IStorageAccessor::IStorageAccessor(IStorage& storage)
@@ -701,21 +701,25 @@ IStorageAccessor::IStorageAccessor(IStorage& storage)
 IStorageAccessor::~IStorageAccessor() = default;

 void IStorageAccessor::GetSize(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 4};

    rb.Push(RESULT_SUCCESS);
    rb.Push(static_cast<u64>(backing.buffer.size()));
-
-    LOG_DEBUG(Service_AM, "called");
 }

 void IStorageAccessor::Write(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};

    const u64 offset{rp.Pop<u64>()};
+    LOG_DEBUG(Service_AM, "called, offset={}", offset);
+
    const std::vector<u8> data{ctx.ReadBuffer()};

    if (data.size() > backing.buffer.size() - offset) {
+        LOG_ERROR(Service_AM, "offset is out of bounds");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(ERR_SIZE_OUT_OF_BOUNDS);
    }
@@ -724,17 +728,19 @@ void IStorageAccessor::Write(Kernel::HLERequestContext& ctx) {

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_DEBUG(Service_AM, "called, offset={}", offset);
 }

 void IStorageAccessor::Read(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};

    const u64 offset{rp.Pop<u64>()};
+    LOG_DEBUG(Service_AM, "called, offset={}", offset);
+
    const std::size_t size{ctx.GetWriteBufferSize()};

    if (size > backing.buffer.size() - offset) {
+        LOG_ERROR(Service_AM, "offset is out of bounds");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(ERR_SIZE_OUT_OF_BOUNDS);
    }
@@ -743,8 +749,6 @@ void IStorageAccessor::Read(Kernel::HLERequestContext& ctx) {

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_DEBUG(Service_AM, "called, offset={}", offset);
 }

 ILibraryAppletCreator::ILibraryAppletCreator() : ServiceFramework("ILibraryAppletCreator") {
@@ -783,6 +787,8 @@ void ILibraryAppletCreator::CreateLibraryApplet(Kernel::HLERequestContext& ctx)
    const auto applet = GetAppletFromId(applet_id);

    if (applet == nullptr) {
+        LOG_ERROR(Service_AM, "Applet doesn't exist!");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(ResultCode(-1));
        return;
@@ -792,23 +798,23 @@ void ILibraryAppletCreator::CreateLibraryApplet(Kernel::HLERequestContext& ctx)

    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<AM::ILibraryAppletAccessor>(applet);
-
-    LOG_DEBUG(Service_AM, "called");
 }

 void ILibraryAppletCreator::CreateStorage(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    const u64 size{rp.Pop<u64>()};
+    LOG_DEBUG(Service_AM, "called, size={}", size);
+
    std::vector<u8> buffer(size);

    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<AM::IStorage>(std::move(buffer));
-
-    LOG_DEBUG(Service_AM, "called, size={}", size);
 }

 void ILibraryAppletCreator::CreateTransferMemoryStorage(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::RequestParser rp{ctx};

    rp.SetCurrentOffset(3);
@@ -819,6 +825,7 @@ void ILibraryAppletCreator::CreateTransferMemoryStorage(Kernel::HLERequestContex
            handle);

    if (shared_mem == nullptr) {
+        LOG_ERROR(Service_AM, "shared_mem is a nullpr");
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(ResultCode(-1));
        return;
@@ -882,38 +889,45 @@ IApplicationFunctions::IApplicationFunctions() : ServiceFramework("IApplicationF
 IApplicationFunctions::~IApplicationFunctions() = default;

 void IApplicationFunctions::EnableApplicationCrashReport(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::BeginBlockingHomeButtonShortAndLongPressed(
    Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::EndBlockingHomeButtonShortAndLongPressed(
    Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::BeginBlockingHomeButton(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::EndBlockingHomeButton(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::PopLaunchParameter(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    LaunchParameters params{};

    params.magic = POP_LAUNCH_PARAMETER_MAGIC;
@@ -932,21 +946,19 @@ void IApplicationFunctions::PopLaunchParameter(Kernel::HLERequestContext& ctx) {
    std::memcpy(buffer.data(), &params, buffer.size());

    rb.PushIpcInterface<AM::IStorage>(buffer);
-
-    LOG_DEBUG(Service_AM, "called");
 }

 void IApplicationFunctions::CreateApplicationAndRequestToStartForQuest(
    Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::EnsureSaveData(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    u128 uid = rp.PopRaw<u128>(); // What does this do?
-
    LOG_WARNING(Service, "(STUBBED) called uid = {:016X}{:016X}", uid[1], uid[0]);

    IPC::ResponseBuilder rb{ctx, 4};
@@ -961,60 +973,62 @@ void IApplicationFunctions::SetTerminateResult(Kernel::HLERequestContext& ctx) {

    IPC::RequestParser rp{ctx};
    u32 result = rp.Pop<u32>();
+    LOG_WARNING(Service_AM, "(STUBBED) called, result=0x{:08X}", result);

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called, result=0x{:08X}", result);
 }

 void IApplicationFunctions::GetDisplayVersion(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 6};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u64>(1);
    rb.Push<u64>(0);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::GetDesiredLanguage(Kernel::HLERequestContext& ctx) {
    // TODO(bunnei): This should be configurable
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 4};
    rb.Push(RESULT_SUCCESS);
    rb.Push(
        static_cast<u64>(Service::Set::GetLanguageCodeFromIndex(Settings::values.language_index)));
-    LOG_DEBUG(Service_AM, "called");
 }

 void IApplicationFunctions::InitializeGamePlayRecording(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::SetGamePlayRecordingState(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::NotifyRunning(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u8>(0); // Unknown, seems to be ignored by official processes
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void IApplicationFunctions::GetPseudoDeviceId(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 6};
    rb.Push(RESULT_SUCCESS);

    // Returns a 128-bit UUID
    rb.Push<u64>(0);
    rb.Push<u64>(0);
-
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 void InstallInterfaces(SM::ServiceManager& service_manager,
@@ -1051,9 +1065,10 @@ IHomeMenuFunctions::IHomeMenuFunctions() : ServiceFramework("IHomeMenuFunctions"
 IHomeMenuFunctions::~IHomeMenuFunctions() = default;

 void IHomeMenuFunctions::RequestToGetForeground(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_AM, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_AM, "(STUBBED) called");
 }

 IGlobalStateController::IGlobalStateController() : ServiceFramework("IGlobalStateController") {
--- a/src/core/hle/service/am/applet_ae.cpp
+++ b/src/core/hle/service/am/applet_ae.cpp
@@ -32,66 +32,75 @@ public:

 private:
    void GetCommonStateGetter(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ICommonStateGetter>(msg_queue);
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetSelfController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ISelfController>(nvflinger);
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetWindowController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IWindowController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetAudioController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IAudioController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetDisplayController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IDisplayController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetProcessWindingController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IProcessWindingController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetDebugFunctions(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IDebugFunctions>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetLibraryAppletCreator(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ILibraryAppletCreator>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetApplicationFunctions(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IApplicationFunctions>();
-        LOG_DEBUG(Service_AM, "called");
    }

    std::shared_ptr<NVFlinger::NVFlinger> nvflinger;
@@ -122,97 +131,110 @@ public:

 private:
    void GetCommonStateGetter(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ICommonStateGetter>(msg_queue);
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetSelfController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ISelfController>(nvflinger);
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetWindowController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IWindowController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetAudioController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IAudioController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetDisplayController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IDisplayController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetDebugFunctions(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IDebugFunctions>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetLibraryAppletCreator(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ILibraryAppletCreator>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetHomeMenuFunctions(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IHomeMenuFunctions>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetGlobalStateController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IGlobalStateController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetApplicationCreator(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IApplicationCreator>();
-        LOG_DEBUG(Service_AM, "called");
    }
    std::shared_ptr<NVFlinger::NVFlinger> nvflinger;
    std::shared_ptr<AppletMessageQueue> msg_queue;
 };

 void AppletAE::OpenSystemAppletProxy(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ISystemAppletProxy>(nvflinger, msg_queue);
-    LOG_DEBUG(Service_AM, "called");
 }

 void AppletAE::OpenLibraryAppletProxy(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ILibraryAppletProxy>(nvflinger, msg_queue);
-    LOG_DEBUG(Service_AM, "called");
 }

 void AppletAE::OpenLibraryAppletProxyOld(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ILibraryAppletProxy>(nvflinger, msg_queue);
-    LOG_DEBUG(Service_AM, "called");
 }

 AppletAE::AppletAE(std::shared_ptr<NVFlinger::NVFlinger> nvflinger,
--- a/src/core/hle/service/am/applet_oe.cpp
+++ b/src/core/hle/service/am/applet_oe.cpp
@@ -35,59 +35,67 @@ public:

 private:
    void GetAudioController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IAudioController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetDisplayController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IDisplayController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetDebugFunctions(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IDebugFunctions>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetWindowController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IWindowController>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetSelfController(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ISelfController>(nvflinger);
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetCommonStateGetter(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ICommonStateGetter>(msg_queue);
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetLibraryAppletCreator(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ILibraryAppletCreator>();
-        LOG_DEBUG(Service_AM, "called");
    }

    void GetApplicationFunctions(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_AM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IApplicationFunctions>();
-        LOG_DEBUG(Service_AM, "called");
    }

    std::shared_ptr<NVFlinger::NVFlinger> nvflinger;
@@ -95,10 +103,11 @@ private:
 };

 void AppletOE::OpenApplicationProxy(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<IApplicationProxy>(nvflinger, msg_queue);
-    LOG_DEBUG(Service_AM, "called");
 }

 AppletOE::AppletOE(std::shared_ptr<NVFlinger::NVFlinger> nvflinger,
--- a/src/core/hle/service/aoc/aoc_u.cpp
+++ b/src/core/hle/service/aoc/aoc_u.cpp
@@ -68,6 +68,8 @@ AOC_U::AOC_U() : ServiceFramework("aoc:u"), add_on_content(AccumulateAOCTitleIDs
 AOC_U::~AOC_U() = default;

 void AOC_U::CountAddOnContent(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AOC, "called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);

@@ -82,6 +84,7 @@ void AOC_U::ListAddOnContent(Kernel::HLERequestContext& ctx) {

    const auto offset = rp.PopRaw<u32>();
    auto count = rp.PopRaw<u32>();
+    LOG_DEBUG(Service_AOC, "called with offset={}, count={}", offset, count);

    const auto current = Core::System::GetInstance().CurrentProcess()->GetTitleID();

@@ -110,6 +113,8 @@ void AOC_U::ListAddOnContent(Kernel::HLERequestContext& ctx) {
 }

 void AOC_U::GetAddOnContentBaseId(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_AOC, "called");
+
    IPC::ResponseBuilder rb{ctx, 4};
    rb.Push(RESULT_SUCCESS);
    const auto title_id = Core::System::GetInstance().CurrentProcess()->GetTitleID();
@@ -128,7 +133,6 @@ void AOC_U::PrepareAddOnContent(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};

    const auto aoc_id = rp.PopRaw<u32>();
-
    LOG_WARNING(Service_AOC, "(STUBBED) called with aoc_id={:08X}", aoc_id);

    IPC::ResponseBuilder rb{ctx, 2};
--- a/src/core/hle/service/apm/interface.cpp
+++ b/src/core/hle/service/apm/interface.cpp
@@ -40,24 +40,22 @@ private:

        auto mode = static_cast<PerformanceMode>(rp.Pop<u32>());
        u32 config = rp.Pop<u32>();
+        LOG_WARNING(Service_APM, "(STUBBED) called mode={} config={}", static_cast<u32>(mode),
+                    config);

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-
-        LOG_WARNING(Service_APM, "(STUBBED) called mode={} config={}", static_cast<u32>(mode),
-                    config);
    }

    void GetPerformanceConfiguration(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};

        auto mode = static_cast<PerformanceMode>(rp.Pop<u32>());
+        LOG_WARNING(Service_APM, "(STUBBED) called mode={}", static_cast<u32>(mode));

        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(static_cast<u32>(PerformanceConfiguration::Config1));
-
-        LOG_WARNING(Service_APM, "(STUBBED) called mode={}", static_cast<u32>(mode));
    }
 };

@@ -73,11 +71,11 @@ APM::APM(std::shared_ptr<Module> apm, const char* name)
 APM::~APM() = default;

 void APM::OpenSession(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_APM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ISession>();
-
-    LOG_DEBUG(Service_APM, "called");
 }

 APM_Sys::APM_Sys() : ServiceFramework{"apm:sys"} {
@@ -98,11 +96,11 @@ APM_Sys::APM_Sys() : ServiceFramework{"apm:sys"} {
 APM_Sys::~APM_Sys() = default;

 void APM_Sys::GetPerformanceEvent(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_APM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ISession>();
-
-    LOG_DEBUG(Service_APM, "called");
 }

 } // namespace Service::APM
--- a/src/core/hle/service/arp/arp.cpp
+++ b/src/core/hle/service/arp/arp.cpp
@@ -59,11 +59,11 @@ public:

 private:
    void AcquireRegistrar(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_ARP, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IRegistrar>();
-
-        LOG_DEBUG(Service_ARP, "called");
    }
 };

--- a/src/core/hle/service/audio/audout_u.cpp
+++ b/src/core/hle/service/audio/audout_u.cpp
@@ -86,6 +86,7 @@ private:

    void GetAudioOutState(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_Audio, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push(static_cast<u32>(stream->IsPlaying() ? AudioState::Started : AudioState::Stopped));
@@ -148,6 +149,7 @@ private:

    void GetReleasedAudioOutBufferImpl(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_Audio, "called {}", ctx.Description());
+
        IPC::RequestParser rp{ctx};
        const u64 max_count{ctx.GetWriteBufferSize() / sizeof(u64)};
        const auto released_buffers{audio_core.GetTagsAndReleaseBuffers(stream, max_count)};
@@ -163,6 +165,7 @@ private:

    void ContainsAudioOutBuffer(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_Audio, "called");
+
        IPC::RequestParser rp{ctx};
        const u64 tag{rp.Pop<u64>()};
        IPC::ResponseBuilder rb{ctx, 3};
@@ -172,6 +175,7 @@ private:

    void GetAudioOutBufferCount(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_Audio, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push(static_cast<u32>(stream->GetQueueSize()));
@@ -189,6 +193,7 @@ private:

 void AudOutU::ListAudioOutsImpl(Kernel::HLERequestContext& ctx) {
    LOG_DEBUG(Service_Audio, "called");
+
    IPC::RequestParser rp{ctx};

    ctx.WriteBuffer(DefaultDevice);
--- a/src/core/hle/service/audio/audren_u.cpp
+++ b/src/core/hle/service/audio/audren_u.cpp
@@ -52,74 +52,79 @@ private:
    }

    void GetSampleRate(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_Audio, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(renderer->GetSampleRate());
-        LOG_DEBUG(Service_Audio, "called");
    }

    void GetSampleCount(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_Audio, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(renderer->GetSampleCount());
-        LOG_DEBUG(Service_Audio, "called");
    }

    void GetState(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_Audio, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(static_cast<u32>(renderer->GetStreamState()));
-        LOG_DEBUG(Service_Audio, "called");
    }

    void GetMixBufferCount(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_Audio, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(renderer->GetMixBufferCount());
-        LOG_DEBUG(Service_Audio, "called");
    }

    void RequestUpdateImpl(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_Audio, "(STUBBED) called");
+
        ctx.WriteBuffer(renderer->UpdateAudioRenderer(ctx.ReadBuffer()));
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_Audio, "(STUBBED) called");
    }

    void Start(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_Audio, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};

        rb.Push(RESULT_SUCCESS);
-
-        LOG_WARNING(Service_Audio, "(STUBBED) called");
    }

    void Stop(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_Audio, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};

        rb.Push(RESULT_SUCCESS);
-
-        LOG_WARNING(Service_Audio, "(STUBBED) called");
    }

    void QuerySystemEvent(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_Audio, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(system_event);
-
-        LOG_WARNING(Service_Audio, "(STUBBED) called");
    }

    void SetRenderingTimeLimit(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        rendering_time_limit_percent = rp.Pop<u32>();
+        LOG_DEBUG(Service_Audio, "called. rendering_time_limit_percent={}",
+                  rendering_time_limit_percent);
+
        ASSERT(rendering_time_limit_percent >= 0 && rendering_time_limit_percent <= 100);

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-
-        LOG_DEBUG(Service_Audio, "called. rendering_time_limit_percent={}",
-                  rendering_time_limit_percent);
    }

    void GetRenderingTimeLimit(Kernel::HLERequestContext& ctx) {
@@ -211,6 +216,7 @@ private:

    void GetActiveChannelCount(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_Audio, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(1);
@@ -235,19 +241,20 @@ AudRenU::AudRenU() : ServiceFramework("audren:u") {
 AudRenU::~AudRenU() = default;

 void AudRenU::OpenAudioRenderer(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_Audio, "called");
+
    IPC::RequestParser rp{ctx};
    auto params = rp.PopRaw<AudioCore::AudioRendererParameter>();
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};

    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<Audio::IAudioRenderer>(std::move(params));
-
-    LOG_DEBUG(Service_Audio, "called");
 }

 void AudRenU::GetAudioRendererWorkBufferSize(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    auto params = rp.PopRaw<AudioCore::AudioRendererParameter>();
+    LOG_DEBUG(Service_Audio, "called");

    u64 buffer_sz = Common::AlignUp(4 * params.mix_buffer_count, 0x40);
    buffer_sz += params.unknown_c * 1024;
@@ -301,26 +308,26 @@ void AudRenU::GetAudioRendererWorkBufferSize(Kernel::HLERequestContext& ctx) {
    rb.Push(RESULT_SUCCESS);
    rb.Push<u64>(output_sz);

-    LOG_DEBUG(Service_Audio, "called, buffer_size=0x{:X}", output_sz);
+    LOG_DEBUG(Service_Audio, "buffer_size=0x{:X}", output_sz);
 }

 void AudRenU::GetAudioDevice(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_Audio, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};

    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<Audio::IAudioDevice>();
-
-    LOG_DEBUG(Service_Audio, "called");
 }

 void AudRenU::GetAudioDeviceServiceWithRevisionInfo(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_Audio, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};

    rb.Push(RESULT_SUCCESS);
-    rb.PushIpcInterface<Audio::IAudioDevice>();
-
-    LOG_WARNING(Service_Audio, "(STUBBED) called"); // TODO(ogniK): Figure out what is different
-                                                    // based on the current revision
+    rb.PushIpcInterface<Audio::IAudioDevice>(); // TODO(ogniK): Figure out what is different
+                                                // based on the current revision
 }

 bool AudRenU::IsFeatureSupported(AudioFeatures feature, u32_le revision) const {
--- a/src/core/hle/service/audio/hwopus.cpp
+++ b/src/core/hle/service/audio/hwopus.cpp
@@ -46,10 +46,13 @@ public:

 private:
    void DecodeInterleaved(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Audio, "called");
+
        u32 consumed = 0;
        u32 sample_count = 0;
        std::vector<opus_int16> samples(ctx.GetWriteBufferSize() / sizeof(opus_int16));
        if (!Decoder_DecodeInterleaved(consumed, sample_count, ctx.ReadBuffer(), samples)) {
+            LOG_ERROR(Audio, "Failed to decode opus data");
            IPC::ResponseBuilder rb{ctx, 2};
            // TODO(ogniK): Use correct error code
            rb.Push(ResultCode(-1));
@@ -63,12 +66,15 @@ private:
    }

    void DecodeInterleavedWithPerformance(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Audio, "called");
+
        u32 consumed = 0;
        u32 sample_count = 0;
        u64 performance = 0;
        std::vector<opus_int16> samples(ctx.GetWriteBufferSize() / sizeof(opus_int16));
        if (!Decoder_DecodeInterleaved(consumed, sample_count, ctx.ReadBuffer(), samples,
                                       performance)) {
+            LOG_ERROR(Audio, "Failed to decode opus data");
            IPC::ResponseBuilder rb{ctx, 2};
            // TODO(ogniK): Use correct error code
            rb.Push(ResultCode(-1));
@@ -88,24 +94,31 @@ private:
        std::optional<std::reference_wrapper<u64>> performance_time = std::nullopt) {
        const auto start_time = std::chrono::high_resolution_clock::now();
        std::size_t raw_output_sz = output.size() * sizeof(opus_int16);
-        if (sizeof(OpusHeader) > input.size())
+        if (sizeof(OpusHeader) > input.size()) {
+            LOG_ERROR(Audio, "Input is smaller than the header size");
            return false;
+        }
        OpusHeader hdr{};
        std::memcpy(&hdr, input.data(), sizeof(OpusHeader));
        if (sizeof(OpusHeader) + static_cast<u32>(hdr.sz) > input.size()) {
+            LOG_ERROR(Audio, "Input does not fit in the opus header size");
            return false;
        }
        auto frame = input.data() + sizeof(OpusHeader);
        auto decoded_sample_count = opus_packet_get_nb_samples(
            frame, static_cast<opus_int32>(input.size() - sizeof(OpusHeader)),
            static_cast<opus_int32>(sample_rate));
-        if (decoded_sample_count * channel_count * sizeof(u16) > raw_output_sz)
+        if (decoded_sample_count * channel_count * sizeof(u16) > raw_output_sz) {
+            LOG_ERROR(Audio, "Decoded data does not fit into the output data");
            return false;
+        }
        auto out_sample_count =
            opus_decode(decoder.get(), frame, hdr.sz, output.data(),
                        (static_cast<int>(raw_output_sz / sizeof(s16) / channel_count)), 0);
-        if (out_sample_count < 0)
+        if (out_sample_count < 0) {
+            LOG_ERROR(Audio, "Incorrect sample count received from opus_decode");
            return false;
+        }
        const auto end_time = std::chrono::high_resolution_clock::now() - start_time;
        sample_count = out_sample_count;
        consumed = static_cast<u32>(sizeof(OpusHeader) + hdr.sz);
@@ -134,14 +147,17 @@ static std::size_t WorkerBufferSize(u32 channel_count) {

 void HwOpus::GetWorkBufferSize(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
-    auto sample_rate = rp.Pop<u32>();
-    auto channel_count = rp.Pop<u32>();
+    const auto sample_rate = rp.Pop<u32>();
+    const auto channel_count = rp.Pop<u32>();
+    LOG_DEBUG(Audio, "called with sample_rate={}, channel_count={}", sample_rate, channel_count);
+
    ASSERT_MSG(sample_rate == 48000 || sample_rate == 24000 || sample_rate == 16000 ||
                   sample_rate == 12000 || sample_rate == 8000,
               "Invalid sample rate");
    ASSERT_MSG(channel_count == 1 || channel_count == 2, "Invalid channel count");
-    u32 worker_buffer_sz = static_cast<u32>(WorkerBufferSize(channel_count));
-    LOG_DEBUG(Audio, "called worker_buffer_sz={}", worker_buffer_sz);
+
+    const u32 worker_buffer_sz = static_cast<u32>(WorkerBufferSize(channel_count));
+    LOG_DEBUG(Audio, "worker_buffer_sz={}", worker_buffer_sz);

    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
@@ -155,6 +171,7 @@ void HwOpus::OpenOpusDecoder(Kernel::HLERequestContext& ctx) {
    auto buffer_sz = rp.Pop<u32>();
    LOG_DEBUG(Audio, "called sample_rate={}, channel_count={}, buffer_size={}", sample_rate,
              channel_count, buffer_sz);
+
    ASSERT_MSG(sample_rate == 48000 || sample_rate == 24000 || sample_rate == 16000 ||
                   sample_rate == 12000 || sample_rate == 8000,
               "Invalid sample rate");
@@ -165,6 +182,7 @@ void HwOpus::OpenOpusDecoder(Kernel::HLERequestContext& ctx) {
    std::unique_ptr<OpusDecoder, OpusDeleter> decoder{
        static_cast<OpusDecoder*>(operator new(worker_sz))};
    if (opus_decoder_init(decoder.get(), sample_rate, channel_count)) {
+        LOG_ERROR(Audio, "Failed to init opus decoder");
        IPC::ResponseBuilder rb{ctx, 2};
        // TODO(ogniK): Use correct error code
        rb.Push(ResultCode(-1));
--- a/src/core/hle/service/bcat/module.cpp
+++ b/src/core/hle/service/bcat/module.cpp
@@ -33,10 +33,11 @@ public:
 };

 void Module::Interface::CreateBcatService(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_BCAT, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<IBcatService>();
-    LOG_DEBUG(Service_BCAT, "called");
 }

 Module::Interface::Interface(std::shared_ptr<Module> module, const char* name)
--- a/src/core/hle/service/btdrv/btdrv.cpp
+++ b/src/core/hle/service/btdrv/btdrv.cpp
@@ -34,13 +34,14 @@ public:

 private:
    void RegisterEvent(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_BTM, "(STUBBED) called");
+
        auto& kernel = Core::System::GetInstance().Kernel();
        register_event =
            Kernel::Event::Create(kernel, Kernel::ResetType::OneShot, "BT:RegisterEvent");
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(register_event);
-        LOG_WARNING(Service_BTM, "(STUBBED) called");
    }
    Kernel::SharedPtr<Kernel::Event> register_event;
 };
--- a/src/core/hle/service/btm/btm.cpp
+++ b/src/core/hle/service/btm/btm.cpp
@@ -57,40 +57,44 @@ public:

 private:
    void GetScanEvent(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_BTM, "(STUBBED) called");
+
        auto& kernel = Core::System::GetInstance().Kernel();
        scan_event =
            Kernel::Event::Create(kernel, Kernel::ResetType::OneShot, "IBtmUserCore:ScanEvent");
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(scan_event);
-        LOG_WARNING(Service_BTM, "(STUBBED) called");
    }
    void GetConnectionEvent(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_BTM, "(STUBBED) called");
+
        auto& kernel = Core::System::GetInstance().Kernel();
        connection_event = Kernel::Event::Create(kernel, Kernel::ResetType::OneShot,
                                                 "IBtmUserCore:ConnectionEvent");
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(connection_event);
-        LOG_WARNING(Service_BTM, "(STUBBED) called");
    }
    void GetDiscoveryEvent(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_BTM, "(STUBBED) called");
+
        auto& kernel = Core::System::GetInstance().Kernel();
        service_discovery =
            Kernel::Event::Create(kernel, Kernel::ResetType::OneShot, "IBtmUserCore:Discovery");
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(service_discovery);
-        LOG_WARNING(Service_BTM, "(STUBBED) called");
    }
    void GetConfigEvent(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_BTM, "(STUBBED) called");
+
        auto& kernel = Core::System::GetInstance().Kernel();
        config_event =
            Kernel::Event::Create(kernel, Kernel::ResetType::OneShot, "IBtmUserCore:ConfigEvent");
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(config_event);
-        LOG_WARNING(Service_BTM, "(STUBBED) called");
    }
    Kernel::SharedPtr<Kernel::Event> scan_event;
    Kernel::SharedPtr<Kernel::Event> connection_event;
@@ -111,10 +115,11 @@ public:

 private:
    void GetCoreImpl(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_BTM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IBtmUserCore>();
-        LOG_DEBUG(Service_BTM, "called");
    }
 };

@@ -209,11 +214,11 @@ public:

 private:
    void GetCoreImpl(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_BTM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IBtmSystemCore>();
-
-        LOG_DEBUG(Service_BTM, "called");
    }
 };

--- a/src/core/hle/service/fgm/fgm.cpp
+++ b/src/core/hle/service/fgm/fgm.cpp
@@ -42,11 +42,11 @@ public:

 private:
    void Initialize(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_FGM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IRequest>();
-
-        LOG_DEBUG(Service_FGM, "called");
    }
 };

--- a/src/core/hle/service/filesystem/fsp_srv.cpp
+++ b/src/core/hle/service/filesystem/fsp_srv.cpp
@@ -62,11 +62,13 @@ private:

        // Error checking
        if (length < 0) {
+            LOG_ERROR(Service_FS, "Invalid length provided");
            IPC::ResponseBuilder rb{ctx, 2};
            rb.Push(FileSys::ERROR_INVALID_SIZE);
            return;
        }
        if (offset < 0) {
+            LOG_ERROR(Service_FS, "Invalid offset provided");
            IPC::ResponseBuilder rb{ctx, 2};
            rb.Push(FileSys::ERROR_INVALID_OFFSET);
            return;
@@ -107,11 +109,13 @@ private:

        // Error checking
        if (length < 0) {
+            LOG_ERROR(Service_FS, "Invalid length provided");
            IPC::ResponseBuilder rb{ctx, 2};
            rb.Push(FileSys::ERROR_INVALID_SIZE);
            return;
        }
        if (offset < 0) {
+            LOG_ERROR(Service_FS, "Invalid offset provided");
            IPC::ResponseBuilder rb{ctx, 2};
            rb.Push(FileSys::ERROR_INVALID_OFFSET);
            return;
@@ -138,11 +142,13 @@ private:

        // Error checking
        if (length < 0) {
+            LOG_ERROR(Service_FS, "Invalid length provided");
            IPC::ResponseBuilder rb{ctx, 2};
            rb.Push(FileSys::ERROR_INVALID_SIZE);
            return;
        }
        if (offset < 0) {
+            LOG_ERROR(Service_FS, "Invalid offset provided");
            IPC::ResponseBuilder rb{ctx, 2};
            rb.Push(FileSys::ERROR_INVALID_OFFSET);
            return;
@@ -180,9 +186,10 @@ private:
    void SetSize(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        const u64 size = rp.Pop<u64>();
-        backend->Resize(size);
        LOG_DEBUG(Service_FS, "called, size={}", size);

+        backend->Resize(size);
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }
@@ -465,6 +472,8 @@ public:
    }

    void ReadSaveDataInfo(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_FS, "called");
+
        // Calculate how many entries we can fit in the output buffer
        const u64 count_entries = ctx.GetWriteBufferSize() / sizeof(SaveDataInfo);

@@ -703,6 +712,8 @@ void FSP_SRV::OpenFileSystemWithPatch(Kernel::HLERequestContext& ctx) {

    const auto type = rp.PopRaw<FileSystemType>();
    const auto title_id = rp.PopRaw<u64>();
+    LOG_WARNING(Service_FS, "(STUBBED) called with type={}, title_id={:016X}",
+                static_cast<u8>(type), title_id);

    IPC::ResponseBuilder rb{ctx, 2, 0, 0};
    rb.Push(ResultCode(-1));
@@ -738,6 +749,7 @@ void FSP_SRV::MountSaveData(Kernel::HLERequestContext& ctx) {
    auto space_id = rp.PopRaw<FileSys::SaveDataSpaceId>();
    auto unk = rp.Pop<u32>();
    LOG_INFO(Service_FS, "called with unknown={:08X}", unk);
+
    auto save_struct = rp.PopRaw<FileSys::SaveDataDescriptor>();

    auto dir = OpenSaveData(space_id, save_struct);
@@ -763,6 +775,7 @@ void FSP_SRV::OpenReadOnlySaveDataFileSystem(Kernel::HLERequestContext& ctx) {
 void FSP_SRV::OpenSaveDataInfoReaderBySaveDataSpaceId(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    const auto space = rp.PopRaw<FileSys::SaveDataSpaceId>();
+    LOG_INFO(Service_FS, "called, space={}", static_cast<u8>(space));

    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
--- a/src/core/hle/service/hid/controllers/npad.cpp
+++ b/src/core/hle/service/hid/controllers/npad.cpp
@@ -524,6 +524,8 @@ void Controller_NPad::SetNpadMode(u32 npad_id, NPadAssignments assignment_mode)

 void Controller_NPad::VibrateController(const std::vector<u32>& controller_ids,
                                        const std::vector<Vibration>& vibrations) {
+    LOG_WARNING(Service_HID, "(STUBBED) called");
+
    if (!can_controllers_vibrate) {
        return;
    }
@@ -533,7 +535,6 @@ void Controller_NPad::VibrateController(const std::vector<u32>& controller_ids,
            // TODO(ogniK): Vibrate the physical controller
        }
    }
-    LOG_WARNING(Service_HID, "(STUBBED) called");
    last_processed_vibration = vibrations.back();
 }

--- a/src/core/hle/service/hid/hid.cpp
+++ b/src/core/hle/service/hid/hid.cpp
@@ -124,10 +124,11 @@ public:

 private:
    void GetSharedMemoryHandle(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(shared_mem);
-        LOG_DEBUG(Service_HID, "called");
    }

    void UpdateControllers(u64 userdata, int cycles_late) {
@@ -163,9 +164,10 @@ public:

 private:
    void ActivateVibrationDevice(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }
 };

@@ -303,6 +305,8 @@ private:
    std::shared_ptr<IAppletResource> applet_resource;

    void CreateAppletResource(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        if (applet_resource == nullptr) {
            applet_resource = std::make_shared<IAppletResource>();
        }
@@ -310,206 +314,228 @@ private:
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IAppletResource>(applet_resource);
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateXpad(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->ActivateController(HidController::XPad);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateDebugPad(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->ActivateController(HidController::DebugPad);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateTouchScreen(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->ActivateController(HidController::Touchscreen);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateMouse(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->ActivateController(HidController::Mouse);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateKeyboard(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->ActivateController(HidController::Keyboard);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateGesture(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->ActivateController(HidController::Gesture);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateNpadWithRevision(Kernel::HLERequestContext& ctx) {
        // Should have no effect with how our npad sets up the data
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->ActivateController(HidController::NPad);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void StartSixAxisSensor(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        auto handle = rp.PopRaw<u32>();
+        LOG_WARNING(Service_HID, "(STUBBED) called with handle={}", handle);
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void SetGyroscopeZeroDriftMode(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void IsSixAxisSensorAtRest(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        // TODO (Hexagon12): Properly implement reading gyroscope values from controllers.
        rb.Push(true);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void SetSupportedNpadStyleSet(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        auto supported_styleset = rp.PopRaw<u32>();
+        LOG_DEBUG(Service_HID, "called with supported_styleset={}", supported_styleset);
+
        applet_resource->GetController<Controller_NPad>(HidController::NPad)
            .SetSupportedStyleSet({supported_styleset});

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-
-        LOG_DEBUG(Service_HID, "called");
    }

    void GetSupportedNpadStyleSet(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        auto& controller = applet_resource->GetController<Controller_NPad>(HidController::NPad);

        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(controller.GetSupportedStyleSet().raw);
-        LOG_DEBUG(Service_HID, "called");
    }

    void SetSupportedNpadIdType(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->GetController<Controller_NPad>(HidController::NPad)
            .SetSupportedNPadIdTypes(ctx.ReadBuffer().data(), ctx.GetReadBufferSize());
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateNpad(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
        applet_resource->ActivateController(HidController::NPad);
-        LOG_DEBUG(Service_HID, "called");
    }

    void AcquireNpadStyleSetUpdateEventHandle(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        auto npad_id = rp.PopRaw<u32>();
+        LOG_DEBUG(Service_HID, "called with npad_id={}", npad_id);
+
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(applet_resource->GetController<Controller_NPad>(HidController::NPad)
                               .GetStyleSetChangedEvent());
-        LOG_DEBUG(Service_HID, "called");
    }

    void DisconnectNpad(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        auto npad_id = rp.PopRaw<u32>();
+        LOG_DEBUG(Service_HID, "called with npad_id={}", npad_id);
+
        applet_resource->GetController<Controller_NPad>(HidController::NPad)
            .DisconnectNPad(npad_id);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void GetPlayerLedPattern(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        auto npad_id = rp.PopRaw<u32>();
+        LOG_DEBUG(Service_HID, "called with npad_id={}", npad_id);
+
        IPC::ResponseBuilder rb{ctx, 4};
        rb.Push(RESULT_SUCCESS);
        rb.PushRaw<u64>(applet_resource->GetController<Controller_NPad>(HidController::NPad)
                            .GetLedPattern(npad_id)
                            .raw);
-        LOG_DEBUG(Service_HID, "called");
    }

    void SetNpadJoyHoldType(Kernel::HLERequestContext& ctx) {
-        auto& controller = applet_resource->GetController<Controller_NPad>(HidController::NPad);
        IPC::RequestParser rp{ctx};
        const auto hold_type = rp.PopRaw<u64>();
+        LOG_DEBUG(Service_HID, "called with hold_type={}", hold_type);
+
+        auto& controller = applet_resource->GetController<Controller_NPad>(HidController::NPad);
        controller.SetHoldType(Controller_NPad::NpadHoldType{hold_type});

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void GetNpadJoyHoldType(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        const auto& controller =
            applet_resource->GetController<Controller_NPad>(HidController::NPad);
        IPC::ResponseBuilder rb{ctx, 4};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u64>(static_cast<u64>(controller.GetHoldType()));
-        LOG_DEBUG(Service_HID, "called");
    }

    void SetNpadJoyAssignmentModeSingleByDefault(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        auto npad_id = rp.PopRaw<u32>();
+        LOG_WARNING(Service_HID, "(STUBBED) called with npad_id={}", npad_id);
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void BeginPermitVibrationSession(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->GetController<Controller_NPad>(HidController::NPad)
            .SetVibrationEnabled(true);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void EndPermitVibrationSession(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        applet_resource->GetController<Controller_NPad>(HidController::NPad)
            .SetVibrationEnabled(false);
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void SendVibrationValue(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        const auto controller_id = rp.PopRaw<u32>();
        const auto vibration_values = rp.PopRaw<Controller_NPad::Vibration>();
+        LOG_DEBUG(Service_HID, "called with controller_id={}", controller_id);

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);

        applet_resource->GetController<Controller_NPad>(HidController::NPad)
            .VibrateController({controller_id}, {vibration_values});
-        LOG_DEBUG(Service_HID, "called");
    }

    void SendVibrationValues(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        const auto controllers = ctx.ReadBuffer(0);
        const auto vibrations = ctx.ReadBuffer(1);

@@ -527,86 +553,96 @@ private:

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void GetActualVibrationValue(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        IPC::ResponseBuilder rb{ctx, 6};
        rb.Push(RESULT_SUCCESS);
        rb.PushRaw<Controller_NPad::Vibration>(
            applet_resource->GetController<Controller_NPad>(HidController::NPad)
                .GetLastVibration());
-        LOG_DEBUG(Service_HID, "called");
    }

    void SetNpadJoyAssignmentModeDual(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        const auto npad_id = rp.PopRaw<u32>();
+        LOG_DEBUG(Service_HID, "called with npad_id={}", npad_id);
+
        auto& controller = applet_resource->GetController<Controller_NPad>(HidController::NPad);
        controller.SetNpadMode(npad_id, Controller_NPad::NPadAssignments::Dual);

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_HID, "called");
    }

    void MergeSingleJoyAsDualJoy(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void SetNpadHandheldActivationMode(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        auto mode = rp.PopRaw<u32>();
+        LOG_WARNING(Service_HID, "(STUBBED) called with mode={}", mode);
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void GetVibrationDeviceInfo(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        IPC::ResponseBuilder rb{ctx, 4};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(1);
        rb.Push<u32>(0);
-        LOG_DEBUG(Service_HID, "called");
    }

    void CreateActiveVibrationDeviceList(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_HID, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IActiveVibrationDeviceList>();
-        LOG_DEBUG(Service_HID, "called");
    }

    void ActivateConsoleSixAxisSensor(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void StartConsoleSixAxisSensor(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void StopSixAxisSensor(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void SetIsPalmaAllConnectable(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }

    void SetPalmaBoostMode(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_HID, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_HID, "(STUBBED) called");
    }
 };

--- a/src/core/hle/service/hid/irs.cpp
+++ b/src/core/hle/service/hid/irs.cpp
@@ -44,115 +44,133 @@ IRS::IRS() : ServiceFramework{"irs"} {
 }

 void IRS::ActivateIrsensor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::DeactivateIrsensor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::GetIrsensorSharedMemoryHandle(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_IRS, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushCopyObjects(shared_mem);
-    LOG_DEBUG(Service_IRS, "called");
 }

 void IRS::StopImageProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::RunMomentProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::RunClusteringProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::RunImageTransferProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::GetImageTransferProcessorState(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 5};
    rb.Push(RESULT_SUCCESS);
    rb.PushRaw<u64>(CoreTiming::GetTicks());
    rb.PushRaw<u32>(0);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::RunTeraPluginProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::GetNpadIrCameraHandle(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.PushRaw<u32>(device_handle);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::RunPointingProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::SuspendImageProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::CheckFirmwareVersion(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::SetFunctionLevel(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::RunImageTransferExProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::RunIrLedProcessor(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::StopImageProcessorAsync(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 void IRS::ActivateIrsensorWithFunctionLevel(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service_IRS, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_WARNING(Service_IRS, "(STUBBED) called");
 }

 IRS::~IRS() = default;
--- a/src/core/hle/service/lbl/lbl.cpp
+++ b/src/core/hle/service/lbl/lbl.cpp
@@ -55,29 +55,29 @@ public:

 private:
    void EnableVrMode(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_LBL, "called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);

        vr_mode_enabled = true;
-
-        LOG_DEBUG(Service_LBL, "called");
    }

    void DisableVrMode(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_LBL, "called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);

        vr_mode_enabled = false;
-
-        LOG_DEBUG(Service_LBL, "called");
    }

    void IsVrModeEnabled(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_LBL, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push(vr_mode_enabled);
-
-        LOG_DEBUG(Service_LBL, "called");
    }

    bool vr_mode_enabled = false;
--- a/src/core/hle/service/ldn/ldn.cpp
+++ b/src/core/hle/service/ldn/ldn.cpp
@@ -44,11 +44,11 @@ public:
    }

    void CreateMonitorService(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_LDN, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IMonitorService>();
-
-        LOG_DEBUG(Service_LDN, "called");
    }
 };

@@ -104,11 +104,11 @@ public:
    }

    void CreateSystemLocalCommunicationService(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_LDN, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ILocalCommunicationService>("ISystemLocalCommunicationService");
-
-        LOG_DEBUG(Service_LDN, "called");
    }
 };

@@ -125,11 +125,11 @@ public:
    }

    void CreateUserLocalCommunicationService(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_LDN, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ILocalCommunicationService>("IUserLocalCommunicationService");
-
-        LOG_DEBUG(Service_LDN, "called");
    }
 };

--- a/src/core/hle/service/ldr/ldr.cpp
+++ b/src/core/hle/service/ldr/ldr.cpp
@@ -97,6 +97,8 @@ public:
        rp.Skip(2, false);
        const VAddr nrr_addr{rp.Pop<VAddr>()};
        const u64 nrr_size{rp.Pop<u64>()};
+        LOG_DEBUG(Service_LDR, "called with nrr_addr={:016X}, nrr_size={:016X}", nrr_addr,
+                  nrr_size);

        if (!initialized) {
            LOG_ERROR(Service_LDR, "LDR:RO not initialized before use!");
@@ -189,6 +191,7 @@ public:
        IPC::RequestParser rp{ctx};
        rp.Skip(2, false);
        const auto nrr_addr{rp.Pop<VAddr>()};
+        LOG_DEBUG(Service_LDR, "called with nrr_addr={:016X}", nrr_addr);

        if (!Common::Is4KBAligned(nrr_addr)) {
            LOG_ERROR(Service_LDR, "NRR Address has invalid alignment (actual {:016X})!", nrr_addr);
@@ -219,6 +222,10 @@ public:
        const u64 nro_size{rp.Pop<u64>()};
        const VAddr bss_addr{rp.Pop<VAddr>()};
        const u64 bss_size{rp.Pop<u64>()};
+        LOG_DEBUG(
+            Service_LDR,
+            "called with nro_addr={:016X}, nro_size={:016X}, bss_addr={:016X}, bss_size={:016X}",
+            nro_addr, nro_size, bss_addr, bss_size);

        if (!initialized) {
            LOG_ERROR(Service_LDR, "LDR:RO not initialized before use!");
@@ -345,6 +352,8 @@ public:
        rp.Skip(2, false);
        const VAddr mapped_addr{rp.PopRaw<VAddr>()};
        const VAddr heap_addr{rp.PopRaw<VAddr>()};
+        LOG_DEBUG(Service_LDR, "called with mapped_addr={:016X}, heap_addr={:016X}", mapped_addr,
+                  heap_addr);

        if (!initialized) {
            LOG_ERROR(Service_LDR, "LDR:RO not initialized before use!");
@@ -393,11 +402,12 @@ public:
    }

    void Initialize(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_LDR, "(STUBBED) called");
+
        initialized = true;

        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_LDR, "(STUBBED) called");
    }

 private:
--- a/src/core/hle/service/lm/lm.cpp
+++ b/src/core/hle/service/lm/lm.cpp
@@ -209,11 +209,11 @@ public:
     *      0: ResultCode
     */
    void OpenLogger(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_LM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ILogger>();
-
-        LOG_DEBUG(Service_LM, "called");
    }
 };

--- a/src/core/hle/service/mm/mm_u.cpp
+++ b/src/core/hle/service/mm/mm_u.cpp
@@ -31,12 +31,14 @@ public:
 private:
    void Initialize(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_MM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }

    void Finalize(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_MM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }
@@ -45,15 +47,16 @@ private:
        IPC::RequestParser rp{ctx};
        min = rp.Pop<u32>();
        max = rp.Pop<u32>();
-        current = min;
-
        LOG_WARNING(Service_MM, "(STUBBED) called, min=0x{:X}, max=0x{:X}", min, max);
+
+        current = min;
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }

    void Get(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_MM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push(current);
@@ -61,6 +64,7 @@ private:

    void InitializeWithId(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_MM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(id); // Any non zero value
@@ -68,6 +72,7 @@ private:

    void FinalizeWithId(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_MM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }
@@ -77,16 +82,17 @@ private:
        u32 input_id = rp.Pop<u32>();
        min = rp.Pop<u32>();
        max = rp.Pop<u32>();
-        current = min;
-
        LOG_WARNING(Service_MM, "(STUBBED) called, input_id=0x{:X}, min=0x{:X}, max=0x{:X}",
                    input_id, min, max);
+
+        current = min;
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }

    void GetWithId(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_MM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push(current);
--- a/src/core/hle/service/nfc/nfc.cpp
+++ b/src/core/hle/service/nfc/nfc.cpp
@@ -43,11 +43,11 @@ public:

 private:
    void CreateAmInterface(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NFC, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IAm>();
-
-        LOG_DEBUG(Service_NFC, "called");
    }
 };

@@ -91,11 +91,11 @@ public:

 private:
    void CreateUserInterface(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NFC, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<MFIUser>();
-
-        LOG_DEBUG(Service_NFC, "called");
    }
 };

@@ -138,19 +138,19 @@ private:
    };

    void InitializeOld(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NFC, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0};
        rb.Push(RESULT_SUCCESS);
-
        // We don't deal with hardware initialization so we can just stub this.
-        LOG_DEBUG(Service_NFC, "called");
    }

    void IsNfcEnabledOld(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NFC, "IsNfcEnabledOld");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.PushRaw<u8>(Settings::values.enable_nfc);
-
-        LOG_DEBUG(Service_NFC, "IsNfcEnabledOld");
    }

    void GetStateOld(Kernel::HLERequestContext& ctx) {
@@ -183,11 +183,11 @@ public:

 private:
    void CreateUserInterface(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NFC, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IUser>();
-
-        LOG_DEBUG(Service_NFC, "called");
    }
 };

@@ -241,11 +241,11 @@ public:

 private:
    void CreateSystemInterface(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NFC, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ISystem>();
-
-        LOG_DEBUG(Service_NFC, "called");
    }
 };

--- a/src/core/hle/service/nfp/nfp.cpp
+++ b/src/core/hle/service/nfp/nfp.cpp
@@ -108,30 +108,29 @@ private:
    static_assert(sizeof(CommonInfo) == 0x40, "CommonInfo is an invalid size");

    void Initialize(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NFC, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0};
        rb.Push(RESULT_SUCCESS);

        state = State::Initialized;
-
-        LOG_DEBUG(Service_NFC, "called");
    }

    void GetState(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NFC, "called");
+
        IPC::ResponseBuilder rb{ctx, 3, 0};
        rb.Push(RESULT_SUCCESS);
        rb.PushRaw<u32>(static_cast<u32>(state));
-
-        LOG_DEBUG(Service_NFC, "called");
    }

    void ListDevices(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        const u32 array_size = rp.Pop<u32>();
+        LOG_DEBUG(Service_NFP, "called, array_size={}", array_size);

        ctx.WriteBuffer(&device_handle, sizeof(device_handle));

-        LOG_DEBUG(Service_NFP, "called, array_size={}", array_size);
-
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(1);
@@ -141,6 +140,7 @@ private:
        IPC::RequestParser rp{ctx};
        const u64 dev_handle = rp.Pop<u64>();
        LOG_DEBUG(Service_NFP, "called, dev_handle=0x{:X}", dev_handle);
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(npad_id);
@@ -150,6 +150,7 @@ private:
        IPC::RequestParser rp{ctx};
        const u64 dev_handle = rp.Pop<u64>();
        LOG_DEBUG(Service_NFP, "called, dev_handle=0x{:X}", dev_handle);
+
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(nfp_interface.GetNFCEvent());
@@ -168,6 +169,7 @@ private:

    void StopDetection(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_NFP, "called");
+
        switch (device_state) {
        case DeviceState::TagFound:
        case DeviceState::TagNearby:
@@ -185,6 +187,7 @@ private:

    void GetDeviceState(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_NFP, "called");
+
        auto nfc_event = nfp_interface.GetNFCEvent();
        if (!nfc_event->ShouldWait(Kernel::GetCurrentThread()) && !has_attached_handle) {
            device_state = DeviceState::TagFound;
@@ -323,6 +326,7 @@ private:

 void Module::Interface::CreateUserInterface(Kernel::HLERequestContext& ctx) {
    LOG_DEBUG(Service_NFP, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<IUser>(*this);
--- a/src/core/hle/service/nifm/nifm.cpp
+++ b/src/core/hle/service/nifm/nifm.cpp
@@ -63,12 +63,14 @@ public:
 private:
    void Submit(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }

    void GetRequestState(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(0);
@@ -76,12 +78,14 @@ private:

    void GetResult(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }

    void GetSystemEventReadableHandles(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2, 2};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(event1, event2);
@@ -89,12 +93,14 @@ private:

    void Cancel(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }

    void SetConnectionConfirmationOption(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }
@@ -122,32 +128,36 @@ private:
    void GetClientId(Kernel::HLERequestContext& ctx) {
        static constexpr u32 client_id = 1;
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 4};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u64>(client_id); // Client ID needs to be non zero otherwise it's considered invalid
    }
    void CreateScanRequest(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIFM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};

        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IScanRequest>();
-
-        LOG_DEBUG(Service_NIFM, "called");
    }
    void CreateRequest(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIFM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};

        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IRequest>();
-
-        LOG_DEBUG(Service_NIFM, "called");
    }
    void RemoveNetworkProfile(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }
    void CreateTemporaryNetworkProfile(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIFM, "called");
+
        ASSERT_MSG(ctx.GetReadBufferSize() == 0x17c, "NetworkProfileData is not the correct size");
        u128 uuid{};
        auto buffer = ctx.ReadBuffer();
@@ -158,23 +168,24 @@ private:
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<INetworkProfile>();
        rb.PushRaw<u128>(uuid);
-
-        LOG_DEBUG(Service_NIFM, "called");
    }
    void IsWirelessCommunicationEnabled(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u8>(0);
    }
    void IsEthernetCommunicationEnabled(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u8>(0);
    }
    void IsAnyInternetRequestAccepted(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_NIFM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u8>(0);
@@ -235,17 +246,19 @@ public:
    }

    void CreateGeneralServiceOld(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIFM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IGeneralService>();
-        LOG_DEBUG(Service_NIFM, "called");
    }

    void CreateGeneralService(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIFM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IGeneralService>();
-        LOG_DEBUG(Service_NIFM, "called");
    }
 };

--- a/src/core/hle/service/nim/nim.cpp
+++ b/src/core/hle/service/nim/nim.cpp
@@ -148,47 +148,53 @@ private:

    void StartTask(Kernel::HLERequestContext& ctx) {
        // No need to connect to the internet, just finish the task straight away.
+        LOG_DEBUG(Service_NIM, "called");
+
        finished_event->Signal();
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_NIM, "called");
    }

    void GetFinishNotificationEvent(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(finished_event);
-        LOG_DEBUG(Service_NIM, "called");
    }

    void GetResult(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_NIM, "called");
    }

    void Cancel(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIM, "called");
+
        finished_event->Clear();
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_DEBUG(Service_NIM, "called");
    }

    void IsProcessing(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIM, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.PushRaw<u32>(0); // We instantly process the request
-        LOG_DEBUG(Service_NIM, "called");
    }

    void GetServerTime(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIM, "called");
+
        const s64 server_time{std::chrono::duration_cast<std::chrono::seconds>(
                                  std::chrono::system_clock::now().time_since_epoch())
                                  .count()};
        IPC::ResponseBuilder rb{ctx, 4};
        rb.Push(RESULT_SUCCESS);
        rb.PushRaw<s64>(server_time);
-        LOG_DEBUG(Service_NIM, "called");
    }
 };

@@ -208,23 +214,26 @@ public:

 private:
    void OpenEnsureNetworkClockAvailabilityService(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NIM, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IEnsureNetworkClockAvailabilityService>();
-        LOG_DEBUG(Service_NIM, "called");
    }

    // TODO(ogniK): Do we need these?
    void SuspendAutonomicTimeCorrection(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_NIM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_NIM, "(STUBBED) called");
    }

    void ResumeAutonomicTimeCorrection(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_NIM, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
-        LOG_WARNING(Service_NIM, "(STUBBED) called");
    }
 };

--- a/src/core/hle/service/ns/ns.cpp
+++ b/src/core/hle/service/ns/ns.cpp
@@ -433,11 +433,11 @@ public:
 private:
    template <typename T>
    void PushInterface(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NS, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<T>();
-
-        LOG_DEBUG(Service_NS, "called");
    }
 };

@@ -526,11 +526,11 @@ public:

 private:
    void OpenSystemUpdateControl(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_NS, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<ISystemUpdateControl>();
-
-        LOG_DEBUG(Service_NS, "called");
    }
 };

--- a/src/core/hle/service/ns/pl_u.cpp
+++ b/src/core/hle/service/ns/pl_u.cpp
@@ -281,6 +281,7 @@ void PL_U::RequestLoad(Kernel::HLERequestContext& ctx) {
    const u32 shared_font_type{rp.Pop<u32>()};
    // Games don't call this so all fonts should be loaded
    LOG_DEBUG(Service_NS, "called, shared_font_type={}", shared_font_type);
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
 }
@@ -288,8 +289,8 @@ void PL_U::RequestLoad(Kernel::HLERequestContext& ctx) {
 void PL_U::GetLoadState(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    const u32 font_id{rp.Pop<u32>()};
-
    LOG_DEBUG(Service_NS, "called, font_id={}", font_id);
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u32>(static_cast<u32>(LoadState::Done));
@@ -298,8 +299,8 @@ void PL_U::GetLoadState(Kernel::HLERequestContext& ctx) {
 void PL_U::GetSize(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    const u32 font_id{rp.Pop<u32>()};
-
    LOG_DEBUG(Service_NS, "called, font_id={}", font_id);
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u32>(impl->GetSharedFontRegion(font_id).size);
@@ -308,8 +309,8 @@ void PL_U::GetSize(Kernel::HLERequestContext& ctx) {
 void PL_U::GetSharedMemoryAddressOffset(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    const u32 font_id{rp.Pop<u32>()};
-
    LOG_DEBUG(Service_NS, "called, font_id={}", font_id);
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u32>(impl->GetSharedFontRegion(font_id).offset);
@@ -317,6 +318,7 @@ void PL_U::GetSharedMemoryAddressOffset(Kernel::HLERequestContext& ctx) {

 void PL_U::GetSharedMemoryNativeHandle(Kernel::HLERequestContext& ctx) {
    // Map backing memory for the font data
+    LOG_DEBUG(Service_NS, "called");
    Core::CurrentProcess()->VMManager().MapMemoryBlock(SHARED_FONT_MEM_VADDR, impl->shared_font, 0,
                                                       SHARED_FONT_MEM_SIZE,
                                                       Kernel::MemoryState::Shared);
@@ -328,7 +330,6 @@ void PL_U::GetSharedMemoryNativeHandle(Kernel::HLERequestContext& ctx) {
        Kernel::MemoryPermission::Read, SHARED_FONT_MEM_VADDR, Kernel::MemoryRegion::BASE,
        "PL_U:shared_font_mem");

-    LOG_DEBUG(Service_NS, "called");
    IPC::ResponseBuilder rb{ctx, 2, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushCopyObjects(impl->shared_font_mem);
@@ -338,6 +339,7 @@ void PL_U::GetSharedFontInOrderOfPriority(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    const u64 language_code{rp.Pop<u64>()}; // TODO(ogniK): Find out what this is used for
    LOG_DEBUG(Service_NS, "called, language_code={:X}", language_code);
+
    IPC::ResponseBuilder rb{ctx, 4};
    std::vector<u32> font_codes;
    std::vector<u32> font_offsets;
--- a/src/core/hle/service/nvdrv/devices/nvhost_as_gpu.cpp
+++ b/src/core/hle/service/nvdrv/devices/nvhost_as_gpu.cpp
@@ -54,6 +54,7 @@ u32 nvhost_as_gpu::InitalizeEx(const std::vector<u8>& input, std::vector<u8>& ou
    IoctlInitalizeEx params{};
    std::memcpy(&params, input.data(), input.size());
    LOG_WARNING(Service_NVDRV, "(STUBBED) called, big_page_size=0x{:X}", params.big_page_size);
+
    return 0;
 }

@@ -191,6 +192,7 @@ u32 nvhost_as_gpu::BindChannel(const std::vector<u8>& input, std::vector<u8>& ou
    IoctlBindChannel params{};
    std::memcpy(&params, input.data(), input.size());
    LOG_DEBUG(Service_NVDRV, "called, fd={:X}", params.fd);
+
    channel = params.fd;
    return 0;
 }
--- a/src/core/hle/service/nvdrv/devices/nvhost_ctrl_gpu.cpp
+++ b/src/core/hle/service/nvdrv/devices/nvhost_ctrl_gpu.cpp
@@ -103,6 +103,7 @@ u32 nvhost_ctrl_gpu::GetTPCMasks(const std::vector<u8>& input, std::vector<u8>&

 u32 nvhost_ctrl_gpu::GetActiveSlotMask(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_DEBUG(Service_NVDRV, "called");
+
    IoctlActiveSlotMask params{};
    if (input.size() > 0) {
        std::memcpy(&params, input.data(), input.size());
@@ -115,6 +116,7 @@ u32 nvhost_ctrl_gpu::GetActiveSlotMask(const std::vector<u8>& input, std::vector

 u32 nvhost_ctrl_gpu::ZCullGetCtxSize(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_DEBUG(Service_NVDRV, "called");
+
    IoctlZcullGetCtxSize params{};
    if (input.size() > 0) {
        std::memcpy(&params, input.data(), input.size());
@@ -126,6 +128,7 @@ u32 nvhost_ctrl_gpu::ZCullGetCtxSize(const std::vector<u8>& input, std::vector<u

 u32 nvhost_ctrl_gpu::ZCullGetInfo(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_DEBUG(Service_NVDRV, "called");
+
    IoctlNvgpuGpuZcullGetInfoArgs params{};

    if (input.size() > 0) {
@@ -148,6 +151,7 @@ u32 nvhost_ctrl_gpu::ZCullGetInfo(const std::vector<u8>& input, std::vector<u8>&

 u32 nvhost_ctrl_gpu::ZBCSetTable(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_WARNING(Service_NVDRV, "(STUBBED) called");
+
    IoctlZbcSetTable params{};
    std::memcpy(&params, input.data(), input.size());
    // TODO(ogniK): What does this even actually do?
@@ -157,6 +161,7 @@ u32 nvhost_ctrl_gpu::ZBCSetTable(const std::vector<u8>& input, std::vector<u8>&

 u32 nvhost_ctrl_gpu::ZBCQueryTable(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_WARNING(Service_NVDRV, "(STUBBED) called");
+
    IoctlZbcQueryTable params{};
    std::memcpy(&params, input.data(), input.size());
    // TODO : To implement properly
@@ -166,6 +171,7 @@ u32 nvhost_ctrl_gpu::ZBCQueryTable(const std::vector<u8>& input, std::vector<u8>

 u32 nvhost_ctrl_gpu::FlushL2(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_WARNING(Service_NVDRV, "(STUBBED) called");
+
    IoctlFlushL2 params{};
    std::memcpy(&params, input.data(), input.size());
    // TODO : To implement properly
@@ -175,6 +181,7 @@ u32 nvhost_ctrl_gpu::FlushL2(const std::vector<u8>& input, std::vector<u8>& outp

 u32 nvhost_ctrl_gpu::GetGpuTime(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_DEBUG(Service_NVDRV, "called");
+
    IoctlGetGpuTime params{};
    std::memcpy(&params, input.data(), input.size());
    params.gpu_time = CoreTiming::cyclesToNs(CoreTiming::GetTicks());
--- a/src/core/hle/service/nvdrv/devices/nvhost_gpu.cpp
+++ b/src/core/hle/service/nvdrv/devices/nvhost_gpu.cpp
@@ -61,12 +61,14 @@ u32 nvhost_gpu::SetNVMAPfd(const std::vector<u8>& input, std::vector<u8>& output
    IoctlSetNvmapFD params{};
    std::memcpy(&params, input.data(), input.size());
    LOG_DEBUG(Service_NVDRV, "called, fd={}", params.nvmap_fd);
+
    nvmap_fd = params.nvmap_fd;
    return 0;
 }

 u32 nvhost_gpu::SetClientData(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_DEBUG(Service_NVDRV, "called");
+
    IoctlClientData params{};
    std::memcpy(&params, input.data(), input.size());
    user_data = params.data;
@@ -75,6 +77,7 @@ u32 nvhost_gpu::SetClientData(const std::vector<u8>& input, std::vector<u8>& out

 u32 nvhost_gpu::GetClientData(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_DEBUG(Service_NVDRV, "called");
+
    IoctlClientData params{};
    std::memcpy(&params, input.data(), input.size());
    params.data = user_data;
@@ -86,6 +89,7 @@ u32 nvhost_gpu::ZCullBind(const std::vector<u8>& input, std::vector<u8>& output)
    std::memcpy(&zcull_params, input.data(), input.size());
    LOG_DEBUG(Service_NVDRV, "called, gpu_va={:X}, mode={:X}", zcull_params.gpu_va,
              zcull_params.mode);
+
    std::memcpy(output.data(), &zcull_params, output.size());
    return 0;
 }
@@ -95,6 +99,7 @@ u32 nvhost_gpu::SetErrorNotifier(const std::vector<u8>& input, std::vector<u8>&
    std::memcpy(&params, input.data(), input.size());
    LOG_WARNING(Service_NVDRV, "(STUBBED) called, offset={:X}, size={:X}, mem={:X}", params.offset,
                params.size, params.mem);
+
    std::memcpy(output.data(), &params, output.size());
    return 0;
 }
@@ -102,6 +107,7 @@ u32 nvhost_gpu::SetErrorNotifier(const std::vector<u8>& input, std::vector<u8>&
 u32 nvhost_gpu::SetChannelPriority(const std::vector<u8>& input, std::vector<u8>& output) {
    std::memcpy(&channel_priority, input.data(), input.size());
    LOG_DEBUG(Service_NVDRV, "(STUBBED) called, priority={:X}", channel_priority);
+
    return 0;
 }

@@ -113,6 +119,7 @@ u32 nvhost_gpu::AllocGPFIFOEx2(const std::vector<u8>& input, std::vector<u8>& ou
                "unk1={:X}, unk2={:X}, unk3={:X}",
                params.num_entries, params.flags, params.unk0, params.unk1, params.unk2,
                params.unk3);
+
    params.fence_out.id = 0;
    params.fence_out.value = 0;
    std::memcpy(output.data(), &params, output.size());
@@ -124,6 +131,7 @@ u32 nvhost_gpu::AllocateObjectContext(const std::vector<u8>& input, std::vector<
    std::memcpy(&params, input.data(), input.size());
    LOG_WARNING(Service_NVDRV, "(STUBBED) called, class_num={:X}, flags={:X}", params.class_num,
                params.flags);
+
    params.obj_id = 0x0;
    std::memcpy(output.data(), &params, output.size());
    return 0;
@@ -179,6 +187,7 @@ u32 nvhost_gpu::GetWaitbase(const std::vector<u8>& input, std::vector<u8>& outpu
    IoctlGetWaitbase params{};
    std::memcpy(&params, input.data(), sizeof(IoctlGetWaitbase));
    LOG_INFO(Service_NVDRV, "called, unknown=0x{:X}", params.unknown);
+
    params.value = 0; // Seems to be hard coded at 0
    std::memcpy(output.data(), &params, output.size());
    return 0;
@@ -188,6 +197,7 @@ u32 nvhost_gpu::ChannelSetTimeout(const std::vector<u8>& input, std::vector<u8>&
    IoctlChannelSetTimeout params{};
    std::memcpy(&params, input.data(), sizeof(IoctlChannelSetTimeout));
    LOG_INFO(Service_NVDRV, "called, timeout=0x{:X}", params.timeout);
+
    return 0;
 }

--- a/src/core/hle/service/nvdrv/devices/nvhost_nvdec.cpp
+++ b/src/core/hle/service/nvdrv/devices/nvhost_nvdec.cpp
@@ -30,6 +30,7 @@ u32 nvhost_nvdec::SetNVMAPfd(const std::vector<u8>& input, std::vector<u8>& outp
    IoctlSetNvmapFD params{};
    std::memcpy(&params, input.data(), input.size());
    LOG_DEBUG(Service_NVDRV, "called, fd={}", params.nvmap_fd);
+
    nvmap_fd = params.nvmap_fd;
    return 0;
 }
--- a/src/core/hle/service/nvdrv/devices/nvhost_nvjpg.cpp
+++ b/src/core/hle/service/nvdrv/devices/nvhost_nvjpg.cpp
@@ -30,6 +30,7 @@ u32 nvhost_nvjpg::SetNVMAPfd(const std::vector<u8>& input, std::vector<u8>& outp
    IoctlSetNvmapFD params{};
    std::memcpy(&params, input.data(), input.size());
    LOG_DEBUG(Service_NVDRV, "called, fd={}", params.nvmap_fd);
+
    nvmap_fd = params.nvmap_fd;
    return 0;
 }
--- a/src/core/hle/service/nvdrv/devices/nvhost_vic.cpp
+++ b/src/core/hle/service/nvdrv/devices/nvhost_vic.cpp
@@ -30,6 +30,7 @@ u32 nvhost_vic::SetNVMAPfd(const std::vector<u8>& input, std::vector<u8>& output
    IoctlSetNvmapFD params{};
    std::memcpy(&params, input.data(), input.size());
    LOG_DEBUG(Service_NVDRV, "called, fd={}", params.nvmap_fd);
+
    nvmap_fd = params.nvmap_fd;
    return 0;
 }
--- a/src/core/hle/service/nvdrv/devices/nvmap.cpp
+++ b/src/core/hle/service/nvdrv/devices/nvmap.cpp
@@ -54,6 +54,7 @@ u32 nvmap::IocCreate(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_DEBUG(Service_NVDRV, "size=0x{:08X}", params.size);

    if (!params.size) {
+        LOG_ERROR(Service_NVDRV, "Size is 0");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }
    // Create a new nvmap object and obtain a handle to it.
@@ -78,10 +79,12 @@ u32 nvmap::IocAlloc(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_DEBUG(Service_NVDRV, "called, addr={:X}", params.addr);

    if (!params.handle) {
+        LOG_ERROR(Service_NVDRV, "Handle is zero");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }

    if ((params.align - 1) & params.align) {
+        LOG_ERROR(Service_NVDRV, "Incorrect alignment");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }

@@ -92,10 +95,12 @@ u32 nvmap::IocAlloc(const std::vector<u8>& input, std::vector<u8>& output) {

    auto object = GetObject(params.handle);
    if (!object) {
+        LOG_ERROR(Service_NVDRV, "Object does not exist");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }

    if (object->status == Object::Status::Allocated) {
+        LOG_ERROR(Service_NVDRV, "Object is already allocated");
        return static_cast<u32>(NvErrCodes::OperationNotPermitted);
    }

@@ -116,11 +121,13 @@ u32 nvmap::IocGetId(const std::vector<u8>& input, std::vector<u8>& output) {
    LOG_WARNING(Service_NVDRV, "called");

    if (!params.handle) {
+        LOG_ERROR(Service_NVDRV, "Handle is zero");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }

    auto object = GetObject(params.handle);
    if (!object) {
+        LOG_ERROR(Service_NVDRV, "Object does not exist");
        return static_cast<u32>(NvErrCodes::OperationNotPermitted);
    }

@@ -139,11 +146,13 @@ u32 nvmap::IocFromId(const std::vector<u8>& input, std::vector<u8>& output) {
    auto itr = std::find_if(handles.begin(), handles.end(),
                            [&](const auto& entry) { return entry.second->id == params.id; });
    if (itr == handles.end()) {
+        LOG_ERROR(Service_NVDRV, "Object does not exist");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }

    auto& object = itr->second;
    if (object->status != Object::Status::Allocated) {
+        LOG_ERROR(Service_NVDRV, "Object is not allocated");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }

@@ -166,10 +175,12 @@ u32 nvmap::IocParam(const std::vector<u8>& input, std::vector<u8>& output) {

    auto object = GetObject(params.handle);
    if (!object) {
+        LOG_ERROR(Service_NVDRV, "Object does not exist");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }

    if (object->status != Object::Status::Allocated) {
+        LOG_ERROR(Service_NVDRV, "Object is not allocated");
        return static_cast<u32>(NvErrCodes::OperationNotPermitted);
    }

@@ -209,9 +220,12 @@ u32 nvmap::IocFree(const std::vector<u8>& input, std::vector<u8>& output) {

    auto itr = handles.find(params.handle);
    if (itr == handles.end()) {
+        LOG_ERROR(Service_NVDRV, "Object does not exist");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }
    if (!itr->second->refcount) {
+        LOG_ERROR(Service_NVDRV,
+                  "There is no references to this object. The object is already freed");
        return static_cast<u32>(NvErrCodes::InvalidValue);
    }

--- a/src/core/hle/service/nvdrv/interface.cpp
+++ b/src/core/hle/service/nvdrv/interface.cpp
@@ -55,6 +55,7 @@ void NVDRV::Close(Kernel::HLERequestContext& ctx) {

 void NVDRV::Initialize(Kernel::HLERequestContext& ctx) {
    LOG_WARNING(Service_NVDRV, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u32>(0);
@@ -75,8 +76,8 @@ void NVDRV::QueryEvent(Kernel::HLERequestContext& ctx) {
 void NVDRV::SetClientPID(Kernel::HLERequestContext& ctx) {
    IPC::RequestParser rp{ctx};
    pid = rp.Pop<u64>();
-
    LOG_WARNING(Service_NVDRV, "(STUBBED) called, pid=0x{:X}", pid);
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u32>(0);
@@ -84,12 +85,14 @@ void NVDRV::SetClientPID(Kernel::HLERequestContext& ctx) {

 void NVDRV::FinishInitialize(Kernel::HLERequestContext& ctx) {
    LOG_WARNING(Service_NVDRV, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
 }

 void NVDRV::GetStatus(Kernel::HLERequestContext& ctx) {
    LOG_WARNING(Service_NVDRV, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
 }
@@ -98,6 +101,7 @@ void NVDRV::DumpGraphicsMemoryInfo(Kernel::HLERequestContext& ctx) {
    // According to SwitchBrew, this has no inputs and no outputs, so effectively does nothing on
    // retail hardware.
    LOG_DEBUG(Service_NVDRV, "called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
 }
--- a/src/core/hle/service/nvflinger/buffer_queue.cpp
+++ b/src/core/hle/service/nvflinger/buffer_queue.cpp
@@ -20,13 +20,13 @@ BufferQueue::BufferQueue(u32 id, u64 layer_id) : id(id), layer_id(layer_id) {
 BufferQueue::~BufferQueue() = default;

 void BufferQueue::SetPreallocatedBuffer(u32 slot, const IGBPBuffer& igbp_buffer) {
+    LOG_WARNING(Service, "Adding graphics buffer {}", slot);
+
    Buffer buffer{};
    buffer.slot = slot;
    buffer.igbp_buffer = igbp_buffer;
    buffer.status = Buffer::Status::Free;

-    LOG_WARNING(Service, "Adding graphics buffer {}", slot);
-
    queue.emplace_back(buffer);
    buffer_wait_event->Signal();
 }
@@ -92,6 +92,7 @@ void BufferQueue::ReleaseBuffer(u32 slot) {

 u32 BufferQueue::Query(QueryType type) {
    LOG_WARNING(Service, "(STUBBED) called type={}", static_cast<u32>(type));
+
    switch (type) {
    case QueryType::NativeWindowFormat:
        // TODO(Subv): Use an enum for this
--- a/src/core/hle/service/pctl/module.cpp
+++ b/src/core/hle/service/pctl/module.cpp
@@ -114,29 +114,33 @@ public:
 private:
    void Initialize(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_PCTL, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 0};
        rb.Push(RESULT_SUCCESS);
    }

    void CheckFreeCommunicationPermission(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_PCTL, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }
 };

 void Module::Interface::CreateService(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_PCTL, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<IParentalControlService>();
-    LOG_DEBUG(Service_PCTL, "called");
 }

 void Module::Interface::CreateServiceWithoutInitialize(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_PCTL, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<IParentalControlService>();
-    LOG_DEBUG(Service_PCTL, "called");
 }

 Module::Interface::Interface(std::shared_ptr<Module> module, const char* name)
--- a/src/core/hle/service/pm/pm.cpp
+++ b/src/core/hle/service/pm/pm.cpp
@@ -20,11 +20,11 @@ public:

 private:
    void GetBootMode(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_PM, "called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(static_cast<u32>(SystemBootMode::Normal)); // Normal boot mode
-
-        LOG_DEBUG(Service_PM, "called");
    }
 };

--- a/src/core/hle/service/psc/psc.cpp
+++ b/src/core/hle/service/psc/psc.cpp
@@ -61,11 +61,11 @@ public:

 private:
    void GetPmModule(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_PSC, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IPmModule>();
-
-        LOG_DEBUG(Service_PSC, "called");
    }
 };

--- a/src/core/hle/service/set/set.cpp
+++ b/src/core/hle/service/set/set.cpp
@@ -49,38 +49,39 @@ static std::array<LanguageCode, size> MakeLanguageCodeSubset() {
 static void PushResponseLanguageCode(Kernel::HLERequestContext& ctx, std::size_t max_size) {
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
-    if (available_language_codes.size() > max_size)
+    if (available_language_codes.size() > max_size) {
        rb.Push(static_cast<u32>(max_size));
-    else
+    } else {
        rb.Push(static_cast<u32>(available_language_codes.size()));
+    }
 }

 void SET::GetAvailableLanguageCodes(Kernel::HLERequestContext& ctx) {
-    if (available_language_codes.size() > pre4_0_0_max_entries)
-        ctx.WriteBuffer(MakeLanguageCodeSubset<pre4_0_0_max_entries>());
-    else
-        ctx.WriteBuffer(available_language_codes);
-
-    PushResponseLanguageCode(ctx, pre4_0_0_max_entries);
-
    LOG_DEBUG(Service_SET, "called");
+
+    if (available_language_codes.size() > pre4_0_0_max_entries) {
+        ctx.WriteBuffer(MakeLanguageCodeSubset<pre4_0_0_max_entries>());
+    } else {
+        ctx.WriteBuffer(available_language_codes);
+    }
+    PushResponseLanguageCode(ctx, pre4_0_0_max_entries);
 }

 void SET::GetAvailableLanguageCodes2(Kernel::HLERequestContext& ctx) {
-    if (available_language_codes.size() > post4_0_0_max_entries)
-        ctx.WriteBuffer(MakeLanguageCodeSubset<post4_0_0_max_entries>());
-    else
-        ctx.WriteBuffer(available_language_codes);
-
-    PushResponseLanguageCode(ctx, post4_0_0_max_entries);
-
    LOG_DEBUG(Service_SET, "called");
+
+    if (available_language_codes.size() > post4_0_0_max_entries) {
+        ctx.WriteBuffer(MakeLanguageCodeSubset<post4_0_0_max_entries>());
+    } else {
+        ctx.WriteBuffer(available_language_codes);
+    }
+    PushResponseLanguageCode(ctx, post4_0_0_max_entries);
 }

 void SET::GetAvailableLanguageCodeCount(Kernel::HLERequestContext& ctx) {
-    PushResponseLanguageCode(ctx, pre4_0_0_max_entries);
-
    LOG_DEBUG(Service_SET, "called");
+
+    PushResponseLanguageCode(ctx, pre4_0_0_max_entries);
 }

 void SET::GetAvailableLanguageCodeCount2(Kernel::HLERequestContext& ctx) {
@@ -90,11 +91,11 @@ void SET::GetAvailableLanguageCodeCount2(Kernel::HLERequestContext& ctx) {
 }

 void SET::GetLanguageCode(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_SET, "called {}", Settings::values.language_index);
+
    IPC::ResponseBuilder rb{ctx, 4};
    rb.Push(RESULT_SUCCESS);
    rb.Push(static_cast<u64>(available_language_codes[Settings::values.language_index]));
-
-    LOG_DEBUG(Service_SET, "called {}", Settings::values.language_index);
 }

 SET::SET() : ServiceFramework("set") {
--- a/src/core/hle/service/set/set_sys.cpp
+++ b/src/core/hle/service/set/set_sys.cpp
@@ -10,22 +10,22 @@
 namespace Service::Set {

 void SET_SYS::GetColorSetId(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_SET, "called");
+
    IPC::ResponseBuilder rb{ctx, 3};

    rb.Push(RESULT_SUCCESS);
    rb.PushEnum(color_set);
-
-    LOG_DEBUG(Service_SET, "called");
 }

 void SET_SYS::SetColorSetId(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_SET, "called");
+
    IPC::RequestParser rp{ctx};
    color_set = rp.PopEnum<ColorSet>();

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-
-    LOG_DEBUG(Service_SET, "called");
 }

 SET_SYS::SET_SYS() : ServiceFramework("set:sys") {
--- a/src/core/hle/service/sm/controller.cpp
+++ b/src/core/hle/service/sm/controller.cpp
@@ -14,25 +14,26 @@ namespace Service::SM {

 void Controller::ConvertSessionToDomain(Kernel::HLERequestContext& ctx) {
    ASSERT_MSG(ctx.Session()->IsSession(), "Session is already a domain");
+    LOG_DEBUG(Service, "called, server_session={}", ctx.Session()->GetObjectId());
    ctx.Session()->ConvertToDomain();

    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u32>(1); // Converted sessions start with 1 request handler
-
-    LOG_DEBUG(Service, "called, server_session={}", ctx.Session()->GetObjectId());
 }

 void Controller::DuplicateSession(Kernel::HLERequestContext& ctx) {
    // TODO(bunnei): This is just creating a new handle to the same Session. I assume this is wrong
    // and that we probably want to actually make an entirely new Session, but we still need to
    // verify this on hardware.
+    LOG_DEBUG(Service, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1, IPC::ResponseBuilder::Flags::AlwaysMoveHandles};
    rb.Push(RESULT_SUCCESS);
    Kernel::SharedPtr<Kernel::ClientSession> session{ctx.Session()->parent->client};
    rb.PushMoveObjects(session);

-    LOG_DEBUG(Service, "called, session={}", session->GetObjectId());
+    LOG_DEBUG(Service, "session={}", session->GetObjectId());
 }

 void Controller::DuplicateSessionEx(Kernel::HLERequestContext& ctx) {
@@ -42,11 +43,11 @@ void Controller::DuplicateSessionEx(Kernel::HLERequestContext& ctx) {
 }

 void Controller::QueryPointerBufferSize(Kernel::HLERequestContext& ctx) {
+    LOG_WARNING(Service, "(STUBBED) called");
+
    IPC::ResponseBuilder rb{ctx, 3};
    rb.Push(RESULT_SUCCESS);
    rb.Push<u16>(0x500);
-
-    LOG_WARNING(Service, "(STUBBED) called");
 }

 Controller::Controller() : ServiceFramework("IpcController") {
--- a/src/core/hle/service/sm/sm.cpp
+++ b/src/core/hle/service/sm/sm.cpp
@@ -103,9 +103,10 @@ SM::~SM() = default;
 *      0: ResultCode
 */
 void SM::Initialize(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_SM, "called");
+
    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_DEBUG(Service_SM, "called");
 }

 void SM::GetService(Kernel::HLERequestContext& ctx) {
@@ -172,6 +173,7 @@ void SM::UnregisterService(Kernel::HLERequestContext& ctx) {
    const auto end = std::find(name_buf.begin(), name_buf.end(), '\0');

    const std::string name(name_buf.begin(), end);
+    LOG_DEBUG(Service_SM, "called with name={}", name);

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(service_manager->UnregisterService(name));
--- a/src/core/hle/service/spl/module.cpp
+++ b/src/core/hle/service/spl/module.cpp
@@ -24,6 +24,8 @@ Module::Interface::Interface(std::shared_ptr<Module> module, const char* name)
 Module::Interface::~Interface() = default;

 void Module::Interface::GetRandomBytes(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_SPL, "called");
+
    IPC::RequestParser rp{ctx};

    std::size_t size = ctx.GetWriteBufferSize();
@@ -36,7 +38,6 @@ void Module::Interface::GetRandomBytes(Kernel::HLERequestContext& ctx) {

    IPC::ResponseBuilder rb{ctx, 2};
    rb.Push(RESULT_SUCCESS);
-    LOG_DEBUG(Service_SPL, "called");
 }

 void InstallInterfaces(SM::ServiceManager& service_manager) {
--- a/src/core/hle/service/ssl/ssl.cpp
+++ b/src/core/hle/service/ssl/ssl.cpp
@@ -69,6 +69,7 @@ public:
 private:
    void SetOption(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_SSL, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};

        IPC::ResponseBuilder rb{ctx, 2};
@@ -114,6 +115,7 @@ private:

    void SetInterfaceVersion(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_SSL, "called");
+
        IPC::RequestParser rp{ctx};
        ssl_version = rp.Pop<u32>();

--- a/src/core/hle/service/time/time.cpp
+++ b/src/core/hle/service/time/time.cpp
@@ -72,6 +72,7 @@ private:
                                       std::chrono::system_clock::now().time_since_epoch())
                                       .count()};
        LOG_DEBUG(Service_Time, "called");
+
        IPC::ResponseBuilder rb{ctx, 4};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u64>(time_since_epoch);
@@ -79,6 +80,7 @@ private:

    void GetSystemClockContext(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_Time, "(STUBBED) called");
+
        SystemClockContext system_clock_ontext{};
        IPC::ResponseBuilder rb{ctx, (sizeof(SystemClockContext) / 4) + 2};
        rb.Push(RESULT_SUCCESS);
@@ -98,6 +100,7 @@ public:
 private:
    void GetCurrentTimePoint(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_Time, "called");
+
        SteadyClockTimePoint steady_clock_time_point{
            CoreTiming::cyclesToMs(CoreTiming::GetTicks()) / 1000};
        IPC::ResponseBuilder rb{ctx, (sizeof(SteadyClockTimePoint) / 4) + 2};
@@ -130,6 +133,7 @@ private:

    void GetDeviceLocationName(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_Time, "called");
+
        IPC::ResponseBuilder rb{ctx, (sizeof(LocationName) / 4) + 2};
        rb.Push(RESULT_SUCCESS);
        rb.PushRaw(location_name);
@@ -137,6 +141,7 @@ private:

    void GetTotalLocationNameCount(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_Time, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 3};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u32>(0);
@@ -154,7 +159,6 @@ private:
    void ToCalendarTime(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        const u64 posix_time = rp.Pop<u64>();
-
        LOG_WARNING(Service_Time, "(STUBBED) called, posix_time=0x{:016X}", posix_time);

        TimeZoneRule time_zone_rule{};
@@ -175,7 +179,6 @@ private:
    void ToCalendarTimeWithMyRule(Kernel::HLERequestContext& ctx) {
        IPC::RequestParser rp{ctx};
        const u64 posix_time = rp.Pop<u64>();
-
        LOG_WARNING(Service_Time, "(STUBBED) called, posix_time=0x{:016X}", posix_time);

        CalendarTime calendar_time{2018, 1, 1, 0, 0, 0};
@@ -192,6 +195,7 @@ private:
    void ToPosixTime(Kernel::HLERequestContext& ctx) {
        // TODO(ogniK): Figure out how to handle multiple times
        LOG_WARNING(Service_Time, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        auto calendar_time = rp.PopRaw<CalendarTime>();
        auto posix_time = CalendarToPosix(calendar_time, {});
@@ -204,6 +208,7 @@ private:

    void ToPosixTimeWithMyRule(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_Time, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        auto calendar_time = rp.PopRaw<CalendarTime>();
        auto posix_time = CalendarToPosix(calendar_time, {});
@@ -216,38 +221,43 @@ private:
 };

 void Module::Interface::GetStandardUserSystemClock(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_Time, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ISystemClock>();
-    LOG_DEBUG(Service_Time, "called");
 }

 void Module::Interface::GetStandardNetworkSystemClock(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_Time, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ISystemClock>();
-    LOG_DEBUG(Service_Time, "called");
 }

 void Module::Interface::GetStandardSteadyClock(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_Time, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ISteadyClock>();
-    LOG_DEBUG(Service_Time, "called");
 }

 void Module::Interface::GetTimeZoneService(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_Time, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ITimeZoneService>();
-    LOG_DEBUG(Service_Time, "called");
 }

 void Module::Interface::GetStandardLocalSystemClock(Kernel::HLERequestContext& ctx) {
+    LOG_DEBUG(Service_Time, "called");
+
    IPC::ResponseBuilder rb{ctx, 2, 0, 1};
    rb.Push(RESULT_SUCCESS);
    rb.PushIpcInterface<ISystemClock>();
-    LOG_DEBUG(Service_Time, "called");
 }

 void Module::Interface::GetClockSnapshot(Kernel::HLERequestContext& ctx) {
@@ -265,6 +275,7 @@ void Module::Interface::GetClockSnapshot(Kernel::HLERequestContext& ctx) {
    const std::time_t time(time_since_epoch);
    const std::tm* tm = std::localtime(&time);
    if (tm == nullptr) {
+        LOG_ERROR(Service_Time, "tm is a nullptr");
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(ResultCode(-1)); // TODO(ogniK): Find appropriate error code
        return;
--- a/src/core/hle/service/usb/usb.cpp
+++ b/src/core/hle/service/usb/usb.cpp
@@ -159,11 +159,11 @@ public:

 private:
    void GetPdSession(Kernel::HLERequestContext& ctx) {
+        LOG_DEBUG(Service_USB, "called");
+
        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushIpcInterface<IPdSession>();
-
-        LOG_DEBUG(Service_USB, "called");
    }
 };

--- a/src/core/hle/service/vi/vi.cpp
+++ b/src/core/hle/service/vi/vi.cpp
@@ -504,10 +504,10 @@ private:
        u32 id = rp.Pop<u32>();
        auto transaction = static_cast<TransactionId>(rp.Pop<u32>());
        u32 flags = rp.Pop<u32>();
-        auto buffer_queue = nv_flinger->GetBufferQueue(id);
-
        LOG_DEBUG(Service_VI, "called, transaction={:X}", static_cast<u32>(transaction));

+        auto buffer_queue = nv_flinger->GetBufferQueue(id);
+
        if (transaction == TransactionId::Connect) {
            IGBPConnectRequestParcel request{ctx.ReadBuffer()};
            IGBPConnectResponseParcel response{
@@ -593,9 +593,9 @@ private:
        u32 id = rp.Pop<u32>();
        s32 addval = rp.PopRaw<s32>();
        u32 type = rp.Pop<u32>();
-
        LOG_WARNING(Service_VI, "(STUBBED) called id={}, addval={:08X}, type={:08X}", id, addval,
                    type);
+
        IPC::ResponseBuilder rb{ctx, 2};
        rb.Push(RESULT_SUCCESS);
    }
@@ -604,12 +604,11 @@ private:
        IPC::RequestParser rp{ctx};
        u32 id = rp.Pop<u32>();
        u32 unknown = rp.Pop<u32>();
+        LOG_WARNING(Service_VI, "(STUBBED) called id={}, unknown={:08X}", id, unknown);

        auto buffer_queue = nv_flinger->GetBufferQueue(id);

        // TODO(Subv): Find out what this actually is.
-
-        LOG_WARNING(Service_VI, "(STUBBED) called id={}, unknown={:08X}", id, unknown);
        IPC::ResponseBuilder rb{ctx, 2, 1};
        rb.Push(RESULT_SUCCESS);
        rb.PushCopyObjects(buffer_queue->GetBufferWaitEvent());
@@ -673,6 +672,7 @@ public:
 private:
    void SetLayerZ(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        u64 layer_id = rp.Pop<u64>();
        u64 z_value = rp.Pop<u64>();
@@ -685,13 +685,16 @@ private:
        IPC::RequestParser rp{ctx};
        u64 layer_id = rp.Pop<u64>();
        bool visibility = rp.Pop<bool>();
-        IPC::ResponseBuilder rb{ctx, 2};
-        rb.Push(RESULT_SUCCESS);
        LOG_WARNING(Service_VI, "(STUBBED) called, layer_id=0x{:08X}, visibility={}", layer_id,
                    visibility);
+
+        IPC::ResponseBuilder rb{ctx, 2};
+        rb.Push(RESULT_SUCCESS);
    }

    void GetDisplayMode(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::ResponseBuilder rb{ctx, 6};
        rb.Push(RESULT_SUCCESS);

@@ -707,10 +710,8 @@ private:
                    static_cast<u32>(Settings::values.resolution_factor));
        }

-        rb.PushRaw<float>(60.0f);
+        rb.PushRaw<float>(60.0f); // This wouldn't seem to be correct for 30 fps games.
        rb.Push<u32>(0);
-
-        LOG_DEBUG(Service_VI, "called");
    }
 };

@@ -793,6 +794,7 @@ public:
 private:
    void CloseDisplay(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        u64 display = rp.Pop<u64>();

@@ -802,6 +804,7 @@ private:

    void CreateManagedLayer(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        u32 unknown = rp.Pop<u32>();
        rp.Skip(1, false);
@@ -817,6 +820,7 @@ private:

    void AddToLayerStack(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        u32 stack = rp.Pop<u32>();
        u64 layer_id = rp.Pop<u64>();
@@ -829,10 +833,11 @@ private:
        IPC::RequestParser rp{ctx};
        u64 layer_id = rp.Pop<u64>();
        bool visibility = rp.Pop<bool>();
-        IPC::ResponseBuilder rb{ctx, 2};
-        rb.Push(RESULT_SUCCESS);
        LOG_WARNING(Service_VI, "(STUBBED) called, layer_id=0x{:X}, visibility={}", layer_id,
                    visibility);
+
+        IPC::ResponseBuilder rb{ctx, 2};
+        rb.Push(RESULT_SUCCESS);
    }

    std::shared_ptr<NVFlinger::NVFlinger> nv_flinger;
@@ -878,6 +883,7 @@ private:

    void OpenDisplay(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        auto name_buf = rp.PopRaw<std::array<u8, 0x40>>();
        auto end = std::find(name_buf.begin(), name_buf.end(), '\0');
@@ -893,6 +899,7 @@ private:

    void CloseDisplay(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        u64 display_id = rp.Pop<u64>();

@@ -902,6 +909,7 @@ private:

    void GetDisplayResolution(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        u64 display_id = rp.Pop<u64>();

@@ -923,6 +931,7 @@ private:

    void SetLayerScalingMode(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        u32 scaling_mode = rp.Pop<u32>();
        u64 unknown = rp.Pop<u64>();
@@ -932,6 +941,8 @@ private:
    }

    void ListDisplays(Kernel::HLERequestContext& ctx) {
+        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        DisplayInfo display_info;
        display_info.width *= static_cast<u64>(Settings::values.resolution_factor);
@@ -940,11 +951,11 @@ private:
        IPC::ResponseBuilder rb{ctx, 4};
        rb.Push(RESULT_SUCCESS);
        rb.Push<u64>(1);
-        LOG_WARNING(Service_VI, "(STUBBED) called");
    }

    void OpenLayer(Kernel::HLERequestContext& ctx) {
        LOG_DEBUG(Service_VI, "called");
+
        IPC::RequestParser rp{ctx};
        auto name_buf = rp.PopRaw<std::array<u8, 0x40>>();
        auto end = std::find(name_buf.begin(), name_buf.end(), '\0');
@@ -995,6 +1006,7 @@ private:

    void GetDisplayVsyncEvent(Kernel::HLERequestContext& ctx) {
        LOG_WARNING(Service_VI, "(STUBBED) called");
+
        IPC::RequestParser rp{ctx};
        u64 display_id = rp.Pop<u64>();