PR-10 e PR-11 LogService

This commit is contained in:
bQUARKz 2026-01-16 22:54:38 +00:00 committed by Nilton Constantino
parent 314246f981
commit 60e3145e40
No known key found for this signature in database
14 changed files with 374 additions and 7 deletions

View File

@ -0,0 +1,46 @@
use prometeu_core::log::{LogEvent, LogLevel, LogSource};
pub struct HostConsoleSink {
last_seq: Option<u64>,
}
impl HostConsoleSink {
pub fn new() -> Self {
Self { last_seq: None }
}
pub fn process_events(&mut self, events: Vec<LogEvent>) {
for event in events {
let level_str = match event.level {
LogLevel::Trace => "TRACE",
LogLevel::Debug => "DEBUG",
LogLevel::Info => "INFO",
LogLevel::Warn => "WARN",
LogLevel::Error => "ERROR",
};
let source_buf;
let source_str = match event.source {
LogSource::Pos => "POS",
LogSource::Hub => "HUB",
LogSource::Vm => "VM",
LogSource::Fs => "FS",
LogSource::App { app_id } => {
source_buf = format!("APP:{}", app_id);
&source_buf
}
};
println!(
"[{:06}ms][{}][{}][{}] {}",
event.ts_ms, event.frame, level_str, source_str, event.msg
);
self.last_seq = Some(event.seq);
}
}
pub fn last_seq(&self) -> Option<u64> {
self.last_seq
}
}

View File

@ -1,6 +1,7 @@
mod audio_mixer;
mod prometeu_runner;
mod fs_desktop_backend;
mod log_sink;
use crate::prometeu_runner::PrometeuRunner;
use winit::event_loop::EventLoop;

View File

@ -1,5 +1,6 @@
use crate::audio_mixer::AudioMixer;
use crate::fs_desktop_backend::HostDirBackend;
use crate::log_sink::HostConsoleSink;
use cpal::traits::{DeviceTrait, HostTrait, StreamTrait};
use pixels::{Pixels, SurfaceTexture};
use prometeu_core::firmware::Firmware;
@ -26,6 +27,8 @@ pub struct PrometeuRunner {
input_signals: InputSignals,
fs_root: Option<String>,
log_sink: HostConsoleSink,
frame_target_dt: Duration,
last_frame_time: Instant,
accumulator: Duration,
@ -57,6 +60,7 @@ impl PrometeuRunner {
firmware,
input_signals: InputSignals::default(),
fs_root,
log_sink: HostConsoleSink::new(),
frame_target_dt: Duration::from_nanos(1_000_000_000 / target_fps),
last_frame_time: Instant::now(),
accumulator: Duration::ZERO,
@ -328,6 +332,15 @@ impl ApplicationHandler for PrometeuRunner {
self.audio_load_samples = 0;
}
// Processa logs do sistema
let last_seq = self.log_sink.last_seq().unwrap_or(u64::MAX);
let new_events = if last_seq == u64::MAX {
self.firmware.os.log_service.get_recent(4096)
} else {
self.firmware.os.log_service.get_after(last_seq)
};
self.log_sink.process_events(new_events);
self.request_redraw();
}
}

View File

