Merge pull request #1801 from ogniK5377/log-before-execute

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

src/core/hle/kernel/svc.cpp

@@ -63,43 +63,77 @@ bool IsInsideNewMapRegion(const VMManager& vm, VAddr address, u64 size) {
                                 vm.GetNewMapRegionEndAddress());
 }
 
+// 8 GiB
+constexpr u64 MAIN_MEMORY_SIZE = 0x200000000;
+
 // Helper function that performs the common sanity checks for svcMapMemory
 // and svcUnmapMemory. This is doable, as both functions perform their sanitizing
 // in the same order.
 ResultCode MapUnmapMemorySanityChecks(const VMManager& vm_manager, VAddr dst_addr, VAddr src_addr,
                                       u64 size) {
-    if (!Common::Is4KBAligned(dst_addr) || !Common::Is4KBAligned(src_addr)) {
+    if (!Common::Is4KBAligned(dst_addr)) {
+        LOG_ERROR(Kernel_SVC, "Destination address is not aligned to 4KB, 0x{:016X}", dst_addr);
         return ERR_INVALID_ADDRESS;
     }
 
-    if (size == 0 || !Common::Is4KBAligned(size)) {
+    if (!Common::Is4KBAligned(src_addr)) {
+        LOG_ERROR(Kernel_SVC, "Source address is not aligned to 4KB, 0x{:016X}", src_addr);
+        return ERR_INVALID_SIZE;
+    }
+
+    if (size == 0) {
+        LOG_ERROR(Kernel_SVC, "Size is 0");
+        return ERR_INVALID_SIZE;
+    }
+
+    if (!Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Size is not aligned to 4KB, 0x{:016X}", size);
         return ERR_INVALID_SIZE;
     }
 
     if (!IsValidAddressRange(dst_addr, size)) {
+        LOG_ERROR(Kernel_SVC,
+                  "Destination is not a valid address range, addr=0x{:016X}, size=0x{:016X}",
+                  dst_addr, size);
         return ERR_INVALID_ADDRESS_STATE;
     }
 
     if (!IsValidAddressRange(src_addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Source is not a valid address range, addr=0x{:016X}, size=0x{:016X}",
+                  src_addr, size);
         return ERR_INVALID_ADDRESS_STATE;
     }
 
     if (!IsInsideAddressSpace(vm_manager, src_addr, size)) {
+        LOG_ERROR(Kernel_SVC,
+                  "Source is not within the address space, addr=0x{:016X}, size=0x{:016X}",
+                  src_addr, size);
         return ERR_INVALID_ADDRESS_STATE;
     }
 
     if (!IsInsideNewMapRegion(vm_manager, dst_addr, size)) {
+        LOG_ERROR(Kernel_SVC,
+                  "Destination is not within the new map region, addr=0x{:016X}, size=0x{:016X}",
+                  dst_addr, size);
         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,
+                  "Destination does not fit within the heap region, addr=0x{:016X}, "
+                  "size=0x{:016X}, end_addr=0x{:016X}",
+                  dst_addr, size, dst_end_address);
         return ERR_INVALID_MEMORY_RANGE;
     }
 
     if (dst_end_address > vm_manager.GetMapRegionBaseAddress() &&
         vm_manager.GetMapRegionEndAddress() > dst_addr) {
+        LOG_ERROR(Kernel_SVC,
+                  "Destination does not fit within the map region, addr=0x{:016X}, "
+                  "size=0x{:016X}, end_addr=0x{:016X}",
+                  dst_addr, size, dst_end_address);
         return ERR_INVALID_MEMORY_RANGE;
     }
 
@@ -143,8 +177,15 @@ ResultVal<s64> RetrieveResourceLimitValue(Handle resource_limit, u32 resource_ty
 static ResultCode SetHeapSize(VAddr* heap_addr, u64 heap_size) {
     LOG_TRACE(Kernel_SVC, "called, heap_size=0x{:X}", heap_size);
 
-    // Size must be a multiple of 0x200000 (2MB) and be equal to or less than 4GB.
+    // Size must be a multiple of 0x200000 (2MB) and be equal to or less than 8GB.
-    if ((heap_size & 0xFFFFFFFE001FFFFF) != 0) {
+    if ((heap_size % 0x200000) != 0) {
+        LOG_ERROR(Kernel_SVC, "The heap size is not a multiple of 2MB, heap_size=0x{:016X}",
+                  heap_size);
+        return ERR_INVALID_SIZE;
+    }
+
+    if (heap_size >= 0x200000000) {
+        LOG_ERROR(Kernel_SVC, "The heap size is not less than 8GB, heap_size=0x{:016X}", heap_size);
         return ERR_INVALID_SIZE;
     }
 
@@ -159,20 +200,31 @@ 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 to 4KB, addr=0x{:016X}", addr);
         return ERR_INVALID_ADDRESS;
     }
 
-    if (size == 0 || !Common::Is4KBAligned(size)) {
+    if (size == 0) {
+        LOG_ERROR(Kernel_SVC, "Size is 0");
+        return ERR_INVALID_SIZE;
+    }
+
+    if (!Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Size is not aligned to 4KB, size=0x{:016X}", size);
         return ERR_INVALID_SIZE;
     }
 
     if (!IsValidAddressRange(addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is not a valid address range, addr=0x{:016X}, size=0x{:016X}",
+                  addr, size);
         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, "Invalid memory permission specified, Got memory permission=0x{:08X}",
+                  static_cast<u32>(permission));
         return ERR_INVALID_MEMORY_PERMISSIONS;
     }
 
@@ -180,11 +232,15 @@ 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,
+                  "Source is not within the address space, addr=0x{:016X}, size=0x{:016X}", addr,
+                  size);
         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 for address=0x{:016X}", addr);
         return ERR_INVALID_ADDRESS_STATE;
     }
 
@@ -239,6 +295,9 @@ 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,
+                  "Port Name Address is not a valid virtual address, port_name_address=0x{:016X}",
+                  port_name_address);
         return ERR_NOT_FOUND;
     }
 
