MissionLogger.hpp

Go to the documentation of this file.

#pragma once

 
#include <icarus/core/CoreTypes.hpp>
#include <icarus/io/data/DataDictionary.hpp>
#include <icarus/io/log/Console.hpp>
#include <icarus/io/report/Banner.hpp>
#include <icarus/io/report/FlightManifest.hpp>
#include <icarus/io/report/MissionDebrief.hpp>
#include <icarus/sim/SimulatorConfig.hpp>
#include <icarus/staging/StagingTypes.hpp>
 
#include <chrono>
#include <cmath>
#include <fstream>
#include <iomanip>
#include <iostream>
#include <map>
#include <numbers>
#include <sstream>
#include <string>
#include <vector>
 
namespace icarus {

namespace LifecycleStrings {
constexpr const char *Init = "INIT";
constexpr const char *Provision = "PROVISION";
constexpr const char *Stage = "STAGE";
constexpr const char *Run = "RUN";
constexpr const char *Shutdown = "SHUTDOWN";
} // namespace LifecycleStrings

class MissionLogger {
  public:
    using Clock = std::chrono::high_resolution_clock;
    using TimePoint = Clock::time_point;
 
    MissionLogger() : startup_time_(Clock::now()) {}
 
    explicit MissionLogger(const std::string &log_file_path)
        : startup_time_(Clock::now()), log_file_(log_file_path), log_file_name_(log_file_path) {}
 
    // === Configuration ===

    void SetConsoleLevel(LogLevel level) { console_.SetLogLevel(level); }

    void SetFileLevel(LogLevel level) { file_level_ = level; }

    void SetVersion(const std::string &version) { version_ = version; }

    void SetBuildType(const std::string &build_type) { build_type_ = build_type; }

    void SetProgressEnabled(bool enabled) { progress_enabled_ = enabled; }

    void SetProfilingEnabled(bool enabled) { profiling_enabled_ = enabled; }

    [[nodiscard]] std::string GetLogFileName() const { return log_file_name_; }

    [[nodiscard]] LogLevel GetConsoleLevel() const { return console_.GetLogLevel(); }

    [[nodiscard]] bool IsProgressEnabled() const { return progress_enabled_; }

    [[nodiscard]] bool IsProfilingEnabled() const { return profiling_enabled_; }

    [[nodiscard]] std::chrono::nanoseconds WallElapsed() const {
        return Clock::now() - startup_time_;
    }

    void SetLogFile(const std::string &path) {
        if (log_file_.is_open()) {
            log_file_.close();
        }
        log_file_name_ = path;
        if (!path.empty()) {
            log_file_.open(path);
        }
    }
 
    // === Lifecycle Logging ===

    void LogStartup() {
        std::string splash = Banner::GetSplashScreen(build_type_, icarus::Version());
        console_.WriteLine(splash);
        WriteToFile(splash);
    }

    void LogSimulationConfig(const std::string &name, const std::string &version,
                             const std::string &description = "") {
        std::ostringstream oss;
        oss << "[SIM] Simulation: " << name << " (v" << version << ")";
        Log(LogLevel::Info, oss.str());
 
        if (!description.empty()) {
            // Log first line of description
            std::string first_line = description;
            auto pos = first_line.find('\n');
            if (pos != std::string::npos) {
                first_line = first_line.substr(0, pos);
            }
            if (!first_line.empty()) {
                Log(LogLevel::Debug, "         " + first_line);
            }
        }
    }

    void LogConfigFile(const std::string &path) { Log(LogLevel::Info, "[CFG] Config: " + path); }

    void LogTimeConfig(double t_start, double t_end, double dt) {
        std::ostringstream oss;
        oss << "[CFG] Time: start=" << std::fixed << std::setprecision(1) << t_start
            << "s, end=" << t_end << "s, dt=" << std::setprecision(4) << dt << "s";
        Log(LogLevel::Info, oss.str());
    }

    void LogIntegrator(const std::string &type) {
        Log(LogLevel::Debug, "[CFG] Integrator: " + type);
    }

    void LogIntegrator(IntegratorType type) { LogIntegrator(to_string(type)); }

    void LogPhaseConfig(const PhaseConfig &config) {
        if (config.definitions.empty()) {
            return;
        }
        std::ostringstream oss;
        oss << "[PHASE] Configured with " << config.definitions.size()
            << " phases, initial: " << config.initial_phase;
        Log(LogLevel::Debug, oss.str());
    }

    void BeginLifecycle(const char *lifecycle_name) {
        current_lifecycle_ = lifecycle_name;
        lifecycle_start_time_ = Clock::now();
 
        std::string header = Banner::GetLifecycleHeader(lifecycle_name);
        console_.WriteLine(header);
        WriteToFile(header);
    }

