Try a different format of HLE logging.

Common/Log.h

@@ -91,6 +91,7 @@ void GenericLog(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type,
 		__attribute__((format(printf, 5, 6)))
 #endif
 		;
+bool GenericLogEnabled(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type);
 
 #if defined(LOGGING) || defined(_DEBUG) || defined(DEBUGFAST) || defined(_WIN32)
 #define MAX_LOGLEVEL DEBUG_LEVEL

Common/LogManager.cpp

@@ -46,6 +46,12 @@ void GenericLog(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type,
 	va_end(args);
 }
 
+bool GenericLogEnabled(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type) {
+	if (LogManager::GetInstance())
+		return g_Config.bEnableLogging && LogManager::GetInstance()->IsEnabled(level, type);
+	return false;
+}
+
 LogManager *LogManager::logManager_ = NULL;
 
 struct LogNameTableEntry {
@@ -219,6 +225,13 @@ void LogManager::Log(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, const
 	log->Trigger(level, msg);
 }
 
+bool LogManager::IsEnabled(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type) {
+	LogChannel *log = log_[type];
+	if (level > log->GetLevel() || !log->IsEnabled() || !log->HasListeners())
+		return false;
+	return true;
+}
+
 void LogManager::Init() {
 	logManager_ = new LogManager();
 }

Common/LogManager.h

@@ -140,6 +140,7 @@ public:
 
 	void Log(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type, 
 			 const char *file, int line, const char *fmt, va_list args);
+	bool IsEnabled(LogTypes::LOG_LEVELS level, LogTypes::LOG_TYPE type);
 
 	LogChannel *GetLogChannel(LogTypes::LOG_TYPE type) {
 		return log_[type];
@@ -183,7 +184,7 @@ public:
 		return ringLog_;
 	}
 
-	static LogManager* GetInstance() {
+	static inline LogManager* GetInstance() {
 		return logManager_;
 	}
 

Core/HLE/HLE.cpp

@@ -15,6 +15,7 @@
 // Official git repository and contact information can be found at
 // https://github.com/hrydgard/ppsspp and http://www.ppsspp.org/.
 
+#include <cstdarg>
 #include <map>
 #include <vector>
 #include <string>
@@ -62,6 +63,7 @@ static std::vector<HLEModule> moduleDB;
 static int delayedResultEvent = -1;
 static int hleAfterSyscall = HLE_AFTER_NOTHING;
 static const char *hleAfterSyscallReschedReason;
+static const HLEFunction *latestSyscall = nullptr;
 
 void hleDelayResultFinish(u64 userdata, int cycleslate)
 {
@@ -100,6 +102,7 @@ void HLEDoState(PointerWrap &p)
 void HLEShutdown()
 {
 	hleAfterSyscall = HLE_AFTER_NOTHING;
+	latestSyscall = nullptr;
 	moduleDB.clear();
 }
 
@@ -434,6 +437,7 @@ inline void updateSyscallStats(int modulenum, int funcnum, double total)
 
 inline void CallSyscallWithFlags(const HLEFunction *info)
 {
+	latestSyscall = info;
 	const u32 flags = info->flags;
 
 	if (flags & HLE_CLEAR_STACK_BYTES) {
@@ -462,6 +466,7 @@ inline void CallSyscallWithFlags(const HLEFunction *info)
 
 inline void CallSyscallWithoutFlags(const HLEFunction *info)
 {
+	latestSyscall = info;
 	info->func();
 
 	if (hleAfterSyscall != HLE_AFTER_NOTHING)
@@ -554,3 +559,113 @@ void CallSyscall(MIPSOpcode op)
 		updateSyscallStats(modulenum, funcnum, total);
 	}
 }
+
+size_t hleFormatLogArgs(char *message, size_t sz, const char *argmask) {
+	char *p = message;
+	size_t used = 0;
+
+#define APPEND_FMT(...) do { \
+	if (used < sz) { \
+		size_t c = snprintf(p, sz - used, __VA_ARGS__); \
+		used += c; \
+		p += c; \
+	} \
+} while (false)
+
+	for (size_t i = 0, n = strlen(argmask); i < n; ++i) {
+		switch (argmask[i]) {
+		case 'p':
+			if (Memory::IsValidAddress(PARAM(i))) {
+				APPEND_FMT("%08x[%08x]", PARAM(i), Memory::Read_U32(PARAM(i)));
+			} else {
+				APPEND_FMT("%08x[invalid]", PARAM(i));
+			}
+			break;
+
+		case 's':
+			if (Memory::IsValidAddress(PARAM(i))) {
+				APPEND_FMT("%s", Memory::GetCharPointer(PARAM(i)));
+			} else {
+				APPEND_FMT("(invalid)");
+			}
+			break;
+
+		case 'x':
+			APPEND_FMT("%08x", PARAM(i));
+			break;
+
+		case 'i':
+			APPEND_FMT("%d", PARAM(i));
+			break;
+
+		default:
+			_assert_msg_(HLE, false, "Invalid argmask character: %c", argmask[i]);
+			APPEND_FMT(" -- invalid arg format: %c -- %08x", argmask[i], PARAM(i));
+			break;
+		}
+		if (i + 1 < n) {
+			APPEND_FMT(", ");
+		}
+	}
+
+	if (used > sz) {
+		message[sz - 1] = '\0';
+	} else {
+		message[used] = '\0';
+	}
+
+#undef APPEND_FMT
+	return used;
+}
+
+u32 hleDoLog(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u32 res, char retmask, const char *argmask, const char *file, int line, const char *reportTag, const char *reason, ...) {
+	if (level > MAX_LOGLEVEL || !GenericLogEnabled(level, t)) {
+		return res;
+	}
+
+	char formatted_reason[4096] = {0};
+	if (reason != nullptr) {
+		va_list args;
+		va_start(args, reason);
+		formatted_reason[0] = ':';
+		formatted_reason[1] = ' ';
+		vsnprintf(formatted_reason + 2, sizeof(formatted_reason) - 3, reason, args);
+		formatted_reason[sizeof(formatted_reason)] = '\0';
+		va_end(args);
+	}
+
+	char formatted_args[4096];
+	hleFormatLogArgs(formatted_args, sizeof(formatted_args), argmask);
+
+	const char *fmt;
+	if (retmask == 'x') {
+		fmt = "%08x=%s(%s)%s";
+	} else if (retmask == 'i') {
+		fmt = "%d=%s(%s)%s";
+	} else {
+		_assert_msg_(HLE, false, "Invalid return format: %c", retmask);
+		fmt = "%08x=%s(%s)%s";
+	}
+
+	GenericLog(level, t, file, line, fmt, res, latestSyscall->name, formatted_args, formatted_reason);
+
+	if (reportTag != nullptr) {
+		// A blank string means always log, not just once.
+		if (reportTag[0] == '\0' || Reporting::ShouldLogOnce(reportTag)) {
+			// Here we want the original key, so that different args, etc. group together.
+			std::string key = std::string("%08x=") + latestSyscall->name + "(%s)";
+			if (reason != nullptr)
+				key += std::string(": ") + reason;
+
+			char formatted_message[8192];
+			snprintf(formatted_message, sizeof(formatted_message), fmt, res, latestSyscall->name, formatted_args, formatted_reason);
+			Reporting::ReportMessageFormatted(key.c_str(), formatted_message);
+		}
+	}
+
+	return res;
+}
+
+u32 hleDoLog(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u32 res, char retmask, const char *argmask, const char *file, int line, const char *reportTag) {
+	return hleDoLog(t, level, res, retmask, argmask, file, line, reportTag, nullptr);
+}

Core/HLE/HLE.h

@@ -18,6 +18,7 @@
 #pragma once
 
 #include "Common/CommonTypes.h"
+#include "Common/Log.h"
 #include "Core/MIPS/MIPS.h"
 
 class PointerWrap;
@@ -125,3 +126,20 @@ const HLEFunction *GetSyscallInfo(MIPSOpcode op);
 // For jit, takes arg: const HLEFunction *
 void *GetQuickSyscallFunc(MIPSOpcode op);
 
+u32 hleDoLog(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u32 res, char retmask, const char *argmask, const char *file, int line, const char *reportTag, const char *reason, ...);
+u32 hleDoLog(LogTypes::LOG_TYPE t, LogTypes::LOG_LEVELS level, u32 res, char retmask, const char *argmask, const char *file, int line, const char *reportTag);
+
+// Only one side of the ?: is evaluated (per c++ standard), so this should be safe.
+#define hleLogHelper(t, level, res, retmask, argmask, ...) (LogTypes::level > MAX_LOGLEVEL ? res : hleDoLog(LogTypes::t, LogTypes::level, res, retmask, argmask, __FILE__, __LINE__, nullptr, __VA_ARGS__))
+#define hleLogError(t, res, argmask, ...) hleLogHelper(t, LERROR, res, 'x', argmask, __VA_ARGS__)
+#define hleLogWarning(t, res, argmask, ...) hleLogHelper(t, LWARNING, res, 'x', argmask, __VA_ARGS__)
+#define hleLogDebug(t, res, argmask, ...) hleLogHelper(t, LDEBUG, res, 'x', argmask, __VA_ARGS__)
+#define hleLogSuccessX(t, res, argmask, ...) hleLogHelper(t, LDEBUG, res, 'x', argmask, __VA_ARGS__)
+#define hleLogSuccessI(t, res, argmask, ...) hleLogHelper(t, LDEBUG, res, 'i', argmask, __VA_ARGS__)
+#define hleLogSuccessVerboseX(t, res, argmask, ...) hleLogHelper(t, LVERBOSE, res, 'x', argmask, __VA_ARGS__)
+#define hleLogSuccessVerboseI(t, res, argmask, ...) hleLogHelper(t, LVERBOSE, res, 'x', argmask, __VA_ARGS__)
+
+#define hleReportError(t, res, argmask, ...) hleDoLog(LogTypes::t, LogTypes::LERROR, res, 'x', argmask, __FILE__, __LINE__, "", __VA_ARGS__)
+#define hleReportWarning(t, res, argmask, ...) hleDoLog(LogTypes::t, LogTypes::LWARNING, res, 'x', argmask, __FILE__, __LINE__, "", __VA_ARGS__)
+#define hleReportDebug(t, res, argmask, ...) hleDoLog(LogTypes::t, LogTypes::LDEBUG, res, 'x', argmask, __FILE__, __LINE__, "", __VA_ARGS__)
+#define hleReportVerbose(t, res, argmask, ...) hleDoLog(LogTypes::t, LogTypes::LVERBOSE, res, 'x', argmask, __FILE__, __LINE__, "", __VA_ARGS__)

Core/HLE/sceKernelThread.cpp

@@ -3010,8 +3010,6 @@ SceUID sceKernelCreateCallback(const char *name, u32 entrypoint, u32 signalArg)
 
 int sceKernelDeleteCallback(SceUID cbId)
 {
-	DEBUG_LOG(SCEKERNEL, "sceKernelDeleteCallback(%i)", cbId);
-
 	u32 error;
 	Callback *cb = kernelObjects.Get<Callback>(cbId, error);
 	if (cb)
@@ -3022,38 +3020,35 @@ int sceKernelDeleteCallback(SceUID cbId)
 		if (cb->nc.notifyCount != 0)
 			readyCallbacksCount--;
 
-		return kernelObjects.Destroy<Callback>(cbId);
+		return hleLogSuccessI(SCEKERNEL, kernelObjects.Destroy<Callback>(cbId), "d");
+	} else {
+		return hleLogError(SCEKERNEL, error, "i", "bad cbId");
 	}
-	return error;
 }
 
 // Generally very rarely used, but Numblast uses it like candy.
 int sceKernelNotifyCallback(SceUID cbId, int notifyArg)
 {
-	DEBUG_LOG(SCEKERNEL,"sceKernelNotifyCallback(%i, %i)", cbId, notifyArg);
 	u32 error;
 	Callback *cb = kernelObjects.Get<Callback>(cbId, error);
 	if (cb) {
 		__KernelNotifyCallback(cbId, notifyArg);
-		return 0;
+		return hleLogSuccessI(SCEKERNEL, 0, "ii");
 	} else {
-		ERROR_LOG(SCEKERNEL, "sceKernelCancelCallback(%i) - bad cbId", cbId);
-		return error;
+		return hleLogError(SCEKERNEL, error, "ii", "bad cbId");
 	}
 }
 
 int sceKernelCancelCallback(SceUID cbId)
 {
-	DEBUG_LOG(SCEKERNEL, "sceKernelCancelCallback(%i)", cbId);
 	u32 error;
 	Callback *cb = kernelObjects.Get<Callback>(cbId, error);
 	if (cb) {
 		// This just resets the notify count.
 		cb->nc.notifyArg = 0;
-		return 0;
+		return hleLogSuccessI(SCEKERNEL, 0, "i");
 	} else {
-		ERROR_LOG(SCEKERNEL, "sceKernelCancelCallback(%i) - bad cbId", cbId);
-		return error;
+		return hleLogError(SCEKERNEL, error, "i", "bad cbId");
 	}
 }
 
@@ -3062,10 +3057,9 @@ int sceKernelGetCallbackCount(SceUID cbId)
 	u32 error;
 	Callback *cb = kernelObjects.Get<Callback>(cbId, error);
 	if (cb) {
-		return cb->nc.notifyCount;
+		return hleLogSuccessVerboseI(SCEKERNEL, cb->nc.notifyCount, "i");
 	} else {
-		ERROR_LOG(SCEKERNEL, "sceKernelGetCallbackCount(%i) - bad cbId", cbId);
-		return error;
+		return hleLogError(SCEKERNEL, error, "i", "bad cbId");
 	}
 }
 
@@ -3074,40 +3068,30 @@ int sceKernelReferCallbackStatus(SceUID cbId, u32 statusAddr)
 	u32 error;
 	Callback *c = kernelObjects.Get<Callback>(cbId, error);
 	if (c) {
-		DEBUG_LOG(SCEKERNEL, "sceKernelReferCallbackStatus(%i, %08x)", cbId, statusAddr);
 		if (Memory::IsValidAddress(statusAddr) && Memory::Read_U32(statusAddr) != 0) {
 			Memory::WriteStruct(statusAddr, &c->nc);
+			return hleLogSuccessI(SCEKERNEL, 0, "ip");
+		} else {
+			return hleLogDebug(SCEKERNEL, 0, "ip", "struct size was 0");
 		}
-		return 0;
 	} else {
-		ERROR_LOG(SCEKERNEL, "sceKernelReferCallbackStatus(%i, %08x) - bad cbId", cbId, statusAddr);
-		return error;
+		return hleLogError(SCEKERNEL, error, "ip", "bad cbId");
 	}
 }
 
 u32 sceKernelExtendThreadStack(u32 size, u32 entryAddr, u32 entryParameter)
 {
 	if (size < 512)
-	{
-		ERROR_LOG_REPORT(SCEKERNEL, "sceKernelExtendThreadStack(%08x, %08x, %08x) - stack size too small", size, entryAddr, entryParameter);
-		return SCE_KERNEL_ERROR_ILLEGAL_STACK_SIZE;
-	}
+		return hleReportError(SCEKERNEL, SCE_KERNEL_ERROR_ILLEGAL_STACK_SIZE, "xxx", "stack size too small");
 
 	Thread *thread = __GetCurrentThread();
 	if (!thread)
-	{
-		ERROR_LOG_REPORT(SCEKERNEL, "sceKernelExtendThreadStack(%08x, %08x, %08x) - not on a thread?", size, entryAddr, entryParameter);
-		return -1;
-	}
+		return hleReportError(SCEKERNEL, -1, "xxx", "not on a thread?");
 
 	if (!thread->PushExtendedStack(size))
-	{
-		ERROR_LOG_REPORT(SCEKERNEL, "sceKernelExtendThreadStack(%08x, %08x, %08x) - could not allocate new stack", size, entryAddr, entryParameter);
-		return SCE_KERNEL_ERROR_NO_MEMORY;
-	}
+		return hleReportError(SCEKERNEL, SCE_KERNEL_ERROR_NO_MEMORY, "xxx", "could not allocate new stack");
 
 	// The stack has been changed now, so it's do or die time.
-	DEBUG_LOG(SCEKERNEL, "sceKernelExtendThreadStack(%08x, %08x, %08x)", size, entryAddr, entryParameter);
 
 	// Push the old SP, RA, and PC onto the stack (so we can restore them later.)
 	Memory::Write_U32(currentMIPS->r[MIPS_REG_RA], thread->currentStack.end - 4);
@@ -3121,7 +3105,7 @@ u32 sceKernelExtendThreadStack(u32 size, u32 entryAddr, u32 entryParameter)
 	currentMIPS->r[MIPS_REG_SP] = thread->currentStack.end - 0x10;
 
 	hleSkipDeadbeef();
-	return 0;
+	return hleLogSuccessI(SCEKERNEL, 0, "xxx");
 }
 
 void __KernelReturnFromExtendStack()

Core/Reporting.cpp

@@ -403,6 +403,21 @@ namespace Reporting
 		th.detach();
 	}
 
+	void ReportMessageFormatted(const char *message, const char *formatted)
+	{
+		if (!IsEnabled() || CheckSpamLimited())
+			return;
+
+		int pos = payloadBufferPos++ % PAYLOAD_BUFFER_SIZE;
+		Payload &payload = payloadBuffer[pos];
+		payload.type = MESSAGE;
+		payload.string1 = message;
+		payload.string2 = formatted;
+
+		std::thread th(Process, pos);
+		th.detach();
+	}
+
 	void ReportCompatibility(const char *compat, int graphics, int speed, int gameplay)
 	{
 		if (!IsEnabled())

Core/Reporting.h

@@ -65,6 +65,9 @@ namespace Reporting
 	// Report a message string, using the format string as a key.
 	void ReportMessage(const char *message, ...);
 
+	// The same, but with a preformatted version (message is still the key.)
+	void ReportMessageFormatted(const char *message, const char *formatted);
+
 	// Report the compatibility of the current game / configuration.
 	void ReportCompatibility(const char *compat, int graphics, int speed, int gameplay);