@@ -246,6 +305,8 @@ 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, expected {} but got {}", PortNameMaxLength,
+                  port_name.size());
         return ERR_OUT_OF_RANGE;
     }
 
@@ -294,6 +355,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, "Thread handle does not exist, handle=0x{:08X}", thread_handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -308,6 +370,8 @@ 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, "Process handle does not exist, process_handle=0x{:08X}",
+                  process_handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -337,12 +401,18 @@ 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,
+                  "Handle address is not a valid virtual address, handle_address=0x{:016X}",
+                  handles_address);
         return ERR_INVALID_POINTER;
+    }
 
     static constexpr u64 MaxHandles = 0x40;
 
     if (handle_count > MaxHandles) {
+        LOG_ERROR(Kernel_SVC, "Handle count specified is too large, expected {} but got {}",
+                  MaxHandles, handle_count);
         return ERR_OUT_OF_RANGE;
     }
 
@@ -357,6 +427,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;
         }
 
@@ -380,11 +451,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);
@@ -405,6 +478,8 @@ 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, "Thread handle does not exist, thread_handle=0x{:08X}",
+                  thread_handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -423,10 +498,13 @@ 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, "Mutex Address is a kernel virtual address, mutex_addr={:016X}",
+                  mutex_addr);
         return ERR_INVALID_ADDRESS_STATE;
     }
 
     if (!Common::IsWordAligned(mutex_addr)) {
+        LOG_ERROR(Kernel_SVC, "Mutex Address is not word aligned, mutex_addr={:016X}", mutex_addr);
         return ERR_INVALID_ADDRESS;
     }
 
@@ -440,10 +518,13 @@ 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, "Mutex Address is a kernel virtual address, mutex_addr={:016X}",
+                  mutex_addr);
         return ERR_INVALID_ADDRESS_STATE;
     }
 
     if (!Common::IsWordAligned(mutex_addr)) {
+        LOG_ERROR(Kernel_SVC, "Mutex Address is not word aligned, mutex_addr={:016X}", mutex_addr);
         return ERR_INVALID_ADDRESS;
     }
 
@@ -634,10 +715,14 @@ 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, "Process Handle is non zero, expected 0 result but got {:016X}",
+                      handle);
             return ERR_INVALID_HANDLE;
         }
 
         if (info_sub_id >= Process::RANDOM_ENTROPY_SIZE) {
+            LOG_ERROR(Kernel_SVC, "Entropy size is out of range, expected {} but got {}",
+                      Process::RANDOM_ENTROPY_SIZE, info_sub_id);
             return ERR_INVALID_COMBINATION;
         }
 