    void EndLifecycle(double sim_time = 0.0) {
        auto elapsed = std::chrono::duration<double>(Clock::now() - lifecycle_start_time_).count();
        std::ostringstream oss;
        oss << "[SYS] " << current_lifecycle_ << " phase complete (" << FormatDuration(elapsed)
            << ")";
        LogTimed(LogLevel::Info, sim_time, oss.str());
    }

    [[nodiscard]] std::string GetDictionaryPath() const {
        if (log_file_name_.empty()) {
            return "signal_dictionary.dict";
        }
        // Extract base name without extension
        std::string base = log_file_name_;
        auto dot_pos = base.rfind('.');
        if (dot_pos != std::string::npos) {
            base = base.substr(0, dot_pos);
        }
        return base + "_signal_dictionary.dict";
    }

    void LogManifest(const DataDictionary &dict) {
        FlightManifest manifest(console_);
        manifest.SetVersion(icarus::Version());
        manifest.SetOutputPath(GetDictionaryPath());
        manifest.Generate(dict);
 
        // Also write summary to log file
        WriteToFile(manifest.GenerateSummary(dict));
    }

    void LogRunStart(double t_start, double t_end, double dt) {
        run_start_wall_time_ = Clock::now();
        std::ostringstream oss;
        oss << "[SYS] Starting simulation (t=" << std::fixed << std::setprecision(3) << t_start
            << " → " << std::setprecision(1) << t_end << " s, dt=" << std::setprecision(4) << dt
            << " s)";
        LogTimed(LogLevel::Info, t_start, oss.str());
    }

    void LogRunProgress(double sim_time, double t_end) {
        double progress = (t_end > 0) ? (sim_time / t_end) * 100.0 : 0.0;
        auto wall_elapsed =
            std::chrono::duration<double>(Clock::now() - run_start_wall_time_).count();
        double rtf = (wall_elapsed > 0) ? sim_time / wall_elapsed : 0.0;
 
        std::ostringstream oss;
        oss << "[RUN] Progress: " << std::fixed << std::setprecision(1) << progress << "% ("
            << std::setprecision(1) << sim_time << "/" << t_end
            << " s, RTF: " << std::setprecision(1) << rtf << "x)";
        LogTimed(LogLevel::Trace, sim_time, oss.str());
    }

    void LogDebrief(double sim_time, double wall_time) {
        MissionDebrief debrief(console_);
        debrief.SetExitStatus(ExitStatus::EndConditionMet);
        debrief.SetExitReason("Reached end of simulation time");
        debrief.SetTiming(sim_time, wall_time);
 
        if (profiling_enabled_) {
            debrief.SetProfilingData(GetProfilingStats());
        }
 
        std::string output = debrief.Generate();
        console_.Write(output);
        WriteToFile(output);
    }
 
    // === Provision Phase Logging ===

    void LogEntityLoad(const std::string &entity_name) {
        LogTimed(LogLevel::Info, 0.0, "[LOD] Loading Entity: " + entity_name);
    }

    void LogComponentAdd(const std::string &component_name, const std::string &type,
                         const std::string &config_source = "defaults", bool is_last = false) {
        std::string prefix = is_last ? "└─" : "├─";
        std::ostringstream oss;
        oss << "         " << prefix << " [CMP] " << component_name << " (" << type << ")";
        if (config_source != "defaults") {
            oss << " [" << config_source << "]";
        }
        console_.WriteLine(oss.str());
        WriteToFile(oss.str());
    }

    void LogAssetLoad(const std::string &asset_name, const std::string &description) {
        LogTimed(LogLevel::Debug, 0.0, "[AST] " + asset_name + ": " + description);
    }

    void LogStateAllocation(std::size_t continuous, std::size_t discrete = 0) {
        std::ostringstream oss;
        oss << "[MEM] States: " << continuous << " continuous";
        if (discrete > 0) {
            oss << ", " << discrete << " discrete";
        }
        LogTimed(LogLevel::Info, 0.0, oss.str());
    }
 
    // === Stage Phase Logging ===

    void LogWiring(const std::string &source, const std::string &target, bool is_warning = false) {
        std::string prefix = is_warning ? "[!WIR]" : "[WIR]";
        std::ostringstream oss;
        oss << "         ├─ " << source << " >> " << target;
        if (is_warning) {
            console_.Warning(oss.str());
        } else {
            Log(LogLevel::Debug, oss.str());
        }
    }

