fsp_srv: Fix filesystem access logging

This introduces a new setting Enable FS Access Log which saves the filesystem access log to sdmc:/FsAccessLog.txt

If this setting is not enabled, this will indicate to FS to not call OutputAccessLogToSdCard.

Fixes softlocks during loading in Xenoblade Chronicles 2 when certain DLC is enabled.

src/common/settings.h

@@ -218,6 +218,7 @@ struct Values {
     std::string program_args;
     bool dump_exefs;
     bool dump_nso;
+    bool enable_fs_access_log;
     bool reporting_services;
     bool quest_flag;
     bool disable_macro_jit;

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

@@ -13,6 +13,7 @@
 #include "common/common_types.h"
 #include "common/hex_util.h"
 #include "common/logging/log.h"
+#include "common/settings.h"
 #include "common/string_util.h"
 #include "core/core.h"
 #include "core/file_sys/directory.h"
@@ -785,6 +786,10 @@ FSP_SRV::FSP_SRV(Core::System& system_)
     };
     // clang-format on
     RegisterHandlers(functions);
+
+    if (Settings::values.enable_fs_access_log) {
+        access_log_mode = AccessLogMode::SdCard;
+    }
 }
 
 FSP_SRV::~FSP_SRV() = default;
@@ -1041,9 +1046,9 @@ void FSP_SRV::DisableAutoSaveDataCreation(Kernel::HLERequestContext& ctx) {
 
 void FSP_SRV::SetGlobalAccessLogMode(Kernel::HLERequestContext& ctx) {
     IPC::RequestParser rp{ctx};
-    log_mode = rp.PopEnum<LogMode>();
+    access_log_mode = rp.PopEnum<AccessLogMode>();
 
-    LOG_DEBUG(Service_FS, "called, log_mode={:08X}", log_mode);
+    LOG_DEBUG(Service_FS, "called, access_log_mode={}", access_log_mode);
 
     IPC::ResponseBuilder rb{ctx, 2};
     rb.Push(ResultSuccess);
@@ -1054,7 +1059,7 @@ void FSP_SRV::GetGlobalAccessLogMode(Kernel::HLERequestContext& ctx) {
 
     IPC::ResponseBuilder rb{ctx, 3};
     rb.Push(ResultSuccess);
-    rb.PushEnum(log_mode);
+    rb.PushEnum(access_log_mode);
 }
 
 void FSP_SRV::OutputAccessLogToSdCard(Kernel::HLERequestContext& ctx) {
@@ -1062,9 +1067,9 @@ void FSP_SRV::OutputAccessLogToSdCard(Kernel::HLERequestContext& ctx) {
     auto log = Common::StringFromFixedZeroTerminatedBuffer(
         reinterpret_cast<const char*>(raw.data()), raw.size());
 
-    LOG_DEBUG(Service_FS, "called, log='{}'", log);
+    LOG_DEBUG(Service_FS, "called");
 
-    reporter.SaveFilesystemAccessReport(log_mode, std::move(log));
+    reporter.SaveFSAccessLog(log);
 
     IPC::ResponseBuilder rb{ctx, 2};
     rb.Push(ResultSuccess);

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

@@ -24,11 +24,10 @@ enum class AccessLogVersion : u32 {
     Latest = V7_0_0,
 };
 
-enum class LogMode : u32 {
-    Off,
+enum class AccessLogMode : u32 {
+    None,
     Log,
-    RedirectToSdCard,
-    LogToSdCard = Log | RedirectToSdCard,
+    SdCard,
 };
 
 class FSP_SRV final : public ServiceFramework<FSP_SRV> {
@@ -59,13 +58,12 @@ private:
 
     FileSystemController& fsc;
     const FileSys::ContentProvider& content_provider;
+    const Core::Reporter& reporter;
 
     FileSys::VirtualFile romfs;
     u64 current_process_id = 0;
     u32 access_log_program_index = 0;
-    LogMode log_mode = LogMode::LogToSdCard;
-
-    const Core::Reporter& reporter;
+    AccessLogMode access_log_mode = AccessLogMode::None;
 };
 
 } // namespace Service::FileSystem

src/core/reporter.cpp

@@ -195,7 +195,9 @@ json GetHLERequestContextData(Kernel::HLERequestContext& ctx, Core::Memory::Memo
 
 namespace Core {
 
-Reporter::Reporter(System& system_) : system(system_) {}
+Reporter::Reporter(System& system_) : system(system_) {
+    ClearFSAccessLog();
+}
 
 Reporter::~Reporter() = default;
 
@@ -362,22 +364,12 @@ void Reporter::SaveErrorReport(u64 title_id, ResultCode result,
     SaveToFile(std::move(out), GetPath("error_report", title_id, timestamp));
 }
 
-void Reporter::SaveFilesystemAccessReport(Service::FileSystem::LogMode log_mode,
-                                          std::string log_message) const {
-    if (!IsReportingEnabled())
-        return;
+void Reporter::SaveFSAccessLog(std::string_view log_message) const {
+    const auto access_log_path =
+        Common::FS::GetYuzuPath(Common::FS::YuzuPath::SDMCDir) / "FsAccessLog.txt";
 
-    const auto timestamp = GetTimestamp();
-    const auto title_id = system.CurrentProcess()->GetTitleID();
-    json out;
-
-    out["yuzu_version"] = GetYuzuVersionData();
-    out["report_common"] = GetReportCommonData(title_id, ResultSuccess, timestamp);
-
-    out["log_mode"] = fmt::format("{:08X}", static_cast<u32>(log_mode));
-    out["log_message"] = std::move(log_message);
-
-    SaveToFile(std::move(out), GetPath("filesystem_access_report", title_id, timestamp));
+    void(Common::FS::AppendStringToFile(access_log_path, Common::FS::FileType::TextFile,
+                                        log_message));
 }
 
 void Reporter::SaveUserReport() const {
@@ -392,6 +384,18 @@ void Reporter::SaveUserReport() const {
                GetPath("user_report", title_id, timestamp));
 }
 
+void Reporter::ClearFSAccessLog() const {
+    const auto access_log_path =
+        Common::FS::GetYuzuPath(Common::FS::YuzuPath::SDMCDir) / "FsAccessLog.txt";
+
+    Common::FS::IOFile access_log_file{access_log_path, Common::FS::FileAccessMode::Write,
+                                       Common::FS::FileType::TextFile};
+
+    if (!access_log_file.IsOpen()) {
+        LOG_ERROR(Common_Filesystem, "Failed to clear the filesystem access log.");
+    }
+}
+
 bool Reporter::IsReportingEnabled() const {
     return Settings::values.reporting_services;
 }

src/core/reporter.h

@@ -16,10 +16,6 @@ namespace Kernel {
 class HLERequestContext;
 } // namespace Kernel
 
-namespace Service::FileSystem {
-enum class LogMode : u32;
-}
-
 namespace Service::LM {
 struct LogMessage;
 } // namespace Service::LM
@@ -69,14 +65,15 @@ public:
                          std::optional<std::string> custom_text_main = {},
                          std::optional<std::string> custom_text_detail = {}) const;
 
-    void SaveFilesystemAccessReport(Service::FileSystem::LogMode log_mode,
-                                    std::string log_message) const;
+    void SaveFSAccessLog(std::string_view log_message) const;
 
     // Can be used anywhere to generate a backtrace and general info report at any point during
     // execution. Not intended to be used for anything other than debugging or testing.
     void SaveUserReport() const;
 
 private:
+    void ClearFSAccessLog() const;
+
     bool IsReportingEnabled() const;
 
     System& system;

src/yuzu/configuration/config.cpp

@@ -647,6 +647,8 @@ void Config::ReadDebuggingValues() {
         ReadSetting(QStringLiteral("program_args"), QString{}).toString().toStdString();
     Settings::values.dump_exefs = ReadSetting(QStringLiteral("dump_exefs"), false).toBool();
     Settings::values.dump_nso = ReadSetting(QStringLiteral("dump_nso"), false).toBool();
+    Settings::values.enable_fs_access_log =
+        ReadSetting(QStringLiteral("enable_fs_access_log"), false).toBool();
     Settings::values.reporting_services =
         ReadSetting(QStringLiteral("reporting_services"), false).toBool();
     Settings::values.quest_flag = ReadSetting(QStringLiteral("quest_flag"), false).toBool();
@@ -1258,6 +1260,8 @@ void Config::SaveDebuggingValues() {
                  QString::fromStdString(Settings::values.program_args), QString{});
     WriteSetting(QStringLiteral("dump_exefs"), Settings::values.dump_exefs, false);
     WriteSetting(QStringLiteral("dump_nso"), Settings::values.dump_nso, false);
+    WriteSetting(QStringLiteral("enable_fs_access_log"), Settings::values.enable_fs_access_log,
+                 false);
     WriteSetting(QStringLiteral("quest_flag"), Settings::values.quest_flag, false);
     WriteSetting(QStringLiteral("use_debug_asserts"), Settings::values.use_debug_asserts, false);
     WriteSetting(QStringLiteral("disable_macro_jit"), Settings::values.disable_macro_jit, false);

src/yuzu/configuration/configure_debug.cpp

@@ -28,17 +28,21 @@ ConfigureDebug::ConfigureDebug(QWidget* parent) : QWidget(parent), ui(new Ui::Co
 ConfigureDebug::~ConfigureDebug() = default;
 
 void ConfigureDebug::SetConfiguration() {
-    ui->toggle_console->setEnabled(!Core::System::GetInstance().IsPoweredOn());
+    const bool runtime_lock = !Core::System::GetInstance().IsPoweredOn();
+
+    ui->toggle_console->setEnabled(runtime_lock);
     ui->toggle_console->setChecked(UISettings::values.show_console);
     ui->log_filter_edit->setText(QString::fromStdString(Settings::values.log_filter));
     ui->homebrew_args_edit->setText(QString::fromStdString(Settings::values.program_args));
+    ui->fs_access_log->setEnabled(runtime_lock);
+    ui->fs_access_log->setChecked(Settings::values.enable_fs_access_log);
     ui->reporting_services->setChecked(Settings::values.reporting_services);
     ui->quest_flag->setChecked(Settings::values.quest_flag);
     ui->use_debug_asserts->setChecked(Settings::values.use_debug_asserts);
     ui->use_auto_stub->setChecked(Settings::values.use_auto_stub);
-    ui->enable_graphics_debugging->setEnabled(!Core::System::GetInstance().IsPoweredOn());
+    ui->enable_graphics_debugging->setEnabled(runtime_lock);
     ui->enable_graphics_debugging->setChecked(Settings::values.renderer_debug);
-    ui->disable_macro_jit->setEnabled(!Core::System::GetInstance().IsPoweredOn());
+    ui->disable_macro_jit->setEnabled(runtime_lock);
     ui->disable_macro_jit->setChecked(Settings::values.disable_macro_jit);
     ui->extended_logging->setChecked(Settings::values.extended_logging);
 }
@@ -47,6 +51,7 @@ void ConfigureDebug::ApplyConfiguration() {
     UISettings::values.show_console = ui->toggle_console->isChecked();
     Settings::values.log_filter = ui->log_filter_edit->text().toStdString();
     Settings::values.program_args = ui->homebrew_args_edit->text().toStdString();
+    Settings::values.enable_fs_access_log = ui->fs_access_log->isChecked();
     Settings::values.reporting_services = ui->reporting_services->isChecked();
     Settings::values.quest_flag = ui->quest_flag->isChecked();
     Settings::values.use_debug_asserts = ui->use_debug_asserts->isChecked();

src/yuzu/configuration/configure_debug.ui

@@ -144,9 +144,16 @@
    <item>
     <widget class="QGroupBox" name="groupBox_5">
      <property name="title">
-      <string>Dump</string>
+      <string>Debugging</string>
      </property>
      <layout class="QVBoxLayout" name="verticalLayout_7">
+      <item>
+       <widget class="QCheckBox" name="fs_access_log">
+        <property name="text">
+         <string>Enable FS Access Log</string>
+        </property>
+       </widget>
+      </item>
       <item>
        <widget class="QCheckBox" name="reporting_services">
         <property name="text">

src/yuzu_cmd/config.cpp

@@ -477,6 +477,8 @@ void Config::ReadValues() {
     Settings::values.program_args = sdl2_config->Get("Debugging", "program_args", "");
     Settings::values.dump_exefs = sdl2_config->GetBoolean("Debugging", "dump_exefs", false);
     Settings::values.dump_nso = sdl2_config->GetBoolean("Debugging", "dump_nso", false);
+    Settings::values.enable_fs_access_log =
+        sdl2_config->GetBoolean("Debugging", "enable_fs_access_log", false);
     Settings::values.reporting_services =
         sdl2_config->GetBoolean("Debugging", "reporting_services", false);
     Settings::values.quest_flag = sdl2_config->GetBoolean("Debugging", "quest_flag", false);

src/yuzu_cmd/default_ini.h

@@ -338,6 +338,8 @@ record_frame_times =
 dump_exefs=false
 # Determines whether or not yuzu will dump all NSOs it attempts to load while loading them
 dump_nso=false
+# Determines whether or not yuzu will save the filesystem access log.
+enable_fs_access_log=false
 # Determines whether or not yuzu will report to the game that the emulated console is in Kiosk Mode
 # false: Retail/Normal Mode (default), true: Kiosk Mode
 quest_flag =