@ -1,6 +1,7 @@
use crate::firmware::firmware_state::{FirmwareState, LaunchHubStep};
use crate::firmware::prometeu_context::PrometeuContext;
use crate::model::Color;
use crate::log::{LogLevel, LogSource};
#[derive(Debug, Clone)]
pub struct AppCrashesStep {
@ -8,7 +9,9 @@ pub struct AppCrashesStep {
}
impl AppCrashesStep {
pub fn on_enter(&mut self, _ctx: &mut PrometeuContext) {}
pub fn on_enter(&mut self, ctx: &mut PrometeuContext) {
ctx.os.log(LogLevel::Error, LogSource::Pos, 0, format!("App Crashed: {}", self.error));
}
pub fn on_update(&mut self, ctx: &mut PrometeuContext) -> Option<FirmwareState> {
// Atualiza periféricos para input na tela de crash

View File

@ -1,11 +1,14 @@
use crate::firmware::firmware_state::{AppCrashesStep, FirmwareState};
use crate::firmware::prometeu_context::PrometeuContext;
use crate::log::{LogLevel, LogSource};
#[derive(Debug, Clone)]
pub struct GameRunningStep;
impl GameRunningStep {
pub fn on_enter(&mut self, _ctx: &mut PrometeuContext) {}
pub fn on_enter(&mut self, ctx: &mut PrometeuContext) {
ctx.os.log(LogLevel::Info, LogSource::Pos, 0, "Entering GameRunning".to_string());
}
pub fn on_update(&mut self, ctx: &mut PrometeuContext) -> Option<FirmwareState> {
let result = ctx.os.step_frame(ctx.vm, ctx.signals, ctx.hw);

View File

@ -1,11 +1,14 @@
use crate::firmware::firmware_state::{AppCrashesStep, FirmwareState};
use crate::firmware::prometeu_context::PrometeuContext;
use crate::log::{LogLevel, LogSource};
#[derive(Debug, Clone)]
pub struct HubHomeStep;
impl HubHomeStep {
pub fn on_enter(&mut self, _ctx: &mut PrometeuContext) {}
pub fn on_enter(&mut self, ctx: &mut PrometeuContext) {
ctx.os.log(LogLevel::Info, LogSource::Hub, 0, "Entering HubHome".to_string());
}
pub fn on_update(&mut self, ctx: &mut PrometeuContext) -> Option<FirmwareState> {
let mut error = None;

View File

@ -1,11 +1,13 @@
use crate::firmware::firmware_state::{FirmwareState, HubHomeStep};
use crate::firmware::prometeu_context::PrometeuContext;
use crate::log::{LogLevel, LogSource};
#[derive(Debug, Clone)]
pub struct LaunchHubStep;
impl LaunchHubStep {
pub fn on_enter(&mut self, ctx: &mut PrometeuContext) {
ctx.os.log(LogLevel::Info, LogSource::Pos, 0, "Launching Hub".to_string());
ctx.hub.init();
}

View File

@ -1,6 +1,7 @@
use crate::firmware::firmware_state::{FirmwareState, GameRunningStep, HubHomeStep};
use crate::firmware::prometeu_context::PrometeuContext;
use crate::model::{AppMode, Cartridge, Color, Rect};
use crate::log::{LogLevel, LogSource};
#[derive(Debug, Clone)]
pub struct LoadCartridgeStep {
@ -9,6 +10,7 @@ pub struct LoadCartridgeStep {
impl LoadCartridgeStep {
pub fn on_enter(&mut self, ctx: &mut PrometeuContext) {
ctx.os.log(LogLevel::Info, LogSource::Pos, 0, format!("Loading cartridge: {}", self.cartridge.header.title));
ctx.os.initialize_vm(ctx.vm, &self.cartridge);
}

View File

@ -1,11 +1,13 @@
use crate::firmware::firmware_state::{FirmwareState, SplashScreenStep};
use crate::firmware::prometeu_context::PrometeuContext;
use crate::log::{LogLevel, LogSource};
#[derive(Debug, Clone)]
pub struct ResetStep;
impl ResetStep {
pub fn on_enter(&mut self, ctx: &mut PrometeuContext) {
ctx.os.log(LogLevel::Info, LogSource::Pos, 0, "Firmware Reset".to_string());
ctx.os.reset(ctx.vm);
}

View File

@ -2,6 +2,7 @@ use crate::firmware::firmware_state::{FirmwareState, LaunchHubStep};
use crate::firmware::prometeu_context::PrometeuContext;
use crate::hardware::LoopMode;
use crate::model::Color;
use crate::log::{LogLevel, LogSource};
#[derive(Debug, Clone)]
pub struct SplashScreenStep {
@ -10,6 +11,7 @@ pub struct SplashScreenStep {
impl SplashScreenStep {
pub fn on_enter(&mut self, ctx: &mut PrometeuContext) {
ctx.os.log(LogLevel::Info, LogSource::Pos, 0, "Showing SplashScreen".to_string());
// Tocar som no enter
if let Some(sample) = ctx.os.sample_square.clone() {
ctx.hw.audio_mut().play(sample, 0, 255, 127, 1.0, 0, LoopMode::Off);

View File

@ -1,4 +1,5 @@
pub mod hardware;
pub mod log;
pub mod virtual_machine;
mod model;
pub mod firmware;

View File

@ -0,0 +1,121 @@
use std::collections::VecDeque;
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum LogLevel {
Trace,
Debug,
Info,
Warn,
Error,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum LogSource {
Pos,
Hub,
Vm,
Fs,
App { app_id: u32 },
}
#[derive(Debug, Clone)]
pub struct LogEvent {
pub seq: u64,
pub ts_ms: u64,
pub frame: u64,
pub level: LogLevel,
pub source: LogSource,
pub tag: u16,
pub msg: String,
}
pub struct LogService {
events: VecDeque<LogEvent>,
capacity: usize,
next_seq: u64,
}
impl LogService {
pub fn new(capacity: usize) -> Self {
Self {
events: VecDeque::with_capacity(capacity),
capacity,
next_seq: 0,
}
}
pub fn log(&mut self, ts_ms: u64, frame: u64, level: LogLevel, source: LogSource, tag: u16, msg: String) {
if self.events.len() >= self.capacity {
self.events.pop_front();
}
self.events.push_back(LogEvent {
seq: self.next_seq,
ts_ms,
frame,
level,
source,
tag,
msg,
});
self.next_seq += 1;
}
pub fn get_recent(&self, n: usize) -> Vec<LogEvent> {
self.events.iter().rev().take(n).cloned().collect::<Vec<_>>().into_iter().rev().collect()
}
pub fn get_after(&self, seq: u64) -> Vec<LogEvent> {
self.events.iter().filter(|e| e.seq > seq).cloned().collect()
}
pub fn last_seq(&self) -> Option<u64> {
self.events.back().map(|e| e.seq)
}
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn test_ring_buffer_capacity() {
let mut service = LogService::new(3);
service.log(100, 1, LogLevel::Info, LogSource::Pos, 0, "Log 1".to_string());
service.log(110, 1, LogLevel::Info, LogSource::Pos, 0, "Log 2".to_string());
service.log(120, 1, LogLevel::Info, LogSource::Pos, 0, "Log 3".to_string());
assert_eq!(service.events.len(), 3);
assert_eq!(service.events[0].msg, "Log 1");
service.log(130, 1, LogLevel::Info, LogSource::Pos, 0, "Log 4".to_string());
assert_eq!(service.events.len(), 3);
assert_eq!(service.events[0].msg, "Log 2");
assert_eq!(service.events[2].msg, "Log 4");
}
#[test]
fn test_get_recent() {
let mut service = LogService::new(10);
for i in 0..5 {
service.log(i as u64, 1, LogLevel::Info, LogSource::Pos, 0, format!("Log {}", i));
}
let recent = service.get_recent(2);
assert_eq!(recent.len(), 2);
assert_eq!(recent[0].msg, "Log 3");
assert_eq!(recent[1].msg, "Log 4");
}
#[test]
fn test_get_after() {
let mut service = LogService::new(10);
for i in 0..5 {
service.log(i as u64, 1, LogLevel::Info, LogSource::Pos, 0, format!("Log {}", i));
}
let after = service.get_after(2); // seqs são 0, 1, 2, 3, 4. Deve retornar 3 e 4.
assert_eq!(after.len(), 2);
assert_eq!(after[0].msg, "Log 3");
assert_eq!(after[1].msg, "Log 4");
}
}

View File

@ -1,4 +1,5 @@
use crate::hardware::HardwareBridge;
use crate::log::{LogLevel, LogSource};
use crate::model::{Color, Rect, Window, WindowId};
use crate::prometeu_os::PrometeuOS;
@ -65,18 +66,22 @@ impl PrometeuHub {
// Inicializa o Window System e lista apps
}
pub fn gui_update(&mut self, _os: &mut PrometeuOS, hw: &mut dyn HardwareBridge) {
pub fn gui_update(&mut self, os: &mut PrometeuOS, hw: &mut dyn HardwareBridge) {
hw.gfx_mut().clear(Color::BLACK);
let mut next_window = None;
if hw.pad().a.pressed {
os.log(LogLevel::Debug, LogSource::Hub, 0, "window A opened".to_string());
next_window = Some(("Green Window".to_string(), Rect { x: 0, y: 0, w: 160, h: 90 }, Color::GREEN));
} else if hw.pad().b.pressed {
os.log(LogLevel::Debug, LogSource::Hub, 0, "window B opened".to_string());
next_window = Some(("Indigo Window".to_string(), Rect { x: 160, y: 0, w: 160, h: 90 }, Color::INDIGO));
} else if hw.pad().x.pressed {
os.log(LogLevel::Debug, LogSource::Hub, 0, "window X opened".to_string());
next_window = Some(("Yellow Window".to_string(), Rect { x: 0, y: 90, w: 160, h: 90 }, Color::YELLOW));
} else if hw.pad().y.pressed {
os.log(LogLevel::Debug, LogSource::Hub, 0, "window Y opened".to_string());
next_window = Some(("Red Window".to_string(), Rect { x: 160, y: 90, w: 160, h: 90 }, Color::RED));
}

View File

@ -1,10 +1,12 @@
use crate::fs::{FsBackend, FsState, VirtualFS};
use crate::hardware::{HardwareBridge, InputSignals};
use crate::log::{LogLevel, LogService, LogSource};
use crate::model::{Cartridge, Color, Sample};
use crate::prometeu_os::NativeInterface;
use crate::virtual_machine::{Value, VirtualMachine};
use crate::fs::{VirtualFS, FsBackend, FsState};
use std::sync::Arc;
use std::collections::HashMap;
use std::sync::Arc;
use std::time::Instant;
/// PrometeuOS (POS): O firmware/base do sistema.
/// Autoridade máxima do boot, periféricos, execução da PVM e tratamento de falhas.
@ -25,13 +27,23 @@ pub struct PrometeuOS {
pub fs_state: FsState,
pub open_files: HashMap<u32, String>,
pub next_handle: u32,
// Log Service
pub log_service: LogService,
pub current_app_id: u32,
pub logs_written_this_frame: HashMap<u32, u32>,
boot_time: Instant,
}
impl PrometeuOS {
pub const CYCLES_PER_LOGICAL_FRAME: u64 = 100_000;
pub const SLICE_PER_TICK: u64 = 100_000; // Por enquanto, o mesmo, mas permite granularidade diferente
pub const MAX_LOG_LEN: usize = 256;
pub const MAX_LOGS_PER_FRAME: u32 = 10;
pub fn new() -> Self {
let boot_time = Instant::now();
let mut os = Self {
tick_index: 0,
logical_frame_index: 0,
@ -45,20 +57,36 @@ impl PrometeuOS {
fs_state: FsState::Unmounted,
open_files: HashMap::new(),
next_handle: 1,
log_service: LogService::new(4096),
current_app_id: 0,
logs_written_this_frame: HashMap::new(),
boot_time,
};
// Inicializa samples básicos (mesma lógica do LogicalHardware)
os.sample_square = Some(Arc::new(Self::create_square_sample(440.0, 0.1)));
os.log(LogLevel::Info, LogSource::Pos, 0, "PrometeuOS starting...".to_string());
os
}
pub fn log(&mut self, level: LogLevel, source: LogSource, tag: u16, msg: String) {
let ts_ms = self.boot_time.elapsed().as_millis() as u64;
let frame = self.logical_frame_index;
self.log_service.log(ts_ms, frame, level, source, tag, msg);
}
pub fn mount_fs(&mut self, backend: Box<dyn FsBackend>) {
self.log(LogLevel::Info, LogSource::Fs, 0, "Attempting to mount filesystem".to_string());
match self.fs.mount(backend) {
Ok(_) => {
self.fs_state = FsState::Mounted;
self.log(LogLevel::Info, LogSource::Fs, 0, "Filesystem mounted successfully".to_string());
}
Err(e) => {
let err_msg = format!("Failed to mount filesystem: {:?}", e);
self.log(LogLevel::Error, LogSource::Fs, 0, err_msg);
self.fs_state = FsState::Error(e);
}
}
@ -72,6 +100,7 @@ impl PrometeuOS {
fn update_fs(&mut self) {
if self.fs_state == FsState::Mounted {
if !self.fs.is_healthy() {
self.log(LogLevel::Error, LogSource::Fs, 0, "Filesystem became unhealthy, unmounting".to_string());
self.unmount_fs();
}
}
@ -89,6 +118,13 @@ impl PrometeuOS {
/// Carrega um cartucho na PVM e reseta o estado de execução.
pub fn initialize_vm(&mut self, vm: &mut VirtualMachine, cartridge: &Cartridge) {
vm.initialize(cartridge.program.clone());
// Determina o app_id numérico (hash da string app_id)
use std::collections::hash_map::DefaultHasher;
use std::hash::{Hash, Hasher};
let mut s = DefaultHasher::new();
cartridge.header.app_id.hash(&mut s);
self.current_app_id = s.finish() as u32;
}
/// Executa um tick do host (60Hz).
@ -123,7 +159,9 @@ impl PrometeuOS {
}
}
Err(e) => {
return Some(format!("PVM Fault: {:?}", e));
let err_msg = format!("PVM Fault: {:?}", e);
self.log(LogLevel::Error, LogSource::Vm, 0, err_msg.clone());
return Some(err_msg);
}
}
}
@ -134,10 +172,44 @@ impl PrometeuOS {
fn begin_logical_frame(&mut self, _signals: &InputSignals, hw: &mut dyn HardwareBridge) {
hw.audio_mut().clear_commands();
self.logs_written_this_frame.clear();
}
// Helper para syscalls
fn syscall_log_write(&mut self, level_val: i64, tag: u16, msg: String) -> Result<u64, String> {
let level = match level_val {
0 => LogLevel::Trace,
1 => LogLevel::Debug,
2 => LogLevel::Info,
3 => LogLevel::Warn,
4 => LogLevel::Error,
_ => return Err(format!("Invalid log level: {}", level_val)),
};
let app_id = self.current_app_id;
let count = *self.logs_written_this_frame.get(&app_id).unwrap_or(&0);
if count >= Self::MAX_LOGS_PER_FRAME {
if count == Self::MAX_LOGS_PER_FRAME {
self.logs_written_this_frame.insert(app_id, count + 1);
self.log(LogLevel::Warn, LogSource::App { app_id }, 0, "App exceeded log limit per frame".to_string());
}
return Ok(50);
}
self.logs_written_this_frame.insert(app_id, count + 1);
let mut final_msg = msg;
if final_msg.len() > Self::MAX_LOG_LEN {
final_msg.truncate(Self::MAX_LOG_LEN);
}
self.log(level, LogSource::App { app_id }, tag, final_msg);
Ok(100)
}
pub fn get_color(&self, index: usize, hw: &mut dyn HardwareBridge) -> Color {
if let Some(bank) = hw.gfx().banks[0].as_ref() {
bank.palettes[0][index % 16]
@ -285,6 +357,75 @@ mod tests {
assert!(cycles_after_tick_2 > cycles_after_tick_1, "VM should have consumed more cycles because FrameSync reset the budget");
}
#[test]
fn test_syscall_log_write_and_rate_limit() {
let mut os = PrometeuOS::new();
let mut vm = VirtualMachine::default();
let mut hw = Hardware::new();
os.current_app_id = 123;
// 1. Teste de log normal
vm.push(Value::Integer(2)); // Info
vm.push(Value::String("Hello Log".to_string()));
let res = os.syscall(0x5001, &mut vm, &mut hw);
assert!(res.is_ok());
let recent = os.log_service.get_recent(1);
assert_eq!(recent[0].msg, "Hello Log");
assert_eq!(recent[0].level, LogLevel::Info);
assert_eq!(recent[0].source, LogSource::App { app_id: 123 });
// 2. Teste de truncamento
let long_msg = "A".repeat(300);
vm.push(Value::Integer(3)); // Warn
vm.push(Value::String(long_msg));
os.syscall(0x5001, &mut vm, &mut hw).unwrap();
let recent = os.log_service.get_recent(1);
assert_eq!(recent[0].msg.len(), 256);
assert!(recent[0].msg.starts_with("AAAAA"));
// 3. Teste de Rate Limit
// Já fizemos 2 logs. O limite é 10.
for i in 0..8 {
vm.push(Value::Integer(2));
vm.push(Value::String(format!("Log {}", i)));
os.syscall(0x5001, &mut vm, &mut hw).unwrap();
}
// O 11º log deve ser ignorado (e deve gerar um aviso do sistema)
vm.push(Value::Integer(2));
vm.push(Value::String("Eleventh log".to_string()));
os.syscall(0x5001, &mut vm, &mut hw).unwrap();
let recent = os.log_service.get_recent(2);
// O último log deve ser o aviso de rate limit (veio depois do 10º log tentado)
assert_eq!(recent[1].msg, "App exceeded log limit per frame");
assert_eq!(recent[1].level, LogLevel::Warn);
// O log "Eleventh log" não deve estar lá
assert_ne!(recent[0].msg, "Eleventh log");
// 4. Teste de reset do rate limit no próximo frame
os.begin_logical_frame(&InputSignals::default(), &mut hw);
vm.push(Value::Integer(2));
vm.push(Value::String("New frame log".to_string()));
os.syscall(0x5001, &mut vm, &mut hw).unwrap();
let recent = os.log_service.get_recent(1);
assert_eq!(recent[0].msg, "New frame log");
// 5. Teste de LOG_WRITE_TAG
vm.push(Value::Integer(2)); // Info
vm.push(Value::Integer(42)); // Tag
vm.push(Value::String("Tagged Log".to_string()));
os.syscall(0x5002, &mut vm, &mut hw).unwrap();
let recent = os.log_service.get_recent(1);
assert_eq!(recent[0].msg, "Tagged Log");
assert_eq!(recent[0].tag, 42);
}
}
impl NativeInterface for PrometeuOS {
@ -450,6 +591,28 @@ impl NativeInterface for PrometeuOS {
Ok(500)
}
// --- Log Syscalls (0x5000) ---
// LOG_WRITE(level, msg)
0x5001 => {
let msg = match vm.pop()? {
Value::String(s) => s,
_ => return Err("Expected string message".into()),
};
let level = vm.pop_integer()?;
self.syscall_log_write(level, 0, msg)
}
// LOG_WRITE_TAG(level, tag, msg)
0x5002 => {
let msg = match vm.pop()? {
Value::String(s) => s,
_ => return Err("Expected string message".into()),
};
let tag = vm.pop_integer()? as u16;
let level = vm.pop_integer()?;
self.syscall_log_write(level, tag, msg)
}
_ => Err(format!("Unknown syscall: 0x{:08X}", id)),
}
}