@@ -675,12 +760,16 @@ 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, "Core count is out of range, expected {} but got {}", num_cpus,
+                      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 handle does not exist, handle=0x{:08X}",
+                      static_cast<Handle>(handle));
             return ERR_INVALID_HANDLE;
         }
 
@@ -723,14 +812,22 @@ 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 handle does not exist, handle=0x{:08X}", handle);
         return ERR_INVALID_HANDLE;
     }
 
     if (thread->GetOwnerProcess() != current_process) {
+        LOG_ERROR(Kernel_SVC,
+                  "The current process does not own the current thread, thread_handle={:08X} "
+                  "thread_pid={}, "
+                  "current_process_pid={}",
+                  handle, thread->GetOwnerProcess()->GetProcessID(),
+                  current_process->GetProcessID());
         return ERR_INVALID_HANDLE;
     }
 
     if (thread == GetCurrentThread()) {
+        LOG_ERROR(Kernel_SVC, "The thread handle specified is the current running thread");
         return ERR_ALREADY_REGISTERED;
     }
 
@@ -751,9 +848,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, "Thread handle does not exist, handle=0x{:08X}", handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -763,7 +863,13 @@ 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,
+            "An invalid priority was specified, expected {} but got {} for thread_handle={:08X}",
+            THREADPRIO_LOWEST, priority, handle);
         return ERR_INVALID_THREAD_PRIORITY;
     }
 
@@ -771,6 +877,7 @@ static ResultCode SetThreadPriority(Handle handle, u32 priority) {
 
     SharedPtr<Thread> thread = current_process->GetHandleTable().Get<Thread>(handle);
     if (!thread) {
+        LOG_ERROR(Kernel_SVC, "Thread handle does not exist, handle=0x{:08X}", handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -793,32 +900,46 @@ 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 to 4KB, addr=0x{:016X}", addr);
         return ERR_INVALID_ADDRESS;
     }
 
-    if (size == 0 || !Common::Is4KBAligned(size)) {
+    if (size == 0) {
+        LOG_ERROR(Kernel_SVC, "Size is 0");
+        return ERR_INVALID_SIZE;
+    }
+
+    if (!Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Size is not aligned to 4KB, size=0x{:016X}", size);
         return ERR_INVALID_SIZE;
     }
 
     if (!IsValidAddressRange(addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is not a valid address range, addr=0x{:016X}, size=0x{:016X}",
+                  addr, size);
         return ERR_INVALID_ADDRESS_STATE;
     }
 
     const auto permissions_type = static_cast<MemoryPermission>(permissions);
     if (permissions_type != MemoryPermission::Read &&
         permissions_type != MemoryPermission::ReadWrite) {
-        LOG_ERROR(Kernel_SVC, "Invalid permissions=0x{:08X}", permissions);
+        LOG_ERROR(Kernel_SVC, "Expected Read or ReadWrite permission but got permissions=0x{:08X}",
+                  permissions);
         return ERR_INVALID_MEMORY_PERMISSIONS;
     }
 
     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 does not exist, shared_memory_handle=0x{:08X}",
+                  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. addr=0x{:016X}, size={:016X}",
+                  addr, size);
         return ERR_INVALID_MEMORY_RANGE;
     }
 
@@ -830,25 +951,38 @@ 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 to 4KB, addr=0x{:016X}", addr);
         return ERR_INVALID_ADDRESS;
     }
 
-    if (size == 0 || !Common::Is4KBAligned(size)) {
+    if (size == 0) {
+        LOG_ERROR(Kernel_SVC, "Size is 0");
+        return ERR_INVALID_SIZE;
+    }
+
+    if (!Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Size is not aligned to 4KB, size=0x{:016X}", size);
         return ERR_INVALID_SIZE;
     }
 
     if (!IsValidAddressRange(addr, size)) {
+        LOG_ERROR(Kernel_SVC, "Region is not a valid address range, addr=0x{:016X}, size=0x{:016X}",
+                  addr, size);
         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 does not exist, shared_memory_handle=0x{:08X}",
+                  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. addr=0x{:016X}, size={:016X}",
+                  addr, size);
         return ERR_INVALID_MEMORY_RANGE;
     }
 