    void LogWiringWarning(const std::string &message) {
        LogTimed(LogLevel::Warning, 0.0, "[WIR] " + message);
    }

    void LogExecutionOrder(const std::vector<std::string> &component_order) {
        Log(LogLevel::Debug, "[ORD] Execution Order:");
        for (std::size_t i = 0; i < component_order.size(); ++i) {
            std::ostringstream oss;
            oss << "         " << (i + 1) << ". " << component_order[i];
            Log(LogLevel::Debug, oss.str());
        }
    }

    void LogSchedulerOrder(double sim_rate_hz, const std::vector<SchedulerGroupConfig> &groups,
                           const std::unordered_map<std::string, int> &divisors) {
        std::ostringstream header;
        header << "[SCH] Scheduler (sim rate: " << sim_rate_hz << " Hz)";
        Log(LogLevel::Debug, header.str());
 
        for (std::size_t i = 0; i < groups.size(); ++i) {
            const auto &group = groups[i];
            auto it = divisors.find(group.name);
            int divisor = (it != divisors.end()) ? it->second : 1;
            double group_dt = 1.0 / group.rate_hz;
 
            std::ostringstream oss;
            bool is_last = (i == groups.size() - 1);
            oss << "         " << (is_last ? "└─" : "├─") << " [" << group.name << "] "
                << group.rate_hz << " Hz (÷" << divisor << ", dt=" << std::fixed
                << std::setprecision(6) << group_dt << "s)";
            Log(LogLevel::Debug, oss.str());
 
            for (std::size_t j = 0; j < group.members.size(); ++j) {
                const auto &member = group.members[j];
                std::ostringstream mem_oss;
                bool mem_last = (j == group.members.size() - 1);
                mem_oss << "         " << (is_last ? "   " : "│  ") << (mem_last ? "└─" : "├─")
                        << " " << member.component;
                Log(LogLevel::Debug, mem_oss.str());
            }
        }
    }

    void LogTrimStart(const std::string &mode,
                      const std::vector<std::pair<std::string, double>> &targets) {
        Log(LogLevel::Info, "[TRM] Trim Solver: " + mode);
        for (const auto &[name, value] : targets) {
            std::ostringstream oss;
            oss << "         └─ Target: " << name << " = " << value;
            Log(LogLevel::Debug, oss.str());
        }
    }
 
    void LogTrimIteration(int iteration, double residual) {
        std::ostringstream oss;
        oss << "[TRM] Iteration " << iteration << ": residual = " << std::scientific << residual;
        Log(LogLevel::Debug, oss.str());
    }
 
    void LogTrimConverged(int iterations) {
        std::ostringstream oss;
        oss << "[TRM] Converged in " << iterations << " iterations";
        Log(LogLevel::Info, oss.str());
    }
 
    void LogTrimFailed(const std::string &reason) {
        Log(LogLevel::Error, "[TRM] Trim failed: " + reason);
    }
 
    // === Linearization Logging ===

