[nim] unstub IShopServiceAsync (#4272)

- [x] I have read and followed the [Contribution Guidelines](https://git.eden-emu.dev/eden-emu/eden/src/branch/master/CONTRIBUTING.md#code-contributions).
- [x] I have read and followed the [AI Policy](https://git.eden-emu.dev/eden-emu/eden/src/branch/master/docs/policies/AI.md)
- [x] I have read and followed the [Coding Guidelines](https://git.eden-emu.dev/eden-emu/eden/src/branch/master/docs/policies/Coding.md) to the best of my ability.

-------------------
 unstub IShopServiceAsync (but still stub Request, with empty JSON response)

Reviewed-on: https://git.eden-emu.dev/eden-emu/eden/pulls/4272
Reviewed-by: Samuel <lizzie@eden-emu.dev>
Reviewed-by: MaranBr <maranbr@eden-emu.dev>

src/common/logging.cpp

@@ -10,7 +10,6 @@
 #include <cstdlib>
 #include <regex>
 #include <thread>
-#include <fmt/base.h>
 
 #if defined(__ANDROID__)
 #include <android/log.h>
@@ -40,19 +39,6 @@
 
 namespace Common::Log {
 
-/// @brief A log entry. Log entries are store in a structured format to permit more varied output
-/// formatting on different frontends, as well as facilitating filtering and aggregation.
-struct Entry {
-    char const* message = nullptr;
-    size_t message_len = 0;
-    std::chrono::microseconds timestamp;
-    Class log_class{};
-    Level log_level{};
-    const char* filename = nullptr;
-    const char* function = nullptr;
-    uint32_t line_num = 0;
-};
-
 namespace {
 
 /// @brief Returns the name of the passed log class as a C-string. Subclasses are separated by periods
@@ -84,6 +70,8 @@ const char* GetLevelName(Level log_level) {
     }
 }
 
+}
+
 // Some IDEs prefer <file>:<line> instead, so let's just do that :)
 std::string FormatLogMessage(const Entry& entry) noexcept {
     if (!entry.filename) return "";
@@ -91,9 +79,10 @@ std::string FormatLogMessage(const Entry& entry) noexcept {
     auto const time_fractional = uint32_t(entry.timestamp.count() % 1000000);
     auto const class_name = GetLogClassName(entry.log_class);
     auto const level_name = GetLevelName(entry.log_level);
-    return fmt::format("[{:4d}.{:06d}] {} <{}> {}:{}:{}: {}\n", time_seconds, time_fractional, class_name, level_name, entry.filename, entry.line_num, entry.function, entry.message);
+    return fmt::format("[{:4d}.{:06d}] {} <{}> {}:{}:{}: {}", time_seconds, time_fractional, class_name, level_name, entry.filename, entry.line_num, entry.function, entry.message);
 }
 
+namespace {
 template <typename It>
 Level GetLevelByName(const It begin, const It end) {
     for (u32 i = 0; i < u32(Level::Count); ++i) {
@@ -138,6 +127,25 @@ bool ParseFilterRule(Filter& instance, Iterator begin, Iterator end) {
     instance.SetClassLevel(log_class, level);
     return true;
 }
+} // Anonymous namespace
+
+void Filter::ParseFilterString(std::string_view filter_view) {
+    auto clause_begin = filter_view.cbegin();
+    while (clause_begin != filter_view.cend()) {
+        auto clause_end = std::find(clause_begin, filter_view.cend(), ' ');
+        // If clause isn't empty
+        if (clause_end != clause_begin) {
+            ParseFilterRule(*this, clause_begin, clause_end);
+        }
+        if (clause_end != filter_view.cend()) {
+            // Skip over the whitespace
+            ++clause_end;
+        }
+        clause_begin = clause_end;
+    }
+}
+
+namespace {
 
 /// @brief Trims up to and including the last of ../, ..\, src/, src\ in a string
 /// do not be fooled this isn't generating new strings on .rodata :)
@@ -212,24 +220,22 @@ struct ColorConsoleBackend final : public Backend {
     ~ColorConsoleBackend() noexcept override {}
     void Write(const Entry& entry) noexcept override {
         if (enabled) {
+#define ESC "\x1b"
             auto const color_str = [&entry]() -> const char* {
                 switch (entry.log_level) {
-                case Level::Debug: return "[0;36m"; // Cyan
-                case Level::Info: return "[0;37m"; // Bright gray
-                case Level::Warning: return "[1;33m"; // Bright yellow
-                case Level::Error: return "[1;31m"; // Bright red
-                case Level::Critical: return "[1;35m"; // Bright magenta
-                default: return "[1;30m"; // Grey
+#define CCB_MAKE_COLOR_FMT(X) ESC X CCB_PRINTF_FMT ESC "[0m\n"
+                case Level::Debug: return CCB_MAKE_COLOR_FMT("[0;36m"); // Cyan
+                case Level::Info: return CCB_MAKE_COLOR_FMT("[0;37m"); // Bright gray
+                case Level::Warning: return CCB_MAKE_COLOR_FMT("[1;33m"); // Bright yellow
+                case Level::Error: return CCB_MAKE_COLOR_FMT("[1;31m"); // Bright red
+                case Level::Critical: return CCB_MAKE_COLOR_FMT("[1;35m"); // Bright magenta
+                default: return CCB_MAKE_COLOR_FMT("[1;30m"); // Grey
+#undef CCB_MAKE_COLOR_FMT
                 }
             }();
             auto const df = GetDirectFormatArgs(entry);
-            // more restrictive, because take for example this simple prelude:
-            // [  50.872256] Config <Info> common/settings.cpp:142:LogSettings:
-            char buffer[100];
-            auto result = fmt::format_to_n(buffer, sizeof(buffer) - 1, "\x1b{}[{:4d}.{:06d}] {} <{}> {}:{}:{}: ", color_str, df.time_seconds, df.time_fractional, df.class_name, df.level_name, entry.filename, entry.line_num, entry.function, entry.message);
-            std::fwrite(buffer, 1, result.size, stdout);
-            std::fwrite(entry.message, 1, entry.message_len, stdout);
-            std::fwrite("\x1b[0m\n", 1, sizeof("\x1b[0m\n"), stdout);
+            std::fprintf(stdout, color_str, df.time_seconds, df.time_fractional, df.class_name, df.level_name, entry.filename, entry.line_num, entry.function, entry.message.c_str());
+#undef ESC
         }
     }
     void Flush() noexcept override {}
@@ -240,7 +246,7 @@ struct ColorConsoleBackend final : public Backend {
 #ifndef __OPENORBIS__
 /// @brief Backend that writes to a file passed into the constructor
 struct FileBackend final : public Backend {
-    explicit FileBackend(const std::filesystem::path filename) noexcept {
+    explicit FileBackend(const std::filesystem::path& filename) noexcept {
         auto old_filename = filename;
         old_filename += ".old.txt";
         // Existence checks are done within the functions themselves.
@@ -255,7 +261,7 @@ struct FileBackend final : public Backend {
         if (!enabled)
             return;
 
-        auto message = FormatLogMessage(entry);
+        auto message = FormatLogMessage(entry).append(1, '\n');
 #ifndef __ANDROID__
         if (Settings::values.censor_username.GetValue()) {
             // This must be a static otherwise it would get checked on EVERY
@@ -263,7 +269,8 @@ struct FileBackend final : public Backend {
             static std::string username = []() -> std::string {
                 // in order of precedence
                 // LOGNAME usually works on UNIX, USERNAME on Windows
-                // Some UNIX systems suck and don't use LOGNAME so we also need USER :(
+                // Some UNIX systems suck and don't use LOGNAME so we also
+                // need USER :(
                 for (auto const var : { "LOGNAME", "USERNAME", "USER", })
                     if (auto const s = ::getenv(var); s != nullptr)
                         return std::string{s};
@@ -273,7 +280,7 @@ struct FileBackend final : public Backend {
                 boost::replace_all(message, username, "user");
         }
 #endif
-        bytes_written += file->WriteSpan(std::span<const char>{message.begin(), message.end()});
+        bytes_written += file->WriteString(message);
 
         // Option to log each line rather than 4k buffers
         if (Settings::values.log_flush_line.GetValue())
@@ -301,13 +308,14 @@ private:
     bool enabled = true;
 };
 #endif
+
 #ifdef _WIN32
 /// @brief Backend that writes to Visual Studio's output window
 struct DebuggerBackend final : public Backend {
     explicit DebuggerBackend() noexcept = default;
     ~DebuggerBackend() noexcept override = default;
     void Write(const Entry& entry) noexcept override {
-        ::OutputDebugStringW(UTF8ToUTF16W(FormatLogMessage(entry)).c_str());
+        ::OutputDebugStringW(UTF8ToUTF16W(FormatLogMessage(entry).append(1, '\n')).c_str());
     }
     void Flush() noexcept override {}
 };
@@ -369,23 +377,7 @@ struct Impl {
 #endif
     std::chrono::steady_clock::time_point time_origin{std::chrono::steady_clock::now()};
 };
-} // Anonymous namespace
-
-void Filter::ParseFilterString(std::string_view filter_view) {
-    auto clause_begin = filter_view.cbegin();
-    while (clause_begin < filter_view.cend()) {
-        auto clause_end = std::find(clause_begin, filter_view.cend(), ' ');
-        // If clause isn't empty
-        if (clause_end != clause_begin) {
-            ParseFilterRule(*this, clause_begin, clause_end);
-        }
-        if (clause_end != filter_view.cend()) {
-            // Skip over the whitespace
-            ++clause_end;
-        }
-        clause_begin = clause_end;
-    }
-}
+} // namespace
 
 // Constructor shall NOT depend upon Settings() or whatever
 // it's ran at global static ctor() time... so BE CAREFUL MFER!
@@ -426,14 +418,10 @@ void SetColorConsoleBackendEnabled(bool enabled) {
 
 void FmtLogMessageImpl(Class log_class, Level log_level, const char* filename, unsigned int line_num, const char* function, fmt::string_view format, const fmt::format_args& args) {
     if (logging_instance && logging_instance->filter.CheckMessage(log_class, log_level)) {
-        char buffer[BUFSIZ];
-        auto result = fmt::vformat_to_n(buffer, sizeof(buffer) - 1, format, args);
-        buffer[result.size] = '\0';
         auto const flush = ::Settings::values.log_flush_line.GetValue();
         logging_instance->ForEachBackend([=](Backend& backend) {
             backend.Write(Entry{
-                .message = buffer,
-                .message_len = result.size,
+                .message = fmt::vformat(format, args),
                 .timestamp = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::steady_clock::now() - logging_instance->time_origin),
                 .log_class = log_class,
                 .log_level = log_level,

src/common/logging.h

@@ -140,4 +140,25 @@ void Stop();
 void SetGlobalFilter(const Filter& filter);
 void SetColorConsoleBackendEnabled(bool enabled);
 
+/// @brief A log entry. Log entries are store in a structured format to permit more varied output
+/// formatting on different frontends, as well as facilitating filtering and aggregation.
+struct Entry {
+    std::string message;
+    std::chrono::microseconds timestamp;
+    Class log_class{};
+    Level log_level{};
+    const char* filename = nullptr;
+    const char* function = nullptr;
+    unsigned int line_num = 0;
+};
+
+/// Formats a log entry into the provided text buffer.
+std::string FormatLogMessage(const Entry& entry) noexcept;
+
+/// Prints the same message as `PrintMessage`, but colored according to the severity level.
+void PrintColoredMessage(const Entry& entry) noexcept;
+
+/// Formats and prints a log entry to the android logcat.
+void PrintMessageToLogcat(const Entry& entry) noexcept;
+
 } // namespace Common::Log

src/core/hle/service/nim/nim.cpp

@@ -5,33 +5,136 @@
 // SPDX-License-Identifier: GPL-2.0-or-later
 
 #include <chrono>
-#include <ctime>
+#include <mutex>
+#include <string>
+#include <vector>
+
 #include "core/core.h"
 #include "core/hle/kernel/k_event.h"
+#include "core/hle/service/cmif_serialization.h"
+#include "core/hle/service/cmif_types.h"
 #include "core/hle/service/ipc_helpers.h"
 #include "core/hle/service/kernel_helpers.h"
 #include "core/hle/service/nim/nim.h"
+#include "core/hle/service/os/event.h"
 #include "core/hle/service/server_manager.h"
 #include "core/hle/service/service.h"
 
 namespace Service::NIM {
-
 class IShopServiceAsync final : public ServiceFramework<IShopServiceAsync> {
 public:
     explicit IShopServiceAsync(Core::System& system_)
-        : ServiceFramework{system_, "IShopServiceAsync"} {
+        : ServiceFramework{system_, "IShopServiceAsync"},
+          service_context{system_, "IShopServiceAsync"} {
         // clang-format off
         static const FunctionInfo functions[] = {
-            {0, nullptr, "Cancel"},
-            {1, nullptr, "GetSize"},
-            {2, nullptr, "Read"},
-            {3, nullptr, "GetErrorCode"},
-            {4, nullptr, "Request"},
-            {5, nullptr, "Prepare"},
+            {0, D<&IShopServiceAsync::Cancel>, "Cancel"},
+            {1, D<&IShopServiceAsync::GetSize>, "GetSize"},
+            {2, D<&IShopServiceAsync::Read>, "Read"},
+            {3, D<&IShopServiceAsync::GetErrorCode>, "GetErrorCode"},
+            {4, D<&IShopServiceAsync::Request>, "Request"},
+            {5, D<&IShopServiceAsync::Prepare>, "Prepare"},
         };
         // clang-format on
 
         RegisterHandlers(functions);
+
+        completion_event = service_context.CreateEvent("IShopServiceAsync:Completion");
+    }
+
+    ~IShopServiceAsync() override {
+        CancelImpl();
+        service_context.CloseEvent(completion_event);
+    }
+
+    Kernel::KReadableEvent* GetEvent() const {
+        return &completion_event->GetReadableEvent();
+    }
+
+private:
+    KernelHelpers::ServiceContext service_context;
+    Kernel::KEvent* completion_event;
+
+    std::jthread worker;
+    std::atomic<u32> error_code{0};
+
+    std::mutex data_mutex;
+    std::vector<u8> download_data;
+
+    void CancelImpl() {
+        worker.request_stop();
+        if (worker.joinable()) {
+            worker.join();
+        }
+    }
+
+    Result Cancel() {
+        LOG_DEBUG(Service_NIM, "called");
+        CancelImpl();
+        R_SUCCEED();
+    }
+
+    Result GetSize(Out<u64> out_size) {
+        LOG_DEBUG(Service_NIM, "called");
+        std::scoped_lock lock{data_mutex};
+        *out_size = download_data.size();
+        R_SUCCEED();
+    }
+
+    Result Read(Out<u64> out_size, u64 offset, OutBuffer<BufferAttr_HipcAutoSelect> out_buffer) {
+        std::scoped_lock lock{data_mutex};
+
+        u64 actual_read = 0;
+        if (offset < download_data.size()) {
+            actual_read = std::min<u64>(out_buffer.size(), download_data.size() - offset);
+            std::memcpy(out_buffer.data(), download_data.data() + offset, actual_read);
+        }
+
+        *out_size = actual_read;
+        R_SUCCEED();
+    }
+
+    Result GetErrorCode(Out<u32> out_error_code) {
+        LOG_DEBUG(Service_NIM, "called");
+        *out_error_code = error_code.load();
+        R_SUCCEED();
+    }
+
+    Result Request() {
+        LOG_DEBUG(Service_NIM, "(STUBBED) called");
+        CancelImpl();
+
+        error_code.store(0);
+        completion_event->Clear(system.Kernel());
+
+        {
+            std::scoped_lock lock{data_mutex};
+            download_data.clear();
+        }
+
+        worker = std::jthread([this](const std::stop_token& stop_token) {
+            if (stop_token.stop_requested()) {
+                error_code.store(1);
+            } else {
+                std::scoped_lock lock{data_mutex};
+                // Dummy JSON response, else it fails...
+                const std::string dummy_response = "{}";
+                download_data.assign(dummy_response.begin(), dummy_response.end());
+                error_code.store(0);
+            }
+            completion_event->Signal(system.Kernel());
+        });
+
+        R_SUCCEED();
+    }
+
+    Result Prepare(InArray<char, BufferAttr_HipcMapAlias> in_path, InArray<char, BufferAttr_HipcMapAlias> in_post) {
+        LOG_DEBUG(Service_NIM, "called");
+        if (!in_path.empty()) {
+            std::string url(in_path.data(), in_path.size());
+            LOG_INFO(Service_NIM, "Preparing request for URL: {}", url);
+        }
+        R_SUCCEED();
     }
 };
 
@@ -49,11 +152,13 @@ public:
     }
 
 private:
-    void CreateAsyncInterface(HLERequestContext& ctx) {
-        LOG_WARNING(Service_NIM, "(STUBBED) called");
-        IPC::ResponseBuilder rb{ctx, 2, 0, 1};
+    void CreateAsyncInterface(HLERequestContext& ctx) {LOG_DEBUG(Service_NIM, "called");
+        auto async_interface = std::make_shared<IShopServiceAsync>(system);
+
+        IPC::ResponseBuilder rb{ctx, 2, 1, 1};
         rb.Push(ResultSuccess);
-        rb.PushIpcInterface<IShopServiceAsync>(ctx, system);
+        rb.PushCopyObjects(ctx, async_interface->GetEvent());
+        rb.PushIpcInterface<IShopServiceAsync>(ctx, std::move(async_interface));
     }
 };