@@ -858,9 +992,12 @@ 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, "Process handle does not exist, process_handle=0x{:08X}",
+                  process_handle);
         return ERR_INVALID_HANDLE;
     }
     auto vma = process->VMManager().FindVMA(addr);
@@ -876,8 +1013,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;
 }
 
@@ -906,7 +1041,14 @@ 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, "An invalid priority was specified, expected {} but got {}",
+                  THREADPRIO_LOWEST, priority);
         return ERR_INVALID_THREAD_PRIORITY;
     }
 
@@ -937,6 +1079,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);
@@ -944,11 +1088,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;
 }
 
@@ -959,6 +1098,8 @@ 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 handle does not exist, thread_handle=0x{:08X}",
+                  thread_handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -1138,10 +1279,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, address={:016X}", address);
         return ERR_INVALID_ADDRESS_STATE;
     }
     // If the address is not properly aligned to 4 bytes, return invalid address.
-    if (address % sizeof(u32) != 0) {
+    if (!Common::IsWordAligned(address)) {
+        LOG_ERROR(Kernel_SVC, "Address is not word aligned, address={:016X}", address);
         return ERR_INVALID_ADDRESS;
     }
 
@@ -1153,6 +1296,10 @@ 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, expected WaitIfLessThan, DecrementAndWaitIfLessThan "
+                  "or WaitIfEqual but got {}",
+                  type);
         return ERR_INVALID_ENUM_VALUE;
     }
 }
@@ -1163,10 +1310,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, address={:016X}", address);
         return ERR_INVALID_ADDRESS_STATE;
     }
     // If the address is not properly aligned to 4 bytes, return invalid address.
-    if (address % sizeof(u32) != 0) {
+    if (!Common::IsWordAligned(address)) {
+        LOG_ERROR(Kernel_SVC, "Address is not word aligned, address={:016X}", address);
         return ERR_INVALID_ADDRESS;
     }
 
@@ -1179,12 +1328,18 @@ 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 signal type, expected Signal, IncrementAndSignalIfEqual "
+                  "or ModifyByWaitingCountAndSignalIfEqual but got {}",
+                  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.
@@ -1258,6 +1413,8 @@ 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 handle does not exist, thread_handle=0x{:08X}",
+                  thread_handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -1268,12 +1425,14 @@ 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 handle does not exist, thread_handle=0x{:08X}",
+                  thread_handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -1288,6 +1447,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;
     }
 
@@ -1297,11 +1457,14 @@ 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 core specified, got {}", core);
         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, "Core is not enabled for the current mask, core={}, mask={:016X}",
+                  core, mask);
         return ERR_INVALID_COMBINATION;
     }
 
@@ -1314,21 +1477,36 @@ static ResultCode CreateSharedMemory(Handle* handle, u64 size, u32 local_permiss
                                      u32 remote_permissions) {
     LOG_TRACE(Kernel_SVC, "called, size=0x{:X}, localPerms=0x{:08X}, remotePerms=0x{:08X}", size,
               local_permissions, remote_permissions);
+    if (size == 0) {
+        LOG_ERROR(Kernel_SVC, "Size is 0");
+        return ERR_INVALID_SIZE;
+    }
+    if (!Common::Is4KBAligned(size)) {
+        LOG_ERROR(Kernel_SVC, "Size is not aligned to 4KB, 0x{:016X}", size);
+        return ERR_INVALID_SIZE;
+    }
 
-    // Size must be a multiple of 4KB and be less than or equal to
+    if (size >= MAIN_MEMORY_SIZE) {
-    // approx. 8 GB (actually (1GB - 512B) * 8)
+        LOG_ERROR(Kernel_SVC, "Size is not less than 8GB, 0x{:016X}", size);
-    if (size == 0 || (size & 0xFFFFFFFE00000FFF) != 0) {
         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 local memory permissions, expected Read or ReadWrite but got "
+                  "local_permissions={}",
+                  static_cast<u32>(local_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 remote memory permissions, expected Read, ReadWrite or DontCare but got "
+                  "remote_permissions={}",
+                  static_cast<u32>(remote_permissions));
         return ERR_INVALID_MEMORY_PERMISSIONS;
     }
 
@@ -1348,6 +1526,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, "Event handle does not exist, handle=0x{:08X}", handle);
         return ERR_INVALID_HANDLE;
     }
 
