diff --git a/common/audio/audio_formats.cpp b/common/audio/audio_formats.cpp index 62398aa4f8..657e06b487 100644 --- a/common/audio/audio_formats.cpp +++ b/common/audio/audio_formats.cpp @@ -1,5 +1,6 @@ #include "audio_formats.h" +#include "common/log/log.h" #include "common/util/BinaryWriter.h" #include "third-party/fmt/core.h" @@ -254,7 +255,7 @@ void test_encode_adpcm(const std::vector& samples, } if (debug) { - fmt::print("Range: {}\n", max_sample - min_sample); + lg::debug("Range: {}", max_sample - min_sample); } // see how many bits we need and pick shift. @@ -283,11 +284,11 @@ void test_encode_adpcm(const std::vector& samples, if (filter_errors[best_filter] || best_filter != filter_debug[block_idx] || best_shift != shift_debug[block_idx]) { - fmt::print("Block {} me {}, {} : answer {} {}: ERR {}\n", block_idx, best_filter, best_shift, - filter_debug[block_idx], shift_debug[block_idx], filter_errors[best_filter]); - fmt::print("filter errors:\n"); + lg::error("Block {} me {}, {} : answer {} {}: ERR {}", block_idx, best_filter, best_shift, + filter_debug[block_idx], shift_debug[block_idx], filter_errors[best_filter]); + lg::error("filter errors:"); for (int i = 0; i < 5; i++) { - fmt::print(" [{}] {} {}\n", i, filter_errors[i], filter_shifts[i]); + lg::error(" [{}] {} {}", i, filter_errors[i], filter_shifts[i]); } ASSERT_MSG(false, fmt::format("prev: {} {}", prev_block_samples[0], prev_block_samples[1])); } diff --git a/common/cross_sockets/XSocket.cpp b/common/cross_sockets/XSocket.cpp index 5ff7bd1e66..71223e77b4 100644 --- a/common/cross_sockets/XSocket.cpp +++ b/common/cross_sockets/XSocket.cpp @@ -18,6 +18,7 @@ #include #include "third-party/fmt/core.h" +#include "common/log/log.h" // clang-format on int open_socket(int af, int type, int protocol) { @@ -29,7 +30,7 @@ int open_socket(int af, int type, int protocol) { // Initialize Winsock iResult = WSAStartup(MAKEWORD(2, 2), &wsaData); if (iResult != 0) { - printf("WSAStartup failed: %d\n", iResult); + lg::error("WSAStartup failed: {}", iResult); return 1; } return socket(af, type, protocol); @@ -71,7 +72,7 @@ int accept_socket(int socket, sockaddr* addr, int* addrLen) { // Initialize Winsock iResult = WSAStartup(MAKEWORD(2, 2), &wsaData); if (iResult != 0) { - printf("WSAStartup failed: %d\n", iResult); + lg::error("WSAStartup failed: {}", iResult); return 1; } return accept(socket, addr, addrLen); @@ -116,13 +117,13 @@ void close_socket(int sock) { int set_socket_option(int socket, int level, int optname, const void* optval, int optlen) { int ret = setsockopt(socket, level, optname, (const char*)optval, optlen); if (ret < 0) { - printf("Failed to setsockopt(%d, %d, %d, _, _) - Error: %s\n", socket, level, optname, - strerror(errno)); + lg::error("Failed to setsockopt({},{}, {}, _, _) - Error: {}", socket, level, optname, + strerror(errno)); } #ifdef _WIN32 if (ret < 0) { int err = WSAGetLastError(); - printf("WSAGetLastError: %d\n", err); + lg::error("WSAGetLastError: {}", err); } #endif return ret; @@ -153,7 +154,7 @@ int write_to_socket(int socket, const char* buf, int len) { bytes_wrote = send(socket, buf, len, 0); #endif if (bytes_wrote < 0) { - fmt::print(stderr, "[XSocket:{}] Error writing to socket\n", socket); + lg::error("[XSocket:{}] Error writing to socket", socket); } return bytes_wrote; } diff --git a/common/cross_sockets/XSocketServer.cpp b/common/cross_sockets/XSocketServer.cpp index 40a1ba246c..6a47671dc7 100644 --- a/common/cross_sockets/XSocketServer.cpp +++ b/common/cross_sockets/XSocketServer.cpp @@ -12,6 +12,7 @@ #include #include #endif +#include "common/log/log.h" // clang-format on XSocketServer::XSocketServer(std::function shutdown_callback, @@ -67,19 +68,19 @@ bool XSocketServer::init_server() { addr.sin_port = htons(tcp_port); if (bind(listening_socket, (sockaddr*)&addr, sizeof(addr)) < 0) { - fmt::print("[XSocketServer:{}] failed to bind\n", tcp_port); + lg::error("[XSocketServer:{}] failed to bind", tcp_port); close_server_socket(); return false; } if (listen(listening_socket, 0) < 0) { - fmt::print("[XSocketServer:{}] failed to listen\n", tcp_port); + lg::error("[XSocketServer:{}] failed to listen", tcp_port); close_server_socket(); return false; } server_initialized = true; - fmt::print("[XSocketServer:{}] initialized\n", tcp_port); + lg::info("[XSocketServer:{}] initialized", tcp_port); post_init(); return true; } diff --git a/common/custom_data/pack_helpers.cpp b/common/custom_data/pack_helpers.cpp index 0025c596b5..6bed346832 100644 --- a/common/custom_data/pack_helpers.cpp +++ b/common/custom_data/pack_helpers.cpp @@ -2,13 +2,15 @@ #include +#include "common/log/log.h" + constexpr float kClusterSize = 4096 * 40; // 100 in-game meters constexpr float kMasterOffset = 12000 * 4096; std::pair position_to_cluster_and_offset(float in) { in += kMasterOffset; if (in < 0) { - fmt::print("negative: {}\n", in); + lg::print("negative: {}\n", in); } ASSERT(in >= 0); int cluster_cell = (in / kClusterSize); @@ -69,4 +71,4 @@ void pack_tfrag_vertices(tfrag3::PackedTfragVertices* result, } ASSERT(next_cluster_idx < UINT16_MAX); -} \ No newline at end of file +} diff --git a/common/dma/dma_copy.cpp b/common/dma/dma_copy.cpp index b02f10df55..5890beccc8 100644 --- a/common/dma/dma_copy.cpp +++ b/common/dma/dma_copy.cpp @@ -3,6 +3,7 @@ #include "common/dma/dma_chain_read.h" #include "common/goal_constants.h" +#include "common/log/log.h" #include "common/util/Timer.h" #include "third-party/fmt/core.h" @@ -36,11 +37,11 @@ void diff_dma_chains(DmaFollower ref, DmaFollower dma) { auto ref_tag = ref.current_tag(); auto dma_tag = dma.current_tag(); if (ref_tag.kind != dma_tag.kind) { - fmt::print("Bad dma tag kinds\n"); + lg::warn("Bad dma tag kinds"); } if (ref_tag.qwc != dma_tag.qwc) { - fmt::print("Bad dma tag qwc: {} {}\n", ref_tag.qwc, dma_tag.qwc); + lg::warn("Bad dma tag qwc: {} {}", ref_tag.qwc, dma_tag.qwc); } auto ref_result = ref.read_and_advance(); @@ -48,19 +49,19 @@ void diff_dma_chains(DmaFollower ref, DmaFollower dma) { for (int i = 0; i < (int)ref_result.size_bytes; i++) { if (ref_result.data[i] != dma_result.data[i]) { - fmt::print("Bad data ({} vs {}) at {} into transfer: {} {}\n", ref_result.data[i], - dma_result.data[i], i, ref_tag.print(), dma_tag.print()); + lg::error("Bad data ({} vs {}) at {} into transfer: {} {}", ref_result.data[i], + dma_result.data[i], i, ref_tag.print(), dma_tag.print()); return; } } } if (!ref.ended()) { - fmt::print("dma ended early\n"); + lg::warn("dma ended early"); } if (!dma.ended()) { - fmt::print("dma had extra data\n"); + lg::warn("dma had extra data"); } } @@ -175,12 +176,12 @@ const DmaData& FixedChunkDmaCopier::run(const void* memory, u32 offset, bool ver auto v2 = flatten_dma(DmaFollower(m_result.data.data(), m_result.start_offset)); if (ref != v2) { - fmt::print("Verification has failed.\n"); - fmt::print("size diff: {} {}\n", ref.size(), v2.size()); + lg::error("Verification has failed."); + lg::error("size diff: {} {}", ref.size(), v2.size()); for (size_t i = 0; i < std::min(ref.size(), v2.size()); i++) { if (ref[i] != v2[i]) { - fmt::print("first diff at {}\n", i); + lg::error("first diff at {}", i); break; } } @@ -188,10 +189,10 @@ const DmaData& FixedChunkDmaCopier::run(const void* memory, u32 offset, bool ver DmaFollower(m_result.data.data(), m_result.start_offset)); ASSERT(false); } else { - fmt::print("verification ok: {} bytes\n", ref.size()); + lg::debug("verification ok: {} bytes", ref.size()); } } m_result.stats.sync_time_ms = timer.getMs(); return m_result; -} \ No newline at end of file +} diff --git a/common/global_profiler/GlobalProfiler.cpp b/common/global_profiler/GlobalProfiler.cpp index 54b563da26..1a459dfd7c 100644 --- a/common/global_profiler/GlobalProfiler.cpp +++ b/common/global_profiler/GlobalProfiler.cpp @@ -24,6 +24,7 @@ u32 get_current_tid() { return (u32)GetCurrentThreadId(); } #endif +#include "common/log/log.h" // clang-format on u64 get_current_ts() { @@ -157,18 +158,17 @@ void GlobalProfiler::dump_to_json(const std::string& path) { // ts json_event["ts"] = (event.ts - lowest_ts) / 1000.f; if (event.ts < info.debug) { - fmt::print("out of order: {} {} {} ms\n", event.ts / 1000.f, info.debug / 1000.f, - (info.debug - event.ts) / 1000000.f); - fmt::print(" idx: {}, range {} {}\n", event_idx, info.lowest_at_target, - info.highest_at_target); - fmt::print(" now: {}\n", m_next_idx); + lg::debug("out of order: {} {} {} ms", event.ts / 1000.f, info.debug / 1000.f, + (info.debug - event.ts) / 1000000.f); + lg::debug(" idx: {}, range {} {}", event_idx, info.lowest_at_target, info.highest_at_target); + lg::debug(" now: {}", m_next_idx); } info.debug = event.ts; } for (auto& t : info_per_thread) { - fmt::print("thread: {}: {} -> {}\n", t.first, t.second.lowest_at_target, - t.second.highest_at_target); + lg::debug("thread: {}: {} -> {}", t.first, t.second.lowest_at_target, + t.second.highest_at_target); } file_util::write_text_file(path, json.dump()); diff --git a/common/goos/PrettyPrinter.cpp b/common/goos/PrettyPrinter.cpp index ee3c994c1c..0e25ec9115 100644 --- a/common/goos/PrettyPrinter.cpp +++ b/common/goos/PrettyPrinter.cpp @@ -13,7 +13,6 @@ #include "Reader.h" #include "common/goos/PrettyPrinter2.h" -#include "common/log/log.h" #include "common/util/Assert.h" #include "third-party/fmt/core.h" diff --git a/common/goos/Reader.cpp b/common/goos/Reader.cpp index 93fd976298..9934b71884 100644 --- a/common/goos/Reader.cpp +++ b/common/goos/Reader.cpp @@ -13,6 +13,7 @@ #include "ReplUtils.h" +#include "common/log/log.h" #include "common/util/FileUtil.h" #include "common/util/FontUtils.h" @@ -291,11 +292,16 @@ Object Reader::internal_read(std::shared_ptr text, ts.seek_past_whitespace_and_comments(); // read list! - auto objs = read_list(ts, false); - if (add_top_level) { - return PairObject::make_new(SymbolObject::make_new(symbolTable, "top-level"), objs); - } else { - return objs; + try { + auto objs = read_list(ts, false); + if (add_top_level) { + return PairObject::make_new(SymbolObject::make_new(symbolTable, "top-level"), objs); + } else { + return objs; + } + } catch (std::exception& e) { + lg::print("{}", e.what()); + throw e; } } diff --git a/common/log/log.cpp b/common/log/log.cpp index 2fd546fed1..b1904a117f 100644 --- a/common/log/log.cpp +++ b/common/log/log.cpp @@ -46,10 +46,14 @@ void log_message(level log_level, LogTime& now, const char* message) { auto now_milliseconds = now.tv.tv_usec / 1000; strftime(date_time_buffer, 128, "%Y-%m-%d %H:%M:%S", localtime(&now_seconds)); std::string date_string = fmt::format("[{}:{:03d}]", date_time_buffer, now_milliseconds); + strftime(date_time_buffer, 128, "%M:%S", localtime(&now_seconds)); + std::string time_condensed = fmt::format("[{}]:{:03d}]", date_time_buffer, now_milliseconds); #else char date_time_buffer[128]; strftime(date_time_buffer, 128, "%Y-%m-%d %H:%M:%S", localtime(&now.tim)); std::string date_string = fmt::format("[{}]", date_time_buffer); + strftime(date_time_buffer, 128, "%M:%S", localtime(&now.tim)); + std::string time_condensed = fmt::format("[{}]", date_time_buffer); #endif { @@ -65,11 +69,12 @@ void log_message(level log_level, LogTime& now, const char* message) { } if (log_level >= gLogger.stdout_log_level) { - fmt::print("{} [", date_string); + fmt::print("{} [", time_condensed); fmt::print(fg(log_colors[int(log_level)]), "{}", log_level_names[int(log_level)]); fmt::print("] {}\n", message); if (log_level >= gLogger.flush_level) { fflush(stdout); + fflush(stderr); } } } @@ -78,6 +83,26 @@ void log_message(level log_level, LogTime& now, const char* message) { exit(-1); } } + +void log_print(const char* message) { + { + // We always immediately flush prints because since it has no associated level + // it could be anything from a fatal error to a useless debug log. + std::lock_guard lock(gLogger.mutex); + if (gLogger.fp) { + // Log to File + std::string msg(message); + fwrite(msg.c_str(), msg.length(), 1, gLogger.fp); + fflush(gLogger.fp); + } + + if (gLogger.stdout_log_level < lg::level::off) { + fmt::print(message); + fflush(stdout); + fflush(stderr); + } + } +} } // namespace internal void set_file(const std::string& filename) { diff --git a/common/log/log.h b/common/log/log.h index b26d0dd230..34470f47a1 100644 --- a/common/log/log.h +++ b/common/log/log.h @@ -7,6 +7,7 @@ #endif #include +#include "third-party/fmt/color.h" #include "third-party/fmt/core.h" namespace lg { @@ -27,6 +28,7 @@ enum class level { trace = 0, debug = 1, info = 2, warn = 3, error = 4, die = 5, namespace internal { // log implementation stuff, not to be called by the user void log_message(level log_level, LogTime& now, const char* message); +void log_print(const char* message); } // namespace internal void set_file(const std::string& filename); @@ -49,6 +51,17 @@ void log(level log_level, const std::string& format, Args&&... args) { internal::log_message(log_level, now, formatted_message.c_str()); } +template +void print(const std::string& format, Args&&... args) { + std::string formatted_message = fmt::format(format, std::forward(args)...); + internal::log_print(formatted_message.c_str()); +} +template +void print(const fmt::text_style& ts, const std::string& format, Args&&... args) { + std::string formatted_message = fmt::format(ts, format, std::forward(args)...); + internal::log_print(formatted_message.c_str()); +} + template void trace(const std::string& format, Args&&... args) { log(level::trace, format, std::forward(args)...); diff --git a/common/serialization/subtitles/subtitles_ser.cpp b/common/serialization/subtitles/subtitles_ser.cpp index dd3d8a9256..36619a8bc2 100644 --- a/common/serialization/subtitles/subtitles_ser.cpp +++ b/common/serialization/subtitles/subtitles_ser.cpp @@ -389,7 +389,7 @@ void GameSubtitleGroups::hydrate_from_asset_file() { m_groups[key] = val.get>(); } } catch (std::exception& ex) { - fmt::print("Bad subtitle group entry - {} - {}", key, ex.what()); + lg::print("Bad subtitle group entry - {} - {}", key, ex.what()); } } } diff --git a/common/type_system/Type.cpp b/common/type_system/Type.cpp index e816b86343..7dbd35e74d 100644 --- a/common/type_system/Type.cpp +++ b/common/type_system/Type.cpp @@ -7,6 +7,7 @@ #include +#include "common/log/log.h" #include "common/util/Assert.h" #include "third-party/fmt/core.h" @@ -196,8 +197,8 @@ std::string Type::get_name() const { std::string Type::get_runtime_name() const { if (!m_allow_in_runtime) { - fmt::print("[TypeSystem] Tried to use type {} as a runtime type, which is not allowed.\n", - get_name()); + lg::print("[TypeSystem] Tried to use type {} as a runtime type, which is not allowed.\n", + get_name()); throw std::runtime_error("get_runtime_name"); } return m_runtime_name; diff --git a/common/type_system/TypeFieldLookup.cpp b/common/type_system/TypeFieldLookup.cpp index 5b690d75de..06eea7e2bd 100644 --- a/common/type_system/TypeFieldLookup.cpp +++ b/common/type_system/TypeFieldLookup.cpp @@ -7,6 +7,8 @@ #include "TypeSystem.h" +#include "common/log/log.h" + #include "third-party/fmt/core.h" namespace { @@ -452,8 +454,8 @@ void try_reverse_lookup(const FieldReverseLookupInput& input, FieldReverseMultiLookupOutput* output, int max_count) { if (debug_reverse_lookup) { - fmt::print(" try_reverse_lookup on {} offset {} deref {} stride {}\n", input.base_type.print(), - input.offset, input.deref.has_value(), input.stride); + lg::debug(" try_reverse_lookup on {} offset {} deref {} stride {}", input.base_type.print(), + input.offset, input.deref.has_value(), input.stride); } auto base_input_type = input.base_type.base_type(); @@ -484,15 +486,15 @@ FieldReverseLookupOutput TypeSystem::reverse_field_lookup( /* if (multi_result.results.size() > 1) { - fmt::print("Multiple:\n"); + lg::print("Multiple:\n"); for (auto& result : multi_result.results) { - fmt::print(" [{}] [{}] ", result.total_score, result.result_type.print()); + lg::print(" [{}] [{}] ", result.total_score, result.result_type.print()); for (auto& tok : result.tokens) { - fmt::print("{} ", tok.print()); + lg::print("{} ", tok.print()); } - fmt::print("\n"); + lg::print("\n"); } - fmt::print("\n\n\n"); + lg::print("\n\n\n"); } */ @@ -510,8 +512,8 @@ FieldReverseMultiLookupOutput TypeSystem::reverse_field_multi_lookup( const FieldReverseLookupInput& input, int max_count) const { if (debug_reverse_lookup) { - fmt::print("reverse_field_lookup on {} offset {} deref {} stride {}\n", input.base_type.print(), - input.offset, input.deref.has_value(), input.stride); + lg::debug("reverse_field_lookup on {} offset {} deref {} stride {}", input.base_type.print(), + input.offset, input.deref.has_value(), input.stride); } FieldReverseMultiLookupOutput result; diff --git a/common/type_system/TypeSystem.cpp b/common/type_system/TypeSystem.cpp index 4490649ff7..a4baa95ab8 100644 --- a/common/type_system/TypeSystem.cpp +++ b/common/type_system/TypeSystem.cpp @@ -9,6 +9,7 @@ #include +#include "common/log/log.h" #include "common/util/Assert.h" #include "common/util/math_util.h" @@ -18,11 +19,11 @@ namespace { template [[noreturn]] void throw_typesystem_error(const std::string& str, Args&&... args) { - fmt::print(fg(fmt::color::crimson) | fmt::emphasis::bold, "-- Type Error! --\n"); + lg::print(fg(fmt::color::crimson) | fmt::emphasis::bold, "-- Type Error! --\n"); if (!str.empty() && str.back() == '\n') { - fmt::print(fg(fmt::color::yellow), str, std::forward(args)...); + lg::print(fg(fmt::color::yellow), str, std::forward(args)...); } else { - fmt::print(fg(fmt::color::yellow), str + '\n', std::forward(args)...); + lg::print(fg(fmt::color::yellow), str + '\n', std::forward(args)...); } throw std::runtime_error( @@ -63,8 +64,8 @@ Type* TypeSystem::add_type(const std::string& name, std::unique_ptr type) if (m_allow_redefinition || std::find(m_types_allowed_to_be_redefined.begin(), m_types_allowed_to_be_redefined.end(), kv->second->get_name()) != m_types_allowed_to_be_redefined.end()) { - fmt::print("[TypeSystem] Type {} was originally\n{}\nand is redefined as\n{}\n", - kv->second->get_name(), kv->second->print(), type->print()); + lg::print("[TypeSystem] Type {} was originally\n{}\nand is redefined as\n{}\n", + kv->second->get_name(), kv->second->print(), type->print()); // extra dangerous, we have allowed type redefinition! // keep the unique_ptr around, just in case somebody references this old type pointer. @@ -1530,11 +1531,11 @@ bool TypeSystem::typecheck_and_throw(const TypeSpec& expected, if (!success) { if (print_on_error) { if (error_source_name.empty()) { - fmt::print("[TypeSystem] Got type \"{}\" when expecting \"{}\"\n", actual.print(), - expected.print()); + lg::print("[TypeSystem] Got type \"{}\" when expecting \"{}\"\n", actual.print(), + expected.print()); } else { - fmt::print("[TypeSystem] For {}, got type \"{}\" when expecting \"{}\"\n", - error_source_name, actual.print(), expected.print()); + lg::print("[TypeSystem] For {}, got type \"{}\" when expecting \"{}\"\n", error_source_name, + actual.print(), expected.print()); } } diff --git a/common/type_system/deftype.cpp b/common/type_system/deftype.cpp index b5f8cea431..b8467530ec 100644 --- a/common/type_system/deftype.cpp +++ b/common/type_system/deftype.cpp @@ -7,6 +7,7 @@ #include "deftype.h" #include "common/goos/ParseHelpers.h" +#include "common/log/log.h" #include "third-party/fmt/core.h" @@ -402,7 +403,7 @@ StructureDefResult parse_structure_def( fmt::format("Process heap underflow in type {}: heap-base is {} vs. auto-detected {}", type->get_name(), flags.heap_base, auto_hb)); //} else if (flags.heap_base != auto_hb) { - // fmt::print("Type {} has manual heap-base ({} vs {}). This is fine. \n", type->get_name(), + // lg::print("Type {} has manual heap-base ({} vs {}). This is fine. \n", type->get_name(), // flags.heap_base, auto_hb); } } @@ -623,14 +624,14 @@ DeftypeResult parse_deftype(const goos::Object& deftype, new_type->set_pack(true); } if (sr.allow_misaligned) { - fmt::print( + lg::print( "[TypeSystem] :allow-misaligned was set on {}, which is a basic and cannot " "be misaligned\n", name); throw std::runtime_error("invalid pack option on basic"); } if (sr.always_stack_singleton) { - fmt::print( + lg::print( "[TypeSystem] :always-stack-singleton was set on {}, which is a basic and cannot " "be a stack singleton\n", name); diff --git a/common/util/Assert.cpp b/common/util/Assert.cpp index 9844d97839..be4e88288c 100644 --- a/common/util/Assert.cpp +++ b/common/util/Assert.cpp @@ -6,20 +6,23 @@ #include #include +#include "common/log/log.h" + void private_assert_failed(const char* expr, const char* file, int line, const char* function, const char* msg) { if (!msg || msg[0] == '\0') { - fprintf(stderr, "Assertion failed: '%s'\n\tSource: %s:%d\n\tFunction: %s\n", expr, file, line, - function); + std::string log = fmt::format("Assertion failed: '{}'\n\tSource: {}:{}\n\tFunction: {}\n", expr, + file, line, function); + lg::die(log); } else { - fprintf(stderr, "Assertion failed: '%s'\n\tMessage: %s\n\tSource: %s:%d\n\tFunction: %s\n", - expr, msg, file, line, function); + std::string log = + fmt::format("Assertion failed: '{}'\n\tMessage: {}\n\tSource: {}:{}\n\tFunction: {}\n", + expr, msg, file, line, function); + lg::die(log); } - fflush(stdout); // ensure any stdout logs are flushed before we terminate - fflush(stderr); abort(); } diff --git a/common/util/FileUtil.cpp b/common/util/FileUtil.cpp index 0234383710..b9f2835039 100644 --- a/common/util/FileUtil.cpp +++ b/common/util/FileUtil.cpp @@ -139,7 +139,7 @@ bool setup_project_path(std::optional project_path_override) { if (project_path_override) { gFilePathInfo.path_to_data = *project_path_override; gFilePathInfo.initialized = true; - fmt::print("Using explicitly set project path: {}\n", project_path_override->string()); + lg::info("Using explicitly set project path: {}", project_path_override->string()); return true; } @@ -147,7 +147,7 @@ bool setup_project_path(std::optional project_path_override) { if (data_path) { gFilePathInfo.path_to_data = *data_path; gFilePathInfo.initialized = true; - fmt::print("Using data path: {}\n", data_path->string()); + lg::info("Using data path: {}", data_path->string()); return true; } @@ -155,11 +155,11 @@ bool setup_project_path(std::optional project_path_override) { if (development_repo_path) { gFilePathInfo.path_to_data = *development_repo_path; gFilePathInfo.initialized = true; - fmt::print("Using development repo path: {}\n", *development_repo_path); + lg::info("Using development repo path: {}", *development_repo_path); return true; } - fmt::print("Failed to initialize project path.\n"); + lg::error("Failed to initialize project path."); return false; } diff --git a/decompiler/Function/CfgVtx.cpp b/decompiler/Function/CfgVtx.cpp index e70be31832..9da41edfd6 100644 --- a/decompiler/Function/CfgVtx.cpp +++ b/decompiler/Function/CfgVtx.cpp @@ -3,6 +3,7 @@ #include "Function.h" #include "common/goos/PrettyPrinter.h" +#include "common/log/log.h" #include "common/symbols.h" #include "common/util/Assert.h" @@ -496,12 +497,12 @@ bool ControlFlowGraph::is_while_loop(CfgVtx* b0, CfgVtx* b1, CfgVtx* b2) { bool debug = b0->to_string() == "Seq CONDNE104 ... Block 18100"; if (debug) { - fmt::print("try while: {} | {} | {}\n", b0->to_string(), b1->to_string(), b2->to_string()); + lg::debug("try while: {} | {} | {}", b0->to_string(), b1->to_string(), b2->to_string()); } if (b0->end_branch.asm_branch || b1->end_branch.asm_branch) { if (debug) - fmt::print("reject 1 {} {}\n", b0->end_branch.asm_branch, b1->end_branch.asm_branch); + lg::debug("reject 1 {} {}", b0->end_branch.asm_branch, b1->end_branch.asm_branch); return false; } @@ -532,17 +533,17 @@ bool ControlFlowGraph::is_while_loop(CfgVtx* b0, CfgVtx* b1, CfgVtx* b2) { return false; ASSERT(!b1->end_branch.has_branch); if (!b2->has_pred(b0)) { - printf("expect b2 (%s) to have pred b0 (%s)\n", b2->to_string().c_str(), - b0->to_string().c_str()); - printf("but it doesn't! instead it has:\n"); + lg::debug("expect b2 ({}) to have pred b0 ({})", b2->to_string().c_str(), + b0->to_string().c_str()); + lg::debug("but it doesn't! instead it has:"); for (auto* x : b2->pred) { - printf(" %s\n", x->to_string().c_str()); + lg::debug(" {}", x->to_string().c_str()); } if (b0->succ_ft) { - printf("b0's succ_ft: %s\n", b0->succ_ft->to_string().c_str()); + lg::debug("b0's succ_ft: {}", b0->succ_ft->to_string().c_str()); } if (b0->succ_branch) { - printf("b0's succ_branch: %s\n", b0->succ_branch->to_string().c_str()); + lg::debug("b0's succ_branch: {}", b0->succ_branch->to_string().c_str()); } } ASSERT(b2->has_pred(b0)); @@ -583,12 +584,9 @@ bool ControlFlowGraph::is_until_loop(CfgVtx* b1, CfgVtx* b2) { return false; ASSERT(!b1->end_branch.has_branch); - if (!b2->has_pred(b1)) { - fmt::print("Graph error {} (s {}) should have pred {} (s {})\n", b2->to_string(), - b2->get_first_block_id(), b1->to_string(), b1->get_first_block_id()); - } - - ASSERT(b2->has_pred(b1)); + ASSERT_MSG(b2->has_pred(b1), + fmt::format("Graph error {} (s {}) should have pred {} (s {})\n", b2->to_string(), + b2->get_first_block_id(), b1->to_string(), b1->get_first_block_id())); if (b2->pred.size() != 1) return false; @@ -938,8 +936,6 @@ bool ControlFlowGraph::find_infinite_continue() { int my_block = b0->get_first_block_id(); int dest_block = b0->succ_branch->get_first_block_id(); - // fmt::print("Considering {} as an infinite continue:\n", b0->to_string()); - if (b0->end_branch.asm_branch) { return true; } @@ -1155,8 +1151,8 @@ bool ControlFlowGraph::clean_up_asm_branches() { } if (debug_asm_branch) { - fmt::print("Looks like asm likely branch: {} {} to {}\n", b0->to_string(), bds->to_string(), - b1->to_string()); + lg::debug("Looks like asm likely branch: {} {} to {}", b0->to_string(), bds->to_string(), + b1->to_string()); } auto* b0_seq = dynamic_cast(b0); @@ -1174,7 +1170,7 @@ bool ControlFlowGraph::clean_up_asm_branches() { for (auto* new_pred : b0->pred) { if (debug_asm_branch) { - fmt::print(" pred {}\n", new_pred->to_string()); + lg::debug(" pred {}", new_pred->to_string()); } new_pred->replace_succ_and_check(b0, new_seq); } @@ -1294,19 +1290,19 @@ bool ControlFlowGraph::clean_up_asm_branches() { else { lg::error("unhandled sequences in clean_up_asm_branches likely seq: {} {}", !!b0_seq, !!b1_seq); - lg::error("{} {}\n", b0->get_first_block_id(), b1->get_first_block_id()); + lg::error("{} {}", b0->get_first_block_id(), b1->get_first_block_id()); } } else { if (debug_asm_branch) { - fmt::print("Looks like asm normal branch: {} to {}\n", b0->to_string(), b1->to_string()); + lg::debug("Looks like asm normal branch: {} to {}", b0->to_string(), b1->to_string()); } auto* b0_seq = dynamic_cast(b0); auto* b1_seq = dynamic_cast(b1); if (!b0_seq && !b1_seq) { if (debug_asm_branch) { - fmt::print("[combo nn] {} and {}\n", b0->get_first_block_id(), b1->get_first_block_id()); + lg::debug("[combo nn] {} and {}", b0->get_first_block_id(), b1->get_first_block_id()); } // build new sequence replaced = true; @@ -1330,19 +1326,19 @@ bool ControlFlowGraph::clean_up_asm_branches() { for (auto* new_succ : b1->succs()) { if (debug_asm_branch) { - fmt::print("changing {}'s pred {} to seq. bc: {}", new_succ->to_string(), - b1->to_string(), new_succ->pred.size()); + lg::debug("changing {}'s pred {} to seq. bc: {}", new_succ->to_string(), + b1->to_string(), new_succ->pred.size()); } new_succ->replace_pred_and_check(b1, new_seq); if (debug_asm_branch) { - fmt::print(" ac: {}\n", new_succ->pred.size()); + lg::debug(" ac: {}", new_succ->pred.size()); } } new_seq->succ_ft = b1->succ_ft; if (b1->succ_branch && debug_asm_branch) { - fmt::print("combining {} and {} into a sequence, succ {}\n", b0->get_first_block_id(), - b1->get_first_block_id(), b1->succ_branch->get_first_block_id()); + lg::debug("combining {} and {} into a sequence, succ {}", b0->get_first_block_id(), + b1->get_first_block_id(), b1->succ_branch->get_first_block_id()); } new_seq->succ_branch = b1->succ_branch; @@ -1367,13 +1363,13 @@ bool ControlFlowGraph::clean_up_asm_branches() { return false; } else if (b0_seq && !b1_seq) { if (debug_asm_branch) { - fmt::print("[combo sn] {} and {}\n", b0->get_first_block_id(), b1->get_first_block_id()); - fmt::print("expanding sequence: {} (s {}) to include {}\n", b0_seq->to_string(), - b0_seq->get_first_block_id(), b1->get_first_block_id()); + lg::debug("[combo sn] {} and {}", b0->get_first_block_id(), b1->get_first_block_id()); + lg::debug("expanding sequence: {} (s {}) to include {}", b0_seq->to_string(), + b0_seq->get_first_block_id(), b1->get_first_block_id()); } if (b1->succ_ft) { if (debug_asm_branch) { - fmt::print(" b1 succ_ft is {}\n", b1->succ_ft->to_string()); + lg::debug(" b1 succ_ft is {}", b1->succ_ft->to_string()); } ASSERT(b1->succ_ft->has_pred(b1)); } @@ -1386,18 +1382,18 @@ bool ControlFlowGraph::clean_up_asm_branches() { if (b0->succ_branch) { if (debug_asm_branch) { - fmt::print("succ {} has {} preds parent: {}\n", b0->succ_branch->get_first_block_id(), - b0->succ_branch->pred.size(), !!b0->succ_branch->parent); + lg::debug("succ {} has {} preds parent: {}", b0->succ_branch->get_first_block_id(), + b0->succ_branch->pred.size(), !!b0->succ_branch->parent); } b0->succ_branch->replace_preds_with_and_check({b0}, nullptr); if (debug_asm_branch) { - fmt::print("OKOK\n"); + lg::debug("OKOK"); } } for (auto* new_succ : b1->succs()) { if (debug_asm_branch) { - fmt::print("fixing up succ {}\n", new_succ->to_string()); + lg::debug("fixing up succ {}", new_succ->to_string()); } new_succ->replace_pred_and_check(b1, b0); } @@ -1419,7 +1415,7 @@ bool ControlFlowGraph::clean_up_asm_branches() { } if (seq->succ_branch && debug_asm_branch) { - fmt::print(" new sb: {}\n", seq->succ_branch->get_first_block_id()); + lg::debug(" new sb: {}", seq->succ_branch->get_first_block_id()); } seq->next = b1->next; if (seq->next) { @@ -1434,8 +1430,8 @@ bool ControlFlowGraph::clean_up_asm_branches() { return false; } else if (b0_seq && b1_seq) { if (debug_asm_branch) { - fmt::print("[combo ss] {} and {}\n", b0->get_first_block_id(), b1->get_first_block_id()); - fmt::print(" {} and {}\n", b0->to_string(), b1->to_string()); + lg::debug("[combo ss] {} and {}", b0->get_first_block_id(), b1->get_first_block_id()); + lg::debug(" {} and {}", b0->to_string(), b1->to_string()); } // printf("make seq type 3 %s %s\n", b0->to_string().c_str(), b1->to_string().c_str()); @@ -1449,8 +1445,8 @@ bool ControlFlowGraph::clean_up_asm_branches() { if (b0->succ_branch) { if (debug_asm_branch) { - fmt::print(" sbp: {}\n", !!b0->succ_branch->parent); - fmt::print(" sb: {}\n", b0->succ_branch->to_string()); + lg::debug(" sbp: {}", !!b0->succ_branch->parent); + lg::debug(" sb: {}", b0->succ_branch->to_string()); } b0->succ_branch->replace_preds_with_and_check({b0}, nullptr); } @@ -1467,7 +1463,7 @@ bool ControlFlowGraph::clean_up_asm_branches() { seq->succ_branch = old_seq->succ_branch; seq->succ_branch = b1->succ_branch; if (seq->succ_branch && debug_asm_branch) { - fmt::print(" DS new sb: {}\n", seq->succ_branch->get_first_block_id()); + lg::debug(" DS new sb: {}", seq->succ_branch->get_first_block_id()); } seq->succ_ft = old_seq->succ_ft; seq->end_branch = old_seq->end_branch; @@ -1483,15 +1479,15 @@ bool ControlFlowGraph::clean_up_asm_branches() { } else if (!b0_seq && b1_seq) { replaced = true; if (!b0->succ_branch) { - fmt::print("bad: {}\n", b0->to_string()); + lg::debug("bad: {}", b0->to_string()); } m_blocks.at(b0->succ_branch->get_first_block_id())->needs_label = true; auto* old_seq = dynamic_cast(b1); ASSERT(old_seq); if (b0->succ_branch) { if (debug_asm_branch) { - fmt::print(" sbp: {}\n", !!b0->succ_branch->parent); - fmt::print(" sb: {}\n", b0->succ_branch->to_string()); + lg::debug(" sbp: {}", !!b0->succ_branch->parent); + lg::debug(" sb: {}", b0->succ_branch->to_string()); } b0->succ_branch->replace_preds_with_and_check({b0}, nullptr); } @@ -2318,18 +2314,18 @@ bool ControlFlowGraph::find_short_circuits() { ShortCircuit::Entry candidate = {vtx, vtx->next}; CfgVtx* end = vtx->next->succ_branch; - // fmt::print("Starting loop\n"); + // lg::print("Starting loop\n"); while (true) { // check candidate: if (!candidate.condition || !candidate.likely_delay || !end) { - // fmt::print("reject begin {} {} {}\n", !!candidate.condition, + // lg::print("reject begin {} {} {}\n", !!candidate.condition, // !!candidate.likely_delay, // !!end); return true; } - // fmt::print(" try {} and {} end {}\n", candidate.condition->to_string(), + // lg::print(" try {} and {} end {}\n", candidate.condition->to_string(), // candidate.likely_delay->to_string(), end->to_string()); if (candidate.condition->next == end) { @@ -2341,13 +2337,13 @@ bool ControlFlowGraph::find_short_circuits() { candidate.likely_delay = nullptr; entries.push_back(candidate); - // fmt::print("all done!"); + // lg::print("all done!"); break; } } if (!candidate.condition->next || !candidate.condition->succ_branch) { - // fmt::print(" fail 0 {}, {}\n", !!candidate.condition->next, + // lg::print(" fail 0 {}, {}\n", !!candidate.condition->next, // !!candidate.condition->succ_branch); return true; } @@ -2357,12 +2353,12 @@ bool ControlFlowGraph::find_short_circuits() { candidate.condition->next != candidate.condition->succ_branch || !candidate.condition->end_branch.branch_likely || candidate.condition->end_branch.kind != CfgVtx::DelaySlotKind::NO_DELAY) { - // fmt::print(" fail 1 {} {} {} {}\n", !candidate.condition->next, + // lg::print(" fail 1 {} {} {} {}\n", !candidate.condition->next, // candidate.condition->next != candidate.condition->succ_branch, // !candidate.condition->end_branch.branch_likely, // candidate.condition->end_branch.kind != // CfgVtx::DelaySlotKind::NO_DELAY); - // fmt::print(" fail 1 condition->next {}, condition->succ_branch {}\n", + // lg::print(" fail 1 condition->next {}, condition->succ_branch {}\n", // candidate.condition->next->to_string(), // candidate.condition->succ_branch->to_string()); return true; @@ -2371,7 +2367,7 @@ bool ControlFlowGraph::find_short_circuits() { if (entries.empty() && candidate.likely_delay->next == end) { entries.push_back(candidate); - // fmt::print("all don2!"); + // lg::print("all don2!"); break; } @@ -2380,7 +2376,7 @@ bool ControlFlowGraph::find_short_circuits() { !candidate.likely_delay->end_branch.branch_always || candidate.likely_delay->end_branch.branch_likely || candidate.likely_delay->end_branch.kind != CfgVtx::DelaySlotKind::NO_DELAY) { - // fmt::print(" fail 2 {} {} {} {} {} {} {}\n", candidate.likely_delay->pred.size() + // lg::print(" fail 2 {} {} {} {} {} {} {}\n", candidate.likely_delay->pred.size() // != 1, // !!candidate.likely_delay->succ_ft, // !candidate.likely_delay->succ_branch, @@ -2389,21 +2385,21 @@ bool ControlFlowGraph::find_short_circuits() { // !!candidate.likely_delay->end_branch.branch_likely, // candidate.likely_delay->end_branch.kind != // CfgVtx::DelaySlotKind::NO_DELAY); - // fmt::print("delay {} has ft {}\n", candidate.likely_delay->to_string(), + // lg::print("delay {} has ft {}\n", candidate.likely_delay->to_string(), // candidate.likely_delay->succ_ft->to_string()); return true; } // slot -> end if (candidate.likely_delay->succ_branch != end) { - // fmt::print(" fail 3\n"); + // lg::print(" fail 3\n"); return true; } // root -> next root if (!candidate.condition->next->next || candidate.condition->next->next != candidate.condition->succ_ft) { - // fmt::print(" fail 4\n"); + // lg::print(" fail 4\n"); return true; } @@ -2415,10 +2411,10 @@ bool ControlFlowGraph::find_short_circuits() { // pre next root check if (next_root->pred.size() != 1) { - // fmt::print(" fail 5\n"); + // lg::print(" fail 5\n"); return true; } - // fmt::print("on to next!\n"); + // lg::print("on to next!\n"); } auto new_sc = alloc(); @@ -2618,7 +2614,7 @@ std::shared_ptr build_cfg(const LinkedObjectFile& file, const CondWithElseLengthHack& cond_with_else_hack, const std::unordered_set& blocks_ending_in_asm_br, GameVersion version) { - // fmt::print("START {}\n", func.guessed_name.to_string()); + // lg::print("START {}\n", func.guessed_name.to_string()); auto cfg = std::make_shared(); const auto& blocks = cfg->create_blocks(func.basic_blocks.size()); @@ -2769,7 +2765,7 @@ std::shared_ptr build_cfg(const LinkedObjectFile& file, if (blocks_ending_in_asm_br.find(i) != blocks_ending_in_asm_br.end()) { b->end_branch.asm_branch = true; if (debug_asm_branch) { - fmt::print("OVERRIDE asm branch at block {}\n", i); + lg::debug("OVERRIDE asm branch at block {}", i); } continue; } @@ -2785,9 +2781,8 @@ std::shared_ptr build_cfg(const LinkedObjectFile& file, if (branch_delay_asm(following, version)) { b->end_branch.asm_branch = true; if (debug_asm_branch) { - fmt::print("LIKELY ASM BRANCH: {} and {}\n", - likely_branch_candidate.to_string(file.labels), - following.to_string(file.labels)); + lg::debug("LIKELY ASM BRANCH: {} and {}", likely_branch_candidate.to_string(file.labels), + following.to_string(file.labels)); } } } @@ -2801,8 +2796,8 @@ std::shared_ptr build_cfg(const LinkedObjectFile& file, if (branch_delay_asm(delay_slot_candidate, version)) { b->end_branch.asm_branch = true; if (debug_asm_branch) { - fmt::print("NORMAL ASM BRANCH: {} and {}\n", branch_candidate.to_string(file.labels), - delay_slot_candidate.to_string(file.labels)); + lg::debug("NORMAL ASM BRANCH: {} and {}", branch_candidate.to_string(file.labels), + delay_slot_candidate.to_string(file.labels)); } } } diff --git a/decompiler/Function/Function.cpp b/decompiler/Function/Function.cpp index 7dc33c21af..c64c9546f3 100644 --- a/decompiler/Function/Function.cpp +++ b/decompiler/Function/Function.cpp @@ -658,7 +658,7 @@ void Function::find_type_defs(LinkedObjectFile& file, DecompilerTypeSystem& dts) if (instr.kind == InstructionKind::SLL && instr.get_dst(0).get_reg() == make_gpr(Reg::V0) && instr.get_src(0).get_reg() == make_gpr(Reg::RA) && instr.get_src(1).get_imm() == 0) { // done! - // fmt::print("Got type {} parent {}\n", type_name, parent_type); + // lg::print("Got type {} parent {}\n", type_name, parent_type); dts.add_type_parent(type_name, parent_type); DecompilerLabel flag_label = file.labels.at(label_idx); u64 word = file.read_data_word(flag_label); @@ -667,7 +667,7 @@ void Function::find_type_defs(LinkedObjectFile& file, DecompilerTypeSystem& dts) word |= (word2 << 32); types_defined.push_back(type_name); dts.add_type_flags(type_name, word); - // fmt::print("Flags are 0x{:x}\n", word); + // lg::print("Flags are 0x{:x}\n", word); state = 0; continue; } diff --git a/decompiler/IR2/AtomicOpForm.cpp b/decompiler/IR2/AtomicOpForm.cpp index c4e1e6f364..a022f968d8 100644 --- a/decompiler/IR2/AtomicOpForm.cpp +++ b/decompiler/IR2/AtomicOpForm.cpp @@ -119,14 +119,14 @@ FormElement* SetVarOp::get_as_form(FormPool& pool, const Env& env) const { menv->disable_use(src_var); } - // fmt::print("marked {} as dead set\n", to_string(env)); + // lg::print("marked {} as dead set\n", to_string(env)); } } else if (m_src.get_arg(0).is_sym_val() && m_src.get_arg(0).get_str() == "#f" && m_dst.reg().allowed_local_gpr()) { auto& ri = env.reg_use().op.at(m_my_idx); if (ri.written_and_unused.find(dst().reg()) != ri.written_and_unused.end()) { result->mark_as_dead_false(); - // fmt::print("marked {} as dead set false\n", to_string(env)); + // lg::print("marked {} as dead set false\n", to_string(env)); } } } diff --git a/decompiler/IR2/AtomicOpTypeAnalysis.cpp b/decompiler/IR2/AtomicOpTypeAnalysis.cpp index 8584821a56..01a46fd86a 100644 --- a/decompiler/IR2/AtomicOpTypeAnalysis.cpp +++ b/decompiler/IR2/AtomicOpTypeAnalysis.cpp @@ -314,7 +314,7 @@ TP_Type get_stack_type_at_constant_offset(int offset, auto rd = dts.ts.reverse_field_lookup(rd_in); if (rd.success) { auto result = TP_Type::make_from_ts(coerce_to_reg_type(rd.result_type)); - fmt::print("Matched a stack variable! {}\n", result.print()); + lg::print("Matched a stack variable! {}\n", result.print()); return result; } */ diff --git a/decompiler/IR2/Env.cpp b/decompiler/IR2/Env.cpp index a8efa145a1..858ea36405 100644 --- a/decompiler/IR2/Env.cpp +++ b/decompiler/IR2/Env.cpp @@ -7,6 +7,7 @@ #include "Form.h" #include "common/goos/PrettyPrinter.h" +#include "common/log/log.h" #include "common/util/math_util.h" #include "decompiler/analysis/atomic_op_builder.h" @@ -175,7 +176,7 @@ VariableWithCast Env::get_variable_and_cast(const RegisterAccess& access) const // note - this may be stricter than needed. but that's ok. if (type_of_var != type_of_reg) { - // fmt::print("casting {} (reg {}, idx {}): reg type {} var type {} remapped var + // lg::print("casting {} (reg {}, idx {}): reg type {} var type {} remapped var // type // {}\n ", // lookup_name, reg.to_charp(), atomic_idx, type_of_reg.print(), @@ -190,7 +191,7 @@ VariableWithCast Env::get_variable_and_cast(const RegisterAccess& access) const // let's leave this to set!'s for now. This is tricky with stuff like (if y x) where the // move is eliminated so the RegisterAccess points to the "wrong" place. // if (!dts->ts.tc(type_of_var, type_of_reg)) { - // fmt::print("op {} reg {} type {}\n", atomic_idx, reg.to_charp(), + // lg::print("op {} reg {} type {}\n", atomic_idx, reg.to_charp(), // get_types_for_op_mode(atomic_idx, mode).get(reg).print()); return // pretty_print::build_list("the-as", type_of_reg.print(), lookup_name); // } diff --git a/decompiler/IR2/ExpressionHelpers.cpp b/decompiler/IR2/ExpressionHelpers.cpp index e907f14378..0c58d2264f 100644 --- a/decompiler/IR2/ExpressionHelpers.cpp +++ b/decompiler/IR2/ExpressionHelpers.cpp @@ -1,6 +1,7 @@ #include "ExpressionHelpers.h" #include "common/goal_constants.h" +#include "common/log/log.h" #include "decompiler/IR2/Env.h" #include "decompiler/IR2/Form.h" @@ -44,14 +45,14 @@ FormElement* handle_get_property_value_float(const std::vector& forms, // get the mode. It must be interp. auto mode_atom = form_as_atom(forms.at(2)); if (!mode_atom || !mode_atom->is_sym_ptr("interp")) { - fmt::print("fail: bad mode {}\n", forms.at(2)->to_string(env)); + lg::error("fail: bad mode {}", forms.at(2)->to_string(env)); return nullptr; } // get the time. It must be DEFAULT_RES_TIME auto lookup_time = try_get_const_float(forms.at(3)); if (!lookup_time || *lookup_time != DEFAULT_RES_TIME) { - fmt::print("fail: bad time {}\n", forms.at(3)->to_string(env)); + lg::error("fail: bad time {}\n", forms.at(3)->to_string(env)); return nullptr; } @@ -119,7 +120,7 @@ FormElement* handle_get_property_data_or_structure(const std::vector& for // get the mode. It must be interp. auto mode_atom = form_as_atom(forms.at(2)); if (!mode_atom || !mode_atom->is_sym_ptr("interp")) { - fmt::print("fail data: bad mode {}\n", forms.at(2)->to_string(env)); + lg::error("fail data: bad mode {}", forms.at(2)->to_string(env)); return nullptr; } @@ -134,7 +135,7 @@ FormElement* handle_get_property_data_or_structure(const std::vector& for Form* default_value = forms.at(4); // but let's see if it's 0, because that's the default in the macro if (default_value->to_string(env) != expcted_default) { - fmt::print("fail data: bad default {}\n", default_value->to_string(env)); + lg::error("fail data: bad default {}", default_value->to_string(env)); return nullptr; } @@ -184,7 +185,7 @@ FormElement* handle_get_property_value(const std::vector& forms, // get the mode. It must be interp. auto mode_atom = form_as_atom(forms.at(2)); if (!mode_atom || !mode_atom->is_sym_ptr("interp")) { - fmt::print("fail data: bad mode {}\n", forms.at(2)->to_string(env)); + lg::error("fail data: bad mode {}", forms.at(2)->to_string(env)); return nullptr; } @@ -318,7 +319,7 @@ FormElement* last_two_in_and_to_handle_get_proc(Form* first, } // auto first_use_of_in = *first_result.maps.regs.at(reg_input_1); - // fmt::print("reg1: {}\n", first_use_of_in.to_string(env)); + // lg::print("reg1: {}\n", first_use_of_in.to_string(env)); auto setup_matcher = Matcher::set_var( Matcher::deref(Matcher::any_reg(reg_input_2), false, @@ -368,22 +369,22 @@ FormElement* last_two_in_and_to_handle_get_proc(Form* first, const auto& temp_use_def = env.get_use_def_info(*second_result.maps.regs.at(reg_temp_1)); if (temp_use_def.use_count() != 2 || temp_use_def.def_count() != 1) { - fmt::print("failed usedef: {} {}\n", temp_use_def.use_count(), temp_use_def.def_count()); + lg::error("failed usedef: {} {}", temp_use_def.use_count(), temp_use_def.def_count()); return nullptr; } if (part_of_longer_sc) { // check that our temporary name matches (it's the var used inside the macro) if (in_name != longer_sc_var.to_string(env)) { - fmt::print("failed var name: {} vs {}\n", temp_name, longer_sc_var.to_string(env)); + lg::error("failed var name: {} vs {}", temp_name, longer_sc_var.to_string(env)); return nullptr; } // check that our temporary has the right usage pattern. const auto& outer_temp_usedef = env.get_use_def_info(longer_sc_var); if (outer_temp_usedef.use_count() != 3 || outer_temp_usedef.def_count() != 1) { - fmt::print("failed usedef2: {} {}\n", outer_temp_usedef.use_count(), - outer_temp_usedef.def_count()); + lg::error("failed usedef2: {} {}", outer_temp_usedef.use_count(), + outer_temp_usedef.def_count()); return nullptr; } @@ -400,7 +401,7 @@ FormElement* last_two_in_and_to_handle_get_proc(Form* first, menv->disable_use(in3); auto repopped = stack.pop_reg(in1, {}, env, true); - // fmt::print("repopped: {}\n", repopped->to_string(env)); + // lg::print("repopped: {}\n", repopped->to_string(env)); if (!repopped) { repopped = var_to_form(in1, pool); @@ -414,4 +415,4 @@ FormElement* last_two_in_and_to_handle_get_proc(Form* first, cast_type_for_result, pool); } } -} // namespace decompiler \ No newline at end of file +} // namespace decompiler diff --git a/decompiler/IR2/FormExpressionAnalysis.cpp b/decompiler/IR2/FormExpressionAnalysis.cpp index d57b651fb9..39e011fb15 100644 --- a/decompiler/IR2/FormExpressionAnalysis.cpp +++ b/decompiler/IR2/FormExpressionAnalysis.cpp @@ -3,6 +3,7 @@ #include "GenericElementMatcher.h" #include "common/goos/PrettyPrinter.h" +#include "common/log/log.h" #include "common/type_system/state.h" #include "common/util/Assert.h" #include "common/util/BitUtils.h" @@ -402,7 +403,7 @@ void pop_helper(const std::vector& vars, submit_regs.push_back(var.reg()); } else { // auto var_id = env.get_program_var_id(var); - // fmt::print( + // lg::print( // "Unsafe to pop {}: used {} times, def {} times, expected use {} ({} {} rd: // {}) ({} " // "{})\n", @@ -413,7 +414,7 @@ void pop_helper(const std::vector& vars, // if (var.to_string(env) == "a3-0") { // for (auto& use : use_def.uses) { // if (!use.disabled) { - // fmt::print(" at instruction {}\n", use.op_id); + // lg::print(" at instruction {}\n", use.op_id); // } // } // } @@ -1231,7 +1232,7 @@ void SimpleExpressionElement::update_from_stack_add_i(const Env& env, } } } - // fmt::print("here {} {} {}\n", rd_in.base_type.print(), rd.success, + // lg::print("here {} {} {}\n", rd_in.base_type.print(), rd.success, // rd.has_variable_token()); if (idx_of_success >= 0) { @@ -1261,7 +1262,7 @@ void SimpleExpressionElement::update_from_stack_add_i(const Env& env, return; } else { // TODO - output error to IR - lg::error("Bad {} at OP: {}\n", args.at(0)->to_string(env), m_my_idx); + lg::error("Bad {} at OP: {}", args.at(0)->to_string(env), m_my_idx); throw std::runtime_error("Failed to match product_with_constant inline array access 2."); } } @@ -1525,7 +1526,7 @@ void SimpleExpressionElement::update_from_stack_pcypld(const Env& env, result->push_back(as_mod); return; } else { - fmt::print("pcpyud rewrite form fail: {} {}\n", base_form.print(), a1_form.print()); + lg::warn("pcpyud rewrite form fail: {} {}", base_form.print(), a1_form.print()); } } auto new_form = pool.alloc_element( @@ -1995,7 +1996,7 @@ void SimpleExpressionElement::update_from_stack_logor_or_logand(const Env& env, auto repopped = stack.pop_reg(var_b, {}, env, true, stack.size() - 1); if (!repopped) { - fmt::print("repop failed.\n{}\n", stack.print(env)); + lg::warn("repop failed.\n{}", stack.print(env)); repopped = var_to_form(var_b, pool); } @@ -2592,7 +2593,7 @@ void SetFormFormElement::push_to_stack(const Env& env, FormPool& pool, FormStack m_src = value; } } else if (src_as_bf_set) { - fmt::print("invalid bf set: {}\n", src_as_bf_set->to_string(env)); + lg::warn("invalid bf set: {}", src_as_bf_set->to_string(env)); } // setting a bitfield to zero is wonky. @@ -3014,12 +3015,12 @@ Form* get_set_next_state(FormElement* set_elt, const Env& env) { Matcher::deref(Matcher::any_reg(0), false, {DerefTokenMatcher::string("next-state")}); auto mr = match(dst_matcher, dst); if (!mr.matched) { - fmt::print("failed to match dst {}\n", dst->to_string(env)); + lg::error("failed to match dst {}", dst->to_string(env)); return nullptr; } if (mr.maps.regs.at(0)->reg() != Register(Reg::GPR, Reg::S6)) { - fmt::print("failed to match pp reg, got {}\n", mr.maps.regs.at(0)->reg().to_string()); + lg::error("failed to match pp reg, got {}", mr.maps.regs.at(0)->reg().to_string()); return nullptr; } @@ -3236,11 +3237,11 @@ void FunctionCallElement::update_from_stack(const Env& env, } if (should_use_virtual) { - // fmt::print("STACK\n{}\n\n", stack.print(env)); + // lg::print("STACK\n{}\n\n", stack.print(env)); auto pop = pop_to_forms({*arg0_mr.maps.regs.at(0)}, env, pool, stack, allow_side_effects, {}, {2}) .at(0); - // fmt::print("GOT: {}\n", pop->to_string(env)); + // lg::print("GOT: {}\n", pop->to_string(env)); arg_forms.at(0) = pop; auto head = mr.maps.forms.at(1); @@ -3855,7 +3856,7 @@ Form* try_rewrite_as_process_to_ppointer(CondNoElseElement* value, return nullptr; } - // fmt::print("Matched condition {} in {}\n", condition_var.to_string(env), + // lg::print("Matched condition {} in {}\n", condition_var.to_string(env), // value->to_string(env)); auto* menv = const_cast(&env); @@ -3909,7 +3910,7 @@ Form* try_rewrite_as_pppointer_to_process(CondNoElseElement* value, return nullptr; } - // fmt::print("Matched condition {} in {}\n", condition_var.to_string(env), + // lg::print("Matched condition {} in {}\n", condition_var.to_string(env), // value->to_string(env)); auto* menv = const_cast(&env); @@ -4045,7 +4046,7 @@ void CondNoElseElement::push_to_stack(const Env& env, FormPool& pool, FormStack& stack.push_value_to_reg(write_as_value, as_ja_group, true, env.get_variable_type(final_destination, false)); } else { - // fmt::print("func {} final destination {} type {}\n", env.func->name(), + // lg::print("func {} final destination {} type {}\n", env.func->name(), // final_destination.to_string(env), // env.get_variable_type(final_destination, false).print()); stack.push_value_to_reg(write_as_value, pool.alloc_single_form(nullptr, this), true, @@ -4213,24 +4214,24 @@ void CondWithElseElement::push_to_stack(const Env& env, FormPool& pool, FormStac // (set! x (if y z (expr))) and z requires a cast, but the move from z to x is // eliminated by GOAL's register allocator. - // fmt::print("func: {}\n", env.func->name()); + // lg::print("func: {}\n", env.func->name()); // - // fmt::print("checking:\n"); + // lg::print("checking:\n"); // for (auto& t : source_types) { - // fmt::print(" {}\n", t.print()); + // lg::print(" {}\n", t.print()); // } auto expected_type = env.get_variable_type(*last_var, true); - // fmt::print("The expected type is {}\n", expected_type.print()); + // lg::print("The expected type is {}\n", expected_type.print()); auto result_type = source_types.empty() ? expected_type : env.dts->ts.lowest_common_ancestor(source_types); - // fmt::print("but we actually got {}\n", result_type.print()); + // lg::print("but we actually got {}\n", result_type.print()); Form* result_value = pool.alloc_single_form(nullptr, this); if (!env.dts->ts.tc(expected_type, result_type)) { result_value = pool.form(expected_type, result_value); } - // fmt::print("{}\n", result_value->to_string(env)); + // lg::print("{}\n", result_value->to_string(env)); stack.push_value_to_reg(*last_var, result_value, true, env.get_variable_type(*last_var, false)); @@ -5323,7 +5324,7 @@ void AsmBranchElement::push_to_stack(const Env& env, FormPool& pool, FormStack& auto op = pool.alloc_element( branch_condition, m_branch_delay, m_branch_op->label_id(), m_branch_op->is_likely()); - // fmt::print("rewrote as {}\n", op->to_string(env)); + // lg::print("rewrote as {}\n", op->to_string(env)); stack.push_form_element(op, true); } @@ -5381,7 +5382,7 @@ void BranchElement::push_to_stack(const Env& env, FormPool& pool, FormStack& sta ASSERT(!m_op->likely()); auto op = pool.alloc_element(branch_condition, branch_delay, m_op->label_id(), m_op->likely()); - // fmt::print("rewrote (non-asm) as {}\n", op->to_string(env)); + // lg::print("rewrote (non-asm) as {}\n", op->to_string(env)); stack.push_form_element(op, true); } @@ -5502,7 +5503,7 @@ void ArrayFieldAccess::update_with_val(Form* new_val, if (!match_result.matched) { result->push_back(this); return; - fmt::print("power {}\n", power_of_two); + lg::error("power {}", power_of_two); throw std::runtime_error( "Couldn't match ArrayFieldAccess (stride power of 2, 0 offset) values: " + new_val->to_string(env)); diff --git a/decompiler/IR2/bitfields.cpp b/decompiler/IR2/bitfields.cpp index 99b8bb2a4e..87f994c05f 100644 --- a/decompiler/IR2/bitfields.cpp +++ b/decompiler/IR2/bitfields.cpp @@ -1,6 +1,7 @@ #include "bitfields.h" #include "common/goos/PrettyPrinter.h" +#include "common/log/log.h" #include "common/util/BitUtils.h" #include "common/util/Range.h" @@ -563,7 +564,7 @@ FormElement* BitfieldAccessElement::push_step(const BitfieldManip step, // in this case, we expect the value we're oring with to be the appropriate mask for the field. - fmt::print("Rare bitfield set!\n"); + lg::info("Rare bitfield set!"); u64 value = step.amount; auto type = ts.lookup_type(m_type); auto as_bitfield = dynamic_cast(type); @@ -621,7 +622,7 @@ FormElement* BitfieldAccessElement::push_step(const BitfieldManip step, } lg::error("Current: {}", step.print()); if (m_got_pcpyud) { - lg::error("Got pcpyud\n"); + lg::error("Got pcpyud"); } throw std::runtime_error("Unknown state in BitfieldReadElement"); diff --git a/decompiler/ObjectFile/LinkedObjectFileCreation.cpp b/decompiler/ObjectFile/LinkedObjectFileCreation.cpp index 51db88689e..3931fd45e2 100644 --- a/decompiler/ObjectFile/LinkedObjectFileCreation.cpp +++ b/decompiler/ObjectFile/LinkedObjectFileCreation.cpp @@ -9,6 +9,7 @@ #include #include "common/link_types.h" +#include "common/log/log.h" #include "common/util/Assert.h" #include "common/util/BitUtils.h" diff --git a/decompiler/ObjectFile/ObjectFileDB.cpp b/decompiler/ObjectFile/ObjectFileDB.cpp index dd75acc271..81c78ad101 100644 --- a/decompiler/ObjectFile/ObjectFileDB.cpp +++ b/decompiler/ObjectFile/ObjectFileDB.cpp @@ -150,7 +150,7 @@ ObjectFileDB::ObjectFileDB(const std::vector& _dgos, auto name = obj_filename_to_name(obj.string()); if (auto it = config.object_patches.find(name); it != config.object_patches.end()) { // print the file CRC - fmt::print("CRC for {} is: 0x{:X}\n", name, crc32(data.data(), data.size())); + lg::print("CRC for {} is: 0x{:X}\n", name, crc32(data.data(), data.size())); // write patch file if necessary if (config.write_patches) { // this is the "target" file we want to patch to @@ -219,7 +219,7 @@ ObjectFileDB::ObjectFileDB(const std::vector& _dgos, } } - lg::info("ObjectFileDB Initialized\n"); + lg::info("ObjectFileDB Initialized"); if (obj_files_by_name.empty()) { lg::error( "No object files have been added. Check that there are input files and the allowed_objects " @@ -496,7 +496,7 @@ void ObjectFileDB::process_link_data(const Config& config) { }); lg::info("Processed Link Data"); - lg::info(" Total {:.2f} ms\n", process_link_timer.getMs()); + lg::info(" Total {:.2f} ms", process_link_timer.getMs()); // printf("\n"); } @@ -511,7 +511,7 @@ void ObjectFileDB::process_labels() { lg::info("Processed Labels:"); lg::info(" Total {} labels", total); - lg::info(" Total {:.2f} ms\n", process_label_timer.getMs()); + lg::info(" Total {:.2f} ms", process_label_timer.getMs()); } /*! @@ -617,7 +617,7 @@ void ObjectFileDB::find_code(const Config& config) { auto total_ops = combined_stats.code_bytes / 4; lg::info(" Decoded {} / {} ({:.3f} %)", combined_stats.decoded_ops, total_ops, 100.f * (float)combined_stats.decoded_ops / total_ops); - lg::info(" Total {:.3f} ms\n", timer.getMs()); + lg::info(" Total {:.3f} ms", timer.getMs()); } /*! @@ -643,7 +643,7 @@ void ObjectFileDB::find_and_write_scripts(const fs::path& output_dir) { file_util::write_text_file(file_name, all_scripts); lg::info("Found scripts:"); - lg::info(" Total {:.3f} ms\n", timer.getMs()); + lg::info(" Total {:.3f} ms", timer.getMs()); } std::string ObjectFileDB::process_tpages(TextureDB& tex_db, const fs::path& output_path) { @@ -741,10 +741,10 @@ void get_art_info(ObjectFileDB& db, ObjectFileData& obj) { const auto& words = obj.linked_data.words_by_seg.at(MAIN_SEGMENT); if (words.at(0).kind() == LinkedWord::Kind::TYPE_PTR && words.at(0).symbol_name() == "art-group") { - // fmt::print("art-group {}:\n", obj.to_unique_name()); + // lg::print("art-group {}:\n", obj.to_unique_name()); auto name = obj.linked_data.get_goal_string_by_label(words.at(2).label_id()); int length = words.at(3).data; - // fmt::print(" length: {}\n", length); + // lg::print(" length: {}\n", length); std::unordered_map art_group_elts; for (int i = 0; i < length; ++i) { const auto& word = words.at(8 + i); @@ -772,7 +772,7 @@ void get_art_info(ObjectFileDB& db, ObjectFileData& obj) { fmt::format("unknown art elt type {} in {}", elt_type, obj.to_unique_name())); } art_group_elts[i] = unique_name; - // fmt::print(" {}: {} ({}) -> {}\n", i, elt_name, elt_type, unique_name); + // lg::print(" {}: {} ({}) -> {}\n", i, elt_name, elt_type, unique_name); } db.dts.art_group_info[obj.to_unique_name()] = art_group_elts; } @@ -795,7 +795,7 @@ void ObjectFileDB::extract_art_info() { } }); - lg::info("Processed art groups: in {:.2f} ms\n", timer.getMs()); + lg::info("Processed art groups: in {:.2f} ms", timer.getMs()); } /*! @@ -822,7 +822,7 @@ void ObjectFileDB::dump_art_info(const fs::path& output_dir) { file_util::write_text_file(filename, result); } - lg::info("Written art group info: in {:.2f} ms\n", timer.getMs()); + lg::info("Written art group info: in {:.2f} ms", timer.getMs()); } void ObjectFileDB::dump_raw_objects(const fs::path& output_dir) { diff --git a/decompiler/ObjectFile/ObjectFileDB_IR2.cpp b/decompiler/ObjectFile/ObjectFileDB_IR2.cpp index 159395d0e2..cddd5df9ce 100644 --- a/decompiler/ObjectFile/ObjectFileDB_IR2.cpp +++ b/decompiler/ObjectFile/ObjectFileDB_IR2.cpp @@ -50,7 +50,7 @@ void ObjectFileDB::analyze_functions_ir2( int file_idx = 1; for_each_obj([&](ObjectFileData& data) { Timer file_timer; - fmt::print("[{:3d}/{}]------ {}\n", file_idx++, total_file_count, data.to_unique_name()); + lg::info("[{:3d}/{}]------ {}", file_idx++, total_file_count, data.to_unique_name()); ir2_do_segment_analysis_phase1(TOP_LEVEL_SEGMENT, config, data); ir2_do_segment_analysis_phase1(DEBUG_SEGMENT, config, data); ir2_do_segment_analysis_phase1(MAIN_SEGMENT, config, data); @@ -125,7 +125,7 @@ void ObjectFileDB::analyze_functions_ir2( }); } - fmt::print("Done in {:.2f}ms\n", file_timer.getMs()); + lg::info("Done in {:.2f}ms", file_timer.getMs()); }); lg::info("{}", stats.let.print()); @@ -172,7 +172,7 @@ void ObjectFileDB::ir2_setup_labels(const Config& config, ObjectFileData& data) std::make_unique(config_labels, data.linked_data.labels, dts); analyze_labels(data.linked_data.label_db.get(), &data.linked_data); } catch (const std::exception& e) { - lg::die("Error parsing labels for {}: {}\n", data.to_unique_name(), e.what()); + lg::die("Error parsing labels for {}: {}", data.to_unique_name(), e.what()); } } } @@ -296,7 +296,7 @@ void ObjectFileDB::ir2_top_level_pass(const Config& config) { lg::info("{:4d} global {:.2f}%", total_named_global_functions, 100.f * total_named_global_functions / total_functions); lg::info("{:4d} methods {:.2f}%", total_methods, 100.f * total_methods / total_functions); - lg::info("{:4d} logins {:.2f}%\n", total_top_levels, 100.f * total_top_levels / total_functions); + lg::info("{:4d} logins {:.2f}%", total_top_levels, 100.f * total_top_levels / total_functions); } void ObjectFileDB::ir2_analyze_all_types(const fs::path& output_file, diff --git a/decompiler/VuDisasm/VuDisassembler.cpp b/decompiler/VuDisasm/VuDisassembler.cpp index c330465ad0..1c8e2be0e5 100644 --- a/decompiler/VuDisasm/VuDisassembler.cpp +++ b/decompiler/VuDisasm/VuDisassembler.cpp @@ -3,6 +3,7 @@ #include #include +#include "common/log/log.h" #include "common/util/Assert.h" #include "common/util/print_float.h" @@ -414,15 +415,15 @@ VuProgram VuDisassembler::disassemble(void* data, int size_bytes, bool debug_pri // debug if (debug_print) { - fmt::print("{}\n", to_string(VuInstructionPair{upper_instr, lower_instr})); + lg::print("{}\n", to_string(VuInstructionPair{upper_instr, lower_instr})); } } name_labels(); if (debug_print) { - fmt::print("----------------------------------\n"); - fmt::print("{}\n", to_string(prog)); + lg::print("----------------------------------\n"); + lg::print("{}\n", to_string(prog)); } return prog; @@ -1014,7 +1015,7 @@ std::string VuDisassembler::to_cpp(const VuInstruction& instr, bool mips2c_forma instr.src.at(1).to_string(m_label_names)); default: unk++; - fmt::print("unknown 0 is {}\n", to_string(instr)); + lg::print("unknown 0 is {}\n", to_string(instr)); return "ASSERT(false);"; //"???"; } @@ -1022,7 +1023,7 @@ std::string VuDisassembler::to_cpp(const VuInstruction& instr, bool mips2c_forma unknown: unk++; - fmt::print("unknown 1 is {}\n", to_string(instr)); + lg::print("unknown 1 is {}\n", to_string(instr)); return "ASSERT(false);"; } @@ -1262,7 +1263,7 @@ std::string VuDisassembler::to_string_with_cpp(const VuProgram& prog, bool mips2 } } } - fmt::print("TOTAL unk: {}\n", unk); + lg::print("TOTAL unk: {}\n", unk); return result; } diff --git a/decompiler/analysis/analyze_inspect_method.cpp b/decompiler/analysis/analyze_inspect_method.cpp index a42dcd3872..d3cfc652c0 100644 --- a/decompiler/analysis/analyze_inspect_method.cpp +++ b/decompiler/analysis/analyze_inspect_method.cpp @@ -1,4 +1,5 @@ #include "analyze_inspect_method.h" +#include "common/log/log.h" #include "decompiler/Disasm/InstructionMatching.h" #include "decompiler/ObjectFile/LinkedObjectFile.h" @@ -371,13 +372,13 @@ FieldPrint get_field_print(const std::string& str) { int get_start_idx_process(Function& function, const std::string& parent_type, Env& env) { if (function.basic_blocks.size() != 5) { - fmt::print("[iim] inspect {} had {} basic blocks, expected 5\n", function.name(), - function.basic_blocks.size()); + lg::print("[iim] inspect {} had {} basic blocks, expected 5\n", function.name(), + function.basic_blocks.size()); return -1; } if (!function.ir2.atomic_ops) { - fmt::print("[iim] no atomic ops in {}\n", function.name()); + lg::print("[iim] no atomic ops in {}\n", function.name()); return -1; } auto& aos = *function.ir2.atomic_ops; @@ -390,23 +391,23 @@ int get_start_idx_process(Function& function, const std::string& parent_type, En */ if (aos.block_id_to_end_atomic_op.at(0) != 2) { - fmt::print("[iim] block 0 had the wrong number of ops: {} for {}\n", - aos.block_id_to_end_atomic_op.at(0), function.name()); + lg::print("[iim] block 0 had the wrong number of ops: {} for {}\n", + aos.block_id_to_end_atomic_op.at(0), function.name()); return -1; } if (!is_op_2(aos.ops.at(op_idx).get(), SimpleExpression::Kind::IDENTITY, Register(Reg::GPR, Reg::GP), Register(Reg::GPR, Reg::A0))) { - fmt::print("[iim] block 0 op 0 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] block 0 op 0 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; auto br = dynamic_cast(aos.ops.at(op_idx).get()); if (!br) { - fmt::print("[iim] block 0 op 1 bad in {}: {} (not branch)\n", aos.ops.at(1)->to_string(env), - function.name()); + lg::print("[iim] block 0 op 1 bad in {}: {} (not branch)\n", aos.ops.at(1)->to_string(env), + function.name()); return -1; } @@ -415,8 +416,8 @@ int get_start_idx_process(Function& function, const std::string& parent_type, En br->condition().src(0).var().reg() != Register(Reg::GPR, Reg::GP) || br->branch_delay().kind() != IR2_BranchDelay::Kind::SET_REG_FALSE || br->branch_delay().var(0).reg() != Register(Reg::GPR, Reg::V1)) { - fmt::print("[iim] block 0 op 1 bad in {}: {} (bad branch)\n", aos.ops.at(1)->to_string(env), - function.name()); + lg::print("[iim] block 0 op 1 bad in {}: {} (bad branch)\n", aos.ops.at(1)->to_string(env), + function.name()); return -1; } op_idx++; @@ -427,29 +428,29 @@ int get_start_idx_process(Function& function, const std::string& parent_type, En * (b! #t L371 (nop!)) */ if (aos.block_id_to_end_atomic_op.at(1) != 4) { - fmt::print("[iim] block 1 had the wrong number of ops: {} for {}\n", - aos.block_id_to_end_atomic_op.at(1), function.name()); + lg::print("[iim] block 1 had the wrong number of ops: {} for {}\n", + aos.block_id_to_end_atomic_op.at(1), function.name()); return -1; } if (!is_op_2(aos.ops.at(op_idx).get(), SimpleExpression::Kind ::IDENTITY, Register(Reg::GPR, Reg::GP), Register(Reg::GPR, Reg::GP))) { - fmt::print("[iim] op 2 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); + lg::print("[iim] op 2 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); return -1; } op_idx++; auto br2 = dynamic_cast(aos.ops.at(op_idx).get()); if (!br2) { - fmt::print("[iim] op 3 bad in {}: {} (not branch)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op 3 bad in {}: {} (not branch)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } if (br2->likely() || br2->condition().kind() != IR2_Condition::Kind::ALWAYS || br2->branch_delay().kind() != IR2_BranchDelay::Kind::NOP) { - fmt::print("[iim] op3 bad in {}: {} (bad branch)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op3 bad in {}: {} (bad branch)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; @@ -468,37 +469,37 @@ L2: sll v0, ra, 0 */ if (!is_set_reg_to_int(aos.ops.at(op_idx).get(), Register(Reg::GPR, Reg::V1), 0)) { - fmt::print("[iim] op4 bad in {}: {} (bad set 0)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op4 bad in {}: {} (bad set 0)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; if (!is_set_reg_to_symbol_value(aos.ops.at(op_idx).get(), Register(Reg::GPR, Reg::V1), parent_type)) { - fmt::print("[iim] op5 bad in {}: {} (bad set parent type)\n", - aos.ops.at(op_idx)->to_string(env), function.name()); + lg::print("[iim] op5 bad in {}: {} (bad set parent type)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; if (aos.ops.at(op_idx).get()->to_string(env) != "(set! t9 (l.wu (+ v1 28)))") { - fmt::print("[iim] op6 bad in {}: {} (bad load inspect)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op6 bad in {}: {} (bad load inspect)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; if (aos.ops.at(op_idx).get()->to_string(env) != "(set! a0 gp)") { - fmt::print("[iim] op7 bad in {}: {} (bad set arg)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op7 bad in {}: {} (bad set arg)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; if (aos.ops.at(op_idx).get()->to_string(env) != "(call!)") { - fmt::print("[iim] op8 bad in {}: {} (bad call)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op8 bad in {}: {} (bad call)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; @@ -539,13 +540,13 @@ int get_start_idx(Function& function, const std::string& type_name, Env& env) { if (function.basic_blocks.size() != 5) { - fmt::print("[iim] inspect {} had {} basic blocks, expected 5\n", function.name(), - function.basic_blocks.size()); + lg::print("[iim] inspect {} had {} basic blocks, expected 5\n", function.name(), + function.basic_blocks.size()); return -1; } if (!function.ir2.atomic_ops) { - fmt::print("[iim] no atomic ops in {}\n", function.name()); + lg::print("[iim] no atomic ops in {}\n", function.name()); return -1; } auto& aos = *function.ir2.atomic_ops; @@ -558,23 +559,23 @@ int get_start_idx(Function& function, */ if (aos.block_id_to_end_atomic_op.at(0) != 2) { - fmt::print("[iim] block 0 had the wrong number of ops: {} for {}\n", - aos.block_id_to_end_atomic_op.at(0), function.name()); + lg::print("[iim] block 0 had the wrong number of ops: {} for {}\n", + aos.block_id_to_end_atomic_op.at(0), function.name()); return -1; } if (!is_op_2(aos.ops.at(op_idx).get(), SimpleExpression::Kind::IDENTITY, Register(Reg::GPR, Reg::GP), Register(Reg::GPR, Reg::A0))) { - fmt::print("[iim] block 0 op 0 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] block 0 op 0 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; auto br = dynamic_cast(aos.ops.at(op_idx).get()); if (!br) { - fmt::print("[iim] block 0 op 1 bad in {}: {} (not branch)\n", aos.ops.at(1)->to_string(env), - function.name()); + lg::print("[iim] block 0 op 1 bad in {}: {} (not branch)\n", aos.ops.at(1)->to_string(env), + function.name()); return -1; } @@ -583,8 +584,8 @@ int get_start_idx(Function& function, br->condition().src(0).var().reg() != Register(Reg::GPR, Reg::GP) || br->branch_delay().kind() != IR2_BranchDelay::Kind::SET_REG_FALSE || br->branch_delay().var(0).reg() != Register(Reg::GPR, Reg::V1)) { - fmt::print("[iim] block 0 op 1 bad in {}: {} (bad branch)\n", aos.ops.at(1)->to_string(env), - function.name()); + lg::print("[iim] block 0 op 1 bad in {}: {} (bad branch)\n", aos.ops.at(1)->to_string(env), + function.name()); return -1; } op_idx++; @@ -595,29 +596,29 @@ int get_start_idx(Function& function, * (b! #t L371 (nop!)) */ if (aos.block_id_to_end_atomic_op.at(1) != 4) { - fmt::print("[iim] block 1 had the wrong number of ops: {} for {}\n", - aos.block_id_to_end_atomic_op.at(1), function.name()); + lg::print("[iim] block 1 had the wrong number of ops: {} for {}\n", + aos.block_id_to_end_atomic_op.at(1), function.name()); return -1; } if (!is_op_2(aos.ops.at(op_idx).get(), SimpleExpression::Kind ::IDENTITY, Register(Reg::GPR, Reg::GP), Register(Reg::GPR, Reg::GP))) { - fmt::print("[iim] op 2 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); + lg::print("[iim] op 2 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); return -1; } op_idx++; auto br2 = dynamic_cast(aos.ops.at(op_idx).get()); if (!br2) { - fmt::print("[iim] op 3 bad in {}: {} (not branch)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op 3 bad in {}: {} (not branch)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } if (br2->likely() || br2->condition().kind() != IR2_Condition::Kind::ALWAYS || br2->branch_delay().kind() != IR2_BranchDelay::Kind::NOP) { - fmt::print("[iim] op3 bad in {}: {} (bad branch)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op3 bad in {}: {} (bad branch)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); return -1; } op_idx++; @@ -634,38 +635,38 @@ int get_start_idx(Function& function, */ if (!is_set_reg_to_int(aos.ops.at(op_idx).get(), Register(Reg::GPR, Reg::V1), 0)) { - fmt::print("[iim] op4 bad in {}: {} (bad set 0)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op4 bad in {}: {} (bad set 0)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); } op_idx++; if (!is_set_reg_to_symbol_value(aos.ops.at(op_idx).get(), Register(Reg::GPR, Reg::T9), "format")) { - fmt::print("[iim] op5 bad in {}: {} (bad set format)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op5 bad in {}: {} (bad set format)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); } op_idx++; if (!is_set_reg_to_symbol_ptr(aos.ops.at(op_idx).get(), Register(Reg::GPR, Reg::A0), "#t")) { - fmt::print("[iim] op6 bad in {}: {} (bad set #t)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op6 bad in {}: {} (bad set #t)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); } op_idx++; auto type_name_str = get_string_loaded_to_reg(aos.ops.at(op_idx).get(), Register(Reg::GPR, Reg::A1), file); if (!type_name_str) { - fmt::print("[iim] op7 bad in {}: {} (bad string)\n", aos.ops.at(op_idx)->to_string(env), - function.name()); + lg::print("[iim] op7 bad in {}: {} (bad string)\n", aos.ops.at(op_idx)->to_string(env), + function.name()); } else if (type_name_str != "[~8x] ~A~%") { - fmt::print("[iim] op7 bad in {}: {} (bad string: {})\n", aos.ops.at(op_idx)->to_string(env), - function.name(), *type_name_str); + lg::print("[iim] op7 bad in {}: {} (bad string: {})\n", aos.ops.at(op_idx)->to_string(env), + function.name(), *type_name_str); } op_idx++; if (!is_op_2(aos.ops.at(op_idx).get(), SimpleExpression::Kind ::IDENTITY, Register(Reg::GPR, Reg::A2), Register(Reg::GPR, Reg::GP))) { - fmt::print("[iim] op 8 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); + lg::print("[iim] op 8 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); return -1; } op_idx++; @@ -675,13 +676,13 @@ int get_start_idx(Function& function, } else if (aos.ops.at(op_idx)->to_string(env) == "(set! a3 (l.wu (+ gp -4)))") { result->is_basic = true; } else { - fmt::print("[iim] op 9 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); + lg::print("[iim] op 9 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); return -1; } op_idx++; if (!dynamic_cast(aos.ops.at(op_idx).get())) { - fmt::print("[iim] op 10 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); + lg::print("[iim] op 10 bad in {}: {}\n", aos.ops.at(op_idx)->to_string(env), function.name()); return -1; } op_idx++; @@ -1040,7 +1041,7 @@ std::string inspect_inspect_method(Function& inspect_method, DecompilerTypeSystem& previous_game_ts, TypeInspectorCache& ti_cache, ObjectFileDB::PerObjectAllTypeInfo& object_file_meta) { - fmt::print(" iim: {}\n", inspect_method.name()); + lg::print(" iim: {}\n", inspect_method.name()); TypeInspectorResult result; ASSERT(type_name == inspect_method.guessed_name.type_name); TypeFlags flags; @@ -1072,7 +1073,7 @@ std::string inspect_inspect_method(Function& inspect_method, } } if (!result.found_flags) { - fmt::print("[iim] no flags found for {}, maybe defined in the kernel\n", type_name); + lg::print("[iim] no flags found for {}, maybe defined in the kernel\n", type_name); } result.parent_type_name = dts.lookup_parent_from_inspects(type_name); @@ -1495,13 +1496,13 @@ void inspect_top_level_for_metadata(Function& top_level, continue; } - fmt::print("got 1\n"); + lg::print("got 1\n"); // lwu t9, 16(v1) ;; [ 21] (set! t9-0 (l.wu (+ v1-10 16))) // ;; [v1: ] -> [t9: (function symbol type int type) const auto& aop_1 = top_level.ir2.atomic_ops->ops.at(i + 1); if (!is_set_reg_to_load(aop_1.get(), Register(Reg::GPR, Reg::T9), 16)) { - fmt::print("fail1\n"); + lg::print("fail1\n"); continue; } @@ -1509,7 +1510,7 @@ void inspect_top_level_for_metadata(Function& top_level, const auto& aop_2 = top_level.ir2.atomic_ops->ops.at(i + 2); auto type_name = get_set_reg_to_symbol_ptr(aop_2.get(), Register(Reg::GPR, Reg::A0)); if (!type_name) { - fmt::print("fail2\n"); + lg::print("fail2\n"); continue; } @@ -1517,7 +1518,7 @@ void inspect_top_level_for_metadata(Function& top_level, const auto& aop_3 = top_level.ir2.atomic_ops->ops.at(i + 3); auto parent_name = get_set_reg_to_symbol_value(aop_3.get(), Register(Reg::GPR, Reg::A1)); if (!parent_name) { - fmt::print("fail3\n"); + lg::print("fail3\n"); continue; } @@ -1525,14 +1526,14 @@ void inspect_top_level_for_metadata(Function& top_level, const auto& aop_4 = top_level.ir2.atomic_ops->ops.at(i + 4); auto flags = get_set_reg_to_u64_load(aop_4.get(), Register(Reg::GPR, Reg::A2), file); if (!flags) { - fmt::print("fail3\n"); + lg::print("fail3\n"); continue; } // jalr ra, t9 ;; [ 25] (call! a0-0 a1-0 a2-0) const auto& aop_5 = top_level.ir2.atomic_ops->ops.at(i + 5); if (!dynamic_cast(aop_5.get())) { - fmt::print("fial4\n"); + lg::print("fial4\n"); continue; } diff --git a/decompiler/analysis/cfg_builder.cpp b/decompiler/analysis/cfg_builder.cpp index 94ef950a9a..28d729e5c1 100644 --- a/decompiler/analysis/cfg_builder.cpp +++ b/decompiler/analysis/cfg_builder.cpp @@ -4,6 +4,7 @@ */ #include "cfg_builder.h" +#include "common/log/log.h" #include "decompiler/Function/Function.h" #include "decompiler/IR2/Form.h" #include "decompiler/ObjectFile/LinkedObjectFile.h" @@ -716,7 +717,7 @@ void clean_up_cond_no_else_final(Function& func, CondNoElseElement* cne) { ASSERT(fr.has_value()); cne->final_destination = *fr; } else { - fmt::print("failed to clean up cond_no_else_final: {}\n", func.name()); + lg::print("failed to clean up cond_no_else_final: {}\n", func.name()); ASSERT(false); } } @@ -753,7 +754,7 @@ void clean_up_cond_no_else_final(Function& func, CondNoElseElement* cne) { for (size_t i = 0; i < cne->entries.size(); i++) { if (func.ir2.env.has_reg_use()) { auto reg = cne->entries.at(i).false_destination; - // lg::warn("Disable def of {} at {}\n", reg->to_string(func.ir2.env), reg->idx()); + // lg::warn("Disable def of {} at {}", reg->to_string(func.ir2.env), reg->idx()); func.ir2.env.disable_def(*reg, func.warnings); } } @@ -1181,7 +1182,7 @@ SetVarOp get_delay_op(const Function& f, const BlockVtx* vtx) { auto& delay_op = f.ir2.atomic_ops->ops.at(delay_start); auto* delay = dynamic_cast(delay_op.get()); if (!delay) { - fmt::print("bad delay: {}\n", delay_op->to_string(f.ir2.env)); + lg::print("bad delay: {}\n", delay_op->to_string(f.ir2.env)); ASSERT(false); } return *delay; @@ -1196,7 +1197,7 @@ LoadVarOp get_delay_load_op(const Function& f, const BlockVtx* vtx) { auto& delay_op = f.ir2.atomic_ops->ops.at(delay_start); auto* delay = dynamic_cast(delay_op.get()); if (!delay) { - fmt::print("bad delay: {}\n", delay_op->to_string(f.ir2.env)); + lg::print("bad delay: {}\n", delay_op->to_string(f.ir2.env)); ASSERT(false); } return *delay; @@ -1248,69 +1249,69 @@ Form* try_sc_as_type_of_jak2(FormPool& pool, Function& f, const ShortCircuit* vt // get the branch ir's auto b0_ptr = cfg_to_ir(pool, f, b0_c); // should be begin. if (b0_ptr->size() <= 2) { - fmt::print("fail1\n"); + lg::print("fail1\n"); return nullptr; } auto b1_ptr = cfg_to_ir(pool, f, b1_c); if (b1_ptr->size() <= 1) { - fmt::print("fail2\n"); + lg::print("fail2\n"); return nullptr; } auto b2_ptr = cfg_to_ir(pool, f, b2_c); if (b2_ptr->size() <= 1) { - fmt::print("fail3\n"); + lg::print("fail3\n"); return nullptr; } auto b3_ptr = cfg_to_ir(pool, f, b3_c); auto b3_ir = dynamic_cast(b3_ptr->try_as_single_element()); if (!b3_ir) { - fmt::print("fail4\n"); + lg::print("fail4\n"); return nullptr; } // identify the left shift auto set_shift_left = dynamic_cast(b0_ptr->at(b0_ptr->size() - 3)); if (!set_shift_left) { - fmt::print("fail5\n"); + lg::print("fail5\n"); return nullptr; } auto temp_reg0 = set_shift_left->dst(); auto shift_left = dynamic_cast(set_shift_left->src()->try_as_single_element()); if (!shift_left || shift_left->expr().kind() != SimpleExpression::Kind::LEFT_SHIFT) { - fmt::print("fail6\n"); + lg::print("fail6\n"); return nullptr; } auto src_reg = shift_left->expr().get_arg(0).var(); auto sa_left = shift_left->expr().get_arg(1); if (!sa_left.is_int() || sa_left.get_int() != 61) { - fmt::print("fail7\n"); + lg::print("fail7\n"); return nullptr; } // identify the right shift auto set_shift_right = dynamic_cast(b0_ptr->at(b0_ptr->size() - 2)); if (!set_shift_right) { - fmt::print("fail8\n"); + lg::print("fail8\n"); return nullptr; } if (set_shift_right->dst().reg() != set_shift_left->dst().reg()) { - fmt::print("fail9\n"); + lg::print("fail9\n"); return nullptr; } auto shift_right = dynamic_cast(set_shift_right->src()->try_as_single_element()); if (!shift_right || shift_right->expr().kind() != SimpleExpression::Kind::RIGHT_SHIFT_LOGIC) { - fmt::print("fail10\n"); + lg::print("fail10\n"); return nullptr; } if (temp_reg0.reg() != shift_right->expr().get_arg(0).var().reg()) { - fmt::print("fail11\n"); + lg::print("fail11\n"); return nullptr; } auto sa_right = shift_right->expr().get_arg(1); if (!sa_right.is_int() || sa_right.get_int() != 61) { - fmt::print("fail12\n"); + lg::print("fail12\n"); return nullptr; } @@ -1320,7 +1321,7 @@ Form* try_sc_as_type_of_jak2(FormPool& pool, Function& f, const ShortCircuit* vt if (!first_branch || !is_set_symbol_value(b0_delay_op, "binteger") || first_branch->op()->condition().kind() != IR2_Condition::Kind::ZERO || !first_branch->op()->likely()) { - fmt::print("fail13\n"); + lg::print("fail13\n"); return nullptr; } auto temp_reg = first_branch->op()->condition().src(0).var(); @@ -1329,19 +1330,19 @@ Form* try_sc_as_type_of_jak2(FormPool& pool, Function& f, const ShortCircuit* vt // branch 1 if (b1_ptr->size() != 2) { - fmt::print("fail14\n"); + lg::print("fail14\n"); return nullptr; } auto second_branch_pre_op = dynamic_cast(b1_ptr->at(0)); if (!second_branch_pre_op) { - fmt::print("fail15\n"); + lg::print("fail15\n"); return nullptr; } { auto pos = second_branch_pre_op->src(); auto pos_as_se = pos->try_as_element(); if (!pos_as_se || !pos_as_se->expr().is_identity() || !pos_as_se->expr().get_arg(0).is_int(4)) { - fmt::print("fail16\n"); + lg::print("fail16\n"); return nullptr; } } @@ -1357,30 +1358,30 @@ Form* try_sc_as_type_of_jak2(FormPool& pool, Function& f, const ShortCircuit* vt second_branch->op()->condition().src(0).var().reg() != temp_reg0.reg() || !second_branch->op()->condition().src(1).is_var() || second_branch->op()->condition().src(1).var().reg() != temp_reg1.reg()) { - fmt::print("fail17\n"); + lg::print("fail17\n"); return nullptr; } if (!b1_d) { - fmt::print("fail18\n"); + lg::print("fail18\n"); return nullptr; } auto b1_delay_op = get_delay_load_op(f, b1_d); if (b1_delay_op.kind() != LoadVarOp::Kind::UNSIGNED || b1_delay_op.size() != 4) { - fmt::print("fail19\n"); + lg::print("fail19\n"); return nullptr; } IR2_RegOffset ro; if (!get_as_reg_offset(b1_delay_op.src(), &ro)) { - fmt::print("fail20\n"); + lg::print("fail20\n"); return nullptr; } if (ro.offset != -4) { - fmt::print("fail21\n"); + lg::print("fail21\n"); return nullptr; } if (ro.reg != src_reg.reg() || b1_delay_op.get_set_destination().reg() != dst_reg.reg()) { - fmt::print("fail22\n"); + lg::print("fail22\n"); return nullptr; } @@ -1394,19 +1395,19 @@ Form* try_sc_as_type_of_jak2(FormPool& pool, Function& f, const ShortCircuit* vt lw a0, pair(s7) */ if (b2_ptr->size() != 2) { - fmt::print("fail23\n"); + lg::print("fail23\n"); return nullptr; } auto third_branch_pre_op = dynamic_cast(b2_ptr->at(0)); if (!third_branch_pre_op) { - fmt::print("fail24\n"); + lg::print("fail24\n"); return nullptr; } { auto pos = third_branch_pre_op->src(); auto pos_as_se = pos->try_as_element(); if (!pos_as_se || !pos_as_se->expr().is_identity() || !pos_as_se->expr().get_arg(0).is_int(2)) { - fmt::print("fail25\n"); + lg::print("fail25\n"); return nullptr; } } @@ -1417,22 +1418,22 @@ Form* try_sc_as_type_of_jak2(FormPool& pool, Function& f, const ShortCircuit* vt third_branch->op()->condition().src(0).var().reg() != temp_reg0.reg() || !third_branch->op()->condition().src(1).is_var() || third_branch->op()->condition().src(1).var().reg() != temp_reg2.reg()) { - fmt::print("fail26\n"); + lg::print("fail26\n"); return nullptr; } if (!b2_d) { - fmt::print("fail27\n"); + lg::print("fail27\n"); return nullptr; } auto b2_delay_op = get_delay_op(f, b2_d); if (!is_set_symbol_value(b2_delay_op, "pair") || b2_delay_op.dst().reg() != dst_reg.reg()) { - fmt::print("fail28\n"); + lg::print("fail28\n"); return nullptr; } if (!is_set_symbol_value(b3_ir, "symbol")) { - fmt::print("fail29\n"); + lg::print("fail29\n"); return nullptr; } @@ -1708,22 +1709,22 @@ void convert_and_inline(FormPool& pool, Function& f, const BlockVtx* as_block, T auto& ao = f.ir2.atomic_ops->ops.at(j); if (contains(ao->write_regs(), consumed.reg())) { ri.written_and_unused.insert(consumed.reg()); - // fmt::print("GOT 3, making {} wau by {}\n", consumed.reg().to_charp(), + // lg::print("GOT 3, making {} wau by {}\n", consumed.reg().to_charp(), // ao->to_string(f.ir2.env)); // HACK - regenerate: if (add_map.at(j - start_op) != -1) { - // fmt::print("regenerating {} to ", output->at(add_map.at(j - + // lg::print("regenerating {} to ", output->at(add_map.at(j - // start_op))->to_string(f.ir2.env)); output->at(add_map.at(j - start_op)) = f.ir2.atomic_ops->ops.at(j)->get_as_form(pool, f.ir2.env); - // fmt::print("{}\n", output->at(add_map.at(j - + // lg::print("{}\n", output->at(add_map.at(j - // start_op))->to_string(f.ir2.env)); } break; } if (contains(ao->read_regs(), consumed.reg())) { - // fmt::print("GOT 2, making {} consumed by {}\n", + // lg::print("GOT 2, making {} consumed by {}\n", // consumed.reg().to_charp(), // ao->to_string(f.ir2.env)); ri.consumes.insert(consumed.reg()); @@ -1896,8 +1897,8 @@ Form* cfg_to_ir_helper(FormPool& pool, Function& f, const CfgVtx* vtx) { auto& op = f.ir2.atomic_ops->ops.at(delay_start); auto op_as_expr = dynamic_cast(op.get()); if (!op_as_expr) { - fmt::print("bad in {}\n", f.name()); - fmt::print("{}\n", op->to_string(f.ir2.env)); + lg::print("bad in {}\n", f.name()); + lg::print("{}\n", op->to_string(f.ir2.env)); } ASSERT(op_as_expr); e.branch_delay = *op_as_expr; diff --git a/decompiler/analysis/expression_build.cpp b/decompiler/analysis/expression_build.cpp index 96cef58b5c..dc5ee3fddd 100644 --- a/decompiler/analysis/expression_build.cpp +++ b/decompiler/analysis/expression_build.cpp @@ -1,5 +1,6 @@ #include "expression_build.h" #include "common/goos/PrettyPrinter.h" +#include "common/log/log.h" #include "decompiler/Function/Function.h" #include "decompiler/IR2/Form.h" #include "decompiler/IR2/FormStack.h" @@ -46,7 +47,7 @@ bool convert_to_expressions( info.second.name_override = rename->second; } // debug - // fmt::print("STACK {} : {} ({})\n", info.first, info.second.typespec.print(), + // lg::print("STACK {} : {} ({})\n", info.first, info.second.typespec.print(), // info.second.tp_type.print()); } diff --git a/decompiler/analysis/find_defstates.cpp b/decompiler/analysis/find_defstates.cpp index 6237a6dc76..03b3585a00 100644 --- a/decompiler/analysis/find_defstates.cpp +++ b/decompiler/analysis/find_defstates.cpp @@ -2,6 +2,7 @@ #include "find_defstates.h" #include "common/goos/PrettyPrinter.h" +#include "common/log/log.h" #include "common/type_system/state.h" #include "decompiler/IR2/Form.h" #include "decompiler/IR2/GenericElementMatcher.h" @@ -116,7 +117,7 @@ std::vector get_defstate_entries( } if (debug_defstates) { - fmt::print("SET: {} to {}\n", name, val->to_string(env)); + lg::debug("SET: {} to {}", name, val->to_string(env)); } // now we try to find a function @@ -130,7 +131,7 @@ std::vector get_defstate_entries( this_entry.is_behavior = true; if (print_renames) { - fmt::print("RENAME: {} to ", handler_func->name()); + lg::info("RENAME: {} to ", handler_func->name()); } if (virtual_child) { @@ -139,7 +140,7 @@ std::vector get_defstate_entries( handler_func->guessed_name.set_as_nv_state(state_name, handler_kind); } if (print_renames) { - fmt::print("{}\n", handler_func->name()); + lg::info("{}", handler_func->name()); } // scary part - modify the function type! @@ -191,7 +192,7 @@ FormElement* rewrite_nonvirtual_defstate( expected_state_name); } if (debug_defstates) { - fmt::print("State: {} Type: {}\n", info.first, info.second.print()); + lg::debug("State: {} Type: {}", info.first, info.second.print()); } body_index++; @@ -270,7 +271,6 @@ FormElement* rewrite_virtual_defstate( // see if the first thing is an inherit-state. auto maybe_inherit_form = elt->body()->at(body_idx); - // fmt::print("first is {}\n", maybe_inherit_form->to_string(env)); Form temp; temp.elts().push_back(maybe_inherit_form); // (inherit-state gp-1 (method-of-type plat-button dummy-24)) @@ -418,8 +418,6 @@ FormElement* rewrite_virtual_defstate( expected_state_name, method_info.name, method_info.defined_in_type); } - // fmt::print("is a {}\n", typeid(*parent_state->try_as_single_element()).name()); - auto entries = get_defstate_entries( elt->body(), body_idx + 1, env, expected_state_name, elt->entries().at(0).dest, method_info.type.substitute_for_method_call(type_name), pool, type_name, skip_states); @@ -461,7 +459,7 @@ void run_defstate( env.get_variable_type(as_let->entries().at(0).dest, false) == TypeSpec("state")) { std::string expected_state_name = verify_empty_state_and_get_name(src_as_label, env); if (debug_defstates) { - fmt::print("got state let:\n{}\n", pretty_print::to_string(as_let->to_form(env))); + lg::debug("got state let:\n{}", pretty_print::to_string(as_let->to_form(env))); } if (is_nonvirtual_state(as_let)) { diff --git a/decompiler/analysis/inline_asm_rewrite.cpp b/decompiler/analysis/inline_asm_rewrite.cpp index 039001368b..d3f80dea87 100644 --- a/decompiler/analysis/inline_asm_rewrite.cpp +++ b/decompiler/analysis/inline_asm_rewrite.cpp @@ -1,5 +1,6 @@ #include "inline_asm_rewrite.h" #include "common/goos/PrettyPrinter.h" +#include "common/log/log.h" #include "decompiler/Function/Function.h" #include "decompiler/IR2/Form.h" #include "decompiler/IR2/FormStack.h" diff --git a/decompiler/analysis/insert_lets.cpp b/decompiler/analysis/insert_lets.cpp index 555d5abf6a..8e1af0a4dc 100644 --- a/decompiler/analysis/insert_lets.cpp +++ b/decompiler/analysis/insert_lets.cpp @@ -3,6 +3,7 @@ #include #include +#include "common/log/log.h" #include "common/util/Assert.h" #include "common/util/print_float.h" #include "decompiler/IR2/GenericElementMatcher.h" @@ -55,7 +56,7 @@ std::vector path_up_tree(Form* in, const Env&) { in = nullptr; } } - // lg::warn("DONE\n"); + // lg::warn("DONE"); return path; } @@ -65,7 +66,7 @@ Form* lca_form(Form* a, Form* b, const Env& env) { return b; } // - // fmt::print("lca {} ({}) and {} ({})\n", a->to_string(env), (void*)a, b->to_string(env), + // lg::print("lca {} ({}) and {} ({})\n", a->to_string(env), (void*)a, b->to_string(env), // (void*)b); auto a_up = path_up_tree(a, env); @@ -84,12 +85,10 @@ Form* lca_form(Form* a, Form* b, const Env& env) { ai--; bi--; } - if (!result) { - fmt::print("{} bad form is {}\n\n{}\n", env.func->name(), a->to_string(env), b->to_string(env)); - } - ASSERT(result); + ASSERT_MSG(result, fmt::format("{} bad form is {}\n\n{}\n", env.func->name(), a->to_string(env), + b->to_string(env))); - // fmt::print("{}\n\n", result->to_string(env)); + // lg::print("{}\n\n", result->to_string(env)); return result; } @@ -333,7 +332,7 @@ FormElement* rewrite_as_send_event(LetElement* in, auto body = in->body(); if (body->size() < 4) { // from, num-params, message, call - // fmt::print(" fail: size\n"); + // lg::print(" fail: size\n"); return nullptr; } @@ -379,7 +378,7 @@ FormElement* rewrite_as_send_event(LetElement* in, if (!from_mr.matched) { return nullptr; } - fmt::print("case 1: {}\n", from_mr.maps.forms.at(1)->to_string(env)); + lg::print("case 1: {}\n", from_mr.maps.forms.at(1)->to_string(env)); not_proc = true; } @@ -399,13 +398,13 @@ FormElement* rewrite_as_send_event(LetElement* in, Matcher::any_integer(1)); auto num_params_mr = match(set_num_params_matcher, body->at(1)); if (!num_params_mr.matched) { - // fmt::print(" fail: pc1\n"); + // lg::print(" fail: pc1\n"); return nullptr; } int param_count = num_params_mr.maps.ints.at(1); ASSERT(param_count >= 0 && param_count < 7); if (body->size() != 4 + param_count) { - // fmt::print(" fail: pc3\n"); + // lg::print(" fail: pc3\n"); return nullptr; } @@ -416,7 +415,7 @@ FormElement* rewrite_as_send_event(LetElement* in, Matcher::any(1)); auto set_message_mr = match(set_message_matcher, body->at(2)); if (!set_message_mr.matched) { - // fmt::print(" fail: msg1\n"); + // lg::print(" fail: msg1\n"); return nullptr; } Form* message_name = set_message_mr.maps.forms.at(1); @@ -440,7 +439,7 @@ FormElement* rewrite_as_send_event(LetElement* in, Matcher::any(1)); auto set_param_mr = match(set_param_matcher, set_form); if (!set_param_mr.matched) { - // fmt::print(" fail: pv {} 1: {}\n", param_idx, set_form->to_string(env)); + // lg::print(" fail: pv {} 1: {}\n", param_idx, set_form->to_string(env)); return nullptr; } @@ -2066,7 +2065,7 @@ LetStats insert_lets(const Function& func, // Part 2, figure out the lca form which contains all uses of a var for (auto& kv : var_info) { - // fmt::print("--------------------- {}\n", kv.first); + // lg::print("--------------------- {}\n", kv.first); Form* lca = nullptr; for (auto fe : kv.second.elts_using_var) { lca = lca_form(lca, fe->parent_form, env); @@ -2078,7 +2077,7 @@ LetStats insert_lets(const Function& func, // Part 3, find the minimum range of FormElement's within the lca form that contain // all uses. This is the minimum possible range for a set! for (auto& kv : var_info) { - // fmt::print("Setting range for let {}\n", kv.first); + // lg::print("Setting range for let {}\n", kv.first); kv.second.start_idx = std::numeric_limits::max(); kv.second.end_idx = std::numeric_limits::min(); @@ -2099,14 +2098,14 @@ LetStats insert_lets(const Function& func, got_one = true; kv.second.start_idx = std::min(kv.second.start_idx, i); kv.second.end_idx = std::max(kv.second.end_idx, i + 1); - // fmt::print("update range {} to {} because of {}\n", kv.second.start_idx, + // lg::print("update range {} to {} because of {}\n", kv.second.start_idx, // kv.second.end_idx, kv.second.lca_form->at(i)->to_string(env)); } } ASSERT(got_one); } - // fmt::print("\n"); + // lg::print("\n"); // Part 4, sort the var infos in descending size. // this simplifies future passes. @@ -2150,7 +2149,7 @@ LetStats insert_lets(const Function& func, } } // success! - // fmt::print("Want let for {} range {} to {}\n", + // lg::print("Want let for {} range {} to {}\n", // env.get_variable_name(first_form_as_set->dst()), info.start_idx, info.end_idx); if (allowed) { LetInsertion li; @@ -2163,7 +2162,7 @@ LetStats insert_lets(const Function& func, stats.vars_in_lets++; } } else { - // fmt::print("fail for {} : {}\n", info.var_name, first_form->to_string(env)); + // lg::print("fail for {} : {}\n", info.var_name, first_form->to_string(env)); } } @@ -2179,7 +2178,7 @@ LetStats insert_lets(const Function& func, if (let_b.start_elt > let_a.start_elt && let_b.start_elt < let_a.end_elt && let_b.end_elt > let_a.end_elt) { changed = true; - // fmt::print("Resized {}'s end to {}\n", let_a.set_form->dst().to_string(env), + // lg::print("Resized {}'s end to {}\n", let_a.set_form->dst().to_string(env), // let_b.end_elt); let_a.end_elt = let_b.end_elt; } diff --git a/decompiler/analysis/mips2c.cpp b/decompiler/analysis/mips2c.cpp index 127925b9a3..3671fb62a5 100644 --- a/decompiler/analysis/mips2c.cpp +++ b/decompiler/analysis/mips2c.cpp @@ -2,6 +2,7 @@ #include "mips2c.h" +#include "common/log/log.h" #include "common/symbols.h" #include "common/util/print_float.h" #include "decompiler/Disasm/InstructionMatching.h" @@ -1183,7 +1184,7 @@ struct JumpTableBlock { void run_mips2c_jump_table(Function* f, const std::vector& jump_table_locations, GameVersion version) { - fmt::print("mips2c-jump on {}\n", f->name()); + lg::info("mips2c-jump on {}", f->name()); u32 magic_code = std::hash()(f->name()); std::unordered_map loc_to_block; for (size_t bb_idx = 0; bb_idx < f->basic_blocks.size(); bb_idx++) { diff --git a/decompiler/analysis/reg_usage.cpp b/decompiler/analysis/reg_usage.cpp index 7a6d035ee4..95decf5d4e 100644 --- a/decompiler/analysis/reg_usage.cpp +++ b/decompiler/analysis/reg_usage.cpp @@ -212,7 +212,7 @@ RegUsageInfo analyze_ir2_register_usage(const Function& function) { // also useful to know, written and unused. for (auto reg : op->write_regs()) { if (op_info.live.find(reg) == op_info.live.end()) { - // fmt::print("op {} wau {}\n", op->to_string(function.ir2.env), reg.to_string()); + // lg::print("op {} wau {}\n", op->to_string(function.ir2.env), reg.to_string()); op_info.written_and_unused.insert(reg); } } @@ -222,4 +222,4 @@ RegUsageInfo analyze_ir2_register_usage(const Function& function) { ASSERT(result.op.size() == ops->ops.size()); return result; } -} // namespace decompiler \ No newline at end of file +} // namespace decompiler diff --git a/decompiler/analysis/static_refs.cpp b/decompiler/analysis/static_refs.cpp index 7e1cfd1425..c668f118de 100644 --- a/decompiler/analysis/static_refs.cpp +++ b/decompiler/analysis/static_refs.cpp @@ -1,5 +1,6 @@ #include "static_refs.h" #include "common/goos/PrettyPrinter.h" +#include "common/log/log.h" #include "decompiler/Function/Function.h" #include "decompiler/ObjectFile/LinkedObjectFile.h" #include "decompiler/analysis/final_output.h" diff --git a/decompiler/analysis/symbol_def_map.cpp b/decompiler/analysis/symbol_def_map.cpp index 215c7481ec..24cc7785f1 100644 --- a/decompiler/analysis/symbol_def_map.cpp +++ b/decompiler/analysis/symbol_def_map.cpp @@ -1,5 +1,6 @@ #include "symbol_def_map.h" #include "common/link_types.h" +#include "common/log/log.h" #include "decompiler/ObjectFile/ObjectFileDB.h" #include "third-party/json.hpp" @@ -128,4 +129,4 @@ void SymbolMapBuilder::add_deftypes_from_top_level_function(const Function& f, } } -} // namespace decompiler \ No newline at end of file +} // namespace decompiler diff --git a/decompiler/analysis/type_analysis.cpp b/decompiler/analysis/type_analysis.cpp index f9c486e39c..9133cb6134 100644 --- a/decompiler/analysis/type_analysis.cpp +++ b/decompiler/analysis/type_analysis.cpp @@ -1,4 +1,5 @@ #include "type_analysis.h" +#include "common/log/log.h" namespace decompiler { namespace { @@ -37,7 +38,7 @@ void modify_input_types_for_casts( try { auto type_from_cast = TP_Type::make_from_ts(dts.parse_type_spec(cast.type_name)); auto original_type = state->get(cast.reg); - // fmt::print("Cast reg {} : {} -> {}\n", cast.reg.to_string(), original_type.print(), + // lg::print("Cast reg {} : {} -> {}\n", cast.reg.to_string(), original_type.print(), // type_from_cast.print()); if (original_type != type_from_cast) { // the cast will have an effect on types. If we are removing the original type, remember it @@ -63,7 +64,7 @@ void try_modify_input_types_for_casts( DecompilerTypeSystem& dts) { auto kv = casts.find(idx); if (kv != casts.end()) { - // fmt::print("at idx {}, casting:\n", idx); + // lg::print("at idx {}, casting:\n", idx); modify_input_types_for_casts(kv->second, state, changed_types, dts); } @@ -208,7 +209,7 @@ bool run_type_analysis_ir2(const TypeSpec& my_type, DecompilerTypeSystem& dts, F for (auto& info : env.stack_slot_entries) { info.second.typespec = info.second.tp_type.typespec(); // debug - // fmt::print("STACK {} : {} ({})\n", info.first, info.second.typespec.print(), + // lg::print("STACK {} : {} ({})\n", info.first, info.second.typespec.print(), // info.second.tp_type.print()); } diff --git a/decompiler/analysis/variable_naming.cpp b/decompiler/analysis/variable_naming.cpp index e419a92bcd..725b5d2e14 100644 --- a/decompiler/analysis/variable_naming.cpp +++ b/decompiler/analysis/variable_naming.cpp @@ -1,5 +1,6 @@ #include +#include "common/log/log.h" #include "decompiler/Function/Function.h" #include "decompiler/IR2/Env.h" #include "decompiler/util/DecompilerTypeSystem.h" @@ -66,7 +67,7 @@ void VarMapSSA::merge(const VarSSA& var_a, const VarSSA& var_b) { auto b = m_entries.at(var_b.m_entry_id); ASSERT(a.reg == b.reg); if (b.var_id == 0) { - // fmt::print("Merge {} <- {}\n", to_string(var_b), to_string(var_a)); + // lg::print("Merge {} <- {}\n", to_string(var_b), to_string(var_a)); for (auto& entry : m_entries) { if (entry.var_id == a.var_id && entry.reg == a.reg) { @@ -75,7 +76,7 @@ void VarMapSSA::merge(const VarSSA& var_a, const VarSSA& var_b) { } a.var_id = b.var_id; } else { - // fmt::print("Merge {} <- {}\n", to_string(var_a), to_string(var_b)); + // lg::print("Merge {} <- {}\n", to_string(var_a), to_string(var_b)); for (auto& entry : m_entries) { if (entry.var_id == b.var_id && entry.reg == b.reg) { @@ -101,17 +102,17 @@ void VarMapSSA::merge_to_first(const VarSSA& var_a, const VarSSA& var_b) { auto& a = m_entries.at(var_a.m_entry_id); auto b = m_entries.at(var_b.m_entry_id); - // fmt::print("Merge-to-first {} <- {}\n", to_string(var_a), to_string(var_b)); + // lg::print("Merge-to-first {} <- {}\n", to_string(var_a), to_string(var_b)); ASSERT(a.reg == b.reg); // for (auto& entry : m_entries) { for (size_t i = 0; i < m_entries.size(); i++) { auto& entry = m_entries.at(i); if (entry.var_id == b.var_id && entry.reg == b.reg) { - // fmt::print("remap extra {} var_id from {} to {}\n", i, entry.var_id, a.var_id); + // lg::print("remap extra {} var_id from {} to {}\n", i, entry.var_id, a.var_id); entry.var_id = a.var_id; } else { - // fmt::print("no remap at {} (prev is {} {})\n", i, entry.reg.to_charp(), entry.var_id); + // lg::print("no remap at {} (prev is {} {})\n", i, entry.reg.to_charp(), entry.var_id); } } b.var_id = a.var_id; @@ -163,7 +164,7 @@ void VarMapSSA::remap_reg(Register reg, const std::unordered_map& rema void VarMapSSA::debug_print_map() const { for (auto& entry : m_entries) { - fmt::print("[{:02d}] {} {}\n", entry.entry_id, entry.reg.to_charp(), entry.var_id); + lg::print("[{:02d}] {} {}\n", entry.entry_id, entry.reg.to_charp(), entry.var_id); } } @@ -1012,7 +1013,7 @@ void promote_register_class(const Function& func, } for (const auto& promotion : promote_map) { - // fmt::print("Promote {} to {}\n", promotion.first.print(), "uint128"); + // lg::print("Promote {} to {}\n", promotion.first.print(), "uint128"); // first reads: auto read_info = try_lookup_read(result, promotion.first); @@ -1068,21 +1069,21 @@ std::optional run_variable_renaming(const Function& function, debug_in += fmt::format(" out: {}\n\n", reg_to_string(block_info.output)); } - fmt::print("Debug Input\n{}\n----------------------------------\n", debug_in); + lg::print("Debug Input\n{}\n----------------------------------\n", debug_in); } // Create and convert to SSA auto ssa = make_rc_ssa(function, rui, ops); if (debug_prints) { - fmt::print("Basic SSA\n{}\n------------------------------------\n", ssa.print()); + lg::print("Basic SSA\n{}\n------------------------------------\n", ssa.print()); } // eliminate PHIs that are not needed, still keeping us in SSA. while (ssa.simplify()) { } if (debug_prints) { - fmt::print("Simplified SSA\n{}-------------------------------\n", ssa.print()); + lg::print("Simplified SSA\n{}-------------------------------\n", ssa.print()); } // merge special registers @@ -1099,7 +1100,7 @@ std::optional run_variable_renaming(const Function& function, ssa.merge_all_phis(); if (debug_prints) { - fmt::print("{}", ssa.print()); + lg::print("{}", ssa.print()); } if (debug_prints) { ssa.map.debug_print_map(); @@ -1110,7 +1111,7 @@ std::optional run_variable_renaming(const Function& function, // do rename ssa.remap(arg_count(function)); if (debug_prints) { - fmt::print("{}", ssa.print()); + lg::print("{}", ssa.print()); } if (function.ir2.env.has_type_analysis()) { diff --git a/decompiler/config.cpp b/decompiler/config.cpp index 69b2080118..9f2503275b 100644 --- a/decompiler/config.cpp +++ b/decompiler/config.cpp @@ -1,5 +1,6 @@ #include "config.h" +#include "common/log/log.h" #include "common/util/FileUtil.h" #include "common/util/json_util.h" @@ -29,7 +30,7 @@ Config read_config_file(const fs::path& path_to_config_file, const std::string& Config config; auto config_str = file_util::read_text_file(path_to_config_file); auto cfg = parse_commented_json(config_str, path_to_config_file.string()); - fmt::print("Config Overide: '{}'\n", override_json); + lg::info("Config Overide: '{}'\n", override_json); auto cfg_override = parse_commented_json(override_json, ""); cfg.update(cfg_override); diff --git a/decompiler/config/jak2/type_casts.jsonc b/decompiler/config/jak2/type_casts.jsonc index 2ed72cf166..23f9d4c265 100644 --- a/decompiler/config/jak2/type_casts.jsonc +++ b/decompiler/config/jak2/type_casts.jsonc @@ -1832,9 +1832,7 @@ [29, "v1", "fact-info-target"] ], "target-real-post": [[97, "f28", "float"]], - "target-compute-pole": [ - [[12,180], "s2", "swingpole"] - ], + "target-compute-pole": [[[12, 180], "s2", "swingpole"]], "tobot-start": [[26, "s5", "target"]], "(method 10 target)": [[28, "t9", "(function target none)"]], "target-compute-edge": [[48, "a0", "process-drawable"]], diff --git a/decompiler/config/jak2_ntsc_v1.jsonc b/decompiler/config/jak2_ntsc_v1.jsonc index a0a99d6a3a..4caca241f7 100644 --- a/decompiler/config/jak2_ntsc_v1.jsonc +++ b/decompiler/config/jak2_ntsc_v1.jsonc @@ -7,7 +7,7 @@ // if you want to filter to only some object names. // it will make the decompiler much faster. - "allowed_objects": [], + "allowed_objects": ["region"], "banned_objects": ["effect-control", "time-of-day", "target-util", "ctywide-scenes"], //////////////////////////// diff --git a/decompiler/data/TextureDB.cpp b/decompiler/data/TextureDB.cpp index 99a1409e92..9785bdcfb3 100644 --- a/decompiler/data/TextureDB.cpp +++ b/decompiler/data/TextureDB.cpp @@ -1,5 +1,6 @@ #include "TextureDB.h" +#include "common/log/log.h" #include "common/util/Assert.h" #include "third-party/fmt/core.h" @@ -49,11 +50,11 @@ void TextureDB::replace_textures(const fs::path& path) { for (auto& tex : textures) { fs::path full_path = base_path / tpage_names.at(tex.second.page) / (tex.second.name + ".png"); if (fs::exists(full_path)) { - fmt::print("Replacing {}\n", full_path.string().c_str()); + lg::info("Replacing {}", full_path.string().c_str()); int w, h; auto data = stbi_load(full_path.string().c_str(), &w, &h, 0, 4); // rgba channels if (!data) { - fmt::print("failed to load PNG file: {}\n", full_path.string().c_str()); + lg::warn("failed to load PNG file: {}", full_path.string().c_str()); continue; } tex.second.rgba_bytes.resize(w * h); diff --git a/decompiler/data/streamed_audio.cpp b/decompiler/data/streamed_audio.cpp index 466626a0f5..306dd47a8c 100644 --- a/decompiler/data/streamed_audio.cpp +++ b/decompiler/data/streamed_audio.cpp @@ -42,7 +42,7 @@ struct AudioDir { void debug_print() const { for (auto& e : entries) { - fmt::print("\"{}\" 0x{:07x} - 0x{:07x}\n", e.name, e.start_byte, e.end_byte); + lg::debug("\"{}\" 0x{:07x} - 0x{:07x}", e.name, e.start_byte, e.end_byte); } } }; @@ -80,9 +80,9 @@ struct VagFileHeader { char temp_name[17]; memcpy(temp_name, name, 16); temp_name[16] = '\0'; - fmt::print("{}{}{}{} v {} zero {} chan {} samp {} z {} {} {} name {}\n", magic[0], magic[1], - magic[2], magic[3], version, zero, channel_size, sample_rate, z[0], z[1], z[2], - temp_name); + lg::debug("{}{}{}{} v {} zero {} chan {} samp {} z {} {} {} name {}", magic[0], magic[1], + magic[2], magic[3], version, zero, channel_size, sample_rate, z[0], z[1], z[2], + temp_name); } }; @@ -96,7 +96,7 @@ AudioDir read_audio_dir(const fs::path& path) { u32 value; }; auto data = file_util::read_binary_file(path); - lg::info("Got {} bytes of audio dir.\n", data.size()); + lg::info("Got {} bytes of audio dir.", data.size()); auto reader = BinaryReader(data); u32 count = reader.read(); diff --git a/decompiler/level_extractor/BspHeader.cpp b/decompiler/level_extractor/BspHeader.cpp index 6644fc39e3..d3063b7276 100644 --- a/decompiler/level_extractor/BspHeader.cpp +++ b/decompiler/level_extractor/BspHeader.cpp @@ -1,6 +1,7 @@ #include "BspHeader.h" #include "common/dma/dma.h" +#include "common/log/log.h" #include "decompiler/ObjectFile/LinkedObjectFile.h" #include "decompiler/util/DecompilerTypeSystem.h" @@ -215,7 +216,7 @@ void tfrag_debug_print_unpack(Ref start, int qwc_total) { while (word_offset < qwc_total * 4) { VifCode next(deref_u32(start, word_offset)); - fmt::print("{} at: {} bytes, {} qw\n", next.print(), word_offset * 4, word_offset / 4); + lg::debug("{} at: {} bytes, {} qw", next.print(), word_offset * 4, word_offset / 4); word_offset++; switch (next.kind) { case VifCode::Kind::UNPACK_V4_16: { @@ -231,8 +232,8 @@ void tfrag_debug_print_unpack(Ref start, int qwc_total) { words[1] = deref_u32(start, word_offset++); u16 unpacked[4]; memcpy(unpacked, words, 8); - fmt::print(" [{:3d} {:3d} {:3d} {:3d}]\n", unpacked[0], unpacked[1], unpacked[2], - unpacked[3]); + lg::debug(" [{:3d} {:3d} {:3d} {:3d}]", unpacked[0], unpacked[1], unpacked[2], + unpacked[3]); } } break; @@ -249,7 +250,7 @@ void tfrag_debug_print_unpack(Ref start, int qwc_total) { words[1] = deref_u32(start, word_offset++); words[2] = deref_u32(start, word_offset++); words[3] = deref_u32(start, word_offset++); - fmt::print(" [{:3d} {:3d} {:3d} {:3d}]\n", words[0], words[1], words[2], words[3]); + lg::debug(" [{:3d} {:3d} {:3d} {:3d}]", words[0], words[1], words[2], words[3]); } } break; @@ -264,7 +265,7 @@ void tfrag_debug_print_unpack(Ref start, int qwc_total) { words[0] = deref_u32(start, word_offset++); words[1] = deref_u32(start, word_offset++); words[2] = deref_u32(start, word_offset++); - fmt::print(" [{:3d} {:3d} {:3d}]\n", words[0], words[1], words[2]); + lg::debug(" [{:3d} {:3d} {:3d}]", words[0], words[1], words[2]); } } break; @@ -274,7 +275,7 @@ void tfrag_debug_print_unpack(Ref start, int qwc_total) { words[1] = deref_u32(start, word_offset++); words[2] = deref_u32(start, word_offset++); words[3] = deref_u32(start, word_offset++); - fmt::print(" row data [{:3d} {:3d} {:3d} {:3d}]\n", words[0], words[1], words[2], words[3]); + lg::debug(" row data [{:3d} {:3d} {:3d} {:3d}]", words[0], words[1], words[2], words[3]); } break; case VifCode::Kind::STMOD: { @@ -293,7 +294,7 @@ void tfrag_debug_print_unpack(Ref start, int qwc_total) { s8 words[4]; u32 all = deref_u32(start, word_offset++); memcpy(words, &all, 4); - fmt::print(" [{:3d} {:3d} {:3d} {:3d}]\n", words[0], words[1], words[2], words[3]); + lg::debug(" [{:3d} {:3d} {:3d} {:3d}]", words[0], words[1], words[2], words[3]); } } break; case VifCode::Kind::NOP: @@ -302,7 +303,7 @@ void tfrag_debug_print_unpack(Ref start, int qwc_total) { ASSERT_MSG(false, fmt::format("unknown: {}", next.print())); } } - fmt::print("-------------------------------------------\n"); + lg::debug("-------------------------------------------"); } std::vector read_dma_chain(Ref& start, u32 qwc) { @@ -350,22 +351,22 @@ void TFragment::read_from_file(TypedRef ref, if (stats->debug_print_dma_data) { // first, common - fmt::print("DMA COMMON {}, {} qwc:\n", dmas[0].label_name, dma_qwc[0]); + lg::info("DMA COMMON {}, {} qwc:", dmas[0].label_name, dma_qwc[0]); tfrag_debug_print_unpack(dmas[0].ref, dma_qwc[0]); // next "base" - fmt::print("DMA BASE {}, {} qwc:\n", dmas[1].label_name, dma_qwc[1]); + lg::info("DMA BASE {}, {} qwc:", dmas[1].label_name, dma_qwc[1]); tfrag_debug_print_unpack(dmas[1].ref, dma_qwc[1]); // next "level0" - // fmt::print("DMA LEVEL0 {}, {} qwc:\n", dmas[0].label_name, dma_qwc[3]); + // lg::print("DMA LEVEL0 {}, {} qwc:\n", dmas[0].label_name, dma_qwc[3]); // tfrag_debug_print_unpack(dmas[0].ref, dma_qwc[3]); // next "level1" - fmt::print("DMA LEVEL1 {}, {} qwc:\n", dmas[2].label_name, dma_qwc[2]); + lg::info("DMA LEVEL1 {}, {} qwc:", dmas[2].label_name, dma_qwc[2]); tfrag_debug_print_unpack(dmas[2].ref, dma_qwc[2]); - fmt::print("qwc's: {} {} {} {}\n", dma_qwc[0], dma_qwc[1], dma_qwc[2], dma_qwc[3]); + lg::info("qwc's: {} {} {} {}", dma_qwc[0], dma_qwc[1], dma_qwc[2], dma_qwc[3]); } num_base_colors = read_plain_data_field(ref, "num-base-colors", dts); @@ -404,7 +405,7 @@ void TFragment::read_from_file(TypedRef ref, // todo shader ASSERT(num_colors / 4 == color_count); - // fmt::print("colors: {} {} {}\n", num_base_colors, num_level0_colors, num_level1_colors); + // lg::print("colors: {} {} {}\n", num_base_colors, num_level0_colors, num_level1_colors); if (version == GameVersion::Jak1) { ASSERT(read_plain_data_field(ref, "pad0", dts) == 0); ASSERT(read_plain_data_field(ref, "pad1", dts) == 0); @@ -920,7 +921,7 @@ void PrototypeBucketTie::read_from_file(TypedRef ref, break; case GameVersion::Jak2: flags = read_plain_data_field(ref, "flags", dts); - fmt::print("flag: {}\n", flags); + lg::print("flag: {}\n", flags); break; default: ASSERT(false); @@ -1576,7 +1577,7 @@ void PrototypeBucketShrub::read_from_file(TypedRef ref, } if (flags) { // lid in misty has flag 2, not sure what it means yet. - fmt::print("proto: {} flags: {}\n", name, flags); + lg::info("proto: {} flags: {}", name, flags); } in_level = read_plain_data_field(ref, "in-level", dts); utextures = read_plain_data_field(ref, "utextures", dts); diff --git a/decompiler/level_extractor/MercData.cpp b/decompiler/level_extractor/MercData.cpp index 7ff7b3611e..64382057ce 100644 --- a/decompiler/level_extractor/MercData.cpp +++ b/decompiler/level_extractor/MercData.cpp @@ -152,7 +152,7 @@ void MercByteHeader::from_ref(TypedRef tr, const DecompilerTypeSystem& dts) { } else { // ASSERT(!got_end); if (got_end) { - // fmt::print("got something after the end\n"); // todo, should investigate more + // lg::print("got something after the end\n"); // todo, should investigate more } } } @@ -203,10 +203,10 @@ TypedRef MercFragment::from_ref(TypedRef tr, const DecompilerTypeSystem& dts, const MercFragmentControl& control, const MercCtrlHeader& main_control) { - // fmt::print("frag::from_ref:\n{}\n", control.print()); + // lg::print("frag::from_ref:\n{}\n", control.print()); TypedRef byte_hdr(get_field_ref(tr, "header", dts), dts.ts.lookup_type("merc-byte-header")); header.from_ref(byte_hdr, dts); - // fmt::print("{}\n", header.print()); + // lg::print("{}\n", header.print()); // all these offsets are super confusing. // the DMA transfers require source and dest addresses/sized to have alignment of 16 bytes. @@ -225,7 +225,7 @@ TypedRef MercFragment::from_ref(TypedRef tr, // dsll32 s0, v0, 4 // daddu t3, t2, s0 u32 my_u4_count = ((control.unsigned_four_count + 3) / 4) * 16; - // fmt::print("my u4: {} ({} qwc)\n", my_u4_count, my_u4_count / 16); + // lg::print("my u4: {} ({} qwc)\n", my_u4_count, my_u4_count / 16); for (u32 w = 0; w < my_u4_count / 4; w++) { u32 val = deref_u32(tr.ref, w); memcpy(unsigned_four_including_header.emplace_back().data(), &val, 4); @@ -237,7 +237,7 @@ TypedRef MercFragment::from_ref(TypedRef tr, // srl s0, s0, 2 // dsll32 s2, s0, 4 u32 my_l4_count = my_u4_count + ((control.lump_four_count + 3) / 4) * 16; - // fmt::print("my l4: {} ({} qwc)\n", my_l4_count, my_l4_count / 16); + // lg::print("my l4: {} ({} qwc)\n", my_l4_count, my_l4_count / 16); // end of lump should align with mm (main memory?) fp off. which // is used for accessing the fp data in main memory. ASSERT(my_l4_count / 16 == header.mm_quadword_fp_off); @@ -409,4 +409,4 @@ std::string MercCtrl::print() { return result; } -} // namespace decompiler \ No newline at end of file +} // namespace decompiler diff --git a/decompiler/level_extractor/extract_collide_frags.cpp b/decompiler/level_extractor/extract_collide_frags.cpp index d32fd25b83..5f7847e9fd 100644 --- a/decompiler/level_extractor/extract_collide_frags.cpp +++ b/decompiler/level_extractor/extract_collide_frags.cpp @@ -179,7 +179,7 @@ void extract_pats(CollideListItem& item) { auto pat_idx = deref_u8(item.mesh->packed_data, byte_offset++); u32 pat = deref_u32(item.mesh->pat_array, pat_idx); - // fmt::print("pat @ {} is 0x{:x}\n", pat_idx, pat); + // lg::print("pat @ {} is 0x{:x}\n", pat_idx, pat); f.pat = pat; } } diff --git a/decompiler/level_extractor/extract_level.cpp b/decompiler/level_extractor/extract_level.cpp index b20ce552af..aa6e857c88 100644 --- a/decompiler/level_extractor/extract_level.cpp +++ b/decompiler/level_extractor/extract_level.cpp @@ -3,6 +3,7 @@ #include #include +#include "common/log/log.h" #include "common/util/FileUtil.h" #include "common/util/SimpleThreadGroup.h" #include "common/util/compress.h" @@ -38,18 +39,18 @@ std::optional get_bsp_file(const std::vector */ bool is_valid_bsp(const decompiler::LinkedObjectFile& file) { if (file.segments != 1) { - fmt::print("Got {} segments, but expected 1\n", file.segments); + lg::error("Got {} segments, but expected 1", file.segments); return false; } auto& first_word = file.words_by_seg.at(0).at(0); if (first_word.kind() != decompiler::LinkedWord::TYPE_PTR) { - fmt::print("Expected the first word to be a type pointer, but it wasn't.\n"); + lg::error("Expected the first word to be a type pointer, but it wasn't."); return false; } if (first_word.symbol_name() != "bsp-header") { - fmt::print("Expected to get a bsp-header, but got {} instead.\n", first_word.symbol_name()); + lg::error("Expected to get a bsp-header, but got {} instead.", first_word.symbol_name()); return false; } @@ -126,7 +127,7 @@ std::vector extract_bsp_from_level(const ObjectFileDB } std::string level_name = bsp_rec->name.substr(0, bsp_rec->name.length() - 4); - fmt::print("Processing level {} ({})\n", dgo_name, level_name); + lg::info("Processing level {} ({})", dgo_name, level_name); const auto& bsp_file = db.lookup_record(*bsp_rec); bool ok = is_valid_bsp(bsp_file.linked_data); ASSERT(ok); @@ -140,7 +141,7 @@ std::vector extract_bsp_from_level(const ObjectFileDB /* level_tools::PrintSettings settings; settings.expand_collide = true; - fmt::print("{}\n", bsp_header.print(settings)); + lg::print("{}\n", bsp_header.print(settings)); */ const std::set tfrag_trees = { @@ -189,7 +190,7 @@ std::vector extract_bsp_from_level(const ObjectFileDB extract_collide_frags(as_collide_frags, all_ties, fmt::format("{}-{}-collide", dgo_name, i++), level_data, false); } else { - // fmt::print(" unsupported tree {}\n", draw_tree->my_type()); + // lg::print(" unsupported tree {}\n", draw_tree->my_type()); } } level_data.level_name = level_name; @@ -228,10 +229,10 @@ void extract_common(const ObjectFileDB& db, auto compressed = compression::compress_zstd(ser.get_save_result().first, ser.get_save_result().second); - fmt::print("stats for {}\n", dgo_name); + lg::info("stats for {}", dgo_name); print_memory_usage(tfrag_level, ser.get_save_result().second); - fmt::print("compressed: {} -> {} ({:.2f}%)\n", ser.get_save_result().second, compressed.size(), - 100.f * compressed.size() / ser.get_save_result().second); + lg::info("compressed: {} -> {} ({:.2f}%)", ser.get_save_result().second, compressed.size(), + 100.f * compressed.size() / ser.get_save_result().second); file_util::write_binary_file( output_folder / fmt::format("{}.fr3", dgo_name.substr(0, dgo_name.length() - 4)), compressed.data(), compressed.size()); @@ -265,10 +266,10 @@ void extract_from_level(const ObjectFileDB& db, level_data.serialize(ser); auto compressed = compression::compress_zstd(ser.get_save_result().first, ser.get_save_result().second); - fmt::print("stats for {}\n", dgo_name); + lg::info("stats for {}", dgo_name); print_memory_usage(level_data, ser.get_save_result().second); - fmt::print("compressed: {} -> {} ({:.2f}%)\n", ser.get_save_result().second, compressed.size(), - 100.f * compressed.size() / ser.get_save_result().second); + lg::info("compressed: {} -> {} ({:.2f}%)", ser.get_save_result().second, compressed.size(), + 100.f * compressed.size() / ser.get_save_result().second); file_util::write_binary_file( output_folder / fmt::format("{}.fr3", dgo_name.substr(0, dgo_name.length() - 4)), compressed.data(), compressed.size()); diff --git a/decompiler/level_extractor/extract_merc.cpp b/decompiler/level_extractor/extract_merc.cpp index 73c1873c58..74a01f65d0 100644 --- a/decompiler/level_extractor/extract_merc.cpp +++ b/decompiler/level_extractor/extract_merc.cpp @@ -1,5 +1,6 @@ #include "extract_merc.h" +#include "common/log/log.h" #include "common/util/FileUtil.h" #include "common/util/colors.h" @@ -198,8 +199,8 @@ void update_mode_from_alpha1(GsAlpha reg, DrawMode& mode) { else { // unsupported blend: a 0 b 1 c 0 d 2 is this part of generic? - fmt::print("unsupported blend: a {} b {} c {} d {}\n", (int)reg.a_mode(), (int)reg.b_mode(), - (int)reg.c_mode(), (int)reg.d_mode()); + lg::warn("unsupported blend: a {} b {} c {} d {}", (int)reg.a_mode(), (int)reg.b_mode(), + (int)reg.c_mode(), (int)reg.d_mode()); mode.set_alpha_blend(DrawMode::AlphaBlend::SRC_DST_SRC_DST); // ASSERT(false); } @@ -297,8 +298,8 @@ void handle_frag(const std::string& debug_name, MercMemory& memory) { (void)frag_ctrl; (void)debug_name; - // fmt::print("handling frag: {}\n", debug_name); - // fmt::print("{}\n", frag.print()); + // lg::print("handling frag: {}\n", debug_name); + // lg::print("{}\n", frag.print()); // we'll iterate through the lump and rgba data int lump_ptr = 0; // vertex data starts at the beginning of "lump" @@ -490,7 +491,7 @@ void handle_frag(const std::string& debug_name, // dst1_adc = dst0_adc && (mat0_flag >= 0); // dst0_adc = !dst0_adc; // dst1_adc = !dst1_adc; - // fmt::print("{}\n", dst1_adc); + // lg::print("{}\n", dst1_adc); } // write to two spots in memory @@ -510,7 +511,7 @@ void handle_frag(const std::string& debug_name, memory.memory.at(vtx.dst1 + 2).kind = MercOutputQuadword::Kind::INVALID; /* - fmt::print("place vertex {} @ {} {}: {} (adc {} {}) {}\n", current_vtx_idx, vtx.dst0, vtx.dst1, + lg::print("place vertex {} @ {} {}: {} (adc {} {}) {}\n", current_vtx_idx, vtx.dst0, vtx.dst1, vtx.pos.to_string_aligned(), dst0_adc, dst1_adc, mat1_flag); */ @@ -542,7 +543,7 @@ std::vector index_list_from_packet(u32 vtx_ptr, u32 nloop, const MercMemory prev_vtx = vtx_mem.vtx_idx; } else { // missing vertex! - fmt::print("MISSING VERTEX at {}\n", vtx_ptr); + lg::warn("MISSING VERTEX at {}", vtx_ptr); result.push_back(UINT32_MAX); } @@ -759,7 +760,7 @@ ConvertedMercEffect convert_merc_effect(const MercEffect& input_effect, u32 srcdst_ptr = frag.header.srcdest_off; for (u32 sci = 0; sci < frag.header.samecopy_cnt; sci++) { auto& cpy = frag.unsigned_four_including_header[srcdst_ptr]; - // fmt::print("sci: {}\n", cpy.to_string_hex_byte()); + // lg::print("sci: {}\n", cpy.to_string_hex_byte()); u32 src = cpy[0]; auto& vert = merc_memories[memory_buffer_toggle].memory.at(src); u32 dst = cpy[1]; @@ -771,7 +772,7 @@ ConvertedMercEffect convert_merc_effect(const MercEffect& input_effect, dvert.adc = !dvert.adc; } } else { - fmt::print("sc missing vert\n"); + lg::warn("sc missing vert"); dvert.kind = MercOutputQuadword::Kind::INVALID; } @@ -781,7 +782,7 @@ ConvertedMercEffect convert_merc_effect(const MercEffect& input_effect, // "cross" copy from the other output buffer for (u32 cci = 0; cci < frag.header.crosscopy_cnt; cci++) { auto& cpy = frag.unsigned_four_including_header[srcdst_ptr]; - // fmt::print("cci: {}\n", cpy.to_string_hex_byte()); + // lg::print("cci: {}\n", cpy.to_string_hex_byte()); u32 src = cpy[0]; auto& vert = merc_memories[memory_buffer_toggle ^ 1].memory.at(src); u32 dst = cpy[1]; @@ -793,7 +794,7 @@ ConvertedMercEffect convert_merc_effect(const MercEffect& input_effect, dvert.adc = !dvert.adc; } } else { - fmt::print("cc missing vert\n"); + lg::warn("cc missing vert"); dvert.kind = MercOutputQuadword::Kind::INVALID; } srcdst_ptr++; diff --git a/decompiler/level_extractor/extract_shrub.cpp b/decompiler/level_extractor/extract_shrub.cpp index 48daeba7c6..78c50be73c 100644 --- a/decompiler/level_extractor/extract_shrub.cpp +++ b/decompiler/level_extractor/extract_shrub.cpp @@ -2,6 +2,7 @@ #include +#include "common/log/log.h" #include "common/util/FileUtil.h" #include "decompiler/ObjectFile/LinkedObjectFile.h" @@ -157,8 +158,8 @@ DrawSettings adgif_to_draw_mode(const AdGifData& ad, // ADGIF 0 bool weird = (u8)ad.tex0_addr != (u32)GsRegisterAddress::TEX0_1; if (weird) { - fmt::print("---------------- WEIRD: 0x{:x}\n", ad.tex0_addr); - fmt::print("i have {} verts\n", count); + lg::info("---------------- WEIRD: 0x{:x}", ad.tex0_addr); + lg::info("i have {} verts", count); } else { ASSERT(ad.tex0_data == 0 || ad.tex0_data == 0x800000000); // note: decal?? todo } @@ -171,7 +172,7 @@ DrawSettings adgif_to_draw_mode(const AdGifData& ad, u32 new_tex = remap_texture(original_tex, map); // try remapping it if (original_tex != new_tex) { - fmt::print("map from 0x{:x} to 0x{:x}\n", original_tex, new_tex); + lg::info("map from 0x{:x} to 0x{:x}", original_tex, new_tex); } // texture the texture page/texture index, and convert to a PC port texture ID u32 tpage = new_tex >> 20; @@ -181,7 +182,7 @@ DrawSettings adgif_to_draw_mode(const AdGifData& ad, auto tex = tdb.textures.find(tex_combo); ASSERT(tex != tdb.textures.end()); if (weird) { - fmt::print("tex: {}\n", tex->second.name); + lg::info("tex: {}", tex->second.name); } // ADGIF 2 @@ -251,7 +252,7 @@ ShrubProtoInfo extract_proto(const shrub_types::PrototypeBucketShrub& proto, memcpy(adgif_data.data(), frag.textures.data(), frag.textures.size()); if (frag_idx == 0 && proto.name == "vil2-cattail.mb") { - fmt::print("Skipping broken village2 thing\n"); + lg::info("Skipping broken village2 thing"); continue; } diff --git a/decompiler/level_extractor/extract_tfrag.cpp b/decompiler/level_extractor/extract_tfrag.cpp index 6e4c2dd2e3..1f3d3475eb 100644 --- a/decompiler/level_extractor/extract_tfrag.cpp +++ b/decompiler/level_extractor/extract_tfrag.cpp @@ -3,6 +3,7 @@ #include "common/custom_data/pack_helpers.h" #include "common/dma/dma.h" #include "common/dma/gs.h" +#include "common/log/log.h" #include "common/util/Assert.h" #include "common/util/FileUtil.h" @@ -42,7 +43,7 @@ bool verify_node_indices_from_array(const level_tools::DrawableInlineArray* arra if (as_tfrags) { for (auto& elt : as_tfrags->tfragments) { if (elt.id != start) { - fmt::print("bad frag: exp {} got {}\n", start, elt.id); + lg::error("bad frag: exp {} got {}", start, elt.id); return false; } start++; @@ -52,7 +53,7 @@ bool verify_node_indices_from_array(const level_tools::DrawableInlineArray* arra } else if (as_nodes) { for (auto& elt : as_nodes->draw_nodes) { if (elt.id != start) { - fmt::print("bad node: exp {} got {}\n", start, elt.id); + lg::error("bad node: exp {} got {}", start, elt.id); return false; } start++; @@ -60,7 +61,7 @@ bool verify_node_indices_from_array(const level_tools::DrawableInlineArray* arra *end = start; return true; } else { - fmt::print("bad node array type: {}\n", array->my_type()); + lg::error("bad node array type: {}", array->my_type()); return false; } } @@ -368,7 +369,7 @@ int handle_unpack_v4_16_mode1(const VifCode& code, qw[3] = row[3] + (u32)deref_ptr(dma + offset); offset += 2; - // fmt::print(" unpack rgba?: {:x} {:x} {:x} {:x}\n", qw[0], qw[1], qw[2], qw[3]); + // lg::print(" unpack rgba?: {:x} {:x} {:x} {:x}\n", qw[0], qw[1], qw[2], qw[3]); memcpy(vu_mem + (dest_qw * 16), qw, 16); } ASSERT((offset % 4) == 0); @@ -456,7 +457,7 @@ void emulate_chain(UnpackState& state, u32 max_words, const u32* start, u8* vu_m while (word < max_words) { VifCode code(start[word]); word++; - // fmt::print("{}\n", code.print()); + // lg::print("{}\n", code.print()); switch (code.kind) { case VifCode::Kind::STROW: state.row_init = true; @@ -737,7 +738,7 @@ bool emulate_kick_subroutine(VuMemWrapper& mem, // iblez vi12, L123 // iaddi vi09, vi09, 0x1 vi09_draw_addr_book++; // on to the next chunk - // fmt::print("VI09 now {}\n", vars.vi09); + // lg::print("VI09 now {}\n", vars.vi09); // no need for new adgifs, just a new strgif. if (((s16)vi12_vert_count) > 0) { @@ -759,10 +760,10 @@ bool emulate_kick_subroutine(VuMemWrapper& mem, // ilwr.x vi12, vi09 vi12_vert_count = mem.ilw_data(vi09_draw_addr_book, 0); // next vert count! if (DEBUG) { - fmt::print("continue with this adgif, but new strgif. next {} verts (kick zone now {})\n", - vi12_vert_count, vi06_kick_zone_ptr); + lg::debug("continue with this adgif, but new strgif. next {} verts (kick zone now {})", + vi12_vert_count, vi06_kick_zone_ptr); } - // fmt::print("didn't kick, vi12 now {}\n", vars.vi12); + // lg::print("didn't kick, vi12 now {}\n", vars.vi12); all_draws.push_back(current_draw); current_draw.verts.clear(); return false; @@ -773,10 +774,10 @@ bool emulate_kick_subroutine(VuMemWrapper& mem, u16 vi01 = mem.ilw_data(vi09_draw_addr_book - 1, 1); // ? // ilw.z vi13, -1(vi09) vi13_adgifs = mem.ilw_data(vi09_draw_addr_book - 1, 2); // load new adgif addr - // fmt::print("VI09 loads: {} {}\n", m_ptrs.vi01, vars.vi13); + // lg::print("VI09 loads: {} {}\n", m_ptrs.vi01, vars.vi13); // ibeq vi00, vi12, L126 // ilwr.x vi14, vi10 - // fmt::print("val is {}: {}\n", vars.vi10, ilw_kick_zone(vars.vi10, 0)); + // lg::print("val is {}: {}\n", vars.vi10, ilw_kick_zone(vars.vi10, 0)); // vars.vi14 = mem.ilw_kick_zone(vi10_start_of_vert_kick_data, 0); old vert count if (vi12_vert_count != 0) { // ibltz vi01, L124 @@ -838,10 +839,10 @@ bool emulate_kick_subroutine(VuMemWrapper& mem, // ilwr.x vi12, vi09 vi12_vert_count = mem.ilw_data(vi09_draw_addr_book, 0); if (DEBUG) { - fmt::print("done with adgifs but not packet, now moving on to another with {}\n", - (s16)vi12_vert_count); + lg::debug("done with adgifs but not packet, now moving on to another with {}", + (s16)vi12_vert_count); } - // fmt::print("didn't kick 2, vi12 now {}\n", vars.vi12); + // lg::print("didn't kick 2, vi12 now {}\n", vars.vi12); return false; } @@ -857,7 +858,7 @@ bool emulate_kick_subroutine(VuMemWrapper& mem, // ibgez vi13, L125 // iswr.x vi14, vi10 - // fmt::print("kick zone store: {}\n", vars.vi14); + // lg::print("kick zone store: {}\n", vars.vi14); // store_u32_kick_zone(vars.vi14, vars.vi10, 0); set eop. if (((s16)vi13_adgifs) < 0) { // xgkick vi01 @@ -944,7 +945,7 @@ bool emulate_kick_subroutine(VuMemWrapper& mem, // jr vi15 // ilwr.x vi12, vi09 vi12_vert_count = mem.ilw_data(vi09_draw_addr_book, 0); - // fmt::print("did kick, vi12 now {}\n", vars.vi12); + // lg::print("did kick, vi12 now {}\n", vars.vi12); return false; } @@ -960,10 +961,10 @@ bool emulate_kick_subroutine(VuMemWrapper& mem, all_draws.push_back(current_draw); current_draw.verts.clear(); // iadd vi14, vi14, vi11 - // fmt::print("before add: {}\n", vars.vi14); + // lg::print("before add: {}\n", vars.vi14); // vars.vi14 += vars.vi11; // iswr.x vi14, vi10 - // fmt::print("kick zone store: {}\n", vars.vi14); + // lg::print("kick zone store: {}\n", vars.vi14); // store_u32_kick_zone(vars.vi14, vars.vi10, 0); // lq.xyzw vf04, 664(vi00) // todo don't think I needed that load of ambient @@ -978,7 +979,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra VuMemWrapper& mem, TFragColorUnpack& color_indices, TFragExtractStats* /*stats*/) { - // fmt::print("tfrag exec. offset of colors = {}\n", color_indices.unpack_qw_addr); + // lg::print("tfrag exec. offset of colors = {}\n", color_indices.unpack_qw_addr); std::vector all_draws; TFragDraw current_draw; @@ -990,7 +991,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // ilw.w vi08, 4(vi14) | nop u16 vi08_adgif_base = mem.ilw_data(4 + vi14, 3); // is an address, v4/32 unpack. - // fmt::print("------------- VI08 init: {}\n", vars.vi08); + // lg::print("------------- VI08 init: {}\n", vars.vi08); // ilw.z vi09, 4(vi14) | nop u16 vi09_draw_addr_book = mem.ilw_data(4 + vi14, 2); // is an input address, v4/8 unpack (seems small?) @@ -999,17 +1000,17 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra 3 + vi14, 1); // is an input address (v4-8 with strow). a list of addresses for v4-16's with strow - // fmt::print("-------VI03 init: {}\n", vars.vi03); + // lg::print("-------VI03 init: {}\n", vars.vi03); if (DEBUG) { // small, like 9, 54, 66 level_tools::PrintSettings settings; settings.print_tfrag = true; - fmt::print("{}\n", frag.print(settings, 0)); - fmt::print("ints: {} {} {}\n", vi08_adgif_base, vi09_draw_addr_book, vi03_vert_addr_book); + lg::debug("{}", frag.print(settings, 0)); + lg::debug("ints: {} {} {}", vi08_adgif_base, vi09_draw_addr_book, vi03_vert_addr_book); } - // fmt::print("vi09: #x{:x} ({})\n", vars.vi09, vars.vi14); + // lg::print("vi09: #x{:x} ({})\n", vars.vi09, vars.vi14); // fcset 0x0 | nop // iaddi vi07, vi00, -0x1 | nop @@ -1035,7 +1036,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra ASSERT(vi03_vert_addr_book < 328); // should be a buffer 0 addr u16 vi02_pre_vtx_ptr = mem.ilw_data(vi03_vert_addr_book, 0); // is an addr? v4/16 with strom if (DEBUG) { - fmt::print("vi02-warmup 0: {}\n", vi02_pre_vtx_ptr); + lg::debug("vi02-warmup 0: {}", vi02_pre_vtx_ptr); } // lq.xyzw vf09, 8(vi14) | nop @@ -1052,8 +1053,8 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra float vf28_w_addr_of_next_vtx = vf28_load_temp.w(); // addr, of v3-32, with 2, 1 if (DEBUG) { - fmt::print("vf28 load 0: x_f {} y_f {} z_u32 {}\n", vf28_x, vf28_y, - float_2_u32(vf28_w_addr_of_next_vtx)); + lg::debug("vf28 load 0: x_f {} y_f {} z_u32 {}", vf28_x, vf28_y, + float_2_u32(vf28_w_addr_of_next_vtx)); }; // they rotate vi06 to alternate the kick zone buffer. @@ -1065,13 +1066,13 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // ilwr.x vi12, vi09 | nop u16 vi12_vert_count = mem.ilw_data(vi09_draw_addr_book, 0); // some sort of counter? if (DEBUG) { - fmt::print("vi12: 0x{:x}\n", vi12_vert_count); + lg::debug("vi12: 0x{:x}", vi12_vert_count); } // ilwr.z vi13, vi09 | nop u16 vi13_adgifs = mem.ilw_data(vi09_draw_addr_book, 2); if (DEBUG) { - fmt::print("vi13: 0x{:x}\n", vi13_adgifs); + lg::debug("vi13: 0x{:x}", vi13_adgifs); } // mtir vi04, vf28.w | subz.xyz vf24, vf28, vf02 @@ -1092,7 +1093,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // ilwr.y vi02, vi03 | nop vi02_pre_vtx_ptr = mem.ilw_data(vi03_vert_addr_book, 1); if (DEBUG) { - fmt::print("vi02-warmup 1: {}\n", vi02_pre_vtx_ptr); + lg::debug("vi02-warmup 1: {}", vi02_pre_vtx_ptr); } // vertex load @@ -1119,9 +1120,9 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra vf12_vtx_pos_0 = itof0(vf12_vtx_pos_0); if (DEBUG) { - fmt::print("vf28 load 0: x_f {} y_f {} w_u32 {}\n", vf28_x, vf28_y, - float_2_u32(vf28_w_addr_of_next_vtx)); - fmt::print("vtx w0: {}\n", vf12_vtx_pos_0.to_string_aligned()); + lg::debug("vf28 load 0: x_f {} y_f {} w_u32 {}", vf28_x, vf28_y, + float_2_u32(vf28_w_addr_of_next_vtx)); + lg::debug("vtx w0: {}", vf12_vtx_pos_0.to_string_aligned()); }; // mfir.w vf24, vi06 | nop @@ -1168,7 +1169,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // ilwr.z vi02, vi03 | nop vi02_pre_vtx_ptr = mem.ilw_data(vi03_vert_addr_book, 2); if (DEBUG) { - fmt::print("pre-vtx-vi02-warmup 2: {}\n", vi02_pre_vtx_ptr); + lg::debug("pre-vtx-vi02-warmup 2: {}", vi02_pre_vtx_ptr); } // lq.xyzw vf13, 0(vi04) | madday.xyzw ACC, vf07, vf12 @@ -1234,7 +1235,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // ilwr.w vi02, vi03 | mul.xyz vf24, vf24, Q vi02_pre_vtx_ptr = mem.ilw_data(vi03_vert_addr_book, 3); if (DEBUG) { - fmt::print("pre-vtx-vi02-warmup 3: {}\n", vi02_pre_vtx_ptr); + lg::debug("pre-vtx-vi02-warmup 3: {}", vi02_pre_vtx_ptr); } // lq.xyzw vf14, 0(vi04) | madday.xyzw ACC, vf07, vf13 @@ -1355,12 +1356,12 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // ibeq vi05, vi06, L133 | miniz.w vf13, vf13, vf01 bool take_branch = (vi05_end_of_vert_kick_data == vi06_kick_zone_ptr); - // fmt::print("L129 prog: {} {}\n", vars.vi05, vars.vi06_kick_zone_ptr); + // lg::print("L129 prog: {} {}\n", vars.vi05, vars.vi06_kick_zone_ptr); // vars.vf13_root_pos_1.w() = std::min(vars.vf13_root_pos_1.w(), m_tfrag_data.fog.z()); // sqi.xyzw vf12, vi06 | clipw.xyz vf17, vf17 vertex_pipeline[0].pre_cam_trans_pos = vf12_vtx_pos_0; // todo move down? - // fmt::print("C: vf12 store: {}\n", int_vec_debug(vars.vf12_root_pos_0)); + // lg::print("C: vf12 store: {}\n", int_vec_debug(vars.vf12_root_pos_0)); current_draw.verts.push_back(vertex_pipeline[0]); vi06_kick_zone_ptr++; // m_clip_and_3ffff = clip_xyz_plus_minus(vars.vf17_scaled_pos_1); @@ -1426,14 +1427,14 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra vertex_pipeline[1].stq[0] = vf25_stq_1[0]; vertex_pipeline[1].stq[1] = vf25_stq_1[1]; vertex_pipeline[1].stq[2] = vf25_stq_1[2]; - // fmt::print("A: vf25 store: {}\n", vars.vf25.to_string_aligned()); + // lg::print("A: vf25 store: {}\n", vars.vf25.to_string_aligned()); vi06_kick_zone_ptr++; // vf14 += m_tfrag_data.hvdf_offset; // sqi.xyzw vf21, vi06 | ftoi4.xyzw vf13, vf13 // store_vector_kick_zone(vars.vi06_kick_zone_ptr, vars.vf21); vertex_pipeline[1].rgba = vf21_vtx_rgba_1; - // fmt::print("B: vf21 store: {}\n", int_vec_debug(vars.vf21)); + // lg::print("B: vf21 store: {}\n", int_vec_debug(vars.vf21)); vi06_kick_zone_ptr++; // vars.vf13_root_pos_1 = ftoi4(vars.vf13_root_pos_1); @@ -1462,7 +1463,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // store_vector_kick_zone(vars.vi06_kick_zone_ptr, vars.vf13_root_pos_1); vertex_pipeline[1].pre_cam_trans_pos = vf13_vtx_pos_1; current_draw.verts.push_back(vertex_pipeline[1]); - // fmt::print("C: vf13 store: {}\n", int_vec_debug(vars.vf13_root_pos_1)); + // lg::print("C: vf13 store: {}\n", int_vec_debug(vars.vf13_root_pos_1)); vi06_kick_zone_ptr++; // m_clip_and_3ffff = clip_xyz_plus_minus(vars.vf18_scaled_pos_2); @@ -1517,7 +1518,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // lq.xyzw vf21, 1(vi04) | maddz.xyzw vf12, vf08, vf12 vf21_vtx_rgba_1 = color_indices.load_color_idx(vi04_vtx_ptr + 1); - // fmt::print("vf21 load from: {}\n", vars.vi04 + 1); + // lg::print("vf21 load from: {}\n", vars.vi04 + 1); // vars.vf12_root_pos_0 = m_acc + in.vf08_cam_mat_z * vars.vf12_root_pos_0.z(); // sqi.xyzw vf26, vi06 | add.xyzw vf15, vf15, vf10 @@ -1525,14 +1526,14 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra vertex_pipeline[2].stq[0] = vf26_stq_2[0]; vertex_pipeline[2].stq[1] = vf26_stq_2[1]; vertex_pipeline[2].stq[2] = vf26_stq_2[2]; - // fmt::print("A: vf26 store: {}\n", vars.vf26.to_string_aligned()); + // lg::print("A: vf26 store: {}\n", vars.vf26.to_string_aligned()); vi06_kick_zone_ptr++; // vars.vf15_loop_pos_1 += m_tfrag_data.hvdf_offset; // sqi.xyzw vf22, vi06 | ftoi4.xyzw vf14, vf14 // store_vector_kick_zone(vars.vi06_kick_zone_ptr, vars.vf22); vertex_pipeline[2].rgba = vf22_vtx_rgba_2; - // fmt::print("B: vf22 store: {}\n", int_vec_debug(vars.vf22)); + // lg::print("B: vf22 store: {}\n", int_vec_debug(vars.vf22)); vi06_kick_zone_ptr++; // vars.vf14_loop_pos_0 = ftoi4(vars.vf14_loop_pos_0); @@ -1560,7 +1561,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra vertex_pipeline[2].pre_cam_trans_pos = vf14_vtx_pos_2; current_draw.verts.push_back(vertex_pipeline[2]); - // fmt::print("C: vf14 store: {}\n", int_vec_debug(vars.vf14_loop_pos_0)); + // lg::print("C: vf14 store: {}\n", int_vec_debug(vars.vf14_loop_pos_0)); vi06_kick_zone_ptr++; // m_clip_and_3ffff = clip_xyz_plus_minus(vars.vf19_scaled_pos_3); @@ -1623,7 +1624,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra vertex_pipeline[3].stq[0] = vf27_vtx_stq_3[0]; vertex_pipeline[3].stq[1] = vf27_vtx_stq_3[1]; vertex_pipeline[3].stq[2] = vf27_vtx_stq_3[2]; - // fmt::print("A: vf27 store: {}\n", vars.vf27.to_string_aligned()); + // lg::print("A: vf27 store: {}\n", vars.vf27.to_string_aligned()); vi06_kick_zone_ptr++; // vars.vf12_root_pos_0 += m_tfrag_data.hvdf_offset; @@ -1631,7 +1632,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // store_vector_kick_zone(vars.vi06_kick_zone_ptr, vars.vf23); vertex_pipeline[3].rgba = vf23_vtx_rgba_3; - // fmt::print("B: vf23 store: {}\n", int_vec_debug(vars.vf23)); + // lg::print("B: vf23 store: {}\n", int_vec_debug(vars.vf23)); vi06_kick_zone_ptr++; // vars.vf15_loop_pos_1 = ftoi4(vars.vf15_loop_pos_1); @@ -1652,7 +1653,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra // ibne vi05, vi06, L128 | miniz.w vf12, vf12, vf01 take_branch = (vi05_end_of_vert_kick_data != vi06_kick_zone_ptr); - // fmt::print("kick check: {} {}\n", vars.vi05, vars.vi06_kick_zone_ptr); + // lg::print("kick check: {} {}\n", vars.vi05, vars.vi06_kick_zone_ptr); // vars.vf12_root_pos_0.w() = std::min(vars.vf12_root_pos_0.w(), m_tfrag_data.fog.z()); // sqi.xyzw vf15, vi06 | clipw.xyz vf16, vf16 @@ -1660,7 +1661,7 @@ std::vector emulate_tfrag_execution(const level_tools::TFragment& fra vertex_pipeline[3].pre_cam_trans_pos = vf15_vtx_pos_3; current_draw.verts.push_back(vertex_pipeline[3]); vi06_kick_zone_ptr++; - // fmt::print("C: vf15 store: {}\n", int_vec_debug(vars.vf15_loop_pos_1)); + // lg::print("C: vf15 store: {}\n", int_vec_debug(vars.vf15_loop_pos_1)); // m_clip_and_3ffff = clip_xyz_plus_minus(vars.vf16_scaled_pos_0); if (!take_branch) { @@ -1815,7 +1816,7 @@ u32 remap_texture(u32 original, const std::vector& ma auto masked = original & 0xffffff00; for (auto& t : map) { if (t.original_texid == masked) { - fmt::print("OKAY! remapped!\n"); + lg::info("OKAY! remapped!"); return t.new_texid | 20; } } @@ -1896,11 +1897,11 @@ void process_draw_mode(std::vector& all_draws, u32 original_tex = draw.get_adgif_upper(ad_idx); u32 new_tex = remap_texture(original_tex, map); if (original_tex != new_tex) { - fmt::print("map from 0x{:x} to 0x{:x}\n", original_tex, new_tex); + lg::info("map from 0x{:x} to 0x{:x}", original_tex, new_tex); } u32 tpage = new_tex >> 20; u32 tidx = (new_tex >> 8) & 0b1111'1111'1111; - // fmt::print("texture: {} : {}\n", tpage, tidx); + // lg::print("texture: {} : {}\n", tpage, tidx); draw.tpage = tpage; draw.tex_in_page = tidx; } @@ -1922,8 +1923,8 @@ void process_draw_mode(std::vector& all_draws, update_mode_from_alpha1(val, mode); break; default: - fmt::print("Address {} ({}) is not supported in process_draw_mode\n", - register_address_name(addr), ad_idx); + lg::info("Address {} ({}) is not supported in process_draw_mode", + register_address_name(addr), ad_idx); } } draw.mode = mode; @@ -1975,7 +1976,7 @@ std::map> make_draw_groups(std::vector& } } - // fmt::print(" grouped to get {} draw calls\n", dc); + // lg::print(" grouped to get {} draw calls\n", dc); return result; } @@ -2180,7 +2181,7 @@ void extract_tfrag(const level_tools::DrawableTreeTfrag* tree, } bool ok = verify_node_indices(tree); ASSERT(ok); - // fmt::print(" tree has {} arrays and {} tfragments\n", tree->length, + // lg::print(" tree has {} arrays and {} tfragments\n", tree->length, // as_tfrag_array->length); auto vis_nodes = extract_vis_data(tree, as_tfrag_array->tfragments.front().id); diff --git a/decompiler/level_extractor/extract_tie.cpp b/decompiler/level_extractor/extract_tie.cpp index 45eb884db8..e82796c448 100644 --- a/decompiler/level_extractor/extract_tie.cpp +++ b/decompiler/level_extractor/extract_tie.cpp @@ -2,6 +2,7 @@ #include +#include "common/log/log.h" #include "common/util/FileUtil.h" #include "decompiler/ObjectFile/LinkedObjectFile.h" @@ -45,7 +46,7 @@ bool verify_node_indices_from_array(const level_tools::DrawableInlineArray* arra if (as_tie_instances) { for (auto& elt : as_tie_instances->instances) { if (elt.id != start) { - fmt::print("bad inst: exp {} got {}\n", start, elt.id); + lg::error("bad inst: exp {} got {}", start, elt.id); return false; } start++; @@ -55,7 +56,7 @@ bool verify_node_indices_from_array(const level_tools::DrawableInlineArray* arra } else if (as_nodes) { for (auto& elt : as_nodes->draw_nodes) { if (elt.id != start) { - fmt::print("bad node: exp {} got {}\n", start, elt.id); + lg::error("bad node: exp {} got {}", start, elt.id); return false; } start++; @@ -63,7 +64,7 @@ bool verify_node_indices_from_array(const level_tools::DrawableInlineArray* arra *end = start; return true; } else { - fmt::print("bad node array type: {}\n", array->my_type()); + lg::error("bad node array type: {}", array->my_type()); return false; } } @@ -550,7 +551,7 @@ void update_proto_info(std::vector* out, // try remapping it u32 new_tex = remap_texture(original_tex, map); if (original_tex != new_tex) { - fmt::print("map from 0x{:x} to 0x{:x}\n", original_tex, new_tex); + lg::info("map from 0x{:x} to 0x{:x}", original_tex, new_tex); } // texture the texture page/texture index, and convert to a PC port texture ID u32 tpage = new_tex >> 20; @@ -565,7 +566,7 @@ void update_proto_info(std::vector* out, memcpy(&adgif.second_w, &gif_data.at(16 * (tex_idx * 5 + 1) + 12), 4); // todo: figure out if this matters. maybe this is decal? if (ra_tex0_val == 0x800000000) { - // fmt::print("texture {} in {} has weird tex setting\n", tex->second.name, proto.name); + // lg::print("texture {} in {} has weird tex setting\n", tex->second.name, proto.name); } // mipmap settings. we ignore, but get the hidden value @@ -784,7 +785,7 @@ void emulate_tie_prototype_program(std::vector& protos) { // vi06 will be one of our gifbufs we can use. u16 vi06; memcpy(&vi06, &vf_gifbufs.y(), sizeof(u16)); - // fmt::print("vi06: {}\n", vi06); + // lg::print("vi06: {}\n", vi06); ASSERT(vi06 == 470 || vi06 == 286 || vi06 == 654); // should be one of the three gifbufs. // lqi.xyzw vf02, vi_point_ptr | suby.xz vf_gifbufs, vf_gifbufs, vf_gifbufs @@ -801,7 +802,7 @@ void emulate_tie_prototype_program(std::vector& protos) { // and vi05 is our other buffer. u16 vi05; memcpy(&vi05, &vf_gifbufs.x(), sizeof(u16)); - // fmt::print("vi05: {}\n", vi05); + // lg::print("vi05: {}\n", vi05); // check that we understand the buffer rotation. if (vi06 == 470) { ASSERT(vi05 == 286); @@ -831,7 +832,7 @@ void emulate_tie_prototype_program(std::vector& protos) { // store adgifs in one buffer. frag.prog_info.adgif_offset_in_gif_buf_qw.push_back(vi03 - vi05); - // fmt::print("adgifs at offset {}\n", frag.prog_info.adgif_offset_in_gif_buf_qw.back()); + // lg::print("adgifs at offset {}\n", frag.prog_info.adgif_offset_in_gif_buf_qw.back()); // sqi.xyzw vf01, vi03 | nop // sqi.xyzw vf02, vi03 | nop // sqi.xyzw vf03, vi03 | nop @@ -889,7 +890,7 @@ void emulate_tie_prototype_program(std::vector& protos) { // u16 vf04_w = frag.other_gif_data.at(11); ASSERT(vi_ind >= frag.adgifs.size()); // at least 1 draw per shader. ASSERT(vi_ind < 1000); // check for insane value. - // fmt::print("got: {}, other size: {}\n", vi_ind, frag.other_gif_data.size()); + // lg::print("got: {}, other size: {}\n", vi_ind, frag.other_gif_data.size()); // iaddi vi_point_ptr, vi_point_ptr, -0x2 | subw.w vf07, vf07, vf07 vi_point_ptr -= 2; @@ -910,7 +911,7 @@ void emulate_tie_prototype_program(std::vector& protos) { vi04 = frag.ilw_other_gif(vi_point_ptr, 2); // offset - // fmt::print("[{}] 7: {} 8: {} 4: {}, for {}\n", vi_point_ptr, vi07, vi08, vi04, vi_ind - 1); + // lg::print("[{}] 7: {} 8: {} 4: {}, for {}\n", vi_point_ptr, vi07, vi08, vi04, vi_ind - 1); // iaddi vi_ind, vi_ind, -0x1 | nop vi_ind--; @@ -934,7 +935,7 @@ void emulate_tie_prototype_program(std::vector& protos) { vi_ind--; // dec remaining tag // sq.xyzw vf07, 0(vi03) | nop info.address = vi03 - vi05; // store the template. but this doesn't have size or anything. - // fmt::print("strgif at {}, {}\n", vi03, vi04); + // lg::print("strgif at {}, {}\n", vi03, vi04); // iswr.x vi07, vi03 | nop info.nloop = vi07 & 0x7fff; @@ -961,7 +962,7 @@ void emulate_tie_prototype_program(std::vector& protos) { // ibne vi00, vi_ind, L3 | nop // lq.xyz vf07, 967(vi08) | nop next_mode = vi08; - // fmt::print("[{}] 7: {} 8: {} 4: {}, for {}\n", vi_point_ptr, vi07, vi08, vi04, vi_ind); + // lg::print("[{}] 7: {} 8: {} 4: {}, for {}\n", vi_point_ptr, vi07, vi08, vi04, vi_ind); frag.prog_info.str_gifs.push_back(info); } @@ -1017,13 +1018,13 @@ void emulate_tie_prototype_program(std::vector& protos) { vf05 = muli64_xyz(vf05); // mtir vi07, vf04.y | itof0.xyzw vf06, vf06 vi07 = vf04_y; - // fmt::print("bonus points: {}\n", vi07); + // lg::print("bonus points: {}\n", vi07); vf06 = itof0(vf06); // L5: Vector4f vf07; top_of_points_loop: - // fmt::print("{}/{}\n", vi05, vi06); + // lg::print("{}/{}\n", vi05, vi06); // lqi.xyzw vf07, vi05 | itof12.xyz vf16, vf16 vf07 = frag.lq_points_allow_past_end(vi05); vi05++; @@ -1278,10 +1279,10 @@ void emulate_tie_prototype_program(std::vector& protos) { void debug_print_info(const std::vector& out) { for (auto& proto : out) { - fmt::print("[{:40}]\n", proto.name); - fmt::print(" generic: {}\n", proto.uses_generic); - fmt::print(" use count: {}\n", proto.instances.size()); - fmt::print(" stiffness: {}\n", proto.stiffness); + lg::debug("[{:40}]", proto.name); + lg::debug(" generic: {}", proto.uses_generic); + lg::debug(" use count: {}", proto.instances.size()); + lg::debug(" stiffness: {}", proto.stiffness); } } @@ -1379,7 +1380,7 @@ void emulate_tie_instance_program(std::vector& protos) { // iadd vi_tgt_bp2_ptr, vi_tgt_bp2_ptr, vi01 | nop tgt_bp2_ptr += vi01; - // fmt::print("b tgts: {} {}\n", tgt_bp1_ptr, tgt_bp2_ptr); + // lg::print("b tgts: {} {}\n", tgt_bp1_ptr, tgt_bp2_ptr); // lqi.xyzw vf_vtx2, vi_point_ptr | mul.xyz vf_pos02, vf_pos02, Q // div Q, vf00.w, vf_pos13.w | mul.xyz vf_tex0, vf_tex0, Q // mtir vi_ind, vf_inds.z | addx.w vtx_0, vtx_0, vf_gifbufs @@ -1388,13 +1389,13 @@ void emulate_tie_instance_program(std::vector& protos) { // iadd vi_tgt_ip2_ptr, vi_tgt_ip2_ptr, vi01 | madday.xyzw ACC, vf_mtx1, vf_vtx2 tgt_ip1_ptr += vi01; tgt_ip2_ptr += vi01; - // fmt::print("i tgts: {} {}\n", tgt_ip1_ptr, tgt_ip2_ptr); + // lg::print("i tgts: {} {}\n", tgt_ip1_ptr, tgt_ip2_ptr); // lq.xyzw vf_mtx3, 838(vi_ind) | ftoi4.xyz vf_res02, vf_pos02 // ibeq vi_tgt_bp1_ptr, vi_dest_ptr, L40 | maddz.xyzw vf_pos02, vf_clr1, vf_vtx2 // iadd vi_kick_addr, vi_kick_addr, vi01 | nop kick_addr += vi01; if (tgt_bp1_ptr == dest_ptr) { - fmt::print("DRAW FINISH 1 (no points)\n"); + lg::info("DRAW FINISH 1 (no points)"); goto program_end; } @@ -1485,7 +1486,7 @@ void emulate_tie_instance_program(std::vector& protos) { float vtx_w = vert_pos.w() + frag.prog_info.gifbufs.x(); dest_ptr = float_to_u16(vtx_w); auto tex_coord = frag.lq_points(point_ptr); - // fmt::print("texw: [{}] {}\n", point_ptr, tex_coord.w()); + // lg::print("texw: [{}] {}\n", point_ptr, tex_coord.w()); point_ptr++; float tex_w = tex_coord.w() + frag.prog_info.gifbufs.x(); u16 dest2_ptr = float_to_u16(tex_w); @@ -1499,7 +1500,7 @@ void emulate_tie_instance_program(std::vector& protos) { vertex_info.tex.y() = tex_coord.y(); vertex_info.tex.z() = tex_coord.z(); - // fmt::print("double draw: {} {}\n", dest_ptr, dest2_ptr); + // lg::print("double draw: {} {}\n", dest_ptr, dest2_ptr); bool inserted = frag.vertex_by_dest_addr.insert({(u32)dest_ptr, vertex_info}).second; ASSERT(inserted); @@ -1974,8 +1975,8 @@ void update_mode_from_alpha1(u64 val, DrawMode& mode) { } else { - fmt::print("unsupported blend: a {} b {} c {} d {}\n", (int)reg.a_mode(), (int)reg.b_mode(), - (int)reg.c_mode(), (int)reg.d_mode()); + lg::error("unsupported blend: a {} b {} c {} d {}", (int)reg.a_mode(), (int)reg.b_mode(), + (int)reg.c_mode(), (int)reg.d_mode()); mode.set_alpha_blend(DrawMode::AlphaBlend::SRC_DST_SRC_DST); ASSERT(false); } diff --git a/decompiler/level_extractor/tfrag_tie_fixup.cpp b/decompiler/level_extractor/tfrag_tie_fixup.cpp index 3e2f93c80b..3bd89bd81c 100644 --- a/decompiler/level_extractor/tfrag_tie_fixup.cpp +++ b/decompiler/level_extractor/tfrag_tie_fixup.cpp @@ -4,6 +4,7 @@ #include #include +#include "common/log/log.h" #include "common/math/Vector.h" #include "common/util/Assert.h" @@ -246,7 +247,7 @@ void build_graph(std::vector& nodes, int group_a = info_a.source_group; int group_b = info_b.source_group; if (info_a.source_group == info_b.source_group) { - fmt::print("duplicate edge in group!\n"); // ?? + lg::print("duplicate edge in group!\n"); // ?? continue; } @@ -453,4 +454,4 @@ void fixup_and_unstrip_tfrag_tie(const std::vector& stripped_indices, // Part 7 make_final_indices(groups, unstripped); -} \ No newline at end of file +} diff --git a/decompiler/main.cpp b/decompiler/main.cpp index e1c63afddc..e24f8fa579 100644 --- a/decompiler/main.cpp +++ b/decompiler/main.cpp @@ -69,7 +69,7 @@ int main(int argc, char** argv) { in_folder = in_folder / config.game_name; // Verify the in_folder is correct if (!exists(in_folder)) { - fmt::print("Aborting - 'in_folder' does not exist '{}'\n", in_folder.string()); + lg::error("Aborting - 'in_folder' does not exist '{}'", in_folder.string()); return 1; } @@ -80,9 +80,9 @@ int main(int argc, char** argv) { // Warning message if expected ELF isn't found, user could be using bad assets / didn't extract // the ISO properly if (!config.expected_elf_name.empty() && !exists(in_folder / config.expected_elf_name)) { - fmt::print( + lg::error( "WARNING - '{}' does not contain the expected ELF file '{}'. Was the ISO extracted " - "properly or is there a version mismatch?\n", + "properly or is there a version mismatch?", in_folder.string(), config.expected_elf_name); } @@ -90,11 +90,11 @@ int main(int argc, char** argv) { Timer decomp_timer; - fmt::print("[Mem] Top of main: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] Top of main: {} MB\n", get_peak_rss() / (1024 * 1024)); init_opcode_info(); - fmt::print("[Mem] After init: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After init: {} MB\n", get_peak_rss() / (1024 * 1024)); std::vector dgos, objs, strs; for (const auto& dgo_name : config.dgo_names) { @@ -113,13 +113,13 @@ int main(int argc, char** argv) { file_util::create_dir_if_needed(file_util::get_jak_project_dir() / "debug_out"); } - fmt::print("[Mem] After config read: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After config read: {} MB", get_peak_rss() / (1024 * 1024)); // build file database lg::info("Setting up object file DB..."); ObjectFileDB db(dgos, fs::path(config.obj_file_name_map_file), objs, strs, config); - fmt::print("[Mem] After DB setup: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After DB setup: {} MB", get_peak_rss() / (1024 * 1024)); // write out DGO file info file_util::write_text_file(out_folder / "dgo.txt", db.generate_dgo_listing()); @@ -136,10 +136,10 @@ int main(int argc, char** argv) { // process files (required for all analysis) db.process_link_data(config); - fmt::print("[Mem] After link data: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After link data: {} MB", get_peak_rss() / (1024 * 1024)); db.find_code(config); db.process_labels(); - fmt::print("[Mem] After code: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After code: {} MB", get_peak_rss() / (1024 * 1024)); // top level decompile (do this before printing asm so we get function names) if (config.find_functions) { @@ -168,7 +168,7 @@ int main(int argc, char** argv) { config.hacks.types_with_bad_inspect_methods); } - fmt::print("[Mem] After decomp: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After decomp: {} MB", get_peak_rss() / (1024 * 1024)); // write out all symbols file_util::write_text_file(out_folder / "all-syms.gc", db.dts.dump_symbol_types()); @@ -194,7 +194,7 @@ int main(int argc, char** argv) { } } - fmt::print("[Mem] After text: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After text: {} MB", get_peak_rss() / (1024 * 1024)); decompiler::TextureDB tex_db; if (config.process_tpages || config.levels_extract) { @@ -206,7 +206,7 @@ int main(int argc, char** argv) { } } - fmt::print("[Mem] After textures: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After textures: {} MB", get_peak_rss() / (1024 * 1024)); auto replacements_path = file_util::get_jak_project_dir() / "texture_replacements"; if (fs::exists(replacements_path)) { tex_db.replace_textures(replacements_path); @@ -227,7 +227,7 @@ int main(int argc, char** argv) { config.rip_levels, config.extract_collision, level_out_path); } - fmt::print("[Mem] After extraction: {} MB\n", get_peak_rss() / (1024 * 1024)); + lg::info("[Mem] After extraction: {} MB", get_peak_rss() / (1024 * 1024)); if (!config.audio_dir_file_name.empty()) { auto streaming_audio_in = in_folder / "VAG"; diff --git a/decompiler/types2/ForwardProp.cpp b/decompiler/types2/ForwardProp.cpp index 6bf28da1bc..be3ef66811 100644 --- a/decompiler/types2/ForwardProp.cpp +++ b/decompiler/types2/ForwardProp.cpp @@ -1,3 +1,4 @@ +#include "common/log/log.h" #include "common/util/BitUtils.h" #include "decompiler/IR2/AtomicOp.h" @@ -56,8 +57,8 @@ void types2_from_ambiguous_deref(types2::Instruction& instr, } // the previously selected type is gone... not sure what we can do here, but complain and // use the first one (highest scored). - fmt::print("type2_from_ambiguous_deref: wanted type {}, but couldn't find it.\n", - desired_type.print()); + lg::print("type2_from_ambiguous_deref: wanted type {}, but couldn't find it.\n", + desired_type.print()); type.type = TP_Type::make_from_ts(out.front().result_type); return; } else { @@ -379,7 +380,7 @@ void types2_for_label(types2::Type& type_out, env.file->labels.at(label_idx).name)); } else { auto& name = env.file->labels.at(label_idx).name; - // fmt::print("Encountered unknown label: {}\n", name); + // lg::print("Encountered unknown label: {}\n", name); instr.unknown_label_tag = std::make_unique(); instr.unknown_label_tag->label_idx = label_idx; instr.unknown_label_tag->label_name = name; @@ -1035,7 +1036,7 @@ void types2_addr_on_stack(types2::Type& type_out, throw std::runtime_error( fmt::format("Failed to find a stack variable or structure at offset {}", offset)); } else { - // fmt::print("Encountered unknown stack address {} : {}\n", env.func->name(), offset); + // lg::print("Encountered unknown stack address {} : {}\n", env.func->name(), offset); instr.unknown_stack_structure_tag = std::make_unique(); instr.unknown_stack_structure_tag->stack_offset = offset; type_out.tag.unknown_stack_structure = instr.unknown_stack_structure_tag.get(); @@ -1363,8 +1364,8 @@ void types2_for_add(types2::Type& type_out, } } - fmt::print("checks: {} {} {}\n", tc(dts, TypeSpec("structure"), arg1_type), - !expr.get_arg(0).is_int(), is_int_or_uint(dts, arg0_type)); + lg::print("checks: {} {} {}\n", tc(dts, TypeSpec("structure"), arg1_type), + !expr.get_arg(0).is_int(), is_int_or_uint(dts, arg0_type)); throw std::runtime_error( fmt::format("add failed: {} {}\n", arg0_type.print(), arg1_type.print())); @@ -1800,11 +1801,11 @@ void StoreOp::propagate_types2(types2::Instruction& instr, // temp warning if we have multiple store types if (location_type.size() > 1) { - fmt::print("StoreOp::propagate_types2: multiple possible store types: "); + lg::print("StoreOp::propagate_types2: multiple possible store types: "); for (auto& t : location_type) { - fmt::print("{} ", t.print()); + lg::print("{} ", t.print()); } - fmt::print("\n"); + lg::print("\n"); } if (backprop_tagged_type(location_type.at(0), *value_type, dts)) { @@ -2075,13 +2076,13 @@ bool load_var_op_determine_type(types2::Type& type_out, } } else { /* - fmt::print("ambiguous deref. Choices are:\n"); + lg::print("ambiguous deref. Choices are:\n"); for (auto& result : rd.results) { - fmt::print(" {} : ", result.result_type.print()); + lg::print(" {} : ", result.result_type.print()); for (auto& tok : result.tokens) { - fmt::print("{} ", tok.print()); + lg::print("{} ", tok.print()); } - fmt::print("\n"); + lg::print("\n"); } */ diff --git a/decompiler/types2/types2.cpp b/decompiler/types2/types2.cpp index 8ab979aa4a..6c473acce8 100644 --- a/decompiler/types2/types2.cpp +++ b/decompiler/types2/types2.cpp @@ -2,6 +2,8 @@ #include +#include "common/log/log.h" + #include "decompiler/ObjectFile/LinkedObjectFile.h" #include "decompiler/types2/types2.h" #include "decompiler/util/type_utils.h" @@ -316,7 +318,7 @@ void backprop_from_preds(FunctionCache& cache, tag->is_reg = true; tag->reg = reg; tag->type_to_clear = &cache.blocks.at(succ_idx).start_type_state[reg]->type; - // fmt::print("mark to clear {}\n", succ_idx); + // lg::print("mark to clear {}\n", succ_idx); // add the tag to the type. auto& st = succ_cblock.start_types[reg]; ASSERT(!st.tag.has_tag()); @@ -344,7 +346,7 @@ void backprop_from_preds(FunctionCache& cache, if (my_tag->updated) { tags_updated = true; my_tag->updated = false; - // fmt::print("clearing {}\n", block_idx); + // lg::print("clearing {}\n", block_idx); cblock.needs_run = true; // maybe? *my_tag->type_to_clear = {}; // meh.. } @@ -403,9 +405,9 @@ bool tp_lca(types2::TypeState* combined, const types2::TypeState& add, Decompile bool diff = false; auto comb = combined->try_find_stack_spill_slot(x->slot); if (!comb) { - fmt::print("failed to find {}\n", x->slot); + lg::print("failed to find {}\n", x->slot); for (auto& x : combined->stack_slot_types) { - fmt::print("x = {}\n", x->slot); + lg::print("x = {}\n", x->slot); } } ASSERT(comb); @@ -447,7 +449,7 @@ bool propagate_block(FunctionCache& cache, auto& aop = func.ir2.atomic_ops->ops.at(instr->aop_idx); TypePropExtras extras; extras.tags_locked = tag_lock; - // fmt::print("run: {}\n", aop->to_string(func.ir2.env)); + // lg::print("run: {}\n", aop->to_string(func.ir2.env)); try { aop->propagate_types2(*instr, func.ir2.env, *previous_typestate, *func.ir2.env.dts, extras); @@ -682,7 +684,7 @@ end_type_pass: std::string error; if (!convert_to_old_format(out, function_cache, error, input.func->ir2.env.casts(), input.func->ir2.env.stack_casts(), *input.dts, hit_error)) { - fmt::print("Failed convert_to_old_format: {}\n", error); + lg::print("Failed convert_to_old_format: {}\n", error); } else { input.func->ir2.env.types_succeeded = true; auto last_type = out.op_end_types.back().get(Register(Reg::GPR, Reg::V0)).typespec(); @@ -717,7 +719,7 @@ end_type_pass: for (auto& info : env.stack_slot_entries) { info.second.typespec = info.second.tp_type.typespec(); // debug - // fmt::print("STACK {} : {} ({})\n", info.first, info.second.typespec.print(), + // lg::print("STACK {} : {} ({})\n", info.first, info.second.typespec.print(), // info.second.tp_type.print()); } diff --git a/decompiler/util/DecompilerTypeSystem.cpp b/decompiler/util/DecompilerTypeSystem.cpp index c2532caa94..04753bc512 100644 --- a/decompiler/util/DecompilerTypeSystem.cpp +++ b/decompiler/util/DecompilerTypeSystem.cpp @@ -102,7 +102,7 @@ void DecompilerTypeSystem::parse_type_defs(const std::vector& file_ } } catch (std::exception& e) { auto info = m_reader.db.get_info_for(o); - lg::error("{} when parsing decompiler type file:\n{}", e.what(), info); + lg::error("{} when parsing decompiler type file:{}", e.what(), info); throw e; } }); @@ -184,8 +184,8 @@ void DecompilerTypeSystem::add_symbol(const std::string& name, } else { if (ts.tc(type_spec, skv->second)) { } else { - lg::warn("Attempting to redefine type of symbol {} from {} to {}\n", name, - skv->second.print(), type_spec.print()); + lg::warn("Attempting to redefine type of symbol {} from {} to {}", name, skv->second.print(), + type_spec.print()); throw std::runtime_error("Type redefinition"); } } diff --git a/decompiler/util/TP_Type.h b/decompiler/util/TP_Type.h index 476397ba20..f8ffe87e7b 100644 --- a/decompiler/util/TP_Type.h +++ b/decompiler/util/TP_Type.h @@ -1,9 +1,9 @@ #pragma once #include #include +#include #include "common/common_types.h" -#include "common/log/log.h" #include "common/type_system/TypeSpec.h" #include "common/util/Assert.h" diff --git a/decompiler/util/data_decompile.cpp b/decompiler/util/data_decompile.cpp index 45e911e91d..a5c096005d 100644 --- a/decompiler/util/data_decompile.cpp +++ b/decompiler/util/data_decompile.cpp @@ -77,11 +77,11 @@ goos::Object decompile_at_label_with_hint(const LabelInfo& hint, // TODO - having this logic here isn't great. auto stride = align(field_type_info->get_size_in_memory(), field_type_info->get_inline_array_stride_alignment()); - fmt::print("decompiler {} stride {} {} = {}\n", field_type_info->get_name(), - field_type_info->get_size_in_memory(), - field_type_info->get_inline_array_stride_alignment(), - align(field_type_info->get_size_in_memory(), - field_type_info->get_inline_array_stride_alignment())); + lg::info("decompiler {} stride {} {} = {}", field_type_info->get_name(), + field_type_info->get_size_in_memory(), + field_type_info->get_inline_array_stride_alignment(), + align(field_type_info->get_size_in_memory(), + field_type_info->get_inline_array_stride_alignment())); if (dynamic_cast(field_type_info)) { throw std::runtime_error("Plan basic arrays not supported yet"); @@ -363,7 +363,7 @@ goos::Object decomp_ref_to_integer_array_guess_size( const LinkedObjectFile* /*file*/, const TypeSpec& array_elt_type, int stride) { - // fmt::print("Decomp decomp_ref_to_inline_array_guess_size {}\n", array_elt_type.print()); + // lg::print("Decomp decomp_ref_to_inline_array_guess_size {}\n", array_elt_type.print()); // verify types auto elt_type_info = ts.lookup_type(array_elt_type); @@ -392,13 +392,13 @@ goos::Object decomp_ref_to_integer_array_guess_size( end_offset = end_label.offset; } - // fmt::print("Data is from {} to {}\n", start_label.name, end_label.name); + // lg::print("Data is from {} to {}\n", start_label.name, end_label.name); // now we can figure out the size int size_bytes = end_offset - start_label.offset; int size_elts = size_bytes / stride; // 32 bytes per ocean-near-index int leftover_bytes = size_bytes % stride; - // fmt::print("Size is {} bytes ({} elts), with {} bytes left over\n", size_bytes, + // lg::print("Size is {} bytes ({} elts), with {} bytes left over\n", size_bytes, // size_elts,leftover_bytes); // if we have leftover, should verify that its all zeros, or that it's the type pointer @@ -440,7 +440,7 @@ goos::Object decomp_ref_to_inline_array_guess_size( const LinkedObjectFile* file, const TypeSpec& array_elt_type, int stride) { - // fmt::print("Decomp decomp_ref_to_inline_array_guess_size {}\n", array_elt_type.print()); + // lg::print("Decomp decomp_ref_to_inline_array_guess_size {}\n", array_elt_type.print()); // verify the stride matches the type system auto elt_type_info = ts.lookup_type(array_elt_type); @@ -470,13 +470,13 @@ goos::Object decomp_ref_to_inline_array_guess_size( end_offset = end_label.offset; } - // fmt::print("Data is from {} to {}\n", start_label.name, end_label.name); + // lg::print("Data is from {} to {}\n", start_label.name, end_label.name); // now we can figure out the size int size_bytes = end_offset - start_label.offset; int size_elts = size_bytes / stride; // 32 bytes per ocean-near-index int leftover_bytes = size_bytes % stride; - // fmt::print("Size is {} bytes ({} elts), with {} bytes left over\n", size_bytes, + // lg::print("Size is {} bytes ({} elts), with {} bytes left over\n", size_bytes, // size_elts,leftover_bytes); // if we have leftover, should verify that its all zeros, or that it's the type pointer @@ -643,7 +643,7 @@ goos::Object decompile_sound_spec(const TypeSpec& type, const TypeSystem& ts, const LinkedObjectFile* file) { // auto normal = decompile_structure(type, label, labels, words, ts, file, false); - // fmt::print("Doing: {}\n", normal.print()); + // lg::print("Doing: {}\n", normal.print()); auto uncast_type_info = ts.lookup_type(type); auto type_info = dynamic_cast(uncast_type_info); if (!type_info) { @@ -863,7 +863,7 @@ goos::Object decompile_structure(const TypeSpec& type, if (is_basic || !type_info->is_packed()) { throw std::runtime_error(error); } else { - // fmt::print("{}\n", error); + // lg::print("{}\n", error); } } diff --git a/decompiler/util/sparticle_decompile.cpp b/decompiler/util/sparticle_decompile.cpp index 8a0f829c49..c1747c338c 100644 --- a/decompiler/util/sparticle_decompile.cpp +++ b/decompiler/util/sparticle_decompile.cpp @@ -326,10 +326,7 @@ goos::Object decompile_sparticle_rot_x(const std::vector& words, goos::Object decompile_sparticle_int_with_rand_init(const std::vector& words, const std::string& field_name, const std::string& flag_name) { - if (flag_name != "plain-v1") { - fmt::print("Bad {} {}\n", field_name, flag_name); - } - ASSERT(flag_name == "plain-v1"); + ASSERT_MSG(flag_name == "plain-v1", fmt::format("Bad {} {}\n", field_name, flag_name)); if (word_as_s32(words.at(2)) == 0 && word_as_s32(words.at(3)) == 1) { return decompile_sparticle_int_init(words, field_name, flag_name); } @@ -451,7 +448,7 @@ goos::Object decompile_sparticle_group_item(const TypeSpec& type, const TypeSystem& ts, const LinkedObjectFile* /*file*/) { // auto normal = decompile_structure(type, label, labels, words, ts, file, false); - // fmt::print("Doing: {}\n", normal.print()); + // lg::print("Doing: {}\n", normal.print()); auto uncast_type_info = ts.lookup_type(type); auto type_info = dynamic_cast(uncast_type_info); if (!type_info) { @@ -530,7 +527,7 @@ goos::Object decompile_sparticle_group_item(const TypeSpec& type, } result += ')'; - // fmt::print("Result: {}\n", result); + // lg::print("Result: {}\n", result); return pretty_print::to_symbol(result); } @@ -541,7 +538,7 @@ goos::Object decompile_sparticle_field_init(const TypeSpec& type, const TypeSystem& ts, const LinkedObjectFile* file) { auto normal = decompile_structure(type, label, labels, words, ts, file, false); - // fmt::print("Doing: {}\n", normal.print()); + // lg::print("Doing: {}\n", normal.print()); auto uncast_type_info = ts.lookup_type(type); auto type_info = dynamic_cast(uncast_type_info); if (!type_info) { @@ -623,7 +620,7 @@ goos::Object decompile_sparticle_field_init(const TypeSpec& type, } } - // fmt::print("Result: {}\n\n", result.print()); + // lg::print("Result: {}\n\n", result.print()); return result; } @@ -708,7 +705,7 @@ goos::Object decompile_sparticle_field_init(const DefpartElement::StaticInfo::Pa } } - // fmt::print("Result: {}\n\n", result.print()); + // lg::print("Result: {}\n\n", result.print()); return result; } } // namespace decompiler diff --git a/game/graphics/display.cpp b/game/graphics/display.cpp index 652f2e4a62..25c29501e0 100644 --- a/game/graphics/display.cpp +++ b/game/graphics/display.cpp @@ -85,6 +85,7 @@ void GfxDisplay::restore_display_settings() { if (!file_util::file_exists(file_path)) { return; } + lg::info("reading {}", file_path); auto raw = file_util::read_text_file(file_path); auto json = parse_commented_json(raw, "display-settings.json"); if (json.contains("window_xpos")) { diff --git a/game/graphics/gfx.cpp b/game/graphics/gfx.cpp index b9d1d58045..4452f0d5a5 100644 --- a/game/graphics/gfx.cpp +++ b/game/graphics/gfx.cpp @@ -148,6 +148,7 @@ void SavePeripheralSettings() { void LoadPeripheralSettings(const ghc::filesystem::path& filepath) { Pad::DefaultMapping(g_settings.pad_mapping_info); + lg::info("reading {}", filepath.string()); auto file_txt = file_util::read_text_file(filepath); auto configuration = parse_commented_json(file_txt, filepath.string()); diff --git a/game/graphics/opengl_renderer/BucketRenderer.cpp b/game/graphics/opengl_renderer/BucketRenderer.cpp index 64129a19c2..e14717f598 100644 --- a/game/graphics/opengl_renderer/BucketRenderer.cpp +++ b/game/graphics/opengl_renderer/BucketRenderer.cpp @@ -28,10 +28,9 @@ void EmptyBucketRenderer::render(DmaFollower& dma, // CALL auto call_tag = dma.current_tag(); dma.read_and_advance(); - if (!(call_tag.kind == DmaTag::Kind::CALL && call_tag.qwc == 0)) { - fmt::print("Bucket renderer {} ({}) was supposed to be empty, but wasn't\n", m_my_id, m_name); - } - ASSERT(call_tag.kind == DmaTag::Kind::CALL && call_tag.qwc == 0); + ASSERT_MSG(call_tag.kind == DmaTag::Kind::CALL && call_tag.qwc == 0, + fmt::format("Bucket renderer {} ({}) was supposed to be empty, but wasn't\n", + m_my_id, m_name)); // in the default reg buffer: ASSERT(dma.current_tag_offset() == render_state->default_regs_buffer); diff --git a/game/graphics/opengl_renderer/DirectRenderer.cpp b/game/graphics/opengl_renderer/DirectRenderer.cpp index 7dac2af981..de0b76bb89 100644 --- a/game/graphics/opengl_renderer/DirectRenderer.cpp +++ b/game/graphics/opengl_renderer/DirectRenderer.cpp @@ -311,11 +311,10 @@ void DirectRenderer::update_gl_texture(SharedRenderState* render_state, int unit if (!tex) { // TODO Add back if (state.texture_base_ptr >= 8160 && state.texture_base_ptr <= 8600) { - fmt::print("Failed to find texture at {}, using random (eye zone)\n", state.texture_base_ptr); - + lg::warn("Failed to find texture at {}, using random (eye zone)", state.texture_base_ptr); tex = render_state->texture_pool->get_placeholder_texture(); } else { - fmt::print("Failed to find texture at {}, using random\n", state.texture_base_ptr); + lg::warn("Failed to find texture at {}, using random", state.texture_base_ptr); tex = render_state->texture_pool->get_placeholder_texture(); } } @@ -582,9 +581,8 @@ void DirectRenderer::render_gif(const u8* data, handle_tex0_1_packed(data + offset); break; default: - fmt::print("Register {} is not supported in packed mode yet\n", - reg_descriptor_name(reg_desc[reg])); - ASSERT(false); + ASSERT_MSG(false, fmt::format("Register {} is not supported in packed mode yet\n", + reg_descriptor_name(reg_desc[reg]))); } offset += 16; // PACKED = quadwords } @@ -606,9 +604,8 @@ void DirectRenderer::render_gif(const u8* data, handle_xyzf2(register_data, render_state, prof); break; default: - fmt::print("Register {} is not supported in reglist mode yet\n", - reg_descriptor_name(reg_desc[reg])); - ASSERT(false); + ASSERT_MSG(false, fmt::format("Register {} is not supported in reglist mode yet\n", + reg_descriptor_name(reg_desc[reg]))); } offset += 8; // PACKED = quadwords } diff --git a/game/graphics/opengl_renderer/DirectRenderer.h b/game/graphics/opengl_renderer/DirectRenderer.h index 246843ce62..244b0ce78d 100644 --- a/game/graphics/opengl_renderer/DirectRenderer.h +++ b/game/graphics/opengl_renderer/DirectRenderer.h @@ -3,7 +3,6 @@ #include #include "common/dma/gs.h" -#include "common/log/log.h" #include "common/math/Vector.h" #include "common/util/SmallVector.h" diff --git a/game/graphics/opengl_renderer/DirectRenderer2.cpp b/game/graphics/opengl_renderer/DirectRenderer2.cpp index 30383256fb..5d092dca28 100644 --- a/game/graphics/opengl_renderer/DirectRenderer2.cpp +++ b/game/graphics/opengl_renderer/DirectRenderer2.cpp @@ -97,7 +97,7 @@ void DirectRenderer2::reset_state() { m_state = {}; m_stats = {}; if (m_next_free_draw || m_vertices.next_vertex || m_vertices.next_index) { - fmt::print("[{}] Call to reset_state while there was pending draw data!\n", m_name); + lg::warn("[{}] Call to reset_state while there was pending draw data!", m_name); } reset_buffers(); } @@ -156,10 +156,10 @@ void DirectRenderer2::flush_pending(SharedRenderState* render_state, ScopedProfi void DirectRenderer2::draw_call_loop_simple(SharedRenderState* render_state, ScopedProfilerNode& prof) { - fmt::print("------------------------\n"); + lg::debug("------------------------"); for (u32 draw_idx = 0; draw_idx < m_next_free_draw; draw_idx++) { const auto& draw = m_draw_buffer[draw_idx]; - fmt::print("{}", draw.to_single_line_string()); + lg::debug("{}", draw.to_single_line_string()); setup_opengl_for_draw_mode(draw, render_state); setup_opengl_tex(0, draw.tbp, draw.mode.get_filt_enable(), draw.mode.get_clamp_s_enable(), draw.mode.get_clamp_t_enable(), render_state); @@ -354,11 +354,10 @@ void DirectRenderer2::setup_opengl_tex(u16 unit, if (!tex) { // TODO Add back if (tbp_to_lookup >= 8160 && tbp_to_lookup <= 8600) { - fmt::print("Failed to find texture at {}, using random (eye zone)\n", tbp_to_lookup); - + lg::warn("Failed to find texture at {}, using random (eye zone)", tbp_to_lookup); tex = render_state->texture_pool->get_placeholder_texture(); } else { - fmt::print("Failed to find texture at {}, using random\n", tbp_to_lookup); + lg::warn("Failed to find texture at {}, using random", tbp_to_lookup); tex = render_state->texture_pool->get_placeholder_texture(); } } @@ -444,9 +443,8 @@ void DirectRenderer2::render_gif_data(const u8* data, ASSERT(false); // handle_tex0_1_packed(data + offset); break; default: - fmt::print("Register {} is not supported in packed mode yet\n", - reg_descriptor_name(reg_desc[reg])); - ASSERT(false); + ASSERT_MSG(false, fmt::format("Register {} is not supported in packed mode yet\n", + reg_descriptor_name(reg_desc[reg]))); } offset += 16; // PACKED = quadwords } @@ -468,9 +466,8 @@ void DirectRenderer2::render_gif_data(const u8* data, ASSERT(false); // handle_xyzf2(register_data, render_state, prof); break; default: - fmt::print("Register {} is not supported in reglist mode yet\n", - reg_descriptor_name(reg_desc[reg])); - ASSERT(false); + ASSERT_MSG(false, fmt::format("Register {} is not supported in reglist mode yet\n", + reg_descriptor_name(reg_desc[reg]))); } offset += 8; // PACKED = quadwords } diff --git a/game/graphics/opengl_renderer/Profiler.cpp b/game/graphics/opengl_renderer/Profiler.cpp index 430f6dbc44..cca445cbfc 100644 --- a/game/graphics/opengl_renderer/Profiler.cpp +++ b/game/graphics/opengl_renderer/Profiler.cpp @@ -17,13 +17,13 @@ ProfilerNode* ProfilerNode::make_child(const std::string& name) { void ProfilerNode::finish() { if (m_finished) { - lg::error("finish() called twice on {}\n", m_name); + lg::error("finish() called twice on {}", m_name); } else { m_stats.duration = m_timer.getSeconds(); float total_child_time = 0; for (const auto& child : m_children) { if (!child.finished()) { - lg::error("finish() not called on {}\n", child.name()); + lg::error("finish() not called on {}", child.name()); } total_child_time += child.m_stats.duration; m_stats.add_draw_stats(child.m_stats); diff --git a/game/graphics/opengl_renderer/Shader.cpp b/game/graphics/opengl_renderer/Shader.cpp index 5954ae6f94..bbb854035a 100644 --- a/game/graphics/opengl_renderer/Shader.cpp +++ b/game/graphics/opengl_renderer/Shader.cpp @@ -28,7 +28,7 @@ Shader::Shader(const std::string& shader_name, GameVersion version) { glGetShaderiv(m_vert_shader, GL_COMPILE_STATUS, &compile_ok); if (!compile_ok) { glGetShaderInfoLog(m_vert_shader, len, nullptr, err); - lg::error("Failed to compile vertex shader {}:\n{}\n", shader_name.c_str(), err); + lg::error("Failed to compile vertex shader {}:\n{}", shader_name.c_str(), err); m_is_okay = false; return; } @@ -41,7 +41,7 @@ Shader::Shader(const std::string& shader_name, GameVersion version) { glGetShaderiv(m_frag_shader, GL_COMPILE_STATUS, &compile_ok); if (!compile_ok) { glGetShaderInfoLog(m_frag_shader, len, nullptr, err); - lg::error("Failed to compile fragment shader {}:\n{}\n", shader_name.c_str(), err); + lg::error("Failed to compile fragment shader {}:\n{}", shader_name.c_str(), err); m_is_okay = false; return; } @@ -54,7 +54,7 @@ Shader::Shader(const std::string& shader_name, GameVersion version) { glGetProgramiv(m_program, GL_LINK_STATUS, &compile_ok); if (!compile_ok) { glGetProgramInfoLog(m_program, len, nullptr, err); - lg::error("Failed to link shader {}:\n{}\n", shader_name.c_str(), err); + lg::error("Failed to link shader {}:\n{}", shader_name.c_str(), err); m_is_okay = false; return; } diff --git a/game/graphics/opengl_renderer/ShadowRenderer.cpp b/game/graphics/opengl_renderer/ShadowRenderer.cpp index 95d5106da9..02d63f40bf 100644 --- a/game/graphics/opengl_renderer/ShadowRenderer.cpp +++ b/game/graphics/opengl_renderer/ShadowRenderer.cpp @@ -157,9 +157,8 @@ void ShadowRenderer::xgkick(u16 imm) { } break; default: - fmt::print("Register {} is not supported in packed mode yet\n", - reg_descriptor_name(reg_desc[reg])); - ASSERT(false); + ASSERT_MSG(false, fmt::format("Register {} is not supported in packed mode yet\n", + reg_descriptor_name(reg_desc[reg]))); } offset += 16; // PACKED = quadwords } diff --git a/game/graphics/opengl_renderer/Shadow_PS2.cpp b/game/graphics/opengl_renderer/Shadow_PS2.cpp index 285cbb8f97..69fb615e94 100644 --- a/game/graphics/opengl_renderer/Shadow_PS2.cpp +++ b/game/graphics/opengl_renderer/Shadow_PS2.cpp @@ -1,3 +1,5 @@ +#include "common/log/log.h" + #include "game/graphics/opengl_renderer/ShadowRenderer.h" void ShadowRenderer::run_mscal10_vu2c() { @@ -148,7 +150,7 @@ void ShadowRenderer::run_mscal_vu2c(u16 imm) { goto L21; default: - fmt::print("didn't know mscal imm: {}\n", imm); + lg::warn("didn't know mscal imm: {}", imm); // ASSERT(false); } // clang-format off diff --git a/game/graphics/opengl_renderer/SkyRenderer.cpp b/game/graphics/opengl_renderer/SkyRenderer.cpp index 06ad732f19..23db4a837f 100644 --- a/game/graphics/opengl_renderer/SkyRenderer.cpp +++ b/game/graphics/opengl_renderer/SkyRenderer.cpp @@ -1,7 +1,5 @@ #include "SkyRenderer.h" -#include "common/log/log.h" - #include "game/graphics/opengl_renderer/AdgifHandler.h" #include "game/graphics/pipelines/opengl.h" diff --git a/game/graphics/opengl_renderer/Sprite3.cpp b/game/graphics/opengl_renderer/Sprite3.cpp index 0c2089823c..a24bbf2ba8 100644 --- a/game/graphics/opengl_renderer/Sprite3.cpp +++ b/game/graphics/opengl_renderer/Sprite3.cpp @@ -2,6 +2,8 @@ #include "Sprite3.h" +#include "common/log/log.h" + #include "game/graphics/opengl_renderer/background/background_common.h" #include "game/graphics/opengl_renderer/dma_helpers.h" @@ -1069,7 +1071,7 @@ void Sprite3::flush_sprites(SharedRenderState* render_state, tex = render_state->texture_pool->lookup(tbp); if (!tex) { - fmt::print("Failed to find texture at {}, using random\n", tbp); + lg::warn("Failed to find texture at {}, using random", tbp); tex = render_state->texture_pool->get_placeholder_texture(); } ASSERT(tex); @@ -1216,8 +1218,8 @@ void Sprite3::update_mode_from_alpha1(u64 val, DrawMode& mode) { } else { - fmt::print("unsupported blend: a {} b {} c {} d {}\n", (int)reg.a_mode(), (int)reg.b_mode(), - (int)reg.c_mode(), (int)reg.d_mode()); + lg::error("unsupported blend: a {} b {} c {} d {}", (int)reg.a_mode(), (int)reg.b_mode(), + (int)reg.c_mode(), (int)reg.d_mode()); mode.set_alpha_blend(DrawMode::AlphaBlend::SRC_DST_SRC_DST); ASSERT(false); } diff --git a/game/graphics/opengl_renderer/SpriteRenderer.cpp b/game/graphics/opengl_renderer/SpriteRenderer.cpp index 6bedb8a4b0..659bcf8049 100644 --- a/game/graphics/opengl_renderer/SpriteRenderer.cpp +++ b/game/graphics/opengl_renderer/SpriteRenderer.cpp @@ -1,5 +1,7 @@ #include "SpriteRenderer.h" +#include "common/log/log.h" + #include "game/graphics/opengl_renderer/background/background_common.h" #include "game/graphics/opengl_renderer/dma_helpers.h" @@ -614,7 +616,7 @@ void SpriteRenderer::update_gl_texture(SharedRenderState* render_state, int unit } if (!tex) { - fmt::print("Failed to find texture at {}, using random\n", state.texture_base_ptr); + lg::warn("Failed to find texture at {}, using random", state.texture_base_ptr); tex = render_state->texture_pool->get_placeholder_texture(); } ASSERT(tex); diff --git a/game/graphics/opengl_renderer/TextureUploadHandler.cpp b/game/graphics/opengl_renderer/TextureUploadHandler.cpp index 17d92f0ad1..e152b75644 100644 --- a/game/graphics/opengl_renderer/TextureUploadHandler.cpp +++ b/game/graphics/opengl_renderer/TextureUploadHandler.cpp @@ -1,5 +1,7 @@ #include "TextureUploadHandler.h" +#include "common/log/log.h" + #include "game/graphics/opengl_renderer/EyeRenderer.h" #include "game/graphics/pipelines/opengl.h" @@ -82,9 +84,9 @@ void TextureUploadHandler::flush_uploads(std::vector& uploads, else if (uploads.empty()) { // do nothing. } else { - fmt::print("unhandled upload sequence in {}:\n", m_name); + lg::error("unhandled upload sequence in {}:", m_name); for (auto& upload : uploads) { - fmt::print(" page: 0x{:x} mode: {}\n", upload.page, upload.mode); + lg::error(" page: 0x{:x} mode: {}", upload.page, upload.mode); } ASSERT(false); } diff --git a/game/graphics/opengl_renderer/background/Shrub.cpp b/game/graphics/opengl_renderer/background/Shrub.cpp index 5943e918e5..0a356ff003 100644 --- a/game/graphics/opengl_renderer/background/Shrub.cpp +++ b/game/graphics/opengl_renderer/background/Shrub.cpp @@ -1,5 +1,7 @@ #include "Shrub.h" +#include "common/log/log.h" + Shrub::Shrub(const std::string& name, int my_id) : BucketRenderer(name, my_id) { m_color_result.resize(TIME_OF_DAY_COLOR_COUNT); } @@ -184,7 +186,7 @@ bool Shrub::setup_for_level(const std::string& level, SharedRenderState* render_ } if (tfrag3_setup_timer.getMs() > 5) { - fmt::print("Shrub setup: {:.1f}ms\n", tfrag3_setup_timer.getMs()); + lg::info("Shrub setup: {:.1f}ms", tfrag3_setup_timer.getMs()); } return m_has_level; diff --git a/game/graphics/opengl_renderer/background/Tfrag3.cpp b/game/graphics/opengl_renderer/background/Tfrag3.cpp index a1ee89a64a..cf88268e98 100644 --- a/game/graphics/opengl_renderer/background/Tfrag3.cpp +++ b/game/graphics/opengl_renderer/background/Tfrag3.cpp @@ -1,5 +1,7 @@ #include "Tfrag3.h" +#include "common/log/log.h" + #include "third-party/imgui/imgui.h" Tfrag3::Tfrag3() { @@ -161,7 +163,7 @@ bool Tfrag3::setup_for_level(const std::vector& tree_ } if (tfrag3_setup_timer.getMs() > 5) { - fmt::print("TFRAG setup: {:.1f}ms\n", tfrag3_setup_timer.getMs()); + lg::info("TFRAG setup: {:.1f}ms", tfrag3_setup_timer.getMs()); } return m_has_level; diff --git a/game/graphics/opengl_renderer/background/Tie3.cpp b/game/graphics/opengl_renderer/background/Tie3.cpp index d077e756dd..985c997dc4 100644 --- a/game/graphics/opengl_renderer/background/Tie3.cpp +++ b/game/graphics/opengl_renderer/background/Tie3.cpp @@ -1,6 +1,7 @@ #include "Tie3.h" #include "common/global_profiler/GlobalProfiler.h" +#include "common/log/log.h" #include "third-party/imgui/imgui.h" @@ -168,7 +169,7 @@ bool Tie3::setup_for_level(const std::string& level, SharedRenderState* render_s } if (tfrag3_setup_timer.getMs() > 5) { - fmt::print("TIE setup: {:.1f}ms\n", tfrag3_setup_timer.getMs()); + lg::info("TIE setup: {:.1f}ms", tfrag3_setup_timer.getMs()); } return m_has_level; diff --git a/game/graphics/opengl_renderer/dma_helpers.cpp b/game/graphics/opengl_renderer/dma_helpers.cpp index b698f00ac7..3719d6aa6c 100644 --- a/game/graphics/opengl_renderer/dma_helpers.cpp +++ b/game/graphics/opengl_renderer/dma_helpers.cpp @@ -1,5 +1,7 @@ #include "dma_helpers.h" +#include "common/log/log.h" + #include "third-party/fmt/format.h" /*! @@ -15,17 +17,17 @@ bool verify_unpack_with_stcycl(const DmaTransfer& transfer, bool usn, bool flg) { if (transfer.size_bytes != qwc * 16) { - fmt::print("verify_unpack: bad size {} vs {}\n", transfer.size_bytes, qwc * 16); + lg::error("verify_unpack: bad size {} vs {}", transfer.size_bytes, qwc * 16); return false; } if (transfer.vifcode0().kind != VifCode::Kind::STCYCL) { - fmt::print("verify_unpack: bad vifcode 0\n"); + lg::error("verify_unpack: bad vifcode 0"); return false; } if (transfer.vifcode1().kind != unpack_kind) { - fmt::print("verify_unpack: bad vifcode 1\n"); + lg::error("verify_unpack: bad vifcode 1"); return false; } @@ -33,18 +35,18 @@ bool verify_unpack_with_stcycl(const DmaTransfer& transfer, VifCodeUnpack unpack(transfer.vifcode1()); if (stcycl.cl != cl || stcycl.wl != wl) { - fmt::print("verify_unpack: bad cl/wl {}/{} vs {}/{}\n", stcycl.cl, stcycl.wl, cl, wl); + lg::error("verify_unpack: bad cl/wl {}/{} vs {}/{}", stcycl.cl, stcycl.wl, cl, wl); return false; } if (unpack.addr_qw != addr || unpack.use_tops_flag != flg || unpack.is_unsigned != usn) { - fmt::print("verify_unpack: bad unpack {}/{}/{} vs {}/{}/{}", unpack.addr_qw, - unpack.use_tops_flag, unpack.is_unsigned, addr, flg, usn); + lg::error("verify_unpack: bad unpack {}/{}/{} vs {}/{}/{}", unpack.addr_qw, + unpack.use_tops_flag, unpack.is_unsigned, addr, flg, usn); return false; } if (transfer.vifcode1().num != qwc) { - fmt::print("verify_unpack: bad num {} vs {}\n", transfer.vifcode1().num, qwc); + lg::error("verify_unpack: bad num {} vs {}", transfer.vifcode1().num, qwc); return false; } @@ -82,30 +84,30 @@ bool verify_unpack_no_stcycl(const DmaTransfer& transfer, bool usn, bool flg) { if (transfer.size_bytes != qwc * 16) { - fmt::print("verify_unpack: bad size {} vs {}\n", transfer.size_bytes, qwc * 16); + lg::error("verify_unpack: bad size {} vs {}", transfer.size_bytes, qwc * 16); return false; } if (transfer.vifcode0().kind != VifCode::Kind::NOP) { - fmt::print("verify_unpack: bad vifcode 0\n"); + lg::error("verify_unpack: bad vifcode 0"); return false; } if (transfer.vifcode1().kind != unpack_kind) { - fmt::print("verify_unpack: bad vifcode 1\n"); + lg::error("verify_unpack: bad vifcode 1"); return false; } VifCodeUnpack unpack(transfer.vifcode1()); if (unpack.addr_qw != addr || unpack.use_tops_flag != flg || unpack.is_unsigned != usn) { - fmt::print("verify_unpack: bad unpack {}/{}/{} vs {}/{}/{}", unpack.addr_qw, - unpack.use_tops_flag, unpack.is_unsigned, addr, flg, usn); + lg::error("verify_unpack: bad unpack {}/{}/{} vs {}/{}/{}", unpack.addr_qw, + unpack.use_tops_flag, unpack.is_unsigned, addr, flg, usn); return false; } if (transfer.vifcode1().num != qwc) { - fmt::print("verify_unpack: bad num {} vs {}\n", transfer.vifcode1().num, qwc); + lg::error("verify_unpack: bad num {} vs {}", transfer.vifcode1().num, qwc); return false; } @@ -134,4 +136,4 @@ void verify_mscal(const DmaTransfer& transfer, int address) { ASSERT(transfer.vif0() == 0); ASSERT(transfer.vifcode1().kind == VifCode::Kind::MSCAL); ASSERT(transfer.vifcode1().immediate == address); -} \ No newline at end of file +} diff --git a/game/graphics/opengl_renderer/foreground/Generic2_OpenGL.cpp b/game/graphics/opengl_renderer/foreground/Generic2_OpenGL.cpp index e76a39868e..5b17e13780 100644 --- a/game/graphics/opengl_renderer/foreground/Generic2_OpenGL.cpp +++ b/game/graphics/opengl_renderer/foreground/Generic2_OpenGL.cpp @@ -1,3 +1,5 @@ +#include "common/log/log.h" + #include "Generic2.h" void Generic2::opengl_setup() { @@ -223,11 +225,10 @@ void Generic2::setup_opengl_tex(u16 unit, if (!tex) { // TODO Add back if (tbp_to_lookup >= 8160 && tbp_to_lookup <= 8600) { - fmt::print("Failed to find texture at {}, using random (eye zone)\n", tbp_to_lookup); - + lg::warn("Failed to find texture at {}, using random (eye zone)", tbp_to_lookup); tex = render_state->texture_pool->get_placeholder_texture(); } else { - fmt::print("Failed to find texture at {}, using random\n", tbp_to_lookup); + lg::warn("Failed to find texture at {}, using random", tbp_to_lookup); tex = render_state->texture_pool->get_placeholder_texture(); } } diff --git a/game/graphics/opengl_renderer/ocean/CommonOceanRenderer.cpp b/game/graphics/opengl_renderer/ocean/CommonOceanRenderer.cpp index b5e00a239d..ea3c4fc2a0 100644 --- a/game/graphics/opengl_renderer/ocean/CommonOceanRenderer.cpp +++ b/game/graphics/opengl_renderer/ocean/CommonOceanRenderer.cpp @@ -1,5 +1,7 @@ #include "CommonOceanRenderer.h" +#include "common/log/log.h" + CommonOceanRenderer::CommonOceanRenderer() { m_vertices.resize(4096 * 10); // todo decrease for (auto& buf : m_indices) { @@ -252,7 +254,7 @@ void CommonOceanRenderer::handle_near_adgif(const u8* data, u32 offset, u32 coun } break; default: - fmt::print("reg: {}\n", register_address_name(addr)); + lg::debug("reg: {}", register_address_name(addr)); break; } } @@ -412,7 +414,7 @@ void CommonOceanRenderer::handle_mid_adgif(const u8* data, u32 offset) { } break; default: - fmt::print("reg: {}\n", register_address_name(addr)); + lg::debug("reg: {}", register_address_name(addr)); break; } } diff --git a/game/graphics/opengl_renderer/ocean/OceanMid.cpp b/game/graphics/opengl_renderer/ocean/OceanMid.cpp index 0e192fa22d..07237aace9 100644 --- a/game/graphics/opengl_renderer/ocean/OceanMid.cpp +++ b/game/graphics/opengl_renderer/ocean/OceanMid.cpp @@ -1,5 +1,7 @@ #include "OceanMid.h" +#include "common/log/log.h" + static bool is_end_tag(const DmaTag& tag, const VifCode& v0, const VifCode& v1) { return tag.qwc == 2 && tag.kind == DmaTag::Kind::CNT && v0.kind == VifCode::Kind::NOP && v1.kind == VifCode::Kind::DIRECT; @@ -111,7 +113,7 @@ void OceanMid::run(DmaFollower& dma, SharedRenderState* render_state, ScopedProf run_call275_vu2c(); break; default: - fmt::print("unknown call1: {}\n", v1.immediate); + lg::warn("unknown call1: {}", v1.immediate); } } else if (v0.kind == VifCode::Kind::MSCALF && v1.kind == VifCode::Kind::FLUSHA) { switch (v0.immediate) { diff --git a/game/graphics/opengl_renderer/ocean/OceanNear.cpp b/game/graphics/opengl_renderer/ocean/OceanNear.cpp index ac9c753038..210b53567d 100644 --- a/game/graphics/opengl_renderer/ocean/OceanNear.cpp +++ b/game/graphics/opengl_renderer/ocean/OceanNear.cpp @@ -1,5 +1,7 @@ #include "OceanNear.h" +#include "common/log/log.h" + #include "third-party/imgui/imgui.h" OceanNear::OceanNear(const std::string& name, int my_id) @@ -54,7 +56,7 @@ void OceanNear::render(DmaFollower& dma, } if (dma.current_tag().qwc != 2) { - fmt::print("abort!\n"); + lg::error("abort OceanNear::render!"); while (dma.current_tag_offset() != render_state->next_bucket) { dma.read_and_advance(); } diff --git a/game/graphics/texture/TexturePool.cpp b/game/graphics/texture/TexturePool.cpp index 88998c3d91..f978b344a7 100644 --- a/game/graphics/texture/TexturePool.cpp +++ b/game/graphics/texture/TexturePool.cpp @@ -136,11 +136,9 @@ void TexturePool::unload_texture(PcTextureId tex_id, u64 gpu_id) { ASSERT(false); return; } - if (tex->is_placeholder) { - fmt::print("trying to unload something that was already placholdered: {} {}\n", - get_debug_texture_name(tex_id), tex->gpu_textures.size()); - } - ASSERT(!tex->is_placeholder); + ASSERT_MSG(!tex->is_placeholder, + fmt::format("trying to unload something that was already placholdered: {} {}\n", + get_debug_texture_name(tex_id), tex->gpu_textures.size())); auto it = std::find_if(tex->gpu_textures.begin(), tex->gpu_textures.end(), [&](const auto& a) { return a.gl == gpu_id; }); ASSERT(it != tex->gpu_textures.end()); @@ -378,4 +376,4 @@ std::string TexturePool::get_debug_texture_name(PcTextureId id) { } else { return "???"; } -} \ No newline at end of file +} diff --git a/game/overlord/iso_api.cpp b/game/overlord/iso_api.cpp index 77bda54f31..bcab1e3950 100644 --- a/game/overlord/iso_api.cpp +++ b/game/overlord/iso_api.cpp @@ -56,7 +56,7 @@ s32 LoadISOFileToEE(FileRecord* file, uint32_t addr, uint32_t length) { } s32 LoadISOFileChunkToEE(FileRecord* file, uint32_t dest_addr, uint32_t length, uint32_t offset) { - lg::debug("[OVERLORD] LoadISOFileChunkToEE {} : {} offset {}\n", file->name, length, offset); + lg::debug("[OVERLORD] LoadISOFileChunkToEE {} : {} offset {}", file->name, length, offset); IsoCommandLoadSingle cmd; cmd.cmd_id = LOAD_TO_EE_OFFSET_CMD_ID; cmd.messagebox_to_reply = 0; diff --git a/game/overlord/iso_cd.cpp b/game/overlord/iso_cd.cpp index ac3e305054..17ca97acbf 100644 --- a/game/overlord/iso_cd.cpp +++ b/game/overlord/iso_cd.cpp @@ -390,7 +390,7 @@ void LoadDiscID() { for (uint32_t i = 0; i < SECTOR_SIZE / 4; i++) { CD_ID_SectorSum += CD_ID_Sector[i]; } - lg::info("[OVERLORD] DISK_ID.DIZ OK 0x{:x}\n", CD_ID_SectorSum); + lg::info("[OVERLORD] DISK_ID.DIZ OK 0x{:x}", CD_ID_SectorSum); } /*! diff --git a/game/sce/libgraph.cpp b/game/sce/libgraph.cpp index dbfc64b72a..aa7df6d01b 100644 --- a/game/sce/libgraph.cpp +++ b/game/sce/libgraph.cpp @@ -5,6 +5,6 @@ namespace ee { void sceGsResetPath() {} void sceGsResetGraph(int mode, int inter, int omode, int ffmode) { - lg::warn("sceGsResetGraph: mode {} inter {} omode {} fmode {}\n", mode, inter, omode, ffmode); + lg::warn("sceGsResetGraph: mode {} inter {} omode {} fmode {}", mode, inter, omode, ffmode); } -} // namespace ee \ No newline at end of file +} // namespace ee diff --git a/game/sound/989snd/ame_handler.cpp b/game/sound/989snd/ame_handler.cpp index 1be56ecca0..cce42ca856 100644 --- a/game/sound/989snd/ame_handler.cpp +++ b/game/sound/989snd/ame_handler.cpp @@ -2,6 +2,8 @@ // SPDX-License-Identifier: ISC #include "ame_handler.h" +#include "common/log/log.h" + #include "game/sound/989snd/blocksound_handler.h" namespace snd { diff --git a/game/sound/989snd/loader.cpp b/game/sound/989snd/loader.cpp index 5a3f3bc382..237fec6af1 100644 --- a/game/sound/989snd/loader.cpp +++ b/game/sound/989snd/loader.cpp @@ -7,6 +7,8 @@ #include "midi_handler.h" +#include "common/log/log.h" + #include namespace snd { @@ -85,7 +87,7 @@ u32 loader::read_bank(std::fstream& in) { in.read((char*)(&attr), sizeof(attr)); if (attr.type != 1 && attr.type != 3) { - fmt::print("Error: File type {} not supported.", attr.type); + lg::error("Error: File type {} not supported.", attr.type); return -1; } @@ -136,7 +138,7 @@ void loader::load_midi(std::fstream& in) { in.read((char*)midi.get(), attr.where[0].size); auto h = (MIDIBlock*)midi.get(); - fmt::print("Loaded midi {:.4}\n", (char*)&h->ID); + lg::info("Loaded midi {:.4}", (char*)&h->ID); m_midi.emplace(h->ID, (MIDIBlock*)midi.get()); m_midi_chunks.emplace_back(std::move(midi)); diff --git a/game/sound/989snd/midi_handler.cpp b/game/sound/989snd/midi_handler.cpp index 10b24dc382..f891551166 100644 --- a/game/sound/989snd/midi_handler.cpp +++ b/game/sound/989snd/midi_handler.cpp @@ -4,6 +4,8 @@ #include "ame_handler.h" +#include "common/log/log.h" + #include namespace snd { @@ -261,7 +263,7 @@ void midi_handler::channel_pitch() { u32 pitch = (m_seq_ptr[0] << 7) | m_seq_ptr[1]; (void)pitch; (void)channel; - // fmt::print("{}: pitch ch{:01x} {:04x}\n", m_time, channel, pitch); + // lg::debug("{}: pitch ch{:01x} {:04x}", m_time, channel, pitch); m_seq_ptr += 2; } @@ -303,7 +305,7 @@ void midi_handler::system_event() { m_seq_ptr = ptr; if (!cont) { - // fmt::print("{:x} track stopped by ame\n", (u64)this); + // lg::debug("{:x} track stopped by ame", (u64)this); m_track_complete = true; } } else { @@ -325,8 +327,7 @@ bool midi_handler::tick() { step(); } catch (midi_error& e) { m_track_complete = true; - fmt::print("MIDI Error: {}\n", e.what()); - + lg::error("MIDI Error: {}", e.what()); fmt::print("Sequence following: "); for (int i = 0; i < 10; i++) { fmt::print("{:x} ", m_seq_ptr[i]); diff --git a/game/sound/989snd/player.cpp b/game/sound/989snd/player.cpp index fcf92e79dd..750d83f79d 100644 --- a/game/sound/989snd/player.cpp +++ b/game/sound/989snd/player.cpp @@ -10,6 +10,7 @@ #include #include #endif +#include "common/log/log.h" namespace snd { @@ -26,8 +27,8 @@ void player::init_cubeb() { HRESULT hr = CoInitializeEx(nullptr, COINIT_MULTITHREADED); m_coinitialized = SUCCEEDED(hr); if (FAILED(hr) && hr != RPC_E_CHANGED_MODE) { - fmt::print("Couldn't initialize COM\n"); - fmt::print("Cubeb init failed\n"); + lg::error("Couldn't initialize COM"); + lg::error("Cubeb init failed"); return; } #endif @@ -45,20 +46,20 @@ void player::init_cubeb() { u32 latency = 0; err = cubeb_get_min_latency(m_ctx, &outparam, &latency); if (err != CUBEB_OK) { - fmt::print("Cubeb init failed\n"); + lg::error("Cubeb init failed"); return; } err = cubeb_stream_init(m_ctx, &m_stream, "OpenGOAL", nullptr, nullptr, nullptr, &outparam, latency, &sound_callback, &state_callback, this); if (err != CUBEB_OK) { - fmt::print("Cubeb init failed\n"); + lg::error("Cubeb init failed"); return; } err = cubeb_stream_start(m_stream); if (err != CUBEB_OK) { - fmt::print("Cubeb init failed\n"); + lg::error("Cubeb init failed"); return; } } @@ -126,7 +127,7 @@ u32 player::play_sound(u32 bank_id, u32 sound_id, s32 vol, s32 pan, s32 pm, s32 std::scoped_lock lock(m_ticklock); auto bank = m_loader.get_bank_by_handle(bank_id); if (bank == nullptr) { - fmt::print("play_sound: Bank {} does not exist\n", bank_id); + lg::error("play_sound: Bank {} does not exist", bank_id); return 0; } diff --git a/game/sound/989snd/sndplay.cpp b/game/sound/989snd/sndplay.cpp index a39b2d869d..e5ac4dadd6 100644 --- a/game/sound/989snd/sndplay.cpp +++ b/game/sound/989snd/sndplay.cpp @@ -1,5 +1,7 @@ #include "player.h" +#include "common/log/log.h" + int main(int argc, char* argv[]) { snd::player player; unsigned bankid = 0; @@ -9,14 +11,14 @@ int main(int argc, char* argv[]) { if (argc > 2) { bankid = player.load_bank(file, 0); unsigned sound = player.play_sound(bankid, atoi(argv[2]), 0x400, 0, 0, 0); - fmt::print("sound {} started\n", sound); + lg::info("sound {} started", sound); } while (true) { +#ifdef __linux timespec rqtp{}, rmtp{}; rqtp.tv_nsec = 0; rqtp.tv_sec = 1; -#ifdef __linux if (nanosleep(&rqtp, &rmtp) == -1) { break; } diff --git a/game/sound/CMakeLists.txt b/game/sound/CMakeLists.txt index 4dc75ba4a3..f9abcd3df8 100644 --- a/game/sound/CMakeLists.txt +++ b/game/sound/CMakeLists.txt @@ -18,7 +18,7 @@ set(SOUND_SOURCES ) add_library(sound STATIC ${SOUND_SOURCES}) -target_link_libraries(sound PRIVATE fmt cubeb) +target_link_libraries(sound PRIVATE fmt cubeb common) add_executable(sndplay 989snd/sndplay.cpp) if(WIN32) diff --git a/game/system/Deci2Server.cpp b/game/system/Deci2Server.cpp index 54ae18a147..c5a2acf56e 100644 --- a/game/system/Deci2Server.cpp +++ b/game/system/Deci2Server.cpp @@ -21,6 +21,7 @@ #include #include #endif +#include "common/log/log.h" // clang-format on Deci2Server::~Deci2Server() { @@ -37,7 +38,7 @@ Deci2Server::~Deci2Server() { } void Deci2Server::post_init() { - fmt::print("[Deci2Server:{}] awaiting connections\n", tcp_port); + lg::info("[Deci2Server:{}] awaiting connections", tcp_port); accept_thread_running = true; kill_accept_thread = false; accept_thread = std::thread(&Deci2Server::accept_thread_func, this); diff --git a/goalc/build_level/build_level.cpp b/goalc/build_level/build_level.cpp index 240974794e..5136f31250 100644 --- a/goalc/build_level/build_level.cpp +++ b/goalc/build_level/build_level.cpp @@ -21,10 +21,10 @@ void save_pc_data(const std::string& nickname, data.serialize(ser); auto compressed = compression::compress_zstd(ser.get_save_result().first, ser.get_save_result().second); - fmt::print("stats for {}\n", data.level_name); + lg::print("stats for {}\n", data.level_name); print_memory_usage(data, ser.get_save_result().second); - fmt::print("compressed: {} -> {} ({:.2f}%)\n", ser.get_save_result().second, compressed.size(), - 100.f * compressed.size() / ser.get_save_result().second); + lg::print("compressed: {} -> {} ({:.2f}%)\n", ser.get_save_result().second, compressed.size(), + 100.f * compressed.size() / ser.get_save_result().second); file_util::write_binary_file(fr3_output_dir / fmt::format("{}.fr3", nickname), compressed.data(), compressed.size()); } @@ -104,10 +104,10 @@ bool run_build_level(const std::string& input_file, // Save the GOAL level auto result = file.save_object_file(); - fmt::print("Level bsp file size {} bytes\n", result.size()); + lg::print("Level bsp file size {} bytes\n", result.size()); auto save_path = file_util::get_jak_project_dir() / bsp_output_file; file_util::create_dir_if_needed_for_file(save_path); - fmt::print("Saving to {}\n", save_path.string()); + lg::print("Saving to {}\n", save_path.string()); file_util::write_binary_file(save_path, result.data(), result.size()); // Save the PC level diff --git a/goalc/build_level/collide_bvh.cpp b/goalc/build_level/collide_bvh.cpp index 9e3f4a0e6f..abbab4531e 100644 --- a/goalc/build_level/collide_bvh.cpp +++ b/goalc/build_level/collide_bvh.cpp @@ -108,7 +108,7 @@ void split_along_dim(std::vector& faces, std::sort(faces.begin(), faces.end(), [=](const CollideFace& a, const CollideFace& b) { return a.bsphere[dim] < b.bsphere[dim]; }); - fmt::print("splitting with size: {}\n", faces.size()); + lg::print("splitting with size: {}\n", faces.size()); size_t split_idx = faces.size() / 2; out0->insert(out0->end(), faces.begin(), faces.begin() + split_idx); out1->insert(out1->end(), faces.begin() + split_idx, faces.end()); @@ -304,10 +304,10 @@ CollideTree construct_collide_bvh(const std::vector& tris) { } for (auto [size, count] : size_histogram) { - fmt::print(" [{:3d}] {:3d} ({})\n", size, count, size * count); + lg::print(" [{:3d}] {:3d} ({})\n", size, count, size * count); } return tree; } -} // namespace collide \ No newline at end of file +} // namespace collide diff --git a/goalc/build_level/collide_pack.cpp b/goalc/build_level/collide_pack.cpp index 511e695ab1..3e2f7a421b 100644 --- a/goalc/build_level/collide_pack.cpp +++ b/goalc/build_level/collide_pack.cpp @@ -82,7 +82,7 @@ PackedU16Verts pack_verts_to_u16(const std::vector& input) { math::Vector3f vf14_base_trans_float(result.base[0], result.base[1], result.base[2]); vf13_combo_offset -= vf14_base_trans_float; v -= vf13_combo_offset; - fmt::print("error {}\n", (v - input[i]).to_string_aligned());; + lg::print("error {}\n", (v - input[i]).to_string_aligned());; } */ @@ -201,8 +201,8 @@ CollideFragMeshDataArray pack_collide_frags(const std::vector 128) { - fmt::print("frag with too many vertices: {} had {} tris\n", frag_out.vertex_count, - frag_in.faces.size()); + lg::print("frag with too many vertices: {} had {} tris\n", frag_out.vertex_count, + frag_in.faces.size()); lg::error("SHOULD CRASH\n"); } // the diff --git a/goalc/build_level/color_quantization.cpp b/goalc/build_level/color_quantization.cpp index 5ff39cb519..c36950b9b9 100644 --- a/goalc/build_level/color_quantization.cpp +++ b/goalc/build_level/color_quantization.cpp @@ -24,7 +24,7 @@ QuantizedColors quantize_colors_dumb(const std::vector>& in) result.vtx_to_color.push_back(existing->second); } } - fmt::print("quantize_colors_dumb: {} -> {}\n", in.size(), result.final_colors.size()); + lg::print("quantize_colors_dumb: {} -> {}\n", in.size(), result.final_colors.size()); ASSERT(result.final_colors.size() < 8192); return result; } @@ -205,7 +205,7 @@ QuantizedColors quantize_colors_octree(const std::vector>& i float total_error[3] = {0, 0, 0}; for (size_t i = 0; i < in.size(); i++) { - // fmt::print(" {} -> {}\n", in[i].to_string_hex_byte(), + // lg::print(" {} -> {}\n", in[i].to_string_hex_byte(), // out.final_colors[out.vtx_to_color[i]].to_string_hex_byte()); auto diff = in[i].cast() - out.final_colors[out.vtx_to_color[i]].cast(); @@ -219,4 +219,4 @@ QuantizedColors quantize_colors_octree(const std::vector>& i lg::info("Final palette size: {}", out.final_colors.size()); return out; -} \ No newline at end of file +} diff --git a/goalc/build_level/gltf_mesh_extract.cpp b/goalc/build_level/gltf_mesh_extract.cpp index 7ef450bd7c..82359441e6 100644 --- a/goalc/build_level/gltf_mesh_extract.cpp +++ b/goalc/build_level/gltf_mesh_extract.cpp @@ -138,7 +138,7 @@ ExtractedVertices gltf_vertices(const tinygltf::Model& model, ASSERT_MSG(attrib_accessor.componentType == TINYGLTF_COMPONENT_TYPE_FLOAT, "POSITION wasn't float"); // for (auto& attrib : attributes) { - // fmt::print("attrib: {}\n", attrib.first); + // lg::print("attrib: {}\n", attrib.first); //} auto mesh_verts = extract_vec3f(data_ptr, count, byte_stride); result.reserve(mesh_verts.size()); @@ -796,10 +796,10 @@ void extract(const Input& in, for (int j = 0; j < 3; j++) { float output_dist = face.bsphere.w() - (face.bsphere.xyz() - face.v[j]).length(); if (output_dist < 0) { - fmt::print("{}\n", output_dist); - fmt::print("BAD:\n{}\n{}\n{}\n", face.v[0].to_string_aligned(), - face.v[1].to_string_aligned(), face.v[2].to_string_aligned()); - fmt::print("bsphere: {}\n", face.bsphere.to_string_aligned()); + lg::print("{}\n", output_dist); + lg::print("BAD:\n{}\n{}\n{}\n", face.v[0].to_string_aligned(), + face.v[1].to_string_aligned(), face.v[2].to_string_aligned()); + lg::print("bsphere: {}\n", face.bsphere.to_string_aligned()); } } face.pat = pat.pat; diff --git a/goalc/compiler/Compiler.cpp b/goalc/compiler/Compiler.cpp index c2a449f668..e9364cd683 100644 --- a/goalc/compiler/Compiler.cpp +++ b/goalc/compiler/Compiler.cpp @@ -176,35 +176,35 @@ Val* Compiler::compile_error_guard(const goos::Object& code, Env* env) { bool term; auto loc_info = m_goos.reader.db.get_info_for(code, &term); if (term) { - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Location:\n"); - fmt::print(loc_info); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Location:\n"); + lg::print(loc_info); } - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Code:\n"); - fmt::print("{}\n", pretty_print::to_string(code, 120)); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Code:\n"); + lg::print("{}\n", pretty_print::to_string(code, 120)); if (term) { ce.print_err_stack = false; } std::string line(80, '-'); line.push_back('\n'); - fmt::print(line); + lg::print(line); } throw ce; } catch (std::runtime_error& e) { - fmt::print(fg(fmt::color::crimson) | fmt::emphasis::bold, "-- Compilation Error! --\n"); - fmt::print(fmt::emphasis::bold, "{}\n", e.what()); + lg::print(fg(fmt::color::crimson) | fmt::emphasis::bold, "-- Compilation Error! --\n"); + lg::print(fmt::emphasis::bold, "{}\n", e.what()); bool term; auto loc_info = m_goos.reader.db.get_info_for(code, &term); if (term) { - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Location:\n"); - fmt::print(loc_info); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Location:\n"); + lg::print(loc_info); } - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Code:\n"); - fmt::print("{}\n", pretty_print::to_string(code, 120)); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Code:\n"); + lg::print("{}\n", pretty_print::to_string(code, 120)); CompilerException ce("Compiler Exception"); if (term) { @@ -212,7 +212,7 @@ Val* Compiler::compile_error_guard(const goos::Object& code, Env* env) { } std::string line(80, '-'); line.push_back('\n'); - fmt::print(line); + lg::print(line); throw ce; } } @@ -251,13 +251,13 @@ void Compiler::color_object_file(FileEnv* env) { if (regalloc_result_2.ok) { if (regalloc_result_2.num_spilled_vars > 0) { - // fmt::print("Function {} has {} spilled vars.\n", f->name(), + // lg::print("Function {} has {} spilled vars.\n", f->name(), // regalloc_result_2.num_spilled_vars); } num_spills_in_file += regalloc_result_2.num_spills; f->set_allocations(std::move(regalloc_result_2)); } else { - fmt::print( + lg::print( "Warning: function {} failed register allocation with the v2 allocator. Falling back to " "the v1 allocator.\n", f->name()); @@ -281,8 +281,7 @@ std::vector Compiler::codegen_object_file(FileEnv* env) { auto result = gen.run(&m_ts); for (auto& f : env->functions()) { if (f->settings.print_asm) { - fmt::print("{}\n", - debug_info->disassemble_function_by_name(f->name(), &ok, &m_goos.reader)); + lg::print("{}\n", debug_info->disassemble_function_by_name(f->name(), &ok, &m_goos.reader)); } } auto stats = gen.get_obj_stats(); diff --git a/goalc/compiler/Compiler.h b/goalc/compiler/Compiler.h index 74d30abf65..75dff8db8e 100644 --- a/goalc/compiler/Compiler.h +++ b/goalc/compiler/Compiler.h @@ -417,38 +417,38 @@ class Compiler { [[noreturn]] void throw_compiler_error(const goos::Object& code, const std::string& str, Args&&... args) { - fmt::print(fg(fmt::color::crimson) | fmt::emphasis::bold, "-- Compilation Error! --\n"); + lg::print(fg(fmt::color::crimson) | fmt::emphasis::bold, "-- Compilation Error! --\n"); if (!str.empty() && str.back() == '\n') { - fmt::print(fmt::emphasis::bold, str, std::forward(args)...); + lg::print(fmt::emphasis::bold, str, std::forward(args)...); } else { - fmt::print(fmt::emphasis::bold, str + '\n', std::forward(args)...); + lg::print(fmt::emphasis::bold, str + '\n', std::forward(args)...); } - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Form:\n"); - fmt::print("{}\n", code.print()); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Form:\n"); + lg::print("{}\n", code.print()); throw CompilerException("Compilation Error"); } template [[noreturn]] void throw_compiler_error_no_code(const std::string& str, Args&&... args) { - fmt::print(fg(fmt::color::crimson) | fmt::emphasis::bold, "-- Compilation Error! --\n"); + lg::print(fg(fmt::color::crimson) | fmt::emphasis::bold, "-- Compilation Error! --\n"); if (!str.empty() && str.back() == '\n') { - fmt::print(fmt::emphasis::bold, str, std::forward(args)...); + lg::print(fmt::emphasis::bold, str, std::forward(args)...); } else { - fmt::print(fmt::emphasis::bold, str + '\n', std::forward(args)...); + lg::print(fmt::emphasis::bold, str + '\n', std::forward(args)...); } - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Form:\n"); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Form:\n"); throw CompilerException("Compilation Error"); } template void print_compiler_warning(const std::string& str, Args&&... args) { - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "[Warning] "); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "[Warning] "); if (!str.empty() && str.back() == '\n') { - fmt::print(str, std::forward(args)...); + lg::print(str, std::forward(args)...); } else { - fmt::print(str + '\n', std::forward(args)...); + lg::print(str + '\n', std::forward(args)...); } } diff --git a/goalc/compiler/Env.cpp b/goalc/compiler/Env.cpp index de604c7aa0..7e0ed6ff1e 100644 --- a/goalc/compiler/Env.cpp +++ b/goalc/compiler/Env.cpp @@ -5,6 +5,7 @@ #include "IR.h" #include "common/goos/Reader.h" +#include "common/log/log.h" #include "third-party/fmt/core.h" @@ -157,7 +158,7 @@ void FileEnv::add_top_level_function(std::unique_ptr fe) { void FileEnv::debug_print_tl() { if (m_top_level_func) { for (auto& code : m_top_level_func->code()) { - fmt::print("{}\n", code->print()); + lg::print("{}\n", code->print()); } } else { printf("no top level function.\n"); @@ -294,7 +295,7 @@ StackVarAddrVal* FunctionEnv::allocate_aligned_stack_variable(const TypeSpec& ts int size_bytes, int align_bytes) { if (align_bytes > 16) { - fmt::print("\n\n\nBad stack align: {} bytes for {}\n\n\n\n", align_bytes, ts.print()); + lg::print("\n\n\nBad stack align: {} bytes for {}\n\n\n\n", align_bytes, ts.print()); } auto space = allocate_aligned_stack_space(size_bytes, align_bytes); return alloc_val(ts, space.start_slot, space.slot_count); diff --git a/goalc/compiler/Util.cpp b/goalc/compiler/Util.cpp index f4b57fd969..662f7439cb 100644 --- a/goalc/compiler/Util.cpp +++ b/goalc/compiler/Util.cpp @@ -72,7 +72,7 @@ std::vector Compiler::run_test_from_file(const std::string& source_ } return m_listener.stop_recording_messages(); } catch (std::exception& e) { - fmt::print("[Compiler] Failed to compile test program {}: {}\n", source_code, e.what()); + lg::print("[Compiler] Failed to compile test program {}: {}\n", source_code, e.what()); throw e; } } @@ -98,7 +98,7 @@ std::vector Compiler::run_test_from_string(const std::string& src, } return m_listener.stop_recording_messages(); } catch (std::exception& e) { - fmt::print("[Compiler] Failed to compile test program from string {}: {}\n", src, e.what()); + lg::print("[Compiler] Failed to compile test program from string {}: {}\n", src, e.what()); throw e; } } diff --git a/goalc/compiler/compilation/CompilerControl.cpp b/goalc/compiler/compilation/CompilerControl.cpp index d67b463421..c59b2c3212 100644 --- a/goalc/compiler/compilation/CompilerControl.cpp +++ b/goalc/compiler/compilation/CompilerControl.cpp @@ -16,7 +16,6 @@ #include "goalc/data_compiler/dir_tpages.h" #include "goalc/data_compiler/game_count.h" #include "goalc/data_compiler/game_text_common.h" - /*! * Exit the compiler. Disconnects the listener and tells the target to reset itself. * Will actually exit the next time the REPL runs. @@ -369,10 +368,10 @@ Val* Compiler::compile_get_info(const goos::Object& form, const goos::Object& re auto result = m_symbol_info.lookup_exact_name(args.unnamed.at(0).as_symbol()->name); if (!result) { - fmt::print("No results found.\n"); + lg::print("No results found.\n"); } else { for (auto& info : *result) { - fmt::print("{}", make_symbol_info_description(info)); + lg::print("{}", make_symbol_info_description(info)); } } @@ -496,11 +495,11 @@ Val* Compiler::compile_autocomplete(const goos::Object& form, const goos::Object auto time = timer.getMs(); for (auto& x : result) { - fmt::print(" {}\n", x); + lg::print(" {}\n", x); } - fmt::print("Autocomplete: {}/{} symbols matched, took {:.2f} ms\n", result.size(), - m_symbol_info.symbol_count(), time); + lg::print("Autocomplete: {}/{} symbols matched, took {:.2f} ms\n", result.size(), + m_symbol_info.symbol_count(), time); return get_none(); } @@ -562,12 +561,12 @@ Val* Compiler::compile_print_debug_compiler_stats(const goos::Object& form, auto args = get_va(form, rest); va_check(form, args, {}, {}); - fmt::print("Spill operations (total): {}\n", m_debug_stats.num_spills); - fmt::print("Spill operations (v1 only): {}\n", m_debug_stats.num_spills_v1); - fmt::print("Eliminated moves: {}\n", m_debug_stats.num_moves_eliminated); - fmt::print("Total functions: {}\n", m_debug_stats.total_funcs); - fmt::print("Functions requiring v1: {}\n", m_debug_stats.funcs_requiring_v1_allocator); - fmt::print("Size of autocomplete prefix tree: {}\n", m_symbol_info.symbol_count()); + lg::print("Spill operations (total): {}\n", m_debug_stats.num_spills); + lg::print("Spill operations (v1 only): {}\n", m_debug_stats.num_spills_v1); + lg::print("Eliminated moves: {}\n", m_debug_stats.num_moves_eliminated); + lg::print("Total functions: {}\n", m_debug_stats.total_funcs); + lg::print("Functions requiring v1: {}\n", m_debug_stats.funcs_requiring_v1_allocator); + lg::print("Size of autocomplete prefix tree: {}\n", m_symbol_info.symbol_count()); return get_none(); } diff --git a/goalc/compiler/compilation/ConstantPropagation.cpp b/goalc/compiler/compilation/ConstantPropagation.cpp index 6603c0c95b..59736be3e0 100644 --- a/goalc/compiler/compilation/ConstantPropagation.cpp +++ b/goalc/compiler/compilation/ConstantPropagation.cpp @@ -134,8 +134,8 @@ Compiler::ConstPropResult Compiler::try_constant_propagation(const goos::Object& auto ret = constant_propagation_dispatch(form, env); size_t end_size = code_size(env); if (start_size != end_size) { - fmt::print("Compiler bug in constant propagation. Code was generated: {} vs {}\n", start_size, - end_size); + lg::print("Compiler bug in constant propagation. Code was generated: {} vs {}\n", start_size, + end_size); ASSERT(false); } return ret; @@ -315,4 +315,4 @@ ValOrConstFloat Compiler::get_constant_float_or_variable(const goos::Object& in, return ValOrConstFloat(compile_no_const_prop(prop.value, env)); } } -} \ No newline at end of file +} diff --git a/goalc/compiler/compilation/Debug.cpp b/goalc/compiler/compilation/Debug.cpp index 4d13ec2939..9c4dddb022 100644 --- a/goalc/compiler/compilation/Debug.cpp +++ b/goalc/compiler/compilation/Debug.cpp @@ -1,3 +1,4 @@ +#include "common/log/log.h" #include "common/util/FileUtil.h" #include "goalc/compiler/Compiler.h" @@ -57,19 +58,19 @@ Val* Compiler::compile_dbg(const goos::Object& form, const goos::Object& rest, E (void)rest; (void)env; if (!m_debugger.is_valid()) { - fmt::print("[Debugger] Could not start debugger because there is no valid debugging context\n"); + lg::print("[Debugger] Could not start debugger because there is no valid debugging context\n"); return get_none(); } if (m_debugger.is_attached()) { - fmt::print("[Debugger] Could not start debugger because the debugger is already attached.\n"); + lg::print("[Debugger] Could not start debugger because the debugger is already attached.\n"); return get_none(); } if (m_debugger.attach_and_break()) { - fmt::print("Debugger connected.\n"); + lg::print("Debugger connected.\n"); } else { - fmt::print("ERROR\n"); + lg::print("ERROR\n"); } return get_none(); @@ -81,21 +82,21 @@ Val* Compiler::compile_dbs(const goos::Object& form, const goos::Object& rest, E (void)rest; (void)env; - fmt::print(" Listener connected? {}\n", m_listener.is_connected()); - fmt::print(" Debugger context? {}\n", m_debugger.is_valid()); + lg::print(" Listener connected? {}\n", m_listener.is_connected()); + lg::print(" Debugger context? {}\n", m_debugger.is_valid()); if (m_debugger.is_valid()) { - fmt::print(" Attached? {}\n", m_debugger.is_attached()); + lg::print(" Attached? {}\n", m_debugger.is_attached()); if (m_debugger.is_attached()) { - fmt::print(" Halted? {}\n", m_debugger.is_halted()); + lg::print(" Halted? {}\n", m_debugger.is_halted()); } - fmt::print(" Context: {}\n", m_debugger.get_context_string()); + lg::print(" Context: {}\n", m_debugger.get_context_string()); } if (m_debugger.is_valid()) { } else { - fmt::print("There is no valid debug context from the target."); + lg::print("There is no valid debug context from the target."); } return get_none(); @@ -110,8 +111,8 @@ Val* Compiler::compile_cont(const goos::Object& form, const goos::Object& rest, if (m_debugger.is_valid() && m_debugger.is_attached() && m_debugger.is_halted()) { m_debugger.do_continue(); } else { - fmt::print("Couldn't do :cont. Valid {}, attached {}, halted {}\n", m_debugger.is_valid(), - m_debugger.is_attached(), m_debugger.is_halted()); + lg::print("Couldn't do :cont. Valid {}, attached {}, halted {}\n", m_debugger.is_valid(), + m_debugger.is_attached(), m_debugger.is_halted()); } return get_none(); @@ -126,8 +127,8 @@ Val* Compiler::compile_stop(const goos::Object& form, const goos::Object& rest, if (m_debugger.is_valid() && m_debugger.is_attached() && m_debugger.is_halted()) { m_debugger.detach(); } else { - fmt::print("Couldn't do :stop. Valid {}, attached {}, halted {}\n", m_debugger.is_valid(), - m_debugger.is_attached(), m_debugger.is_halted()); + lg::print("Couldn't do :stop. Valid {}, attached {}, halted {}\n", m_debugger.is_valid(), + m_debugger.is_attached(), m_debugger.is_halted()); } return get_none(); @@ -142,8 +143,8 @@ Val* Compiler::compile_break(const goos::Object& form, const goos::Object& rest, if (m_debugger.is_valid() && m_debugger.is_attached() && m_debugger.is_running()) { m_debugger.do_break(); } else { - fmt::print("Couldn't do :break. Valid {}, attached {}, running {}\n", m_debugger.is_valid(), - m_debugger.is_attached(), m_debugger.is_running()); + lg::print("Couldn't do :break. Valid {}, attached {}, running {}\n", m_debugger.is_valid(), + m_debugger.is_attached(), m_debugger.is_running()); } return get_none(); @@ -152,7 +153,7 @@ Val* Compiler::compile_break(const goos::Object& form, const goos::Object& rest, Val* Compiler::compile_dump_all(const goos::Object& form, const goos::Object& rest, Env* env) { (void)env; if (!m_debugger.is_halted()) { - fmt::print("Couldn't dump memory. Must be attached and halted.\n"); + lg::print("Couldn't dump memory. Must be attached and halted.\n"); return get_none(); } @@ -165,7 +166,7 @@ Val* Compiler::compile_dump_all(const goos::Object& form, const goos::Object& re if (!m_debugger.read_memory(buffer + EE_MAIN_MEM_LOW_PROTECT, EE_MAIN_MEM_SIZE - EE_MAIN_MEM_LOW_PROTECT, EE_MAIN_MEM_LOW_PROTECT)) { - fmt::print("Reading memory failed, not dumping.\n"); + lg::print("Reading memory failed, not dumping.\n"); } else { file_util::write_binary_file(file_util::get_file_path({dest_file}), buffer, EE_MAIN_MEM_SIZE); } @@ -203,18 +204,18 @@ void mem_print(T* data, int count, u32 start_addr, PrintMode mode) { for (int i = 0; i < count; i++) { if ((i % elt_per_line) == 0) { // first in line, so we should print the GOAL address - fmt::print(" 0x{:08x}: ", start_addr + (i * sizeof(T))); + lg::print(" 0x{:08x}: ", start_addr + (i * sizeof(T))); } // print the thing - fmt::print(format_string, data[i]); + lg::print(format_string, data[i]); if ((i % elt_per_line) == (elt_per_line - 1)) { // last in line, newline! - fmt::print("\n"); + lg::print("\n"); } } - fmt::print("\n"); + lg::print("\n"); } } // namespace @@ -363,8 +364,8 @@ Val* Compiler::compile_disasm(const goos::Object& form, const goos::Object& rest addr, addr + size, EE_MAIN_MEM_LOW_PROTECT, EE_MAIN_MEM_SIZE); } - fmt::print("{}\n", m_debugger.get_info_about_addr(addr)); - fmt::print("{}\n", m_debugger.disassemble_x86_with_symbols(size, addr)); + lg::print("{}\n", m_debugger.get_info_about_addr(addr)); + lg::print("{}\n", m_debugger.disassemble_x86_with_symbols(size, addr)); return get_none(); } @@ -417,9 +418,9 @@ Val* Compiler::compile_d_sym_name(const goos::Object& form, const goos::Object& auto sym_name = m_debugger.get_symbol_name_from_offset(ofs); if (sym_name) { - fmt::print("symbol name for symbol {:X}h is {}\n", ofs, sym_name); + lg::print("symbol name for symbol {:X}h is {}\n", ofs, sym_name); } else { - fmt::print("symbol {:X}h is not loaded or is invalid\n", ofs); + lg::print("symbol {:X}h is not loaded or is invalid\n", ofs); } return get_none(); diff --git a/goalc/compiler/compilation/Define.cpp b/goalc/compiler/compilation/Define.cpp index 4b9e4d64ab..4a0da76713 100644 --- a/goalc/compiler/compilation/Define.cpp +++ b/goalc/compiler/compilation/Define.cpp @@ -3,8 +3,6 @@ * Forms which define or set things. */ -#include "common/log/log.h" - #include "goalc/compiler/Compiler.h" /*! diff --git a/goalc/compiler/compilation/Macro.cpp b/goalc/compiler/compilation/Macro.cpp index b2cf1580e4..f324b77b18 100644 --- a/goalc/compiler/compilation/Macro.cpp +++ b/goalc/compiler/compilation/Macro.cpp @@ -49,35 +49,35 @@ Val* Compiler::compile_goos_macro(const goos::Object& o, if (ce.print_err_stack) { bool good_info = false; auto info = m_goos.reader.db.get_info_for(o, &good_info); - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Code:\n"); - fmt::print("{}\n", pretty_print::to_string(goos_result, 120)); - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "From macro: "); - fmt::print(fg(fmt::color::orange), "{}\n", name.print()); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Code:\n"); + lg::print("{}\n", pretty_print::to_string(goos_result, 120)); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "From macro: "); + lg::print(fg(fmt::color::orange), "{}\n", name.print()); if (good_info) { - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Used in:\n"); - fmt::print("{}\n", info); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Used in:\n"); + lg::print("{}\n", info); ce.print_err_stack = false; } std::string line(80, '-'); line.push_back('\n'); - fmt::print(line); + lg::print(line); } throw; } catch (std::runtime_error& e) { bool good_info = false; auto info = m_goos.reader.db.get_info_for(o, &good_info); - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Code:\n"); - fmt::print("{}\n", pretty_print::to_string(goos_result, 120)); - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "From macro: "); - fmt::print(fg(fmt::color::orange), "{}\n", name.print()); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Code:\n"); + lg::print("{}\n", pretty_print::to_string(goos_result, 120)); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "From macro: "); + lg::print(fg(fmt::color::orange), "{}\n", name.print()); if (good_info) { - fmt::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Used in:\n"); - fmt::print("{}\n", info); + lg::print(fg(fmt::color::yellow) | fmt::emphasis::bold, "Used in:\n"); + lg::print("{}\n", info); } std::string line(80, '-'); line.push_back('\n'); - fmt::print(line); + lg::print(line); throw; } diff --git a/goalc/compiler/compilation/Type.cpp b/goalc/compiler/compilation/Type.cpp index 6b40c11262..dcf4e958fe 100644 --- a/goalc/compiler/compilation/Type.cpp +++ b/goalc/compiler/compilation/Type.cpp @@ -1,3 +1,4 @@ +#include "common/log/log.h" #include "common/type_system/defenum.h" #include "common/type_system/deftype.h" #include "common/type_system/state.h" @@ -371,8 +372,8 @@ Val* Compiler::compile_deftype(const goos::Object& form, const goos::Object& res auto kv = m_symbol_types.find(result.type.base_type()); if (kv != m_symbol_types.end() && kv->second.base_type() != "type") { // we already have something that's not a type with the same name, this is bad. - fmt::print("[Warning] deftype will redefine {} from {} to a type.\n", result.type.base_type(), - kv->second.print()); + lg::print("[Warning] deftype will redefine {} from {} to a type.\n", result.type.base_type(), + kv->second.print()); } // remember that this is a type m_symbol_types[result.type.base_type()] = m_ts.make_typespec("type"); @@ -958,7 +959,7 @@ Val* Compiler::compile_print_type(const goos::Object& form, const goos::Object& auto args = get_va(form, rest); va_check(form, args, {{}}, {}); auto result = compile(args.unnamed.at(0), env)->to_reg(form, env); - fmt::print("[TYPE] {} {}\n", result->type().print(), result->print()); + lg::print("[TYPE] {} {}\n", result->type().print(), result->print()); return result; } diff --git a/goalc/data_compiler/game_text_common.cpp b/goalc/data_compiler/game_text_common.cpp index 8615ad2d59..d108f34c1b 100644 --- a/goalc/data_compiler/game_text_common.cpp +++ b/goalc/data_compiler/game_text_common.cpp @@ -152,7 +152,7 @@ void compile_game_text(const std::vector& filenames, const std::string& output_prefix) { goos::Reader reader; for (auto& filename : filenames) { - fmt::print("[Build Game Text] {}\n", filename.c_str()); + lg::print("[Build Game Text] {}\n", filename.c_str()); auto code = reader.read_from_file({filename}); parse_text(code, db); } @@ -164,7 +164,7 @@ void compile_game_subtitle(const std::vector& filenames, const std::string& output_prefix) { goos::Reader reader; for (auto& filename : filenames) { - fmt::print("[Build Game Subtitle] {}\n", filename.c_str()); + lg::print("[Build Game Subtitle] {}\n", filename.c_str()); auto code = reader.read_from_file({filename}); parse_subtitle(code, db, filename); } diff --git a/goalc/debugger/Debugger.cpp b/goalc/debugger/Debugger.cpp index b3adb9e74c..0b41ce22e4 100644 --- a/goalc/debugger/Debugger.cpp +++ b/goalc/debugger/Debugger.cpp @@ -7,6 +7,7 @@ #include "Debugger.h" #include "common/goal_constants.h" +#include "common/log/log.h" #include "common/symbols.h" #include "common/util/Assert.h" #include "common/util/Timer.h" @@ -130,7 +131,7 @@ bool Debugger::attach_and_break() { // this may fail if you crash at exactly the wrong time. todo - remove? if (info.kind != xdbg::SignalInfo::BREAK) { - fmt::print("[Debugger] got signal {} when expecting break.\n", (int)info.kind); + lg::print("[Debugger] got signal {} when expecting break.\n", (int)info.kind); } // open the memory of the process @@ -146,13 +147,13 @@ bool Debugger::attach_and_break() { auto signal_count = get_signal_count(); if (signal_count != 0) { - fmt::print("[Debugger] got signal count of {} in attach_and_break\n", signal_count); + lg::print("[Debugger] got signal count of {} in attach_and_break\n", signal_count); } return true; } } else { - fmt::print("[Debugger] attach_and_break can't be done when valid = {} and attached = {}\n", - is_valid(), m_attached); + lg::print("[Debugger] attach_and_break can't be done when valid = {} and attached = {}\n", + is_valid(), m_attached); } return false; } @@ -221,15 +222,15 @@ InstructionPointerInfo Debugger::get_rip_info(u64 rip) { } std::vector Debugger::get_backtrace(u64 rip, u64 rsp) { - fmt::print("Backtrace:\n"); + lg::print("Backtrace:\n"); std::vector bt; if (rip == m_debug_context.base) { // we jumped to NULL. - fmt::print("Jumped to GOAL 0x0. Attempting to find previous function.\n"); + lg::print("Jumped to GOAL 0x0. Attempting to find previous function.\n"); u64 next_rip = 0; if (!read_memory_if_safe(&next_rip, rsp - m_debug_context.base)) { - fmt::print(" failed to read return address off of the stack\n"); + lg::print(" failed to read return address off of the stack\n"); return {}; } @@ -239,8 +240,8 @@ std::vector Debugger::get_backtrace(u64 rip, u64 rsp) { int fails = 0; while (true) { - fmt::print(" rsp: 0x{:x} (#x{:x}) rip: 0x{:x} (#x{:x})\n", rsp, rsp - m_debug_context.base, - rip, rip - m_debug_context.base); + lg::print(" rsp: 0x{:x} (#x{:x}) rip: 0x{:x} (#x{:x})\n", rsp, rsp - m_debug_context.base, + rip, rip - m_debug_context.base); BacktraceFrame frame; frame.rip_info = get_rip_info(rip); frame.rsp_at_rip = rsp; @@ -248,16 +249,16 @@ std::vector Debugger::get_backtrace(u64 rip, u64 rsp) { if (frame.rip_info.knows_function && frame.rip_info.func_debug && frame.rip_info.func_debug->stack_usage) { fails = 0; - fmt::print("<====================== CALL STACK ======================>\n"); - fmt::print("{} from {}\n", frame.rip_info.function_name, frame.rip_info.func_debug->obj_name); + lg::print("<====================== CALL STACK ======================>\n"); + lg::print("{} from {}\n", frame.rip_info.function_name, frame.rip_info.func_debug->obj_name); // we're good! auto disasm = disassemble_at_rip(frame.rip_info); - fmt::print("{}\n", disasm.text); + lg::print("{}\n", disasm.text); u64 rsp_at_call = rsp + *frame.rip_info.func_debug->stack_usage; u64 next_rip = 0; if (!read_memory_if_safe(&next_rip, rsp_at_call - m_debug_context.base)) { - fmt::print("Invalid return address encountered!\n"); + lg::print("Invalid return address encountered!\n"); break; } @@ -267,14 +268,14 @@ std::vector Debugger::get_backtrace(u64 rip, u64 rsp) { } else { if (!frame.rip_info.knows_function) { if (fails == 0) { - fmt::print("Unknown Function at rip\n"); + lg::print("Unknown Function at rip\n"); } /* bool found = false; if (s32(rip - m_debug_context.base) > 0 && m_symbol_name_to_value_map.find("function") != m_symbol_name_to_value_map.cend()) { - fmt::print("Attempting to find function at this address.\n"); + lg::print("Attempting to find function at this address.\n"); u32 function_sym_val = m_symbol_name_to_value_map.at("function"); u32 goal_pc = u32(rip - m_debug_context.base) & -8; @@ -290,21 +291,21 @@ std::vector Debugger::get_backtrace(u64 rip, u64 rsp) { if (wordval == function_sym_val) { // found a function! - fmt::print("Found function after {} bytes!\n", + lg::print("Found function after {} bytes!\n", (rip - m_debug_context.base) - goal_pc); break; } } if (goal_pc <= symtable_end) { - fmt::print("Could not find function within this address.\n"); + lg::print("Could not find function within this address.\n"); } else { rip = goal_pc + m_debug_context.base + BASIC_OFFSET; found = true; } } else*/ if (fails > 70) { - fmt::print( + lg::print( "Backtrace was too long. Exception might have happened outside GOAL code, or the " "stack frame is too long.\n"); break; @@ -312,7 +313,7 @@ std::vector Debugger::get_backtrace(u64 rip, u64 rsp) { // attempt to backtrace anyway! if this fails then rip u64 next_rip = 0; if (!read_memory_if_safe(&next_rip, rsp - m_debug_context.base - 8)) { - fmt::print("Invalid return address encountered!\n"); + lg::print("Invalid return address encountered!\n"); break; } @@ -321,10 +322,10 @@ std::vector Debugger::get_backtrace(u64 rip, u64 rsp) { ++fails; // break; } else if (!frame.rip_info.func_debug) { - fmt::print("Function {} has no debug info.\n", frame.rip_info.function_name); + lg::print("Function {} has no debug info.\n", frame.rip_info.function_name); break; } else { - fmt::print("Function {} with no stack frame data.\n", frame.rip_info.function_name); + lg::print("Function {} with no stack frame data.\n", frame.rip_info.function_name); break; } } @@ -417,21 +418,21 @@ void Debugger::update_break_info() { // todo adjust rip if break instruction???? m_memory_map = m_listener->build_memory_map(); - // fmt::print("{}", m_memory_map.print()); + // lg::print("{}", m_memory_map.print()); read_symbol_table(); m_regs_valid = false; if (!xdbg::get_regs_now(m_debug_context.tid, &m_regs_at_break)) { - fmt::print("[Debugger] get_regs_now failed after break, something is wrong\n"); + lg::print("[Debugger] get_regs_now failed after break, something is wrong\n"); } else { m_regs_valid = true; - fmt::print("{}", m_regs_at_break.print_gprs()); + lg::print("{}", m_regs_at_break.print_gprs()); } if (regs_valid()) { m_break_info = get_rip_info(m_regs_at_break.rip); update_continue_info(); auto dis = disassemble_at_rip(m_break_info); - fmt::print("{}\n", dis.text); + lg::print("{}\n", dis.text); get_backtrace(m_regs_at_break.rip, m_regs_at_break.gprs[emitter::RSP]); } @@ -528,7 +529,7 @@ void Debugger::read_symbol_table_jak1() { if (!xdbg::read_goal_memory(mem.data(), SYM_TABLE_MEM_SIZE, st_base, m_debug_context, m_memory_handle)) { - fmt::print("Read failed during read_symbol_table\n"); + lg::print("Read failed during read_symbol_table\n"); return; } reads++; @@ -562,8 +563,8 @@ void Debugger::read_symbol_table_jak1() { sym_type = sym->type; } else { if (sym_type != sym->type) { - fmt::print("Got bad symbol type. Expected 0x{:x} got 0x{:x}: addr 0x{:x}\n", sym_type, - sym->type, offset + st_base + (uint64_t)m_debug_context.base); + lg::print("Got bad symbol type. Expected 0x{:x} got 0x{:x}: addr 0x{:x}\n", sym_type, + sym->type, offset + st_base + (uint64_t)m_debug_context.base); return; } } @@ -575,7 +576,7 @@ void Debugger::read_symbol_table_jak1() { char str_buff[128]; if (!xdbg::read_goal_memory((u8*)str_buff, 128, info->str + 4, m_debug_context, m_memory_handle)) { - fmt::print("Read symbol string failed during read_symbol_table\n"); + lg::print("Read symbol string failed during read_symbol_table\n"); return; } reads++; @@ -590,7 +591,7 @@ void Debugger::read_symbol_table_jak1() { std::string str(str_buff); if (str.length() >= 50) { - fmt::print("Invalid symbol #x{:x}!\n", sym_offset); + lg::print("Invalid symbol #x{:x}!\n", sym_offset); continue; } @@ -603,7 +604,7 @@ void Debugger::read_symbol_table_jak1() { // to hide this duplicate symbol, we append "-hack-copy" to the end of it. str += "-hack-copy"; } else { - fmt::print("Symbol {} (#x{:x}) appears multiple times!\n", str, sym_offset); + lg::print("Symbol {} (#x{:x}) appears multiple times!\n", str, sym_offset); continue; // ASSERT(false); } @@ -616,8 +617,8 @@ void Debugger::read_symbol_table_jak1() { } ASSERT(m_symbol_offset_to_name_map.size() == m_symbol_name_to_offset_map.size()); - fmt::print("Read symbol table ({} bytes, {} reads, {} symbols, {:.2f} ms)\n", bytes_read, reads, - m_symbol_name_to_offset_map.size(), timer.getMs()); + lg::print("Read symbol table ({} bytes, {} reads, {} symbols, {:.2f} ms)\n", bytes_read, reads, + m_symbol_name_to_offset_map.size(), timer.getMs()); } void Debugger::read_symbol_table_jak2() { @@ -637,7 +638,7 @@ void Debugger::read_symbol_table_jak2() { if (!xdbg::read_goal_memory(mem.data(), SYM_TABLE_MEM_SIZE, st_base, m_debug_context, m_memory_handle)) { - fmt::print("Read failed during read_symbol_table\n"); + lg::print("Read failed during read_symbol_table\n"); return; } reads++; @@ -659,7 +660,7 @@ void Debugger::read_symbol_table_jak2() { // now get the string. char str_buff[128]; if (!xdbg::read_goal_memory((u8*)str_buff, 128, info + 4, m_debug_context, m_memory_handle)) { - fmt::print("Read symbol string failed during read_symbol_table\n"); + lg::print("Read symbol string failed during read_symbol_table\n"); return; } reads++; @@ -674,7 +675,7 @@ void Debugger::read_symbol_table_jak2() { std::string str(str_buff); if (str.length() >= 50) { - fmt::print("Invalid symbol #x{:x}!\n", sym_offset); + lg::print("Invalid symbol #x{:x}!\n", sym_offset); continue; } @@ -687,7 +688,7 @@ void Debugger::read_symbol_table_jak2() { // to hide this duplicate symbol, we append "-hack-copy" to the end of it. str += "-hack-copy"; } else { - fmt::print("Symbol {} (#x{:x}) appears multiple times!\n", str, sym_offset); + lg::print("Symbol {} (#x{:x}) appears multiple times!\n", str, sym_offset); continue; // ASSERT(false); } @@ -700,8 +701,8 @@ void Debugger::read_symbol_table_jak2() { } ASSERT(m_symbol_offset_to_name_map.size() == m_symbol_name_to_offset_map.size()); - fmt::print("Read symbol table ({} bytes, {} reads, {} symbols, {:.2f} ms)\n", bytes_read, reads, - m_symbol_name_to_offset_map.size(), timer.getMs()); + lg::print("Read symbol table ({} bytes, {} reads, {} symbols, {:.2f} ms)\n", bytes_read, reads, + m_symbol_name_to_offset_map.size(), timer.getMs()); } /*! @@ -941,8 +942,8 @@ void Debugger::add_addr_breakpoint(u32 addr) { std::unique_lock lock(m_watcher_mutex); auto kv = m_addr_breakpoints.find(addr); if (kv != m_addr_breakpoints.end()) { - fmt::print("Breakpoint at address 0x{:08x} already exists as breakpoint {}\n", addr, - kv->second.id); + lg::print("Breakpoint at address 0x{:08x} already exists as breakpoint {}\n", addr, + kv->second.id); return; } @@ -950,13 +951,13 @@ void Debugger::add_addr_breakpoint(u32 addr) { bp.goal_addr = addr; bp.id = m_addr_breakpoints.size(); if (!read_memory(&bp.old_data, 1, addr)) { - fmt::print("Failed to read memory for breakpoint, not adding breakpoint\n"); + lg::print("Failed to read memory for breakpoint, not adding breakpoint\n"); return; } u8 int3 = 0xcc; if (!write_memory(&int3, 1, addr)) { - fmt::print("Failed to write memory for breakpoint, not adding breakpoint\n"); + lg::print("Failed to write memory for breakpoint, not adding breakpoint\n"); return; } @@ -970,12 +971,12 @@ void Debugger::remove_addr_breakpoint(u32 addr) { update_continue_info(); auto kv = m_addr_breakpoints.find(addr); if (kv == m_addr_breakpoints.end()) { - fmt::print("Breakpoint at address 0x{:08x} does not exist\n", addr); + lg::print("Breakpoint at address 0x{:08x} does not exist\n", addr); return; } if (!write_memory(&kv->second.old_data, 1, addr)) { - fmt::print("Failed to remove breakpoint\n"); + lg::print("Failed to remove breakpoint\n"); return; } diff --git a/goalc/listener/Listener.cpp b/goalc/listener/Listener.cpp index 84943bcd99..7804d4fe7d 100644 --- a/goalc/listener/Listener.cpp +++ b/goalc/listener/Listener.cpp @@ -29,6 +29,7 @@ #include "common/cross_sockets/XSocket.h" #include "common/util/Assert.h" #include "common/versions.h" +#include "common/log/log.h" #include "Listener.h" @@ -225,7 +226,7 @@ void Listener::receive_func() { if (hdr->msg_id == last_sent_id) { printf("[Listener] Received ACK for most recent message late.\n"); if (last_recvd_id != hdr->msg_id - 1) { - fmt::print( + lg::print( "[Listener] WARNING: message ID jumped from {} to {}. Some messages may have " "been lost. You must wait for an ACK before sending the next message.\n", last_recvd_id, hdr->msg_id); @@ -252,7 +253,7 @@ void Listener::receive_func() { got_ack = true; last_recvd_id = hdr->msg_id; if (last_recvd_id > last_sent_id) { - fmt::print( + lg::print( "[Listener] ERROR: Got an ack message with id of {}, but the last message sent " "had an ID of {}.\n", last_recvd_id, last_sent_id); @@ -550,7 +551,7 @@ void Listener::handle_output_message(const char* msg) { } add_load(name_str.substr(2, name_str.length() - 3), entry); - // fmt::print("LOAD:\n{}", entry.print()); + // lg::print("LOAD:\n{}", entry.print()); } else { // todo unload printf("[Listener Warning] unknown output message \"%s\"\n", msg); diff --git a/goalc/main.cpp b/goalc/main.cpp index a5e0571fd0..b5cf1d04c1 100644 --- a/goalc/main.cpp +++ b/goalc/main.cpp @@ -138,7 +138,7 @@ int main(int argc, char** argv) { // Poll Terminal while (status != ReplStatus::WANT_EXIT) { if (status == ReplStatus::WANT_RELOAD) { - fmt::print("Reloading compiler...\n"); + lg::info("Reloading compiler..."); std::lock_guard lock(compiler_mutex); if (compiler) { compiler->save_repl_history(); @@ -160,7 +160,7 @@ int main(int argc, char** argv) { } } } catch (std::exception& e) { - fmt::print(stderr, "Compiler Fatal Error: {}\n", e.what()); + lg::error("Compiler Fatal Error: {}", e.what()); status = ReplStatus::WANT_EXIT; } diff --git a/goalc/make/MakeSystem.cpp b/goalc/make/MakeSystem.cpp index efda451b6e..0d0b5db421 100644 --- a/goalc/make/MakeSystem.cpp +++ b/goalc/make/MakeSystem.cpp @@ -1,6 +1,7 @@ #include "MakeSystem.h" #include "common/goos/ParseHelpers.h" +#include "common/log/log.h" #include "common/util/FileUtil.h" #include "common/util/Timer.h" @@ -89,8 +90,8 @@ void MakeSystem::load_project_file(const std::string& file_path) { auto data = m_goos.reader.read_from_file({file_path}); // interpret it, which will call various handlers. m_goos.eval(data, m_goos.global_environment.as_env_ptr()); - fmt::print("Loaded project {} with {} steps in {} ms\n", file_path, m_output_to_step.size(), - (int)timer.getMs()); + lg::print("Loaded project {} with {} steps in {} ms\n", file_path, m_output_to_step.size(), + (int)timer.getMs()); } goos::Object MakeSystem::handle_defstep(const goos::Object& form, @@ -256,8 +257,8 @@ std::vector MakeSystem::get_dependencies(const std::string& target) get_dependencies(target, target, &result, &added_deps); - fmt::print("Successfully found all {} dependencies for target in {:.3f}s\n", result.size(), - timer.getSeconds()); + lg::print("Successfully found all {} dependencies for target in {:.3f}s\n", result.size(), + timer.getSeconds()); return result; } @@ -312,8 +313,8 @@ std::vector MakeSystem::filter_dependencies(const std::vector& in, char end) { all_names += name; } if (all_names.length() > 70) { - fmt::print("{}...{}", all_names.substr(0, 70 - 3), end); + lg::print("{}...{}", all_names.substr(0, 70 - 3), end); } else { - fmt::print("{}{}{}", all_names, std::string(70 - all_names.length(), ' '), end); + lg::print("{}{}{}", all_names, std::string(70 - all_names.length(), ' '), end); } } } // namespace @@ -338,21 +339,21 @@ void print_input(const std::vector& in, char end) { bool MakeSystem::make(const std::string& target_in, bool force, bool verbose) { std::string target = m_path_map.apply_remaps(target_in); auto deps = get_dependencies(target); - // fmt::print("All deps:\n"); + // lg::print("All deps:\n"); // for (auto& dep : deps) { - // fmt::print("{}\n", dep); + // lg::print("{}\n", dep); // } if (!force) { deps = filter_dependencies(deps); } - // fmt::print("Filt deps:\n"); + // lg::print("Filt deps:\n"); // for (auto& dep : filtered_deps) { - // fmt::print("{}\n", dep); + // lg::print("{}\n", dep); // } Timer make_timer; - fmt::print("Building {} targets...\n", deps.size()); + lg::print("Building {} targets...\n", deps.size()); int i = 0; for (auto& to_make : deps) { Timer step_timer; @@ -360,10 +361,10 @@ bool MakeSystem::make(const std::string& target_in, bool force, bool verbose) { auto& tool = m_tools.at(rule->tool); int percent = (100.0 * (1 + (i++)) / (deps.size())) + 0.5; if (verbose) { - fmt::print("[{:3d}%] [{:8s}] {}{}\n", percent, tool->name(), rule->input.at(0), - rule->input.size() > 1 ? ", ..." : ""); + lg::print("[{:3d}%] [{:8s}] {}{}\n", percent, tool->name(), rule->input.at(0), + rule->input.size() > 1 ? ", ..." : ""); } else { - fmt::print("[{:3d}%] [{:8s}] ", percent, tool->name()); + lg::print("[{:3d}%] [{:8s}] ", percent, tool->name()); print_input(rule->input, '\r'); } @@ -371,35 +372,35 @@ bool MakeSystem::make(const std::string& target_in, bool force, bool verbose) { try { success = tool->run({rule->input, rule->deps, rule->outputs, rule->arg}, m_path_map); } catch (std::exception& e) { - fmt::print("\n"); - fmt::print("Error: {}\n", e.what()); + lg::print("\n"); + lg::print("Error: {}\n", e.what()); } if (!success) { - fmt::print("Build failed on {}{}.\n", rule->input.at(0), - rule->input.size() > 1 ? ", ..." : ""); + lg::print("Build failed on {}{}.\n", rule->input.at(0), + rule->input.size() > 1 ? ", ..." : ""); throw std::runtime_error("Build failed."); return false; } if (verbose) { if (step_timer.getSeconds() > 0.05) { - fmt::print(fg(fmt::color::yellow), " {:.3f}\n", step_timer.getSeconds()); + lg::print(fg(fmt::color::yellow), " {:.3f}\n", step_timer.getSeconds()); } else { - fmt::print(" {:.3f}\n", step_timer.getSeconds()); + lg::print(" {:.3f}\n", step_timer.getSeconds()); } } else { if (step_timer.getSeconds() > 0.05) { - fmt::print("[{:3d}%] [{:8s}] ", percent, tool->name()); - fmt::print(fg(fmt::color::yellow), "{:.3f} ", step_timer.getSeconds()); + lg::print("[{:3d}%] [{:8s}] ", percent, tool->name()); + lg::print(fg(fmt::color::yellow), "{:.3f} ", step_timer.getSeconds()); print_input(rule->input, '\n'); } else { - fmt::print("[{:3d}%] [{:8s}] {:.3f} ", percent, tool->name(), step_timer.getSeconds()); + lg::print("[{:3d}%] [{:8s}] {:.3f} ", percent, tool->name(), step_timer.getSeconds()); print_input(rule->input, '\n'); } } } - fmt::print("\nSuccessfully built all {} targets in {:.3f}s\n", deps.size(), - make_timer.getSeconds()); + lg::print("\nSuccessfully built all {} targets in {:.3f}s\n", deps.size(), + make_timer.getSeconds()); return true; } diff --git a/goalc/make/Tools.cpp b/goalc/make/Tools.cpp index 2b0657e339..036cba0b05 100644 --- a/goalc/make/Tools.cpp +++ b/goalc/make/Tools.cpp @@ -34,7 +34,7 @@ bool CompilerTool::run(const ToolInput& task, const PathMap& /*path_map*/) { options.write = true; m_compiler->asm_file(options); } catch (std::exception& e) { - fmt::print("Compilation failed: {}\n", e.what()); + lg::print("Compilation failed: {}\n", e.what()); return false; } return true; diff --git a/goalc/regalloc/Allocator.cpp b/goalc/regalloc/Allocator.cpp index fc3d1459c8..948ff7b070 100644 --- a/goalc/regalloc/Allocator.cpp +++ b/goalc/regalloc/Allocator.cpp @@ -7,6 +7,8 @@ #include +#include "common/log/log.h" + #include "goalc/regalloc/allocator_interface.h" #include "third-party/fmt/core.h" @@ -136,7 +138,7 @@ void do_constrained_alloc(RegAllocCache* cache, const AllocationInput& in, bool for (auto& constr : in.constraints) { auto var_id = constr.ireg.id; if (trace_debug) { - fmt::print("[RA] Apply constraint {}\n", constr.to_string()); + lg::print("[RA] Apply constraint {}\n", constr.to_string()); } if (constr.contrain_everywhere) { cache->live_ranges.at(var_id).constrain_everywhere(constr.desired_register); @@ -156,18 +158,18 @@ bool check_constrained_alloc(RegAllocCache* cache, const AllocationInput& in) { auto& lr = cache->live_ranges.at(constr.ireg.id); for (int i = lr.min; i <= lr.max; i++) { if (!lr.conflicts_at(i, constr.desired_register)) { - fmt::print("[RegAlloc Error] There are conflicting constraints on {}: {} and {}\n", - constr.ireg.to_string(), constr.desired_register.print(), - cache->live_ranges.at(constr.ireg.id).get(i).to_string()); + lg::print("[RegAlloc Error] There are conflicting constraints on {}: {} and {}\n", + constr.ireg.to_string(), constr.desired_register.print(), + cache->live_ranges.at(constr.ireg.id).get(i).to_string()); ok = false; } } } else { if (!cache->live_ranges.at(constr.ireg.id) .conflicts_at(constr.instr_idx, constr.desired_register)) { - fmt::print("[RegAlloc Error] There are conflicting constraints on {}: {} and {}\n", - constr.ireg.to_string(), constr.desired_register.print(), - cache->live_ranges.at(constr.ireg.id).get(constr.instr_idx).to_string()); + lg::print("[RegAlloc Error] There are conflicting constraints on {}: {} and {}\n", + constr.ireg.to_string(), constr.desired_register.print(), + cache->live_ranges.at(constr.ireg.id).get(constr.instr_idx).to_string()); ok = false; } } @@ -187,7 +189,7 @@ bool check_constrained_alloc(RegAllocCache* cache, const AllocationInput& in) { auto& ass2 = lr2.get(i); if (ass1.occupies_same_reg(ass2)) { // todo, this error won't be helpful - fmt::print( + lg::print( "[RegAlloc Error] Cannot satisfy constraints at instruction {} due to constraints " "on {} and {}\n", i, lr1.var, lr2.var); @@ -719,10 +721,10 @@ namespace { * Print out the state of the RegAllocCache after doing analysis. */ void print_analysis(const AllocationInput& in, RegAllocCache* cache) { - fmt::print("[RegAlloc] Basic Blocks\n"); - fmt::print("-----------------------------------------------------------------\n"); + lg::print("[RegAlloc] Basic Blocks\n"); + lg::print("-----------------------------------------------------------------\n"); for (auto& b : cache->control_flow.basic_blocks) { - fmt::print("{}\n", b.print(in.instructions)); + lg::print("{}\n", b.print(in.instructions)); } printf("[RegAlloc] Alive Info\n"); @@ -797,14 +799,14 @@ AllocationResult allocate_registers(const AllocationInput& input) { // constraint. if (!check_constrained_alloc(&cache, input)) { result.ok = false; - fmt::print("[RegAlloc Error] Register allocation has failed due to bad constraints.\n"); + lg::print("[RegAlloc Error] Register allocation has failed due to bad constraints.\n"); return result; } // do the allocations! if (!run_allocator(&cache, input, input.debug_settings.allocate_log_level)) { result.ok = false; - fmt::print("[RegAlloc Error] Register allocation has failed.\n"); + lg::print("[RegAlloc Error] Register allocation has failed.\n"); return result; } diff --git a/goalc/regalloc/Allocator_v2.cpp b/goalc/regalloc/Allocator_v2.cpp index 7865dd4188..1a6f3c62bc 100644 --- a/goalc/regalloc/Allocator_v2.cpp +++ b/goalc/regalloc/Allocator_v2.cpp @@ -4,6 +4,7 @@ #include #include +#include "common/log/log.h" #include "common/util/Range.h" #include "third-party/fmt/core.h" @@ -522,7 +523,7 @@ void do_constrained_alloc(RACache* cache, const AllocationInput& input, bool tra for (auto& constr : input.constraints) { auto var_id = constr.ireg.id; if (trace_debug) { - fmt::print("[RA] Apply constraint {}\n", constr.to_string()); + lg::print("[RA] Apply constraint {}\n", constr.to_string()); } cache->vars.at(var_id).constrain_to_register(constr.desired_register); } @@ -573,8 +574,8 @@ bool check_constrained_alloc(RACache* cache, const AllocationInput& in) { for (int i = lr.first_live(); i <= lr.last_live(); i++) { if (lr.assigned()) { if (!lr.assigned_to_reg(constr.desired_register)) { - fmt::print("[RegAlloc Error] There are conflicting constraints on {}: {} and {}\n", - constr.ireg.to_string(), constr.desired_register.print(), "???"); + lg::print("[RegAlloc Error] There are conflicting constraints on {}: {} and {}\n", + constr.ireg.to_string(), constr.desired_register.print(), "???"); ok = false; } } @@ -598,7 +599,7 @@ bool check_constrained_alloc(RACache* cache, const AllocationInput& in) { if (lr1.assigned_to_reg() && lr2.assigned_to_reg()) { if (lr1.reg() == lr2.reg() && !safe_overlap(in, *cache, lr1, lr2, i)) { // todo, this error won't be helpful - fmt::print( + lg::print( "[RegAlloc Error] {} Cannot satisfy constraints at instruction {} due to " "constraints " "on {} and {}, both are assigned to register {}\n", @@ -865,7 +866,7 @@ loop_top: auto& op = input.instructions.at(instr_idx); bool is_read = op.reads(var_idx); bool is_written = op.writes(var_idx); - // fmt::print("op {} {} {}\n", instr_idx, is_read, is_written); + // lg::print("op {} {} {}\n", instr_idx, is_read, is_written); if (!is_read && !is_written) { continue; } @@ -916,7 +917,7 @@ loop_top: } } - fmt::print( + lg::print( "In function {}, register allocator fell back to a highly inefficient strategy to create " "a spill temporary register.\n", input.function_name); @@ -1003,8 +1004,8 @@ bool run_assignment_on_var(const AllocationInput& input, if (vector_contains(allowable_local_var_move_elim, other_var.reg())) { bool worked = check_register_assign(input, *cache, var_idx, other_var.reg()); if (trace) { - fmt::print("m0 trying var {} in {}: {}\n", cache->iregs.at(var_idx).to_string(), - other_var.reg().print(), worked); + lg::print("m0 trying var {} in {}: {}\n", cache->iregs.at(var_idx).to_string(), + other_var.reg().print(), worked); } if (worked) { @@ -1020,10 +1021,10 @@ bool run_assignment_on_var(const AllocationInput& input, const auto& other_var = cache->vars.at(other_live_var_idx); if (trace && var_idx == 5) { - fmt::print(" consider {} {} {} {} [{} {}]\n", other_live_var_idx, - other_var.assigned_to_reg(), var.last_live() == other_var.first_live(), - safe_overlap(input, *cache, var, other_var, var.last_live()), var.last_live(), - other_var.first_live()); + lg::print(" consider {} {} {} {} [{} {}]\n", other_live_var_idx, + other_var.assigned_to_reg(), var.last_live() == other_var.first_live(), + safe_overlap(input, *cache, var, other_var, var.last_live()), var.last_live(), + other_var.first_live()); } if (other_var.assigned_to_reg() && @@ -1031,8 +1032,8 @@ bool run_assignment_on_var(const AllocationInput& input, if (vector_contains(allowable_local_var_move_elim, other_var.reg())) { bool worked = check_register_assign(input, *cache, var_idx, other_var.reg()); if (trace) { - fmt::print("m1 trying var {} in {}: {}\n", cache->iregs.at(var_idx).to_string(), - other_var.reg().print(), worked); + lg::print("m1 trying var {} in {}: {}\n", cache->iregs.at(var_idx).to_string(), + other_var.reg().print(), worked); } if (worked) { @@ -1048,8 +1049,8 @@ bool run_assignment_on_var(const AllocationInput& input, for (auto& reg : assign_order) { bool worked = check_register_assign(input, *cache, var_idx, reg); if (trace) { - fmt::print("m2 trying var {} in {}: {}\n", cache->iregs.at(var_idx).to_string(), - reg.print(), worked); + lg::print("m2 trying var {} in {}: {}\n", cache->iregs.at(var_idx).to_string(), + reg.print(), worked); } if (worked) { var.assign_to_register(reg); @@ -1120,7 +1121,7 @@ AllocationResult allocate_registers_v2(const AllocationInput& input) { check_constrained_alloc(&cache, input); if (!check_constrained_alloc(&cache, input)) { result.ok = false; - fmt::print("[RegAlloc Error] Register allocation has failed due to bad constraints.\n"); + lg::print("[RegAlloc Error] Register allocation has failed due to bad constraints.\n"); return result; } @@ -1157,7 +1158,7 @@ AllocationResult allocate_registers_v2(const AllocationInput& input) { for (int var_idx = 0; var_idx < input.max_vars; var_idx++) { auto& var = cache.vars.at(var_idx); if (var.seen() && !var.assigned()) { - // fmt::print("av2: {} failed\n", input.function_name); + // lg::print("av2: {} failed\n", input.function_name); result.ok = false; return result; } @@ -1212,4 +1213,4 @@ AllocationResult allocate_registers_v2(const AllocationInput& input) { result.num_spills = cache.stats.num_spill_ops; return result; -} \ No newline at end of file +} diff --git a/goalc/regalloc/allocator_interface.cpp b/goalc/regalloc/allocator_interface.cpp index 949b663e8d..f63a4b7699 100644 --- a/goalc/regalloc/allocator_interface.cpp +++ b/goalc/regalloc/allocator_interface.cpp @@ -7,31 +7,32 @@ #include -#include "third-party/fmt/core.h" +#include "common/log/log.h" +#include "third-party/fmt/core.h" /*! * Print out the input data for debugging. */ void print_allocate_input(const AllocationInput& in) { - fmt::print("[RegAlloc] Debug Input Program:\n"); + lg::print("[RegAlloc] Debug Input Program:\n"); if (in.instructions.size() == in.debug_instruction_names.size()) { for (size_t i = 0; i < in.instructions.size(); i++) { - // fmt::print(" [{}] {} -> {}\n", in.debug_instruction_names.at(i), + // lg::print(" [{}] {} -> {}\n", in.debug_instruction_names.at(i), // in.instructions.at(i).print()); - fmt::print(" [{:3d}] {:30} -> {:30}\n", i, in.debug_instruction_names.at(i), - in.instructions.at(i).print()); + lg::print(" [{:3d}] {:30} -> {:30}\n", i, in.debug_instruction_names.at(i), + in.instructions.at(i).print()); } } else { for (const auto& instruction : in.instructions) { - fmt::print(" [{:3d}] {}\n", instruction.print()); + lg::print(" [{:3d}] {}\n", instruction.print()); } } - fmt::print("[RegAlloc] Debug Input Constraints:\n"); + lg::print("[RegAlloc] Debug Input Constraints:\n"); for (const auto& c : in.constraints) { - fmt::print(" {}\n", c.to_string()); + lg::print(" {}\n", c.to_string()); } - fmt::print("\n"); + lg::print("\n"); } /*! diff --git a/test/goalc/test_debugger.cpp b/test/goalc/test_debugger.cpp index dbce885a92..312bb51669 100644 --- a/test/goalc/test_debugger.cpp +++ b/test/goalc/test_debugger.cpp @@ -8,11 +8,11 @@ namespace { void connect_compiler_and_debugger(Compiler& compiler, bool do_break) { - lg::info("connect_compiler_and_debugger:\n"); + lg::info("connect_compiler_and_debugger:"); bool connect_status = compiler.connect_to_target(); - lg::info("connected: {}\n", connect_status); + lg::info("connected: {}", connect_status); ASSERT_TRUE(connect_status); - lg::info("poking...\n"); + lg::info("poking..."); compiler.poke_target(); for (int i = 0; i < 100; i++) { if (compiler.get_debugger().is_valid()) { @@ -25,9 +25,9 @@ void connect_compiler_and_debugger(Compiler& compiler, bool do_break) { ASSERT_TRUE(compiler.get_debugger().is_valid()); if (do_break) { - lg::info("break...\n"); + lg::info("break..."); compiler.run_test_from_string("(dbg)"); - lg::info("OK! {} {} {}\n", compiler.get_debugger().is_valid(), + lg::info("OK! {} {} {}", compiler.get_debugger().is_valid(), compiler.get_debugger().is_attached(), compiler.get_debugger().is_halted()); } }