Log to AVS by default, with optional logfile flag for old behaviour

This commit is contained in:
Will Toohey 2023-08-20 16:30:29 +10:00
parent ae25ecc4ab
commit 6a2772c246
12 changed files with 293 additions and 178 deletions

View File

@ -3,11 +3,14 @@
#include "avs.h"
#include "hook.h"
#include "log.hpp"
#include "3rd_party/MinHook.h"
#include "utils.h"
#define AVS_STRUCT_DEF(ret_type, name, ...) char* name;
const char *avs_loaded_dll_name;
typedef struct {
char *version_name;
char *unique_check; // for IIDX vs SDVX cloud, almost all funcs are identical
@ -25,6 +28,10 @@ const avs_exports_t avs_exports[] = {
[&] { avs_exports_t x = { 0 };
x.version_name = "normal";
x.unique_check = NULL;
x.log_body_fatal = "log_body_fatal";
x.log_body_warning = "log_body_warning";
x.log_body_info = "log_body_info";
x.log_body_misc = "log_body_misc";
x.avs_fs_open = "avs_fs_open";
x.avs_fs_close = "avs_fs_close";
x.avs_fs_convert_path = "avs_fs_convert_path";
@ -52,8 +59,45 @@ const avs_exports_t avs_exports[] = {
return x;
}(),
[&] { avs_exports_t x = { 0 };
x.version_name = "SDVX";
x.version_name = "2.13.x (XC058ba5------)";
x.unique_check = NULL;
x.log_body_fatal = "XC058ba5000084";
x.log_body_warning = "XC058ba50000e1";
x.log_body_info = "XC058ba500015a";
x.log_body_misc = "XC058ba500002d";
x.avs_fs_open = "XC058ba50000b6";
x.avs_fs_close = "XC058ba500011b";
x.avs_fs_convert_path = "XC058ba50000d5";
x.avs_fs_read = "XC058ba5000139";
x.avs_fs_lseek = "XC058ba500000f";
x.avs_fs_fstat = "XC058ba50000d0";
x.avs_fs_lstat = "XC058ba5000063";
x.avs_fs_mount = "XC058ba500009c";
x.mdigest_create = "XC058ba50000db";
x.mdigest_update = "XC058ba5000096";
x.mdigest_finish = "XC058ba500002f";
x.mdigest_destroy = "XC058ba5000004";
x.property_read_query_memsize = "XC058ba5000066";
x.property_read_query_memsize_long = "XC058ba5000091";
x.property_create = "XC058ba5000107";
x.property_insert_read = "XC058ba5000016";
x.property_mem_write = "XC058ba5000162";
x.property_desc_to_buffer = "XC058ba50000cd";
x.property_destroy = "XC058ba500010f";
x.property_node_query_stat = "XC058ba500015e";
x.cstream_create = "XC058ba5000118";
x.cstream_operate = "XC058ba5000078";
x.cstream_finish = "XC058ba5000130";
x.cstream_destroy = "XC058ba500012b";
return x;
}(),
[&] { avs_exports_t x = { 0 };
x.version_name = "2.15.x (XCd229cc------)";
x.unique_check = NULL;
x.log_body_fatal = "XCd229cc0000e6";
x.log_body_warning = "XCd229cc000018";
x.log_body_info = "XCd229cc0000dc";
x.log_body_misc = "XCd229cc000075";
x.avs_fs_open = "XCd229cc000090";
x.avs_fs_close = "XCd229cc00011f";
x.avs_fs_convert_path = "XCd229cc00001e";
@ -81,8 +125,12 @@ const avs_exports_t avs_exports[] = {
return x;
}(),
[&] { avs_exports_t x = { 0 }; // sdvx cloud
x.version_name = "SDVX Cloud/Beatstream";
x.version_name = "2.16.[3-7] (XCnbrep7------)";
x.unique_check = "XCnbrep700013c";
x.log_body_fatal = "XCnbrep700017a";
x.log_body_warning = "XCnbrep700017b";
x.log_body_info = "XCnbrep700017c";
x.log_body_misc = "XCnbrep700017d";
x.avs_fs_open = "XCnbrep700004e";
x.avs_fs_close = "XCnbrep7000055";
x.avs_fs_convert_path = "XCnbrep7000046";
@ -109,37 +157,13 @@ const avs_exports_t avs_exports[] = {
x.cstream_destroy = "XCnbrep7000134";
return x;
}(),
[&] { avs_exports_t x = { 0 };
x.version_name = "IIDX 19";
x.avs_fs_open = "XC058ba50000b6";
x.avs_fs_close = "XC058ba500011b";
x.avs_fs_convert_path = "XC058ba50000d5";
x.avs_fs_read = "XC058ba5000139";
x.avs_fs_lseek = "XC058ba500000f";
x.avs_fs_fstat = "XC058ba50000d0";
x.avs_fs_lstat = "XC058ba5000063";
x.avs_fs_mount = "XC058ba500009c";
x.mdigest_create = "XC058ba50000db";
x.mdigest_update = "XC058ba5000096";
x.mdigest_finish = "XC058ba500002f";
x.mdigest_destroy = "XC058ba5000004";
x.property_read_query_memsize = "XC058ba5000066";
x.property_read_query_memsize_long = "XC058ba5000091";
x.property_create = "XC058ba5000107";
x.property_insert_read = "XC058ba5000016";
x.property_mem_write = "XC058ba5000162";
x.property_desc_to_buffer = "XC058ba50000cd";
x.property_destroy = "XC058ba500010f";
x.property_node_query_stat = "XC058ba500015e";
x.cstream_create = "XC058ba5000118";
x.cstream_operate = "XC058ba5000078";
x.cstream_finish = "XC058ba5000130";
x.cstream_destroy = "XC058ba500012b";
return x;
}(),
[&] { avs_exports_t x = { 0 }; // IIDX, "nbrep but different"
x.version_name = "IIDX before 25";
x.version_name = "2.16.1 (XCnbrep7 but different)",
x.unique_check = NULL;
x.log_body_fatal = "XCnbrep7000168";
x.log_body_warning = "XCnbrep7000169";
x.log_body_info = "XCnbrep700016a";
x.log_body_misc = "XCnbrep700016b";
x.avs_fs_open = "XCnbrep7000039";
x.avs_fs_close = "XCnbrep7000040";
x.avs_fs_convert_path = "XCnbrep7000031";
@ -166,9 +190,13 @@ const avs_exports_t avs_exports[] = {
x.cstream_destroy = "XCnbrep7000128";
return x;
}(),
[&] { avs_exports_t x = { 0 }; // avs 64 bit, pretty much
x.version_name = "museca/IIDX 25+";
x.unique_check = "XCgsqzn000013c";
[&] { avs_exports_t x = { 0 }; // avs 64 bit, pretty much. 2.16.3 with different prefix
x.version_name = "2.17.x (XCgsqzn0------)";
x.unique_check = NULL;
x.log_body_fatal = "XCgsqzn000017a";
x.log_body_warning = "XCgsqzn000017b";
x.log_body_info = "XCgsqzn000017c";
x.log_body_misc = "XCgsqzn000017d";
x.avs_fs_open = "XCgsqzn000004e";
x.avs_fs_close = "XCgsqzn0000055";
x.avs_fs_convert_path = "XCgsqzn0000046";
@ -202,7 +230,7 @@ FOREACH_AVS_FUNC(AVS_FUNC_PTR)
/*void* (*avs_fs_mount)(char* mountpoint, char* fsroot, char* fstype, int a5);
void* hook_avs_fs_mount(char* mountpoint, char* fsroot, char* fstype, int a5) {
logf("Mounting %s at %s with type %s", fsroot, mountpoint, fstype);
log_misc("Mounting %s at %s with type %s", fsroot, mountpoint, fstype);
return avs_fs_mount(mountpoint, fsroot, fstype, a5);
}*/
@ -217,7 +245,7 @@ bool init_avs(void) {
#ifdef _DEBUG
for (int i = 0; i < lenof(avs_exports); i++) {
#define VERBOSE_EXPORT_CHECK(ret_type, name, ...) if(avs_exports[i]. ## name == NULL) logf("MISSING EXPORT %d: %s", i, #name);
#define VERBOSE_EXPORT_CHECK(ret_type, name, ...) if(avs_exports[i]. ## name == NULL) log_warning("MISSING EXPORT %d: %s", i, #name);
FOREACH_AVS_FUNC(VERBOSE_EXPORT_CHECK)
}
#endif
@ -235,7 +263,7 @@ bool init_avs(void) {
}
if (mod_handle == NULL) {
logf("Couldn't find AVS dll");
log_warning("Couldn't find AVS dll in memory");
return false;
}
@ -254,7 +282,8 @@ bool init_avs(void) {
TEST_HOOK_AND_APPLY(avs_fs_read);
success = true;
logf("Detected dll: %s", avs_exports[i].version_name);
avs_loaded_dll_name = avs_exports[i].version_name;
break;
}
return success;
@ -273,7 +302,7 @@ property_t prop_from_file_handle(AVS_FILE f) {
avs_fs_lseek(f, 0, SEEK_SET);
memsize = property_read_query_memsize(avs_fs_read, f, NULL, NULL);
if (memsize < 0) {
logf("Couldn't get memsize %08X (%s)", memsize, get_prop_error_str(memsize));
log_warning("Couldn't get memsize %08X (%s)", memsize, get_prop_error_str(memsize));
goto FAIL;
}
}
@ -282,7 +311,7 @@ property_t prop_from_file_handle(AVS_FILE f) {
prop = property_create(flags, prop_buffer, memsize);
if (prop < 0) {
// double cast to squash truncation warning
logf("Couldn't create prop (%s)", get_prop_error_str((int32_t)(size_t)prop));
log_warning("Couldn't create prop (%s)", get_prop_error_str((int32_t)(size_t)prop));
goto FAIL;
}
@ -291,7 +320,7 @@ property_t prop_from_file_handle(AVS_FILE f) {
avs_fs_close(f);
if (ret < 0) {
logf("Couldn't read prop (%s)", get_prop_error_str(ret));
log_warning("Couldn't read prop (%s)", get_prop_error_str(ret));
goto FAIL;
}
@ -309,7 +338,7 @@ FAIL:
property_t prop_from_file_path(string const&path) {
AVS_FILE f = avs_fs_open(path.c_str(), 1, 420);
if (f < 0) {
logf("Couldn't open prop");
log_warning("Couldn't open prop");
return NULL;
}
@ -328,7 +357,7 @@ char* prop_to_xml_string(property_t prop, rapidxml::xml_document<>& allocator) {
}
else {
xml[0] = '\0';
logf("property_mem_write failed (%s)", get_prop_error_str(written));
log_warning("property_mem_write failed (%s)", get_prop_error_str(written));
}
return xml;
@ -360,7 +389,7 @@ bool rapidxml_from_avs_filepath(
) {
AVS_FILE f = avs_fs_open(path.c_str(), 1, 420);
if (f < 0) {
logf("Couldn't open prop");
log_warning("Couldn't open prop");
return false;
}
@ -388,7 +417,7 @@ bool rapidxml_from_avs_filepath(
// parse_declaration_node: to get the header <?xml version="1.0" encoding="shift-jis"?>
doc.parse<rapidxml::parse_declaration_node | rapidxml::parse_no_utf8>(xml);
} catch (const rapidxml::parse_error& e) {
logf("Couldn't parse xml (%s byte %d)", e.what(), (int)(e.where<char>() - xml));
log_warning("Couldn't parse xml (%s byte %d)", e.what(), (int)(e.where<char>() - xml));
return false;
}
@ -436,7 +465,7 @@ string md5_sum(const char* str) {
unsigned char* lz_compress(unsigned char* input, size_t length, size_t *compressed_length) {
auto compressor = cstream_create(AVS_COMPRESS_AVSLZ);
if (!compressor) {
logf("Couldn't create");
log_warning("Couldn't create");
return NULL;
}
compressor->input_buffer = input;
@ -456,11 +485,11 @@ unsigned char* lz_compress(unsigned char* input, size_t length, size_t *compress
ret = cstream_operate(compressor);
}
if (!ret) {
logf("Couldn't operate");
log_warning("Couldn't operate");
return NULL;
}
if (cstream_finish(compressor)) {
logf("Couldn't finish");
log_warning("Couldn't finish");
return NULL;
}
*compressed_length = compress_size - compressor->output_size;

View File

@ -184,6 +184,11 @@ typedef size_t(*avs_reader_t)(AVS_FILE context, void *bytes, size_t nbytes);
// because the functions are repeated in 3 places, we format them with an X macro
// return value, name, va args...
#define FOREACH_AVS_FUNC(X) \
/* Logging functions */ \
X(void, log_body_fatal, const char *module, const char *fmt, ELLIPSIS) \
X(void, log_body_warning, const char *module, const char *fmt, ELLIPSIS) \
X(void, log_body_info, const char *module, const char *fmt, ELLIPSIS) \
X(void, log_body_misc, const char *module, const char *fmt, ELLIPSIS) \
/* file functions */ \
X(AVS_FILE, avs_fs_open, const char* name, uint16_t mode, int flags) \
X(void, avs_fs_close, AVS_FILE f) \
@ -229,4 +234,6 @@ string md5_sum(const char* str);
bool init_avs(void);
unsigned char* lz_compress(unsigned char* input, size_t length, size_t *compressed_length);
const char* get_prop_error_str(int32_t code);
const char* get_prop_error_str(int32_t code);
extern const char *avs_loaded_dll_name;

View File

@ -3,6 +3,7 @@
#include <shellapi.h>
#include "config.hpp"
#include "log.hpp"
#include "utils.h"
#define VERBOSE_FLAG "--layered-verbose"
@ -10,9 +11,14 @@
#define DISABLE_FLAG "--layered-disable"
#define ALLOWLIST_FLAG "--layered-allowlist"
#define BLOCKLIST_FLAG "--layered-blocklist"
#define LOGFILE_FLAG "--layered-logfile"
config_t config;
// so we can just print the exact arg
static const char *allowlist = NULL;
static const char *blocklist = NULL;
void comma_separated_to_set(std::unordered_set<std::string> &dest, const char* arg) {
char *str = _strdup(arg);
str_tolower_inline(str); // ignore case for filenames
@ -46,13 +52,11 @@ void load_config(void) {
config.verbose_logs = false;
config.developer_mode = false;
config.disable = false;
config.logfile = NULL;
int i;
// so close to just pulling in a third party argparsing lib...
const char *allowlist = NULL;
const char *blocklist = NULL;
for (i = 0; i < __argc; i++) {
if (strcmp(__argv[i], VERBOSE_FLAG) == 0) {
config.verbose_logs = true;
@ -69,13 +73,23 @@ void load_config(void) {
else if (strncmp(__argv[i], BLOCKLIST_FLAG, strlen(BLOCKLIST_FLAG)) == 0) {
blocklist = parse_list(BLOCKLIST_FLAG, __argv[i], config.blocklist);
}
else if (strncmp(__argv[i], LOGFILE_FLAG, strlen(LOGFILE_FLAG)) == 0) {
const char *path = &__argv[i][strlen(LOGFILE_FLAG)];
// correct format: --layered-logfile=whatever.log
if(path[0] == '=' && path[1]) {
config.logfile = &path[1];
}
}
}
}
logf("Options: %s=%d %s=%d %s=%d %s=%s %s=%s",
void print_config(void) {
log_info("Options: %s=%d %s=%d %s=%d %s=%s %s=%s %s=%s",
VERBOSE_FLAG, config.verbose_logs,
DEVMODE_FLAG, config.developer_mode,
DISABLE_FLAG, config.disable,
LOGFILE_FLAG, config.logfile,
ALLOWLIST_FLAG, allowlist,
BLOCKLIST_FLAG, blocklist
);
}
}

View File

@ -7,10 +7,12 @@ typedef struct {
bool verbose_logs;
bool developer_mode;
bool disable;
const char *logfile;
std::unordered_set<std::string> allowlist;
std::unordered_set<std::string> blocklist;
} config_t;
extern config_t config;
void load_config(void);
void load_config(void);
void print_config(void);

View File

@ -27,6 +27,7 @@ using std::string;
#include "ramfs_demangler.h"
#include "config.hpp"
#include "log.hpp"
#include "utils.h"
#include "avs.h"
//#include "jubeat.h"
@ -142,7 +143,7 @@ bool add_images_to_list(string_set &extra_pngs, rapidxml::xml_node<> *texturelis
vector<Bitmap*> textures;
for (auto it = extra_pngs.begin(); it != extra_pngs.end(); ++it) {
logf_verbose("New image: %s", it->c_str());
log_verbose("New image: %s", it->c_str());
string png_tex = *it + ".png";
auto png_loc = find_first_modfile(ifs_mod_path + "/" + png_tex);
@ -164,7 +165,7 @@ bool add_images_to_list(string_set &extra_pngs, rapidxml::xml_node<> *texturelis
unsigned width, height;
LodePNGState state = {};
if (lodepng_inspect(&width, &height, &state, header, 33)) {
logf("couldn't inspect png");
log_warning("couldn't inspect png");
continue;
}
@ -174,10 +175,10 @@ bool add_images_to_list(string_set &extra_pngs, rapidxml::xml_node<> *texturelis
auto pack_start = time();
vector<Packer*> packed_textures;
if (!pack_textures(textures, packed_textures)) {
logf("Couldn't pack textures :(");
log_warning("Couldn't pack textures :(");
return false;
}
logf("Texture packing %d ms", time() - pack_start);
log_misc("Texture packing %d ms", time() - pack_start);
// because the property API, being
// a) written by Konami
@ -242,7 +243,7 @@ bool add_images_to_list(string_set &extra_pngs, rapidxml::xml_node<> *texturelis
}
}
logf("Texture extend total time %d ms", time() - start);
log_misc("Texture extend total time %d ms", time() - start);
return true;
}
@ -253,12 +254,12 @@ void parse_texturelist(string const&path, string const&norm_path, optional<strin
auto ifs_path = norm_path;
// truncate
ifs_path.resize(ifs_path.size() - strlen("/tex/texturelist.xml"));
//logf("Reading ifs %s", ifs_path.c_str());
//log_misc("Reading ifs %s", ifs_path.c_str());
auto ifs_mod_path = ifs_path;
string_replace(ifs_mod_path, ".ifs", "_ifs");
if (!find_first_modfolder(ifs_mod_path)) {
logf_verbose("mod folder doesn't exist, skipping");
log_verbose("mod folder doesn't exist, skipping");
return;
}
@ -272,7 +273,7 @@ void parse_texturelist(string const&path, string const&norm_path, optional<strin
auto texturelist_node = texturelist.first_node("texturelist");
if (!texturelist_node) {
logf("texlist has no texturelist node");
log_warning("texlist has no texturelist node");
return;
}
@ -295,14 +296,14 @@ void parse_texturelist(string const&path, string const&norm_path, optional<strin
auto format = texture->first_attribute("format");
if (!format) {
logf("Texture missing format %s", path_to_open.c_str());
log_warning("Texture missing format %s", path_to_open.c_str());
continue;
}
//<size __type="2u16">128 128</size>
auto size = texture->first_node("size");
if (!size) {
logf("Texture missing size %s", path_to_open.c_str());
log_warning("Texture missing size %s", path_to_open.c_str());
continue;
}
@ -318,7 +319,7 @@ void parse_texturelist(string const&path, string const&norm_path, optional<strin
image = image->next_sibling("image")) {
auto name = image->first_attribute("name");
if (!name) {
logf("Texture missing name %s", path_to_open.c_str());
log_warning("Texture missing name %s", path_to_open.c_str());
continue;
}
@ -326,14 +327,14 @@ void parse_texturelist(string const&path, string const&norm_path, optional<strin
auto imgrect = image->first_node("imgrect");
auto uvrect = image->first_node("uvrect");
if (!imgrect || !uvrect) {
logf("Texture missing dimensions %s", path_to_open.c_str());
log_warning("Texture missing dimensions %s", path_to_open.c_str());
continue;
}
// it's a 4u16
sscanf_s(imgrect->value(), "%" SCNu16 " %" SCNu16 " %" SCNu16 " %" SCNu16, &dimensions[0], &dimensions[1], &dimensions[2], &dimensions[3]);
//logf("Image '%s' compress %d format %d", tmp, compress, format_type);
//log_misc("Image '%s' compress %d format %d", tmp, compress, format_type);
image_t image_info;
image_info.name = name->value();
image_info.name_md5 = md5_sum(name->value());
@ -352,7 +353,7 @@ void parse_texturelist(string const&path, string const&norm_path, optional<strin
}
}
logf_verbose("%d added PNGs", extra_pngs.size());
log_verbose("%d added PNGs", extra_pngs.size());
if (extra_pngs.size() > 0) {
if (add_images_to_list(extra_pngs, texturelist_node, ifs_path, ifs_mod_path, compress))
prop_was_rewritten = true;
@ -361,7 +362,7 @@ void parse_texturelist(string const&path, string const&norm_path, optional<strin
if (prop_was_rewritten) {
string outfolder = CACHE_FOLDER "/" + ifs_mod_path;
if (!mkdir_p(outfolder)) {
logf("Couldn't create cache folder");
log_warning("Couldn't create cache folder");
}
string outfile = outfolder + "/texturelist.xml";
rapidxml_dump_to_file(outfile, texturelist);
@ -372,7 +373,7 @@ void parse_texturelist(string const&path, string const&norm_path, optional<strin
bool cache_texture(string const&png_path, image_t &tex) {
string cache_path = tex.cache_folder();
if (!mkdir_p(cache_path)) {
logf("Couldn't create texture cache folder");
log_warning("Couldn't create texture cache folder");
return false;
}
@ -396,12 +397,12 @@ bool cache_texture(string const&png_path, image_t &tex) {
error = lodepng_decode32_file(&image, &width, &height, png_path.c_str());
if (error) {
logf("can't load png %u: %s\n", error, lodepng_error_text(error));
log_warning("can't load png %u: %s\n", error, lodepng_error_text(error));
return false;
}
if (width != tex.width || height != tex.height) {
logf("Loaded png (%dx%d) doesn't match texturelist.xml (%dx%d), ignoring", width, height, tex.width, tex.height);
log_warning("Loaded png (%dx%d) doesn't match texturelist.xml (%dx%d), ignoring", width, height, tex.width, tex.height);
return false;
}
@ -447,7 +448,7 @@ bool cache_texture(string const&png_path, image_t &tex) {
auto compressed = lz_compress(image, image_size, &compressed_size);
free(image);
if (compressed == NULL) {
logf("Couldn't compress");
log_warning("Couldn't compress");
return false;
}
image = compressed;
@ -456,7 +457,7 @@ bool cache_texture(string const&png_path, image_t &tex) {
fopen_s(&cache, cache_file.c_str(), "wb");
if (!cache) {
logf("can't open cache for writing");
log_warning("can't open cache for writing");
return false;
}
if (tex.compression == AVSLZ) {
@ -479,7 +480,7 @@ void handle_texture(string const&norm_path, optional<string> &mod_path) {
return;
}
//logf("Mapped file %s is found!", norm_path.c_str());
//log_misc("Mapped file %s is found!", norm_path.c_str());
auto tex = tex_search->second;
ifs_textures_mtx.unlock(); // is it safe to unlock this early? Time will tell...
@ -493,15 +494,15 @@ void handle_texture(string const&norm_path, optional<string> &mod_path) {
}
if (tex.compression == UNSUPPORTED_COMPRESS) {
logf("Unsupported compression for %s", png_path->c_str());
log_warning("Unsupported compression for %s", png_path->c_str());
return;
}
if (tex.format == UNSUPPORTED_FORMAT) {
logf("Unsupported texture format for %s", png_path->c_str());
log_warning("Unsupported texture format for %s", png_path->c_str());
return;
}
logf_verbose("Mapped file %s found!", png_path->c_str());
log_verbose("Mapped file %s found!", png_path->c_str());
if (cache_texture(*png_path, tex)) {
mod_path = tex.cache_file();
}
@ -561,17 +562,17 @@ void merge_xmls(string const& path, string const&norm_path, optional<string> &mo
auto first_result = rapidxml_from_avs_filepath(starting, merged_xml, merged_xml);
if (!first_result) {
logf("Couldn't merge (can't load first xml %s)", starting.c_str());
log_warning("Couldn't merge (can't load first xml %s)", starting.c_str());
return;
}
logf("Merging into %s", starting.c_str());
log_info("Merging into %s", starting.c_str());
for (auto &path : to_merge) {
logf(" %s", path.c_str());
log_info(" %s", path.c_str());
rapidxml::xml_document<> rapid_to_merge;
auto merge_load_result = rapidxml_from_avs_filepath(path, rapid_to_merge, merged_xml);
if (!merge_load_result) {
logf("Couldn't merge (can't load xml) %s", path.c_str());
log_warning("Couldn't merge (can't load xml) %s", path.c_str());
return;
}
@ -586,7 +587,7 @@ void merge_xmls(string const& path, string const&norm_path, optional<string> &mo
auto folder_terminator = out.rfind("/");
out_folder = out.substr(0, folder_terminator);
if (!mkdir_p(out_folder)) {
logf("Couldn't create merged cache folder");
log_warning("Couldn't create merged cache folder");
}
rapidxml_dump_to_file(out, merged_xml);
@ -597,14 +598,14 @@ void merge_xmls(string const& path, string const&norm_path, optional<string> &mo
}
mod_path = out;
logf("Merge took %d ms", time() - start);
log_misc("Merge took %d ms", time() - start);
}
int hook_avs_fs_lstat(const char* name, struct avs_stat *st) {
if (name == NULL)
return avs_fs_lstat(name, st);
logf_verbose("statting %s", name);
log_verbose("statting %s", name);
string path = name;
// can it be modded?
@ -615,7 +616,7 @@ int hook_avs_fs_lstat(const char* name, struct avs_stat *st) {
auto mod_path = find_first_modfile(*norm_path);
if (mod_path) {
logf_verbose("Overwriting lstat");
log_verbose("Overwriting lstat");
return avs_fs_lstat(mod_path->c_str(), st);
}
return avs_fs_lstat(name, st);
@ -625,7 +626,7 @@ int hook_avs_fs_convert_path(char dest_name[256], const char *name) {
if (name == NULL)
return avs_fs_convert_path(dest_name, name);
logf_verbose("convert_path %s", name);
log_verbose("convert_path %s", name);
string path = name;
// can it be modded?
@ -636,14 +637,14 @@ int hook_avs_fs_convert_path(char dest_name[256], const char *name) {
auto mod_path = find_first_modfile(*norm_path);
if (mod_path) {
logf_verbose("Overwriting convert_path");
log_verbose("Overwriting convert_path");
return avs_fs_convert_path(dest_name, mod_path->c_str());
}
return avs_fs_convert_path(dest_name, name);
}
int hook_avs_fs_mount(const char* mountpoint, const char* fsroot, const char* fstype, const char* args) {
logf_verbose("mounting %s to %s with type %s and args %s", fsroot, mountpoint, fstype, args);
log_verbose("mounting %s to %s with type %s and args %s", fsroot, mountpoint, fstype, args);
ramfs_demangler_on_fs_mount(mountpoint, fsroot, fstype, args);
return avs_fs_mount(mountpoint, fsroot, fstype, args);
@ -657,7 +658,7 @@ size_t hook_avs_fs_read(AVS_FILE context, void* bytes, size_t nbytes) {
AVS_FILE hook_avs_fs_open(const char* name, uint16_t mode, int flags) {
if(name == NULL)
return avs_fs_open(name, mode, flags);
logf_verbose("opening %s mode %d flags %d", name, mode, flags);
log_verbose("opening %s mode %d flags %d", name, mode, flags);
// only touch reads
if (mode != 1) {
return avs_fs_open(name, mode, flags);
@ -690,13 +691,13 @@ AVS_FILE hook_avs_fs_open(const char* name, uint16_t mode, int flags) {
}
if (mod_path) {
logf("Using %s", mod_path->c_str());
log_info("Using %s", mod_path->c_str());
}
auto to_open = mod_path ? *mod_path : orig_path;
auto ret = avs_fs_open(to_open.c_str(), mode, flags);
ramfs_demangler_on_fs_open(to_open, ret);
// logf("returned %d", ret);
// log_misc("returned %d", ret);
return ret;
}
@ -711,7 +712,7 @@ void avs_playpen() {
auto memsize = property_read_query_memsize(avs_fs_read, f, NULL, NULL);
if (memsize < 0) {
logf("Couldn't get memsize %08X", memsize);
log_warning("Couldn't get memsize %08X", memsize);
goto FAIL;
}
@ -721,7 +722,7 @@ void avs_playpen() {
prop_buffer = malloc(memsize);
prop = property_create(PROP_READ|PROP_WRITE|PROP_APPEND|PROP_CREATE|PROP_JSON, prop_buffer, memsize);
if (!prop) {
logf("Couldn't create prop");
log_warning("Couldn't create prop");
goto FAIL;
}
@ -741,11 +742,11 @@ FAIL:
/*auto d = avs_fs_opendir(MOD_FOLDER);
if (!d) {
logf("couldn't d");
log_warning("couldn't d");
return;
}
for (char* n = avs_fs_readdir(d); n; n = avs_fs_readdir(d))
logf("dir %s", n);
log_info("dir %s", n);
avs_fs_closedir(d);*/
//char name[64];
//auto playpen = prop_from_file("playpen.xml");
@ -757,15 +758,15 @@ FAIL:
//print_node(end);
/*for (int i = 0; i <= 8; i++) {
if (i == 6 || i == 3) continue;
logf("Traverse: %d", i);
log_info("Traverse: %d", i);
auto node = property_search(playpen, NULL, "/root/t2");
auto nnn = property_node_traversal(node, 8);
auto nna = property_node_traversal(nnn, TRAVERSE_FIRST_ATTR);
property_node_name(nna, name, 64);
logf("bloop %s", name);
log_info("bloop %s", name);
for (;node;node = property_node_traversal(node, i)) {
if (!property_node_name(node, name, 64)) {
logf(" %s", name);
log_info(" %s", name);
}
}
}*/
@ -774,32 +775,47 @@ FAIL:
extern "C" {
__declspec(dllexport) int init(void) {
logf("IFS layeredFS v" VERSION " DLL init...");
// all logs up until init_avs succeeds will go to a file for debugging purposes
// find out where we're logging to
load_config();
if (MH_Initialize() != MH_OK) {
logf("Couldn't initialize MinHook");
log_fatal("Couldn't initialize MinHook");
return 1;
}
load_config();
cache_mods();
logf("Hooking ifs operations");
if (!init_avs()) {
logf("Couldn't find ifs operations in dll. Send avs dll (libavs-winxx.dll or avs2-core.dll) to mon.");
log_fatal("Couldn't find ifs operations in dll. Send avs dll (libavs-winxx.dll or avs2-core.dll) to mon.");
return 2;
}
// re-route to AVS logs if no external file specified
if(!config.logfile) {
imp_log_body_fatal = log_body_fatal;
imp_log_body_warning = log_body_warning;
imp_log_body_info = log_body_info;
imp_log_body_misc = log_body_misc;
}
// now we can say hello!
log_info("IFS layeredFS v" VERSION " init");
log_info("AVS DLL detected: %s", avs_loaded_dll_name);
print_config();
cache_mods();
//jb_texhook_init();
if (MH_EnableHook(MH_ALL_HOOKS) != MH_OK) {
logf("Couldn't enable hooks");
log_warning("Couldn't enable hooks");
return 2;
}
logf("Hook DLL init success");
log_info("Hook DLL init success");
logf("Detected mod folders:");
log_info("Detected mod folders:");
for (auto &p : available_mods()) {
logf("%s", p.c_str());
log_info("%s", p.c_str());
}
return 0;

View File

@ -178,7 +178,7 @@
<ClInclude Include="avs.h" />
<ClInclude Include="config.hpp" />
<ClInclude Include="hook.h" />
<ClInclude Include="jubeat.h" />
<ClInclude Include="log.hpp" />
<ClInclude Include="modpath_handler.h" />
<ClInclude Include="ramfs_demangler.h" />
<ClInclude Include="texture_packer.h" />
@ -194,7 +194,7 @@
<ClCompile Include="config.cpp" />
<ClCompile Include="dllmain.cpp" />
<ClCompile Include="hook.cpp" />
<ClCompile Include="jubeat.cpp" />
<ClCompile Include="log.cpp" />
<ClCompile Include="modpath_handler.cpp" />
<ClCompile Include="ramfs_demangler.cpp" />
<ClCompile Include="texture_packer.cpp" />

73
layeredfs/log.cpp Normal file
View File

@ -0,0 +1,73 @@
#include <stdio.h>
#include "config.hpp"
#include "log.hpp"
#include "winxp_mutex.hpp"
#define SUPPRESS_PRINTF
static void log_to_file(char level, const char* fmt, va_list args) {
static CriticalSectionLock log_mutex;
static FILE* logfile = NULL;
static bool tried_to_open = false;
#ifndef SUPPRESS_PRINTF
printf("%c:", level);
vprintf(fmt, args);
printf("\n");
#endif
// don't reopen every time: slow as shit
if (!tried_to_open) {
log_mutex.lock();
if (!logfile) {
// default to ifs_hook.log because we need *something* in the case
// of a fatal error
const char *path = config.logfile ? config.logfile : "ifs_hook.log";
fopen_s(&logfile, path, "w");
}
tried_to_open = true;
log_mutex.unlock();
}
if (logfile) {
log_mutex.lock();
fprintf(logfile, "%c:", level);
vfprintf(logfile, fmt, args);
fprintf(logfile, "\n");
if(config.developer_mode)
fflush(logfile);
log_mutex.unlock();
}
}
void default_log_body_fatal(const char *module, const char *fmt, ...) {
va_list args;
va_start(args, fmt);
log_to_file('F', fmt, args);
va_end(args);
}
void default_log_body_warning(const char *module, const char *fmt, ...) {
va_list args;
va_start(args, fmt);
log_to_file('W', fmt, args);
va_end(args);
}
void default_log_body_info(const char *module, const char *fmt, ...) {
va_list args;
va_start(args, fmt);
log_to_file('I', fmt, args);
va_end(args);
}
void default_log_body_misc(const char *module, const char *fmt, ...) {
va_list args;
va_start(args, fmt);
log_to_file('M', fmt, args);
va_end(args);
}
log_formatter_t imp_log_body_fatal = default_log_body_fatal;
log_formatter_t imp_log_body_warning = default_log_body_warning;
log_formatter_t imp_log_body_info = default_log_body_info;
log_formatter_t imp_log_body_misc = default_log_body_misc;

18
layeredfs/log.hpp Normal file
View File

@ -0,0 +1,18 @@
#include "config.hpp" // since log_verbose uses it
#define LOG_MODULE "layeredfs"
// functions that default to file output, but will be overriden to point to AVS
// logging functions if the user doesn't specify their own log file
#define log_fatal(...) imp_log_body_fatal(LOG_MODULE, __VA_ARGS__)
#define log_warning(...) imp_log_body_warning(LOG_MODULE, __VA_ARGS__)
#define log_info(...) imp_log_body_info(LOG_MODULE, __VA_ARGS__)
#define log_misc(...) imp_log_body_misc(LOG_MODULE, __VA_ARGS__)
// layeredfs super-verbose (since most people have loglevel misc already)
#define log_verbose(...) if(config.verbose_logs) {log_misc(__VA_ARGS__);}
typedef void (*log_formatter_t)(const char *module, const char *fmt, ...);
extern log_formatter_t imp_log_body_fatal;
extern log_formatter_t imp_log_body_warning;
extern log_formatter_t imp_log_body_info;
extern log_formatter_t imp_log_body_misc;

View File

@ -7,6 +7,7 @@
#include "modpath_handler.h"
#include "config.hpp"
#include "log.hpp"
#include "utils.h"
#include "avs.h"
#include "winxp_mutex.hpp"
@ -38,16 +39,16 @@ std::unordered_set<string> walk_dir(const string &path, const string &root) {
if (ffd.dwFileAttributes & FILE_ATTRIBUTE_DIRECTORY) {
// sanity check a common mistake
if (root == "" && !strcmp(ffd.cFileName, "data")) {
logf("WARNING: \"data\" folder detected in mod root. Move all files inside to the mod root, or it will not work");
log_warning("\"data\" folder detected in mod root. Move all files inside to the mod root, or it will not work");
}
result_path = root + ffd.cFileName + "/";
logf_verbose(" %s", result_path.c_str());
log_verbose(" %s", result_path.c_str());
auto subdir_walk = walk_dir(path + "/" + ffd.cFileName, result_path);
result.insert(subdir_walk.begin(), subdir_walk.end());
}
else {
result_path = root + ffd.cFileName;
logf_verbose(" %s", result_path.c_str());
log_verbose(" %s", result_path.c_str());
}
result.insert(result_path);
} while (FindNextFileA(contents, &ffd) != 0);
@ -66,7 +67,7 @@ void cache_mods(void) {
config.developer_mode = devmode;
for (auto &dir : avail_mods) {
logf_verbose("Walking %s", dir.c_str());
log_verbose("Walking %s", dir.c_str());
mod_contents_t mod;
mod.name = dir;
// even in developer mode we want to walk the mods directory for effective logging
@ -152,7 +153,7 @@ vector<string> available_mods() {
// if there is an allowlist, is this mod on it?
if (!config.allowlist.empty() && config.allowlist.find(folder) == config.allowlist.end()) {
if (first_search)
logf("Ignoring non-allowlisted mod %s", folder.c_str());
log_info("Ignoring non-allowlisted mod %s", folder.c_str());
continue;
}
@ -160,7 +161,7 @@ vector<string> available_mods() {
// is this mod in the blocklist?
if (config.blocklist.find(folder) != config.blocklist.end()) {
if (first_search)
logf("Ignoring blocklisted mod %s", folder.c_str());
log_info("Ignoring blocklisted mod %s", folder.c_str());
continue;
}
@ -228,7 +229,7 @@ optional<string> find_first_cached_item(const string &norm_path) {
}
optional<string> find_first_modfile(const string &norm_path) {
//logf_verbose("%s(%s)", __FUNCTION__, norm_path.c_str());
//log_verbose("%s(%s)", __FUNCTION__, norm_path.c_str());
if (config.developer_mode) {
for (auto &dir : available_mods()) {
auto mod_path = dir + "/" + norm_path;

View File

@ -37,6 +37,7 @@
#include "3rd_party/hat-trie/htrie_map.h"
#include "ramfs_demangler.h"
#include "log.hpp"
#include "utils.h"
#include "winxp_mutex.hpp"
@ -103,7 +104,7 @@ void ramfs_demangler_on_fs_read(AVS_FILE context, void* dest) {
if (find != open_file_map.end()) {
auto path = find->second;
// even this is too verbose
//logf_verbose("Mapped %p to %s", dest, path.c_str());
//log_verbose("Mapped %p to %s", dest, path.c_str());
ram_load_map[dest] = path;
auto cleanup = cleanup_map.find(path);
@ -122,13 +123,13 @@ void ramfs_demangler_on_fs_mount(const char* mountpoint, const char* fsroot, con
void* buffer;
if (!flags) {
logf_verbose("ramfs has no flags?");
log_verbose("ramfs has no flags?");
mangling_mtx.unlock();
return;
}
const char* baseptr = strstr(flags, "base=");
if (!baseptr) {
logf_verbose("ramfs has no base pointer?");
log_verbose("ramfs has no base pointer?");
mangling_mtx.unlock();
return;
}
@ -138,7 +139,7 @@ void ramfs_demangler_on_fs_mount(const char* mountpoint, const char* fsroot, con
auto find = ram_load_map.find(buffer);
if (find != ram_load_map.end()) {
auto orig_path = find->second;
logf_verbose("ramfs mount mapped to %s", orig_path.c_str());
log_verbose("ramfs mount mapped to %s", orig_path.c_str());
string mount_path = (string)mountpoint + "/" + fsroot;
ramfs_map[mount_path.c_str()] = orig_path;
@ -152,7 +153,7 @@ void ramfs_demangler_on_fs_mount(const char* mountpoint, const char* fsroot, con
auto find = ramfs_map.longest_prefix(fsroot);
if (find != ramfs_map.end()) {
auto orig_path = *find;
logf_verbose("imagefs mount mapped to %s", orig_path.c_str());
log_verbose("imagefs mount mapped to %s", orig_path.c_str());
mangling_map[mountpoint] = orig_path;
auto cleanup = cleanup_map.find(orig_path);
@ -164,7 +165,7 @@ void ramfs_demangler_on_fs_mount(const char* mountpoint, const char* fsroot, con
// this fixes ifs-inside-ifs by demangling the root location too
string root = (string)fsroot;
ramfs_demangler_demangle_if_possible_nolock(root);
logf_verbose("imagefs mount mapped to %s", root.c_str());
log_verbose("imagefs mount mapped to %s", root.c_str());
mangling_map[mountpoint] = root;
}
}
@ -177,7 +178,7 @@ void ramfs_demangler_demangle_if_possible(std::string& raw_path) {
auto search = mangling_map.longest_prefix(raw_path);
if (search != mangling_map.end()) {
//logf_verbose("can demangle %s to %s", search.key().c_str(), search->c_str());
//log_verbose("can demangle %s to %s", search.key().c_str(), search->c_str());
string_replace(raw_path, search.key().c_str(), search->c_str());
}

View File

@ -1,44 +1,8 @@
#include <stdarg.h>
#include <Windows.h>
#include "utils.h"
#include "avs.h"
#include "winxp_mutex.hpp"
#define SUPPRESS_PRINTF
void logf(char* fmt, ...) {
static CriticalSectionLock log_mutex;
static FILE* logfile = NULL;
static bool tried_to_open = false;
va_list args;
#ifndef SUPPRESS_PRINTF
va_start(args, fmt);
vprintf(fmt, args);
va_end(args);
printf("\n");
#endif
// don't reopen every time: slow as shit
if (!tried_to_open) {
log_mutex.lock();
if (!logfile) {
fopen_s(&logfile, "ifs_hook.log", "w");
}
tried_to_open = true;
log_mutex.unlock();
}
if (logfile) {
log_mutex.lock();
va_start(args, fmt);
vfprintf(logfile, fmt, args);
va_end(args);
fprintf(logfile, "\n");
if(config.developer_mode)
fflush(logfile);
log_mutex.unlock();
}
}
char* snprintf_auto(const char* fmt, ...) {
va_list argList;

View File

@ -1,22 +1,12 @@
#pragma once
#include <stdio.h>
#include <stdlib.h>
#include <stdint.h>
#include <inttypes.h>
#include <Windows.h>
#include <string>
#include <vector>
#include "3rd_party/MinHook.h"
#include "config.hpp"
#define lenof(x) (sizeof(x) / sizeof(*x))
void logf(char* fmt, ...);
#define logf_verbose(...) if(config.verbose_logs) {logf(__VA_ARGS__);}
char* snprintf_auto(const char* fmt, ...);
int string_ends_with(const char * str, const char * suffix);
void string_replace(std::string &str, const char* from, const char* to);
@ -28,4 +18,4 @@ bool file_exists(const char* name);
bool folder_exists(const char* name);
std::vector<std::string> folders_in_folder(const char* root);
time_t file_time(const char* path);
LONG time(void);
LONG time(void);