@@ -1366,11 +1545,14 @@ 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, "Process handle does not exist, process_handle=0x{:08X}",
+                  process_handle);
         return ERR_INVALID_HANDLE;
     }
 
     const auto info_type = static_cast<InfoType>(type);
     if (info_type != InfoType::Status) {
+        LOG_ERROR(Kernel_SVC, "Expected info_type to be Status but got {} instead", type);
         return ERR_INVALID_ENUM_VALUE;
     }
 

src/core/hle/service/acc/acc.cpp

@@ -207,10 +207,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) {
@@ -227,10 +228,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) {

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,39 @@ 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. There is no data in the current normal channel");
+
             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 +639,52 @@ 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. There is no data in the current interactive channel");
+
             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 +703,27 @@ 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, backing_buffer_sz={}, data_size={}, offset={}",
+                  backing.buffer.size(), data.size(), offset);
+
         IPC::ResponseBuilder rb{ctx, 2};
         rb.Push(ERR_SIZE_OUT_OF_BOUNDS);
     }
@@ -724,17 +732,20 @@ 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, backing_buffer_sz={}, size={}, offset={}",
+                  backing.buffer.size(), size, offset);
+
         IPC::ResponseBuilder rb{ctx, 2};
         rb.Push(ERR_SIZE_OUT_OF_BOUNDS);
     }
@@ -743,8 +754,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 +792,8 @@ void ILibraryAppletCreator::CreateLibraryApplet(Kernel::HLERequestContext& ctx)
     const auto applet = GetAppletFromId(applet_id);
 
     if (applet == nullptr) {
+        LOG_ERROR(Service_AM, "Applet doesn't exist! applet_id={}", static_cast<u32>(applet_id));
+
         IPC::ResponseBuilder rb{ctx, 2};
         rb.Push(ResultCode(-1));
         return;
@@ -792,23 +803,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 +830,7 @@ void ILibraryAppletCreator::CreateTransferMemoryStorage(Kernel::HLERequestContex
             handle);
 
     if (shared_mem == nullptr) {
+        LOG_ERROR(Service_AM, "shared_mem is a nullpr for handle={:08X}", handle);
         IPC::ResponseBuilder rb{ctx, 2};
         rb.Push(ResultCode(-1));
         return;
@@ -882,38 +894,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 +951,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 +978,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 +1070,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") {

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,

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,

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};

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

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");
     }
 };
 

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);

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>();
+    rb.PushIpcInterface<Audio::IAudioDevice>(); // TODO(ogniK): Figure out what is different
-
+                                                // based on the current revision
-    LOG_WARNING(Service_Audio, "(STUBBED) called"); // TODO(ogniK): Figure out what is different
-                                                    // based on the current revision
 }
 
 bool AudRenU::IsFeatureSupported(AudioFeatures feature, u32_le revision) const {

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,39 @@ 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, header_sz={}, input_sz={}",
+                      sizeof(OpusHeader), input.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. data_sz={}, input_sz={}",
+                      sizeof(OpusHeader) + static_cast<u32>(hdr.sz), input.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, decoded_sz={}, raw_output_sz={}",
+                decoded_sample_count * channel_count * sizeof(u16), raw_output_sz);
             return false;
+        }
+        const int frame_size = (static_cast<int>(raw_output_sz / sizeof(s16) / channel_count));
         auto out_sample_count =
-            opus_decode(decoder.get(), frame, hdr.sz, output.data(),
+            opus_decode(decoder.get(), frame, hdr.sz, output.data(), frame_size, 0);
-                        (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, "
+                      "output_sample_count={}, frame_size={}, data_sz_from_hdr={}",
+                      out_sample_count, frame_size, static_cast<u32>(hdr.sz));
             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 +155,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>();
+    const auto sample_rate = rp.Pop<u32>();
-    auto channel_count = 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 +179,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");
@@ -164,7 +189,8 @@ void HwOpus::OpenOpusDecoder(Kernel::HLERequestContext& ctx) {
     ASSERT_MSG(buffer_sz >= worker_sz, "Worker buffer too large");
     std::unique_ptr<OpusDecoder, OpusDeleter> decoder{
         static_cast<OpusDecoder*>(operator new(worker_sz))};
-    if (opus_decoder_init(decoder.get(), sample_rate, channel_count)) {
+    if (const int err = opus_decoder_init(decoder.get(), sample_rate, channel_count)) {
+        LOG_ERROR(Audio, "Failed to init opus decoder with error={}", err);
         IPC::ResponseBuilder rb{ctx, 2};
         // TODO(ogniK): Use correct error code
         rb.Push(ResultCode(-1));

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)

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;
 };

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");
     }
 };
 

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");
     }
 };
 