    void LogLinearModel(const staging::LinearModel &model) {
        // Banner
        Log(LogLevel::Info, "[LIN] ═══════════════════════════════════════════════════════");
        Log(LogLevel::Info, "[LIN]   Linear Model at Operating Point");
        Log(LogLevel::Info, "[LIN] ═══════════════════════════════════════════════════════");
 
        // Dimensions (Info level)
        {
            std::ostringstream oss;
            oss << "[LIN] State-Space: A[" << model.A.rows() << "x" << model.A.cols() << "], B["
                << model.B.rows() << "x" << model.B.cols() << "], C[" << model.C.rows() << "x"
                << model.C.cols() << "], D[" << model.D.rows() << "x" << model.D.cols() << "]";
            Log(LogLevel::Info, oss.str());
        }
 
        // Operating point (Debug level)
        Log(LogLevel::Debug, "[LIN] Operating Point (x0):");
        for (std::size_t i = 0; i < model.state_names.size(); ++i) {
            std::ostringstream oss;
            oss << "         " << model.state_names[i] << " = " << std::scientific
                << std::setprecision(4) << model.x0(static_cast<Eigen::Index>(i));
            Log(LogLevel::Debug, oss.str());
        }
 
        // A matrix (Trace level - very verbose)
        Log(LogLevel::Trace, "[LIN] A Matrix (df/dx):");
        for (Eigen::Index i = 0; i < model.A.rows(); ++i) {
            std::ostringstream oss;
            oss << "         [";
            for (Eigen::Index j = 0; j < model.A.cols(); ++j) {
                oss << std::fixed << std::setw(12) << std::setprecision(6) << model.A(i, j);
                if (j < model.A.cols() - 1)
                    oss << ", ";
            }
            oss << "]";
            Log(LogLevel::Trace, oss.str());
        }
 
        // Eigenvalue analysis (Info level - important for stability)
        Log(LogLevel::Info, "[LIN] Eigenvalue Analysis:");
        auto eigenvalues = model.Eigenvalues();
        for (Eigen::Index i = 0; i < eigenvalues.size(); ++i) {
            double real = eigenvalues(i).real();
            double imag = eigenvalues(i).imag();
 
            std::ostringstream oss;
            oss << "         λ" << (i + 1) << " = " << std::scientific << std::setprecision(4)
                << real;
            if (std::abs(imag) > 1e-10) {
                oss << (imag >= 0 ? " + " : " - ") << std::abs(imag) << "i";
                // Compute period from imaginary part
                double period = 2.0 * std::numbers::pi / std::abs(imag);
                oss << std::fixed << std::setprecision(1) << "  (period: " << period
                    << " s = " << period / 60.0 << " min)";
            }
            Log(LogLevel::Info, oss.str());
        }
 
        // Stability and controllability (Info level)
        {
            std::ostringstream oss;
            oss << "[LIN] Stability: " << (model.IsStable() ? "STABLE" : "UNSTABLE")
                << " (Lyapunov sense)";
            Log(LogLevel::Info, oss.str());
        }
        {
            std::ostringstream oss;
            oss << "[LIN] Controllability: " << model.ControllabilityRank() << " / "
                << model.A.rows()
                << (model.ControllabilityRank() == model.A.rows() ? " (fully controllable)" : "");
            Log(LogLevel::Info, oss.str());
        }
        {
            std::ostringstream oss;
            oss << "[LIN] Observability: " << model.ObservabilityRank() << " / " << model.A.rows()
                << (model.ObservabilityRank() == model.A.rows() ? " (fully observable)" : "");
            Log(LogLevel::Info, oss.str());
        }
 
        Log(LogLevel::Info, "[LIN] ═══════════════════════════════════════════════════════");
    }
 
    // === Run Phase Logging ===

    void LogPhaseEvent(const std::string &from_phase, const std::string &to_phase,
                       double sim_time) {
        LogTimed(LogLevel::Event, sim_time,
                 "[PHS] Phase transition: " + from_phase + " -> " + to_phase);
    }

    void LogEvent(const std::string &event_name, double sim_time, const std::string &details = "") {
        std::string msg = "[EVT] " + event_name;
        if (!details.empty()) {
            msg += ": " + details;
        }
        LogTimed(LogLevel::Event, sim_time, msg);
    }

    void LogRunWarning(const std::string &source, const std::string &message, double sim_time) {
        LogTimed(LogLevel::Warning, sim_time, "[" + source + "] " + message);
    }

    void LogRunError(const std::string &source, const std::string &message, double sim_time) {
        LogTimed(LogLevel::Error, sim_time, "[" + source + "] " + message);
    }

    void UpdateProgress(double sim_time, double t_max,
                        const std::map<std::string, double> &key_values = {}) {
        if (!progress_enabled_ || !console_.IsTerminal()) {
            return;
        }
 
        double progress = (t_max > 0) ? (sim_time / t_max) : 0.0;
        int filled = static_cast<int>(progress * static_cast<double>(progress_width_));
 
        std::ostringstream oss;
        oss << "\r[RUN] Time: " << std::fixed << std::setprecision(2) << sim_time << "s | [";
 
        for (int i = 0; i < progress_width_; ++i) {
            if (i < filled) {
                oss << "█";
            } else {
                oss << "░";
            }
        }
 
        oss << "] " << static_cast<int>(progress * 100) << "%";
 
        for (const auto &[key, value] : key_values) {
            oss << " | " << key << ": " << std::fixed << std::setprecision(1) << value;
        }
 
        std::cout << oss.str() << std::flush;
    }

    void ClearProgress() {
        if (progress_enabled_ && console_.IsTerminal()) {
            std::cout << "\r" << std::string(120, ' ') << "\r" << std::flush;
        }
    }
 
    // === Profiling ===

    void BeginComponentTiming(const std::string &component_name) {
        if (!profiling_enabled_) {
            return;
        }
        current_timed_component_ = component_name;
        component_start_time_ = Clock::now();
    }

    void EndComponentTiming() {
        if (!profiling_enabled_ || current_timed_component_.empty()) {
            return;
        }
 
        auto elapsed =
            std::chrono::duration<double, std::micro>(Clock::now() - component_start_time_).count();
 
        auto &stats = component_stats_[current_timed_component_];
        stats.name = current_timed_component_;
        stats.call_count++;
        stats.total_time_us += elapsed;
        stats.max_time_us = std::max(stats.max_time_us, elapsed);
        stats.avg_time_us = stats.total_time_us / static_cast<double>(stats.call_count);
 
        current_timed_component_.clear();
    }

