Skip to content

Commit

Permalink
Unify rust & C++ logs using the Rust facilities. (#92)
Browse files Browse the repository at this point in the history
The choice was to write macros to replace the log crate macros, or
write templates to sink the C++ logging to Rust. I went with Rust
because what good is being in the evangelism task force if I don't
ruthlessly carcinicize?

Wrote the templates by contemplating what the SKSE peeps did to put
templates in front of `spdlog`. These templates are in front of `fmt`
instead. The guts of each implementation routes to shims in front of
the the `log` crate's macros.

The new namespace is `rlog`. All calls to `logger::info()` are now
calls to `rlog::info()` which eventually dispatches to `log::info!()`.

The debug and trace level log templates add filename & line number
information to the start of each log message. Unfortunately those two
levels are decorated with fairly useless information from the rust
logger, which I can't rid of without also affecting rust-sourced log
lines. I'll need to find a new crate. This is, however, good enough 
to ship.

Got rid of spdlog in the build. It remains in the deps because the
CommonLibSSE dll needs it.

Demoted some logs while I was looking at them in the unified context.
I will need to systematically review logging because it feels too
voluminous now that it's all in one file.
  • Loading branch information
ceejbot authored Dec 15, 2023
1 parent f536d43 commit 3a92d1e
Show file tree
Hide file tree
Showing 26 changed files with 377 additions and 221 deletions.
2 changes: 0 additions & 2 deletions CMakeLists.txt
Original file line number Diff line number Diff line change
Expand Up @@ -99,7 +99,6 @@ set(GameVersion "Skyrim")

# Find our vcpkg dependencies.
# find_package(CommonLibSSE CONFIG REQUIRED)
find_package(spdlog REQUIRED CONFIG)
find_package(imgui REQUIRED)

include(cmake/sourcelist.cmake)
Expand Down Expand Up @@ -232,7 +231,6 @@ target_link_libraries(
PRIVATE
${SOULSY_LIB}
CommonLibSSE::CommonLibSSE
spdlog::spdlog
imgui::imgui
wsock32
ws2_32
Expand Down
2 changes: 1 addition & 1 deletion README.md
Original file line number Diff line number Diff line change
Expand Up @@ -25,7 +25,7 @@ Soulsy is a Rust and C++ project, using CMake to drive Cargo to build the Rust p

The plugin requires the following vcpkg libraries, which will be installed for you:

- [spdlog](https://github.com/gabime/spdlog)
- [spdlog](https://github.com/gabime/spdlog) (consumed by CommonLib, not by Soulsy)
- [imgui](https://github.com/ocornut/imgui)

Finally, [CommonLibSSE-NG](https://github.com/CharmedBaryon/CommonLibSSE-NG) is pulled in as a git submodule and built. The repo used is [my fork](https://github.com/ceejbot/CommonLibSSE-NG) of CommonLib, which has some minor fixes in addition to the upstream.
Expand Down
1 change: 1 addition & 0 deletions cmake/sourcelist.cmake
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ set(headers ${headers}
src/plugin/cosave.h
src/plugin/inventory.h
src/plugin/keycodes.h
src/plugin/log.h
src/plugin/menus.h
src/plugin/papyrus.h
src/plugin/sinks.h
Expand Down
2 changes: 1 addition & 1 deletion docs/article-layouts.md
Original file line number Diff line number Diff line change
Expand Up @@ -182,7 +182,7 @@ If the item shown in this slot has a meaningful count-- say, a stack of potions

The next four fields starting with `hotkey_` are, you guessed it, for drawing a hotkey reminder. If this slot has a hotkey associated with it, where and how should the hotkey reminder be drawn? The fields here are similar to all the others. You have rgba colors for the background image and the shortcut image, a size for the background image, and an offset relative to the center of the slot saying where to draw it.

The order the slot fields are in does not matter, so long as they're present. If you are missing a required field, you will not be able to load the layout file. You'll find details about what went wrong in the log file `SoulsyHUD_rust.log`.
The order the slot fields are in does not matter, so long as they're present. If you are missing a required field, you will not be able to load the layout file. You'll find details about what went wrong in the log file `SoulsyHUD.log`.

Repeat this five times, once for each slot, and you have a full layout!

Expand Down
2 changes: 1 addition & 1 deletion docs/article-options.md
Original file line number Diff line number Diff line change
Expand Up @@ -164,7 +164,7 @@ Each SKSE mod that stores data in the cosave file must identify itself to the SK

Enable this toggle and restart the game to make the mod log more verbosely.

All SKSE plugin mods log in the same directory: `Documents/my games/Skyrim Special Edition/SKSE`. SoulsyHUD writes two logs, one for its C++ code and one for its Rust code. (Correctly interleaving log output from the two very different logging systems is more work than it's worth.) The two log files are named `SoulsyHUD.log` and `SoulsyHUD_rust.log`.
All SKSE plugin mods log in the same directory: `Documents/my games/Skyrim Special Edition/SKSE`. SoulsyHUD writes its logs in a file named `SoulsyHUD.log`.

In normal logging mode, SoulsyHUD's logs are designed for you to read to learn about what the mod is doing and how it's making decisions for you. At game load, it will log what all your cycles contain and what your equipment sets are, for example. In debug mode, the logs contain information intended to help the mod author debug. Enable this if you're curious or if you have a problem you're trying to figure out.

Expand Down
6 changes: 3 additions & 3 deletions src/PCH.h
Original file line number Diff line number Diff line change
Expand Up @@ -7,8 +7,6 @@
#include <RE/Skyrim.h>
#include <SKSE/SKSE.h>

#include <spdlog/sinks/basic_file_sink.h>

#include <algorithm>
#include <cctype>
#include <d3d11.h>
Expand All @@ -21,7 +19,9 @@
#include <windows.h>
#include <winuser.h>

namespace logger = SKSE::log;
// Templates for sending C++ logging to Rust.
#include "log.h"

using namespace std::literals;

namespace stl
Expand Down
30 changes: 0 additions & 30 deletions src/controller/facade.rs
Original file line number Diff line number Diff line change
Expand Up @@ -3,14 +3,7 @@
//! on the C++ side. It can include any logic that doesn't demand the controller.
//! In particular, it includes a lot of support for papyrus functions.
use std::ffi::OsString;
use std::fs::File;
#[cfg(target_os = "windows")]
use std::os::windows::ffi::OsStringExt;
use std::path::Path;

use cxx::CxxVector;
use simplelog::*;

use super::cycles::*;
use super::settings::{settings, UserSettings};
Expand All @@ -19,29 +12,6 @@ use crate::data::*;
use crate::layouts::{hud_layout, Layout};
use crate::plugin::*;

// ---------- logging

pub fn initialize_rust_logging(_logdir: &cxx::CxxVector<u16>) {
let config = settings();
let log_level = config.log_level().to_level_filter();

#[cfg(not(target_os = "windows"))]
let chonky_path = OsString::from("placeholder");
#[cfg(target_os = "windows")]
let chonky_path = OsString::from_wide(_logdir.as_slice());
let path = Path::new(chonky_path.as_os_str()).with_file_name("SoulsyHUD_rust.log");

let Ok(logfile) = File::create(path) else {
// Welp, we failed and I have nowhere to write the darn error. Ha ha.
return;
};
let Ok(_) = WriteLogger::init(log_level, Config::default(), logfile) else {
// oh dear
return;
};
log::info!("Rust logging standing by.");
}

// ---------- boxed user settings

pub fn user_settings() -> Box<UserSettings> {
Expand Down
62 changes: 62 additions & 0 deletions src/controller/logs.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,62 @@
//! Logging functions exposed to C++. There's an initialization function
//! that must be called to tell the plugin where to log. The other functions
//! are for C++ to use to share a log file with Rust. For now, C++ must pass
//! a preformatted-string to these functions. This is wasteful, but I don't
//! C strings prove a bit of a pain.
use std::ffi::OsString;
use std::fs::File;
#[cfg(target_os = "windows")]
use std::os::windows::ffi::OsStringExt;
use std::path::Path;

use simplelog::*;

use super::settings::settings;

// ---------- logging

pub fn initialize_rust_logging(_logdir: &cxx::CxxVector<u16>) {
let config = settings();
let log_level = config.log_level().to_level_filter();

#[cfg(not(target_os = "windows"))]
let chonky_path = OsString::from("placeholder");
#[cfg(target_os = "windows")]
let chonky_path = OsString::from_wide(_logdir.as_slice());
let path = Path::new(chonky_path.as_os_str()).with_file_name("SoulsyHUD.log");

let Ok(logfile) = File::create(path) else {
// Welp, we failed and I have nowhere to write the darn error. Ha ha.
return;
};
let config = simplelog::ConfigBuilder::new()
.set_thread_level(LevelFilter::Off)
.set_level_padding(simplelog::LevelPadding::Right)
.build();
let Ok(_) = WriteLogger::init(log_level, config, logfile) else {
// oh dear
return;
};
log::info!("SoulsyHUD version {} coming online.", env!("CARGO_PKG_VERSION"));
}

pub fn log_error(message: String) {
log::error!("{}", message);
}

pub fn log_warn(message: String) {
log::warn!("{}", message);
}

pub fn log_info(message: String) {
log::info!("{}", message);
}

pub fn log_debug(message: String) {
log::debug!("{}", message);
}

pub fn log_trace(message: String) {
log::trace!("{}", message);
}
2 changes: 2 additions & 0 deletions src/controller/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,9 @@ pub mod cycleentries;
pub mod cycles;
pub mod facade;
pub mod keys;
pub mod logs;
pub mod settings;

pub use facade::*;
pub use logs::*;
pub use settings::UserSettings;
30 changes: 15 additions & 15 deletions src/game/equippable.cpp
Original file line number Diff line number Diff line change
@@ -1,8 +1,8 @@
#include "equippable.h"

#include "gear.h"
#include "helpers.h"
#include "player.h"
#include "gear.h"

#include "lib.rs.h"

Expand Down Expand Up @@ -77,14 +77,14 @@ namespace equippable
if (!item_form) { return empty_huditem(); }

KeywordAccumulator::clear();
auto loggerName = game::displayName(item_form);
auto loggerName = game::displayName(item_form);
auto chonker = helpers::chars_to_vec(loggerName);
std::string form_string = helpers::makeFormSpecString(item_form);
bool two_handed = requiresTwoHands(item_form);

if (item_form->Is(RE::FormType::Ammo))
{
logger::info("making HudItem for ammo: '{}'"sv, loggerName);
rlog::debug("making HudItem for ammo: '{}'"sv, loggerName);
const auto* ammo = item_form->As<RE::TESAmmo>()->AsKeywordForm();
ammo->ForEachKeyword(KeywordAccumulator::collect);
auto& keywords = KeywordAccumulator::mKeywords;
Expand All @@ -100,7 +100,7 @@ namespace equippable
const auto* weapon = item_form->As<RE::TESObjectWEAP>();
if (weapon)
{
logger::info("making HudItem for weapon: '{}'"sv, loggerName);
rlog::debug("making HudItem for weapon: '{}'"sv, loggerName);
weapon->ForEachKeyword(KeywordAccumulator::collect);
auto& keywords = KeywordAccumulator::mKeywords;
if (weapon->IsBound()) { keywords->push_back(std::string("OCF_InvColorBound")); }
Expand All @@ -114,7 +114,7 @@ namespace equippable

if (item_form->IsArmor())
{
logger::info("making HudItem for armor: '{}'"sv, loggerName);
rlog::debug("making HudItem for armor: '{}'"sv, loggerName);
const auto* armor = item_form->As<RE::TESObjectARMO>();
armor->ForEachKeyword(KeywordAccumulator::collect);
auto& keywords = KeywordAccumulator::mKeywords;
Expand All @@ -132,7 +132,7 @@ namespace equippable
if (item_form->Is(RE::FormType::Light))
{
// This form type does not have keywords. This presents a problem. Cough.
logger::info("making HudItem for light: '{}';"sv, loggerName);
rlog::debug("making HudItem for light: '{}';"sv, loggerName);
const auto name = std::string(item_form->GetName());
if (name.find("Lantern") != std::string::npos) // yes, very limited in effectiveness
{
Expand All @@ -145,7 +145,7 @@ namespace equippable

if (item_form->Is(RE::FormType::Shout))
{
logger::info("making HudItem for shout: '{}'"sv, loggerName);
rlog::debug("making HudItem for shout: '{}'"sv, loggerName);
auto* shout = item_form->As<RE::TESShout>();

if (!shout) return simple_from_formdata(ItemCategory::Shout, std::move(chonker), form_string);
Expand All @@ -171,7 +171,7 @@ namespace equippable
if (spell_type == RE::MagicSystem::SpellType::kLesserPower ||
spell_type == RE::MagicSystem::SpellType::kPower)
{
logger::info("making HudItem for power: '{}'"sv, loggerName);
rlog::debug("making HudItem for power: '{}'"sv, loggerName);
const auto* costliest = spell->GetCostliestEffectItem();
if (costliest)
{
Expand All @@ -188,7 +188,7 @@ namespace equippable
}

// Regular spells.
logger::info("making HudItem for spell: '{}'"sv, loggerName);
rlog::debug("making HudItem for spell: '{}'"sv, loggerName);
const auto* costliest = spell->GetCostliestEffectItem();
if (costliest)
{
Expand All @@ -208,7 +208,7 @@ namespace equippable

if (item_form->Is(RE::FormType::Scroll))
{
logger::info("making HudItem for scroll: '{}'"sv, loggerName);
rlog::debug("making HudItem for scroll: '{}'"sv, loggerName);
auto* scroll = item_form->As<RE::ScrollItem>();
if (scroll->GetCostliestEffectItem() && scroll->GetCostliestEffectItem()->baseEffect)
{
Expand All @@ -233,7 +233,7 @@ namespace equippable

if (alchemy_potion->IsFood())
{
logger::info("making HudItem for food: '{}'"sv, loggerName);
rlog::debug("making HudItem for food: '{}'"sv, loggerName);
alchemy_potion->ForEachKeyword(KeywordAccumulator::collect);
auto& keywords = KeywordAccumulator::mKeywords;
rust::Box<HudItem> item = hud_item_from_keywords(
Expand All @@ -242,7 +242,7 @@ namespace equippable
}
else
{
logger::info("making HudItem for potion: '{}'"sv, loggerName);
rlog::debug("making HudItem for potion: '{}'"sv, loggerName);
rust::Box<HudItem> item = potion_from_formdata(alchemy_potion->IsPoison(),
static_cast<int32_t>(actor_value),
count,
Expand All @@ -254,7 +254,7 @@ namespace equippable

const auto formtype = item_form->GetFormType();
const auto formtypestr = RE::FormTypeToString(formtype);
logger::debug("hudItemFromForm() fell all the way through; type={}; name='{}'; formspec='{}';",
rlog::debug("hudItemFromForm() fell all the way through; type={}; name='{}'; formspec='{}';",
formtypestr,
item_form->GetName(),
form_string);
Expand All @@ -273,7 +273,7 @@ namespace equippable

void KeywordAccumulator::printKeywords()
{
if (!mKeywords) { logger::debug("no keywords to print"); }
for (std::string kwd : *mKeywords) { logger::info("{}"sv, kwd); }
if (!mKeywords) { rlog::debug("no keywords to print"); }
for (std::string kwd : *mKeywords) { rlog::info("{}"sv, kwd); }
}
}
Loading

0 comments on commit 3a92d1e

Please sign in to comment.