src/core/hle/service/filesystem/fsp_srv.cpp

@@ -62,11 +62,13 @@ private:
 
         // Error checking
         if (length < 0) {
+            LOG_ERROR(Service_FS, "Length is less than 0, length={}", length);
             IPC::ResponseBuilder rb{ctx, 2};
             rb.Push(FileSys::ERROR_INVALID_SIZE);
             return;
         }
         if (offset < 0) {
+            LOG_ERROR(Service_FS, "Offset is less than 0, offset={}", offset);
             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, "Length is less than 0, length={}", length);
             IPC::ResponseBuilder rb{ctx, 2};
             rb.Push(FileSys::ERROR_INVALID_SIZE);
             return;
         }
         if (offset < 0) {
+            LOG_ERROR(Service_FS, "Offset is less than 0, offset={}", offset);
             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, "Length is less than 0, length={}", length);
             IPC::ResponseBuilder rb{ctx, 2};
             rb.Push(FileSys::ERROR_INVALID_SIZE);
             return;
         }
         if (offset < 0) {
+            LOG_ERROR(Service_FS, "Offset is less than 0, offset={}", offset);
             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);

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();
 }
 

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");
     }
 };
 

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;

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;

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");
     }
 };
 

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:

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");
     }
 };
 

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);

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");
     }
 };
 

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);

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");
     }
 };
 

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");
     }
 };
 

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");
     }
 };
 

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;

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;
 }

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());

src/core/hle/service/nvdrv/devices/nvhost_gpu.cpp

@@ -60,12 +60,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;
@@ -74,6 +76,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;
@@ -85,6 +88,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;
 }
@@ -94,6 +98,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;
 }
@@ -101,6 +106,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;
 }
 
@@ -112,6 +118,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());
@@ -123,6 +130,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;
@@ -184,6 +192,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;
@@ -193,6 +202,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;
 }
 

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;
 }

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;
 }

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;
 }

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 0");
         return static_cast<u32>(NvErrCodes::InvalidValue);
     }
 
     if ((params.align - 1) & params.align) {
+        LOG_ERROR(Service_NVDRV, "Incorrect alignment used, alignment={:08X}", params.align);
         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, handle={:08X}", params.handle);
         return static_cast<u32>(NvErrCodes::InvalidValue);
     }
 
     if (object->status == Object::Status::Allocated) {
+        LOG_ERROR(Service_NVDRV, "Object is already allocated, handle={:08X}", params.handle);
         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, handle={:08X}", params.handle);
         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, handle={:08X}", params.handle);
         return static_cast<u32>(NvErrCodes::InvalidValue);
     }
 
     auto& object = itr->second;
     if (object->status != Object::Status::Allocated) {
+        LOG_ERROR(Service_NVDRV, "Object is not allocated, handle={:08X}", params.handle);
         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, handle={:08X}", params.handle);
         return static_cast<u32>(NvErrCodes::InvalidValue);
     }
 
     if (object->status != Object::Status::Allocated) {
+        LOG_ERROR(Service_NVDRV, "Object is not allocated, handle={:08X}", params.handle);
         return static_cast<u32>(NvErrCodes::OperationNotPermitted);
     }
 
@@ -209,9 +220,14 @@ 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, handle={:08X}", params.handle);
         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. handle={:08X}",
+            params.handle);
         return static_cast<u32>(NvErrCodes::InvalidValue);
     }
 

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);
 }

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

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)

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");
     }
 };
 

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");
     }
 };
 

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") {

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") {

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") {

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));

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) {

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>();
 

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;

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");
     }
 };
 

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>();