    [[nodiscard]] std::vector<ComponentStats> GetProfilingStats() const {
        std::vector<ComponentStats> result;
        result.reserve(component_stats_.size());
 
        // Calculate total time for percentage
        double total_time = 0.0;
        for (const auto &[name, stats] : component_stats_) {
            total_time += stats.total_time_us;
        }
 
        for (auto [name, stats] : component_stats_) {
            if (total_time > 0) {
                stats.percent_load = (stats.total_time_us / total_time) * 100.0;
            }
            result.push_back(stats);
        }
 
        return result;
    }
 
    // === Low-Level Access ===

    [[nodiscard]] Console &GetConsole() { return console_; }
    [[nodiscard]] const Console &GetConsole() const { return console_; }

    void Log(LogLevel level, const std::string &message) {
        console_.Log(level, message);
        if (log_file_.is_open() && level >= file_level_) {
            log_file_ << LevelPrefix(level) << " " << StripAnsi(message) << "\n";
            log_file_.flush();
        }
    }
 
    void LogTimed(LogLevel level, double sim_time, const std::string &message) {
        std::string formatted = FormatTime(sim_time) + " " + message;
        console_.Log(level, formatted);
        if (log_file_.is_open() && level >= file_level_) {
            log_file_ << LevelPrefix(level) << " " << StripAnsi(formatted) << "\n";
            log_file_.flush();
        }
    }
 
  private:
    Console console_;
    std::ofstream log_file_;
    std::string log_file_name_;
    LogLevel file_level_ = LogLevel::Debug;
 
    // Simulation metadata
    std::string version_ = icarus::Version();
#ifdef NDEBUG
    std::string build_type_ = "RELEASE";
#else
    std::string build_type_ = "DEBUG";
#endif
 
    // Timing
    TimePoint startup_time_;
    TimePoint lifecycle_start_time_;
    TimePoint run_start_wall_time_;
    std::string current_lifecycle_ = LifecycleStrings::Init;
 
    // Progress display
    bool progress_enabled_ = true;
    int progress_width_ = 40;
 
    // Profiling
    bool profiling_enabled_ = false;
    std::map<std::string, ComponentStats> component_stats_;
    std::string current_timed_component_;
    TimePoint component_start_time_;
 
    // Helpers
    [[nodiscard]] double GetWallClockSeconds() const {
        return std::chrono::duration<double>(Clock::now() - startup_time_).count();
    }

    [[nodiscard]] static std::string FormatTime(double t) {
        std::ostringstream oss;
        if (t >= 1000.0 || t <= -1000.0) {
            oss << "[" << std::scientific << std::setprecision(2) << t << "]";
        } else {
            oss << "[" << std::fixed << std::setprecision(6) << t << "]";
        }
        return oss.str();
    }

    [[nodiscard]] static std::string FormatDuration(double seconds) {
        std::ostringstream oss;
        if (seconds < 0.001) {
            oss << std::fixed << std::setprecision(1) << (seconds * 1e6) << "μs";
        } else if (seconds < 1.0) {
            oss << std::fixed << std::setprecision(2) << (seconds * 1000) << "ms";
        } else {
            oss << std::fixed << std::setprecision(2) << seconds << "s";
        }
        return oss.str();
    }
 
    void WriteToFile(const std::string &message) {
        if (log_file_.is_open()) {
            log_file_ << StripAnsi(message) << "\n";
            log_file_.flush();
        }
    }
 
    [[nodiscard]] static std::string LevelPrefix(LogLevel level) {
        switch (level) {
        case LogLevel::Trace:
            return "[TRC]";
        case LogLevel::Debug:
            return "[DBG]";
        case LogLevel::Info:
            return "[INF]";
        case LogLevel::Event:
            return "[EVT]";
        case LogLevel::Warning:
            return "[WRN]";
        case LogLevel::Error:
            return "[ERR]";
        case LogLevel::Fatal:
            return "[FTL]";
        }
        return "[???]";
    }
 
    [[nodiscard]] static std::string StripAnsi(const std::string &s) {
        std::string result;
        result.reserve(s.size());
        bool in_escape = false;
        for (char c : s) {
            if (c == '\033') {
                in_escape = true;
            } else if (in_escape && c == 'm') {
                in_escape = false;
            } else if (!in_escape) {
                result += c;
            }
        }
        return result;
    }
};
 
} // namespace icarus