mirror of
https://github.com/FelipePrado0/SpartanPort.git
synced 2026-11-09 17:11:49 -10:00
Feat(Launcher): added a timestamped JSON Lines run log (#1196)
EN-US - Added user/last_run.jsonl beside last_run.log, with time, level and area for each line, plus start and exit records - Kept last_run.log, the console copy and the UI log unchanged - Added last_run.jsonl to the update's USER_FILES, .gitignore and the packaging guards - Updated the READMEs to ask for both files in bug reports --- PT-BR - Adicionado user/last_run.jsonl ao lado do last_run.log, com hora, nível e área de cada linha, mais registros de início e de saída - Mantidos sem mudança o last_run.log, a cópia no console e o log da interface - Adicionado last_run.jsonl a USER_FILES da atualização, ao .gitignore e às travas do pacote - Atualizados os READMEs para pedir os dois arquivos nos relatos de bug
This commit is contained in:
1 parent
cbcc3c6d98
commit
d764586005
15 files changed
+1018
-25
No files matched your search
@@ -9,6 +9,7 @@ pgo/
|
||||
# Documentation pictures are part of the repository.
|
||||
!docs/images/*.png
|
||||
last_run.log
|
||||
last_run.jsonl
|
||||
dist/
|
||||
fsr4_411/
|
||||
vkd3d-proton.cache
|
||||
|
||||
@@ -379,6 +379,8 @@ para todas las configuraciones de overlay.
|
||||
**Opciones → Audio → Diálogos** (por ejemplo, texto en español con voces en inglés).
|
||||
- El juego no abre: revisá **Advanced → Log**, o enviá `user\last_run.log` junto con tu reporte.
|
||||
Con una **Saves folder** personalizada, `last_run.log` está en esa carpeta.
|
||||
Junto a él, `last_run.jsonl` tiene las mismas líneas con la hora, el nivel y el área de cada una,
|
||||
para herramientas y para saber qué evento vino primero; adjuntá los dos archivos al reportar un bug.
|
||||
- Texturas amarillas/naranjas/blancas o iluminación incorrecta: probá desactivar **Performance →
|
||||
GPU data → Deferred GPU readbacks** y reiniciar el juego. Esta alternativa puede causar tirones.
|
||||
- Los fallos gráficos por GPU, cierres, problemas de audio y bloqueos de progreso siguen bajo
|
||||
|
||||
@@ -427,6 +427,8 @@ read the joystick; the mapper does not install device drivers.
|
||||
Polish text with English voices).
|
||||
- The game does not open: check **Advanced → Log**, or send `user\last_run.log` with your report.
|
||||
With a custom **Saves folder**, `last_run.log` is in that folder instead.
|
||||
Next to it, `last_run.jsonl` has the same lines with the time, level and area of each one, for
|
||||
tools and for telling which event came first; attach both files when you report a bug.
|
||||
- Yellow/orange/white textures or wrong lighting: try disabling **Performance → GPU data →
|
||||
Deferred GPU readbacks**, then restart. This workaround can cause stutters.
|
||||
- GPU-specific rendering failures, crashes, audio problems and progress blockers remain under
|
||||
|
||||
@@ -373,6 +373,8 @@ uma correção para todas as configurações de overlay.
|
||||
texto em português com vozes em inglês).
|
||||
- O jogo não abre: veja **Advanced → Log**, ou envie o `user\last_run.log` junto com o relato.
|
||||
Se escolheu uma **Saves folder** personalizada, o `last_run.log` fica nessa pasta.
|
||||
Ao lado dele, o `last_run.jsonl` tem as mesmas linhas com a hora, o nível e a área de cada uma,
|
||||
para ferramentas e para saber qual evento veio primeiro; anexe os dois arquivos ao relatar um bug.
|
||||
- Texturas amarelas/laranjas/brancas ou iluminação errada: experimente desligar **Performance →
|
||||
GPU data → Deferred GPU readbacks** e reiniciar o jogo. Esse contorno pode causar travadas.
|
||||
- Falhas de renderização por GPU, crashes, problemas de áudio e bloqueios de progresso seguem
|
||||
|
||||
@@ -345,7 +345,9 @@ com o motivo, contra a referência 2.6.0 (`541739b`).
|
||||
|
||||
- Paridade de arquivos: `tools/launcher_fixtures.py` roda o launcher Python 2.6.0 sobre entradas
|
||||
conhecidas e grava `settings.json`, `spartanport.ini`, `mods.json`, `patches.json` e
|
||||
`last_run.log` em `launcher-rust/fixtures/`; o Rust tem que produzir bytes iguais.
|
||||
`last_run.log` em `launcher-rust/fixtures/`; o Rust tem que produzir bytes iguais. O Rust também
|
||||
grava `last_run.jsonl`, que o Python não tem (`docs/specs/2026-11-02-run-log-journal.md`); o
|
||||
`last_run.log` continua byte a byte igual.
|
||||
- Paridade de ambiente: as 33 variáveis `SPARTAN_*` para cada fixture, comparadas com a saída de
|
||||
`game_environment` capturada em JSON.
|
||||
- Parsers com casos válidos, truncados, vazios e inválidos: param.sfo, `.trp`, `--list` de GPUs
|
||||
|
||||
@@ -479,6 +479,7 @@ assertions uncovered are listed under [Partly covered](#partly-covered).
|
||||
19. A `controls_layout` newer than the launcher's own (`CONTROLS_LAYOUT`, 4) is left as it is: `migrate_controls` returns the settings unchanged (the Python migrates every layout but its own). Only the migration leaves it: a Save still rebuilds `controls` from `control_changes` while `controls_layout` stays as it was. `src/core/controls.rs::tests::a_newer_layout_is_left_alone`.
|
||||
20. The controller mapper looks for SDL3 only in the port's `bin/` and `out/` and in MSYS2's `clang64/bin/` on Windows, and only as `libSDL3.so.0` and `libSDL3.so` on unix (`src/core/joysticks.rs`). The Python ended with `ctypes.util.find_library('SDL3')`, which also searches `PATH` on Windows and finds `libSDL3.dylib` on macOS; without SDL3 in those places the Rust says "SDL3 was not found…".
|
||||
21. The controller mapper is a page of the drawer, opened from the top of Controls (whose tab stays lit), instead of a window over the launcher (`src/ui/pages/mapper.rs`): the drawer header holds its title and note, its table scrolls in the window height less 460 px, and leaving it (Close, Esc, another tab or closing the launcher) lets SDL go without saving. While it is open it takes every key but Esc, as the Python's window held the grab. What opening SDL3 could not read (an unreadable profile) shows in its status line; the Python printed it to a console the windowed launcher does not have. Its dialogs are titled "Set up a controller" and "Could not save mapping", as the Python's message boxes; a mapping that could not be saved names the file. The drawer header keeps its Save button on this page, as on every page: it saves the launcher's settings (active only while they differ from the files), while each mapping row saves itself.
|
||||
22. The Rust launcher also writes `last_run.jsonl` next to `last_run.log`: the same lines with a time, a level and an area, plus the game's exit code (`src/core/log.rs`, `docs/specs/2026-11-02-run-log-journal.md`). `last_run.log` stays byte for byte the Python's; the Python has no `last_run.jsonl`.
|
||||
|
||||
## Partly covered
|
||||
|
||||
|
||||
@@ -0,0 +1,133 @@
|
||||
# Diário do log de execução: `last_run.jsonl`
|
||||
|
||||
Branch: `pr/run-log-timestamps`. Código em `launcher-rust/src/core/log.rs` e
|
||||
`launcher-rust/src/core/launch.rs`.
|
||||
|
||||
## Spec (SDD)
|
||||
|
||||
* **Objetivo:** como mantenedor, testador ou ferramenta (incluindo assistentes de IA) que lê o log de
|
||||
uma execução, quero saber QUANDO cada linha saiu e qual veio primeiro numa cascata de problemas
|
||||
(por exemplo, remoções do cache de texturas minutos antes de um defeito de textura), sem mudar o
|
||||
`last_run.log`.
|
||||
* **Problema hoje:** o `last_run.log` guarda só o texto do jogo. Não há hora nas linhas, nem nível,
|
||||
nem o código de saída do jogo. Quem recebe um relato não consegue ordenar eventos no tempo.
|
||||
* **Contrato:**
|
||||
- Entrada: os mesmos pedaços de saída que a thread leitora de `spawn_game` já grava no
|
||||
`RunLog`, mais o aviso de saída (o conselho de `exit_hint`) e o código de saída.
|
||||
- Saída: o arquivo `last_run.jsonl`, na mesma pasta do `last_run.log`, em JSON Lines (um objeto
|
||||
JSON por linha, UTF-8, terminador `\n`).
|
||||
- API pública: `RunLog::open(path)` e `RunLog::write(text)` não mudam. `RunLog` ganha
|
||||
`finish(self, code, advice)`, que grava o aviso (como `write` o fazia) e o registro de saída.
|
||||
Quem chama (`ui/play.rs`, `runner/mod.rs`) não muda.
|
||||
- O `last_run.log`, a cópia no console, o texto de `GameEvent::Output` e o log da interface
|
||||
continuam byte a byte iguais. O `last_run.jsonl` é novo no launcher Rust; o launcher Python não
|
||||
o grava.
|
||||
* **Esquema dos registros** (um por linha do arquivo; a ordem das chaves é a da tabela):
|
||||
|
||||
| `type` | Campos | Quando |
|
||||
|---|---|---|
|
||||
| `start` | `schema` (1), `time`, `launcher` (versão), `os` | ao abrir o diário |
|
||||
| `line` | `n`, `t`, `time`, `source`, `level`, `area`, `continuation` (só quando `true`), `truncated` (só quando `true`), `text` | uma por linha do `last_run.log` |
|
||||
| `exit` | `t`, `time`, `code`, `advice` | depois que o jogo termina |
|
||||
|
||||
- `time`: hora local em RFC 3339 com milissegundos e deslocamento (`2026-11-02T14:03:21.482-03:00`).
|
||||
- `t`: segundos desde a abertura do diário, arredondados a milissegundos (número JSON).
|
||||
- `n`: número da linha no `last_run.log`, a partir de 1, contando linhas vazias e as linhas do
|
||||
aviso de saída.
|
||||
- `source`: `game` para o que o jogo escreveu, `launcher` para o que o launcher escreveu na saída
|
||||
(o aviso).
|
||||
- `level`: `trace`, `debug`, `info`, `warning`, `error` ou `critical`.
|
||||
- `area`: texto ou `null`.
|
||||
- `text`: a linha sem `\r\n`, com no máximo 64 KiB (cortada num limite de caractere); quando a
|
||||
linha for maior, o registro leva `"truncated":true` e o `last_run.log` continua com a linha
|
||||
inteira.
|
||||
- `t` e `time` de uma linha são a hora em que o primeiro pedaço dela chegou ao launcher, tomada
|
||||
antes de gravar o `last_run.log`.
|
||||
- `code`: inteiro, ou `null` quando `wait` do processo falhou. `advice`: texto, ou `null` quando o
|
||||
launcher não escreveu aviso.
|
||||
* **Critérios de aceite:**
|
||||
- QUANDO o launcher abrir o `last_run.log` O SISTEMA DEVE criar (ou truncar) o `last_run.jsonl` na
|
||||
mesma pasta e gravar o registro `start` como primeira linha.
|
||||
- QUANDO o jogo imprimir uma linha O SISTEMA DEVE gravar um registro `line` com o `n` dessa linha
|
||||
no `last_run.log`, na mesma ordem, com `text` sem `\r\n`.
|
||||
- QUANDO a linha for do logger da GPU (`GPU [Classe] <Nivel> arquivo:linha funcao: msg`) O
|
||||
SISTEMA DEVE usar `Nivel` em minúsculas como `level` e `Classe` como `area`.
|
||||
- QUANDO a linha começar com `STOP:` ou `Fault:` O SISTEMA DEVE gravar `level` `critical`.
|
||||
- QUANDO a linha tiver um prefixo curto antes do primeiro `: ` (até 32 caracteres, começando por
|
||||
letra, sem espaço à esquerda, sem `:` nem `\`) O SISTEMA DEVE usá-lo como `area`; senão, `null`.
|
||||
- QUANDO a linha começar com espaço ou tabulação e vier depois de outra linha O SISTEMA DEVE gravar
|
||||
`"continuation":true` e herdar `level` e `area` da linha anterior.
|
||||
- QUANDO uma linha chegar em vários pedaços de 64 KiB O SISTEMA DEVE gravar um só registro, com a
|
||||
hora em que o primeiro pedaço chegou.
|
||||
- QUANDO a saída terminar sem `\n` final O SISTEMA DEVE gravar a última linha como registro ao
|
||||
encerrar.
|
||||
- QUANDO uma linha passar de 64 KiB O SISTEMA DEVE guardar só os primeiros 64 KiB no registro,
|
||||
cortados num limite de caractere, marcar `"truncated":true` e manter a linha inteira no
|
||||
`last_run.log`, sem que a memória do launcher cresça com o tamanho da linha.
|
||||
- QUANDO gravar o `last_run.log` demorar O SISTEMA DEVE manter no registro a hora de chegada do
|
||||
pedaço, tomada antes dessa gravação.
|
||||
- QUANDO o jogo falhar com um aviso conhecido O SISTEMA DEVE gravar as linhas do aviso (a linha
|
||||
vazia e o aviso) como registros com `source` `launcher` e o `n` do `last_run.log`.
|
||||
- QUANDO o jogo terminar, por qualquer caminho de `spawn_game` O SISTEMA DEVE gravar o registro
|
||||
`exit` como última linha, com o código de saída (`null` se `wait` falhar) e o aviso (`null` se
|
||||
não houve).
|
||||
- QUANDO o `last_run.jsonl` não puder ser criado ou uma gravação nele falhar O SISTEMA DEVE
|
||||
desligar só o diário, em silêncio; o `last_run.log`, a cópia no console e o jogo NÃO DEVEM ser
|
||||
afetados.
|
||||
- QUANDO o `last_run.log` falhar O SISTEMA DEVE continuar gravando o diário (são independentes).
|
||||
* **Requisitos não funcionais:** sem crate novo (`chrono` e `serde_json` já são dependências); sem
|
||||
`unwrap`/`expect` fora dos testes; uma única chamada de escrita por registro; o diário nunca
|
||||
bloqueia nem atrasa a leitura do pipe além de uma escrita pequena por linha; multiplataforma.
|
||||
* **Arquivos afetados:**
|
||||
- `launcher-rust/src/core/log.rs`, `launcher-rust/src/core/launch.rs`
|
||||
- `launcher-rust/src/core/update.rs` (`USER_FILES`: uma atualização não copia o diário)
|
||||
- `launcher-rust/tests/launch.rs`, `launcher-rust/tests/runner.rs`
|
||||
- `.gitignore`, `packaging/windows/package.sh`, `packaging/windows/smoke-test.ps1` (o diário nunca
|
||||
entra no pacote)
|
||||
- `README.md`, `README.pt-BR.md`, `README.es.md`, `packaging/windows/README-Windows.txt`
|
||||
- `docs/specs/2026-10-21-rust-launcher-design.md`, `docs/specs/2026-10-21-rust-launcher-parity.md`
|
||||
* **Plano técnico:**
|
||||
- `RunLog` passa a ter o arquivo e um `RunJournal` opcional. O caminho do diário vem do caminho
|
||||
do log com a extensão trocada por `jsonl`.
|
||||
- `RunJournal` recebe o texto na mesma divisão por `\n` do arquivo, então o `n` bate sem contar
|
||||
à parte: um pedaço sem `\n` fica pendente, com a hora do primeiro pedaço, até o `\n` chegar ou
|
||||
o jogo terminar. O aviso entra pelo mesmo caminho, como texto do launcher.
|
||||
- `level` e `area` vêm de uma função pura sobre o texto da linha; linhas de continuação herdam o
|
||||
resultado da anterior.
|
||||
- `finish` substitui o `write` do aviso e o `drop` no fim da thread leitora, para que o registro
|
||||
`exit` saia em todos os caminhos (saída limpa, saída com falha, erro de `wait`).
|
||||
- A classificação é uma heurística sobre o texto (o jogo usa `printf` com prefixo de área); um
|
||||
prefixo que parece rótulo, mas não é, vira `area` mesmo assim. Quem lê o diário deve tratar
|
||||
`area` como dica, não como contrato.
|
||||
* **Validação:** testes automáticos abaixo (TDD); `cargo fmt --check`, `cargo clippy --all-targets
|
||||
-- -D warnings`, `cargo test` e `cargo build --release`. Não testado: Linux e uma partida real.
|
||||
* **Aprovação:** a definir pelo mantenedor.
|
||||
|
||||
## Ciclo TDD (plano dos testes)
|
||||
|
||||
### 1. Classificação e registros (`src/core/log.rs`)
|
||||
|
||||
* **Comportamento:** registro `start`; registros `line` com `n` e `t` crescentes e CRLF removido;
|
||||
`level` e `area` do logger da GPU, de `STOP:`/`Fault:`, de `Texture cache: memory pressure, ...`
|
||||
e `null` em texto livre; continuação herda `level` e `area`; linha longa em vários pedaços vira um
|
||||
registro; último pedaço sem `\n` é gravado ao encerrar; linhas do aviso com `source` `launcher` e
|
||||
`n` igual ao do `last_run.log`; registro `exit`; erro de escrita no diário deixa o `last_run.log`
|
||||
intacto.
|
||||
* **Testes:** `src/core/log.rs`, módulo `tests` (nomes pelo comportamento).
|
||||
|
||||
### 2. Integração com o jogo (`tests/launch.rs`, `tests/runner.rs`)
|
||||
|
||||
* **Comportamento:** depois de uma execução do `fake-game`, o `last_run.jsonl` existe, seus
|
||||
registros `line` reproduzem o `last_run.log` linha a linha (`n` e `text`) e o registro `exit`
|
||||
traz o código; uma execução com falha e dica conhecida traz o aviso no registro `exit`; `--play`
|
||||
também grava o diário.
|
||||
* **Red:** os testes não compilam enquanto `RunLog::finish` não existir, e falham enquanto o
|
||||
arquivo não for criado.
|
||||
* **Green:** `RunJournal`, `RunLog::finish` e a thread leitora chamando `finish`.
|
||||
|
||||
### 3. Atualização e pacote
|
||||
|
||||
* **Comportamento:** `USER_FILES` lista `last_run.jsonl` ao lado de `last_run.log`; o pacote do
|
||||
Windows recusa `*.jsonl`.
|
||||
* **Teste:** `src/core/update.rs::tests::user_files_include_settings_and_icon`; as verificações dos
|
||||
scripts de empacotamento rodam no CI.
|
||||
@@ -105,7 +105,8 @@ impl GameHandle {
|
||||
|
||||
/// Starts the game with stdin closed and stdout and stderr merged into one pipe. A thread reads
|
||||
/// that pipe and sends the events; it writes the run log, and when the game fails after printing
|
||||
/// a line with a known cause it adds the advice for it to the log.
|
||||
/// a line with a known cause it adds the advice for it to the log. The run log is finished on
|
||||
/// every way out, so its journal always ends with the exit.
|
||||
pub fn spawn_game(launch: Launch<'_>) -> Result<GameHandle, LaunchError> {
|
||||
let Launch {
|
||||
command,
|
||||
@@ -157,11 +158,12 @@ pub fn spawn_game(launch: Launch<'_>) -> Result<GameHandle, LaunchError> {
|
||||
hint = exit_hint(&text).or(hint);
|
||||
let _ = tx.send(GameEvent::Output(text));
|
||||
}
|
||||
let code = child.wait().map_or(-1, returncode);
|
||||
if let Some(hint) = hint.filter(|_| code != 0) {
|
||||
run_log.write(&format!("\n{}\n", tr(&lang, hint.text_en())));
|
||||
}
|
||||
drop(run_log);
|
||||
let status_code = child.wait().map(returncode).ok();
|
||||
let code = status_code.unwrap_or(-1);
|
||||
let advice = hint
|
||||
.filter(|_| code != 0)
|
||||
.map(|hint| tr(&lang, hint.text_en()));
|
||||
run_log.finish(status_code, advice.as_deref());
|
||||
let _ = tx.send(GameEvent::Exited(Exit { code, hint }));
|
||||
});
|
||||
Ok(GameHandle { pid, events, job })
|
||||
|
||||
+754
-15
@@ -1,9 +1,12 @@
|
||||
//! The in-memory log ring, the run log file and the output-line classifiers.
|
||||
|
||||
use chrono::{DateTime, Local, SecondsFormat};
|
||||
use serde_json::{json, Value};
|
||||
use std::collections::VecDeque;
|
||||
use std::fs::File;
|
||||
use std::io::Write;
|
||||
use std::io::{self, Write};
|
||||
use std::path::Path;
|
||||
use std::time::Instant;
|
||||
|
||||
/// Whole lines the launcher log keeps; older ones are dropped.
|
||||
pub const MAX_LOG_LINES: usize = 6000;
|
||||
@@ -78,41 +81,346 @@ impl LogBuffer {
|
||||
}
|
||||
}
|
||||
|
||||
/// The run log file. After any failure it stops writing and never fails again, so the game
|
||||
/// still starts and its output is still drained.
|
||||
/// The run log file, and next to it the timestamped journal of the same lines. After any failure a
|
||||
/// file stops being written and never fails again, so the game still starts and its output is
|
||||
/// still drained; the two fail apart, and the journal never changes what `last_run.log` holds.
|
||||
#[derive(Debug)]
|
||||
pub struct RunLog(Option<File>);
|
||||
pub struct RunLog {
|
||||
file: Option<File>,
|
||||
journal: Option<RunJournal>,
|
||||
}
|
||||
|
||||
impl RunLog {
|
||||
/// Creates the folder, truncates the file; a closed log when that fails.
|
||||
/// Creates the folder and truncates the file, and does the same for `last_run.jsonl` beside
|
||||
/// it; a file that fails is left closed.
|
||||
pub fn open(path: &Path) -> RunLog {
|
||||
let opened = (|| {
|
||||
if let Some(parent) = path.parent() {
|
||||
std::fs::create_dir_all(parent)?;
|
||||
}
|
||||
File::create(path)
|
||||
})();
|
||||
RunLog(opened.ok())
|
||||
let journal = create_truncated(&path.with_extension("jsonl"))
|
||||
.and_then(|file| RunJournal::new(Box::new(file)))
|
||||
.ok();
|
||||
RunLog {
|
||||
file: create_truncated(path).ok(),
|
||||
journal,
|
||||
}
|
||||
}
|
||||
|
||||
pub fn is_open(&self) -> bool {
|
||||
self.0.is_some()
|
||||
self.file.is_some()
|
||||
}
|
||||
|
||||
/// Writes and flushes `text`; on any error the file is dropped and later writes do nothing.
|
||||
pub fn write(&mut self, text: &str) {
|
||||
if let Some(file) = &mut self.0 {
|
||||
self.write_from(text, Source::Game);
|
||||
}
|
||||
|
||||
/// Ends the run: writes the advice for the failed exit (a blank line, then the advice) and the
|
||||
/// journal's `exit` record. `code` is `None` when the exit status could not be read.
|
||||
pub fn finish(mut self, code: Option<i32>, advice: Option<&str>) {
|
||||
if let Some(advice) = advice {
|
||||
self.write_from(&format!("\n{advice}\n"), Source::Launcher);
|
||||
}
|
||||
self.with_journal(|journal| journal.record_exit(code, advice));
|
||||
}
|
||||
|
||||
fn write_from(&mut self, text: &str, source: Source) {
|
||||
let arrival = Arrival::now();
|
||||
if let Some(file) = &mut self.file {
|
||||
if file
|
||||
.write_all(text.as_bytes())
|
||||
.and_then(|()| file.flush())
|
||||
.is_err()
|
||||
{
|
||||
self.0 = None;
|
||||
self.file = None;
|
||||
}
|
||||
}
|
||||
self.with_journal(|journal| journal.record_text(text, source, arrival));
|
||||
}
|
||||
|
||||
fn with_journal(&mut self, record: impl FnOnce(&mut RunJournal) -> io::Result<()>) {
|
||||
if let Some(journal) = &mut self.journal {
|
||||
if record(journal).is_err() {
|
||||
self.journal = None;
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
fn create_truncated(path: &Path) -> io::Result<File> {
|
||||
if let Some(parent) = path.parent() {
|
||||
std::fs::create_dir_all(parent)?;
|
||||
}
|
||||
File::create(path)
|
||||
}
|
||||
|
||||
/// Who wrote a line of the run log.
|
||||
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
|
||||
enum Source {
|
||||
Game,
|
||||
Launcher,
|
||||
}
|
||||
|
||||
impl Source {
|
||||
fn as_str(self) -> &'static str {
|
||||
match self {
|
||||
Source::Game => "game",
|
||||
Source::Launcher => "launcher",
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// How serious a line is.
|
||||
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
|
||||
enum Level {
|
||||
Trace,
|
||||
Debug,
|
||||
Info,
|
||||
Warning,
|
||||
Error,
|
||||
Critical,
|
||||
}
|
||||
|
||||
impl Level {
|
||||
/// The level named by the GPU logger (`Common::Log::Write`), in any case.
|
||||
fn from_gpu_logger(name: &str) -> Option<Level> {
|
||||
match name.to_ascii_lowercase().as_str() {
|
||||
"trace" => Some(Level::Trace),
|
||||
"debug" => Some(Level::Debug),
|
||||
"info" => Some(Level::Info),
|
||||
"warning" => Some(Level::Warning),
|
||||
"error" => Some(Level::Error),
|
||||
"critical" => Some(Level::Critical),
|
||||
_ => None,
|
||||
}
|
||||
}
|
||||
|
||||
fn as_str(self) -> &'static str {
|
||||
match self {
|
||||
Level::Trace => "trace",
|
||||
Level::Debug => "debug",
|
||||
Level::Info => "info",
|
||||
Level::Warning => "warning",
|
||||
Level::Error => "error",
|
||||
Level::Critical => "critical",
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// The longest prefix of a line that still reads as an area label.
|
||||
const MAX_AREA_CHARS: usize = 32;
|
||||
|
||||
/// The level and the area of one output line. The game prints with `printf` and an area prefix
|
||||
/// (`Texture cache: ...`) and its GPU logger prints `GPU [Class] <Level> file:line func: msg`, so
|
||||
/// this is a guess from the text: a prefix that only looks like a label becomes an area too.
|
||||
fn classify(text: &str) -> (Level, Option<&str>) {
|
||||
if let Some(gpu_line) = classify_gpu_logger_line(text) {
|
||||
return gpu_line;
|
||||
}
|
||||
let level = if text.starts_with("STOP:") || text.starts_with("Fault:") {
|
||||
Level::Critical
|
||||
} else {
|
||||
Level::Info
|
||||
};
|
||||
(level, area_prefix(text))
|
||||
}
|
||||
|
||||
fn classify_gpu_logger_line(text: &str) -> Option<(Level, Option<&str>)> {
|
||||
let (class, rest) = text.strip_prefix("GPU [")?.split_once("] <")?;
|
||||
let (level, _) = rest.split_once('>')?;
|
||||
Some((Level::from_gpu_logger(level)?, Some(class)))
|
||||
}
|
||||
|
||||
fn area_prefix(text: &str) -> Option<&str> {
|
||||
let (label, _) = text.split_once(": ")?;
|
||||
let is_label = label.chars().count() <= MAX_AREA_CHARS
|
||||
&& label.starts_with(char::is_alphabetic)
|
||||
&& !label.contains([':', '\\']);
|
||||
is_label.then_some(label)
|
||||
}
|
||||
|
||||
/// The most text one journal record keeps, the size of one pipe read: the rest of a longer line
|
||||
/// is dropped and the record says so, so a line that never ends cannot grow the launcher's memory.
|
||||
const MAX_JOURNAL_LINE_BYTES: usize = 64 * 1024;
|
||||
|
||||
/// When a piece of output reached the launcher. It is taken before `last_run.log` is written, so a
|
||||
/// slow disk does not make the journal's times later than the output.
|
||||
#[derive(Debug, Clone, Copy)]
|
||||
struct Arrival {
|
||||
at: Instant,
|
||||
time: DateTime<Local>,
|
||||
}
|
||||
|
||||
impl Arrival {
|
||||
fn now() -> Arrival {
|
||||
Arrival {
|
||||
at: Instant::now(),
|
||||
time: Local::now(),
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
/// A line whose `\n` has not arrived yet, with when and from whom its first piece came.
|
||||
#[derive(Debug)]
|
||||
struct OpenLine {
|
||||
text: String,
|
||||
truncated: bool,
|
||||
source: Source,
|
||||
arrival: Arrival,
|
||||
}
|
||||
|
||||
impl OpenLine {
|
||||
fn begin(source: Source, arrival: Arrival) -> OpenLine {
|
||||
OpenLine {
|
||||
text: String::new(),
|
||||
truncated: false,
|
||||
source,
|
||||
arrival,
|
||||
}
|
||||
}
|
||||
|
||||
/// Adds `piece` up to `MAX_JOURNAL_LINE_BYTES`, cut at a character boundary.
|
||||
fn push(&mut self, piece: &str) {
|
||||
let room = MAX_JOURNAL_LINE_BYTES.saturating_sub(self.text.len());
|
||||
if piece.len() <= room {
|
||||
self.text.push_str(piece);
|
||||
return;
|
||||
}
|
||||
let mut end = room;
|
||||
while !piece.is_char_boundary(end) {
|
||||
end -= 1;
|
||||
}
|
||||
self.text.push_str(&piece[..end]);
|
||||
self.truncated = true;
|
||||
}
|
||||
}
|
||||
|
||||
/// The level and area of the last line, which an indented continuation line inherits.
|
||||
#[derive(Debug)]
|
||||
struct LineContext {
|
||||
level: Level,
|
||||
area: Option<String>,
|
||||
}
|
||||
|
||||
/// `last_run.jsonl`: one JSON object per line, in order. It splits the text at `\n` exactly as
|
||||
/// `last_run.log` is split, so a record's `n` is that line's number in the log.
|
||||
struct RunJournal {
|
||||
out: Box<dyn Write + Send>,
|
||||
opened: Instant,
|
||||
line_number: u64,
|
||||
open_line: Option<OpenLine>,
|
||||
previous: Option<LineContext>,
|
||||
}
|
||||
|
||||
impl std::fmt::Debug for RunJournal {
|
||||
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
|
||||
f.debug_struct("RunJournal")
|
||||
.field("line_number", &self.line_number)
|
||||
.finish_non_exhaustive()
|
||||
}
|
||||
}
|
||||
|
||||
impl RunJournal {
|
||||
/// Writes the `start` record to `out`.
|
||||
fn new(out: Box<dyn Write + Send>) -> io::Result<RunJournal> {
|
||||
let mut journal = RunJournal {
|
||||
out,
|
||||
opened: Instant::now(),
|
||||
line_number: 0,
|
||||
open_line: None,
|
||||
previous: None,
|
||||
};
|
||||
journal.write_record(&json!({
|
||||
"type": "start",
|
||||
"schema": 1,
|
||||
"time": format_time(Local::now()),
|
||||
"launcher": env!("CARGO_PKG_VERSION"),
|
||||
"os": std::env::consts::OS,
|
||||
}))?;
|
||||
Ok(journal)
|
||||
}
|
||||
|
||||
/// Takes `text` as the next piece of the log: each `\n` completes a line, and what follows
|
||||
/// the last one stays open, stamped by the piece that began it.
|
||||
fn record_text(&mut self, text: &str, source: Source, arrival: Arrival) -> io::Result<()> {
|
||||
let mut rest = text;
|
||||
while let Some(end) = rest.find('\n') {
|
||||
let mut line = self
|
||||
.open_line
|
||||
.take()
|
||||
.unwrap_or_else(|| OpenLine::begin(source, arrival));
|
||||
line.push(&rest[..end]);
|
||||
self.write_line(line)?;
|
||||
rest = &rest[end + 1..];
|
||||
}
|
||||
if !rest.is_empty() {
|
||||
let line = self
|
||||
.open_line
|
||||
.get_or_insert_with(|| OpenLine::begin(source, arrival));
|
||||
line.push(rest);
|
||||
}
|
||||
Ok(())
|
||||
}
|
||||
|
||||
/// Ends the journal: a line still open is written, then the `exit` record.
|
||||
fn record_exit(&mut self, code: Option<i32>, advice: Option<&str>) -> io::Result<()> {
|
||||
if let Some(line) = self.open_line.take() {
|
||||
self.write_line(line)?;
|
||||
}
|
||||
self.write_record(&json!({
|
||||
"type": "exit",
|
||||
"t": self.seconds_since_open(Instant::now()),
|
||||
"time": format_time(Local::now()),
|
||||
"code": code,
|
||||
"advice": advice,
|
||||
}))
|
||||
}
|
||||
|
||||
fn write_line(&mut self, line: OpenLine) -> io::Result<()> {
|
||||
self.line_number += 1;
|
||||
let text = line.text.strip_suffix('\r').unwrap_or(&line.text);
|
||||
let continuation = self.previous.is_some() && text.starts_with(char::is_whitespace);
|
||||
let (level, area) = match (&self.previous, continuation) {
|
||||
(Some(previous), true) => (previous.level, previous.area.clone()),
|
||||
_ => {
|
||||
let (level, area) = classify(text);
|
||||
(level, area.map(str::to_owned))
|
||||
}
|
||||
};
|
||||
let mut record = json!({
|
||||
"type": "line",
|
||||
"n": self.line_number,
|
||||
"t": self.seconds_since_open(line.arrival.at),
|
||||
"time": format_time(line.arrival.time),
|
||||
"source": line.source.as_str(),
|
||||
"level": level.as_str(),
|
||||
"area": area,
|
||||
});
|
||||
if continuation {
|
||||
record["continuation"] = json!(true);
|
||||
}
|
||||
if line.truncated {
|
||||
record["truncated"] = json!(true);
|
||||
}
|
||||
record["text"] = json!(text);
|
||||
self.previous = Some(LineContext { level, area });
|
||||
self.write_record(&record)
|
||||
}
|
||||
|
||||
fn seconds_since_open(&self, at: Instant) -> f64 {
|
||||
at.saturating_duration_since(self.opened).as_millis() as f64 / 1000.0
|
||||
}
|
||||
|
||||
/// One `write_all` per record, so a record is never torn by another writer.
|
||||
fn write_record(&mut self, record: &Value) -> io::Result<()> {
|
||||
let mut bytes = serde_json::to_vec(record)?;
|
||||
bytes.push(b'\n');
|
||||
self.out.write_all(&bytes)?;
|
||||
self.out.flush()
|
||||
}
|
||||
}
|
||||
|
||||
fn format_time(time: DateTime<Local>) -> String {
|
||||
time.to_rfc3339_opts(SecondsFormat::Millis, false)
|
||||
}
|
||||
|
||||
/// Why the game closed, when an output line says so.
|
||||
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
|
||||
pub enum ExitHint {
|
||||
@@ -338,4 +646,435 @@ mod tests {
|
||||
);
|
||||
assert_eq!(line_status("other"), None);
|
||||
}
|
||||
|
||||
use serde_json::Value;
|
||||
use std::path::PathBuf;
|
||||
use std::time::Duration;
|
||||
|
||||
/// A run log in a fresh folder, with the paths of its two files.
|
||||
fn open_in_tempdir() -> (tempfile::TempDir, RunLog, PathBuf, PathBuf) {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let log_path = dir.path().join("last_run.log");
|
||||
let journal_path = dir.path().join("last_run.jsonl");
|
||||
let log = RunLog::open(&log_path);
|
||||
(dir, log, log_path, journal_path)
|
||||
}
|
||||
|
||||
fn records(journal_path: &Path) -> Vec<Value> {
|
||||
std::fs::read_to_string(journal_path)
|
||||
.unwrap()
|
||||
.lines()
|
||||
.map(|line| serde_json::from_str(line).unwrap())
|
||||
.collect()
|
||||
}
|
||||
|
||||
/// The `line` records, without the start and exit ones.
|
||||
fn line_records(journal_path: &Path) -> Vec<Value> {
|
||||
records(journal_path)
|
||||
.into_iter()
|
||||
.filter(|record| record["type"] == "line")
|
||||
.collect()
|
||||
}
|
||||
|
||||
/// Writes `text` as game output and returns the single line record it makes.
|
||||
fn only_line_record(text: &str) -> Value {
|
||||
let (_dir, mut log, _, journal_path) = open_in_tempdir();
|
||||
log.write(text);
|
||||
log.finish(Some(0), None);
|
||||
let mut lines = line_records(&journal_path);
|
||||
assert_eq!(lines.len(), 1, "{lines:?}");
|
||||
lines.remove(0)
|
||||
}
|
||||
|
||||
fn seconds(record: &Value) -> f64 {
|
||||
record["t"].as_f64().unwrap()
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn journal_starts_with_a_start_record_and_truncates_the_old_one() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let journal_path = dir.path().join("last_run.jsonl");
|
||||
std::fs::write(&journal_path, "old\n").unwrap();
|
||||
let log = RunLog::open(&dir.path().join("last_run.log"));
|
||||
drop(log);
|
||||
let all = records(&journal_path);
|
||||
assert_eq!(all.len(), 1, "{all:?}");
|
||||
let start = &all[0];
|
||||
assert_eq!(start["type"], "start");
|
||||
assert_eq!(start["schema"], 1);
|
||||
assert_eq!(start["launcher"], env!("CARGO_PKG_VERSION"));
|
||||
assert_eq!(start["os"], std::env::consts::OS);
|
||||
let time = start["time"].as_str().unwrap();
|
||||
assert!(chrono::DateTime::parse_from_rfc3339(time).is_ok(), "{time}");
|
||||
// Milliseconds, as in 2026-11-02T14:03:21.482-03:00.
|
||||
assert_eq!(time.find('.'), Some(19), "{time}");
|
||||
assert_eq!(time[20..].find(['+', '-', 'Z']), Some(3), "{time}");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn journal_lines_keep_the_log_numbers_and_strip_the_line_ending() {
|
||||
let (_dir, mut log, log_path, journal_path) = open_in_tempdir();
|
||||
log.write("first\r\n");
|
||||
log.write("\n");
|
||||
std::thread::sleep(Duration::from_millis(20));
|
||||
log.write("third\n");
|
||||
log.finish(Some(0), None);
|
||||
let lines = line_records(&journal_path);
|
||||
let numbered: Vec<(u64, &str)> = lines
|
||||
.iter()
|
||||
.map(|r| (r["n"].as_u64().unwrap(), r["text"].as_str().unwrap()))
|
||||
.collect();
|
||||
assert_eq!(numbered, [(1, "first"), (2, ""), (3, "third")]);
|
||||
assert!(seconds(&lines[0]) <= seconds(&lines[1]));
|
||||
assert!(seconds(&lines[2]) - seconds(&lines[1]) >= 0.015);
|
||||
assert!(lines.iter().all(|r| r["source"] == "game"));
|
||||
assert!(lines
|
||||
.iter()
|
||||
.all(|r| chrono::DateTime::parse_from_rfc3339(r["time"].as_str().unwrap()).is_ok()));
|
||||
// The log itself did not change.
|
||||
assert_eq!(
|
||||
std::fs::read_to_string(log_path).unwrap(),
|
||||
"first\r\n\nthird\n"
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_gpu_logger_line_gives_its_level_and_class() {
|
||||
let line = only_line_record(
|
||||
"GPU [Render.Vulkan] <Warning> vk_scheduler.cpp:120 Flush: submit took 31 ms\n",
|
||||
);
|
||||
assert_eq!(line["level"], "warning");
|
||||
assert_eq!(line["area"], "Render.Vulkan");
|
||||
for (name, level) in [
|
||||
("Trace", "trace"),
|
||||
("Debug", "debug"),
|
||||
("Info", "info"),
|
||||
("Error", "error"),
|
||||
("Critical", "critical"),
|
||||
] {
|
||||
let line = only_line_record(&format!("GPU [Shader] <{name}> a.cpp:1 f: m\n"));
|
||||
assert_eq!(line["level"], level);
|
||||
assert_eq!(line["area"], "Shader");
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn stop_and_fault_lines_are_critical() {
|
||||
let stop = only_line_record("STOP: first unsupported PS4 import: sceFoo (index 7)\n");
|
||||
assert_eq!(stop["level"], "critical");
|
||||
assert_eq!(stop["area"], "STOP");
|
||||
let fault = only_line_record("Fault: access violation at 0x1234\n");
|
||||
assert_eq!(fault["level"], "critical");
|
||||
assert_eq!(fault["area"], "Fault");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_prefixed_game_line_is_info_with_the_prefix_as_area() {
|
||||
let line = only_line_record("Texture cache: memory pressure, evicted 12 images\r\n");
|
||||
assert_eq!(line["level"], "info");
|
||||
assert_eq!(line["area"], "Texture cache");
|
||||
assert_eq!(
|
||||
line["text"],
|
||||
"Texture cache: memory pressure, evicted 12 images"
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn free_text_has_no_area() {
|
||||
for text in [
|
||||
"line 1\n",
|
||||
"mmap failed of guest memory (error 1455)\n",
|
||||
"\n",
|
||||
" leading space: not a label\n",
|
||||
"9 lives: starts with a digit\n",
|
||||
"a sentence that is far too long to be a label: and then some text\n",
|
||||
"C:\\games\\x: path-like\n",
|
||||
] {
|
||||
let line = only_line_record(text);
|
||||
assert_eq!(line["level"], "info", "{text}");
|
||||
assert_eq!(line["area"], Value::Null, "{text}");
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn indented_lines_continue_the_previous_line() {
|
||||
let (_dir, mut log, _, journal_path) = open_in_tempdir();
|
||||
log.write(" leading continuation without a previous line\n");
|
||||
log.write("GPU [Shader] <Error> s.cpp:9 compile: failed\n");
|
||||
log.write(" stage: fragment\n");
|
||||
log.write("\tline 12\n");
|
||||
log.write("Runtime: next report\n");
|
||||
log.write(" detail\n");
|
||||
log.finish(Some(0), None);
|
||||
let lines = line_records(&journal_path);
|
||||
let summary: Vec<(bool, &str, Option<&str>)> = lines
|
||||
.iter()
|
||||
.map(|r| {
|
||||
(
|
||||
r.get("continuation").is_some_and(|c| c == true),
|
||||
r["level"].as_str().unwrap(),
|
||||
r["area"].as_str(),
|
||||
)
|
||||
})
|
||||
.collect();
|
||||
assert_eq!(
|
||||
summary,
|
||||
[
|
||||
(false, "info", None),
|
||||
(false, "error", Some("Shader")),
|
||||
(true, "error", Some("Shader")),
|
||||
(true, "error", Some("Shader")),
|
||||
(false, "info", Some("Runtime")),
|
||||
(true, "info", Some("Runtime")),
|
||||
]
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_line_in_several_chunks_is_one_record_with_the_first_time() {
|
||||
let (_dir, mut log, log_path, journal_path) = open_in_tempdir();
|
||||
log.write("Texture cache: ");
|
||||
std::thread::sleep(Duration::from_millis(50));
|
||||
log.write("a very long ");
|
||||
log.write("report\r\n");
|
||||
log.write("next\n");
|
||||
log.finish(Some(0), None);
|
||||
let lines = line_records(&journal_path);
|
||||
assert_eq!(lines.len(), 2, "{lines:?}");
|
||||
assert_eq!(lines[0]["n"], 1);
|
||||
assert_eq!(lines[0]["text"], "Texture cache: a very long report");
|
||||
assert_eq!(lines[0]["area"], "Texture cache");
|
||||
assert_eq!(lines[1]["n"], 2);
|
||||
// The second line was stamped at least the pause after the first chunk of the first.
|
||||
assert!(
|
||||
seconds(&lines[1]) - seconds(&lines[0]) >= 0.045,
|
||||
"{lines:?}"
|
||||
);
|
||||
assert_eq!(
|
||||
std::fs::read_to_string(log_path).unwrap(),
|
||||
"Texture cache: a very long report\r\nnext\n"
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_final_chunk_without_a_newline_is_flushed_at_the_end() {
|
||||
let (_dir, mut log, _, journal_path) = open_in_tempdir();
|
||||
log.write("done\n");
|
||||
log.write("last words");
|
||||
log.finish(Some(3), None);
|
||||
let all = records(&journal_path);
|
||||
let kinds: Vec<&str> = all.iter().map(|r| r["type"].as_str().unwrap()).collect();
|
||||
assert_eq!(kinds, ["start", "line", "line", "exit"]);
|
||||
assert_eq!(all[2]["n"], 2);
|
||||
assert_eq!(all[2]["text"], "last words");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_line_is_stamped_when_it_arrived_not_when_it_was_recorded() {
|
||||
let (_dir, mut log, _, journal_path) = open_in_tempdir();
|
||||
let journal = log.journal.as_mut().unwrap();
|
||||
// As if writing last_run.log had stalled: the piece arrived 1.5 s after the journal opened.
|
||||
let arrival = Arrival {
|
||||
at: journal.opened + Duration::from_millis(1500),
|
||||
time: Local::now(),
|
||||
};
|
||||
journal
|
||||
.record_text("late\n", Source::Game, arrival)
|
||||
.unwrap();
|
||||
log.finish(Some(0), None);
|
||||
let lines = line_records(&journal_path);
|
||||
assert_eq!(seconds(&lines[0]), 1.5, "{lines:?}");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_line_longer_than_the_limit_is_cut_and_marked_but_kept_whole_in_the_log() {
|
||||
let (_dir, mut log, log_path, journal_path) = open_in_tempdir();
|
||||
let long = "x".repeat(MAX_JOURNAL_LINE_BYTES + 100);
|
||||
log.write(&long[..40_000]);
|
||||
log.write(&long[40_000..]);
|
||||
log.write("\nnext\n");
|
||||
log.finish(Some(0), None);
|
||||
let lines = line_records(&journal_path);
|
||||
assert_eq!(lines.len(), 2, "two records");
|
||||
assert_eq!(lines[0]["n"], 1);
|
||||
assert_eq!(lines[0]["truncated"], true);
|
||||
assert_eq!(
|
||||
lines[0]["text"].as_str().unwrap().len(),
|
||||
MAX_JOURNAL_LINE_BYTES
|
||||
);
|
||||
assert_eq!(lines[1]["n"], 2);
|
||||
assert_eq!(lines[1]["text"], "next");
|
||||
assert!(lines[1].get("truncated").is_none(), "{:?}", lines[1]);
|
||||
assert_eq!(
|
||||
std::fs::read_to_string(log_path).unwrap(),
|
||||
format!("{long}\nnext\n")
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_cut_line_ends_on_a_whole_character() {
|
||||
// Three-byte characters: the limit falls inside one of them.
|
||||
let euros = "€".repeat(MAX_JOURNAL_LINE_BYTES / 3 + 10);
|
||||
let record = only_line_record(&format!("{euros}\n"));
|
||||
let text = record["text"].as_str().unwrap();
|
||||
assert!(text.len() <= MAX_JOURNAL_LINE_BYTES, "{}", text.len());
|
||||
assert!(text.chars().all(|c| c == '€'));
|
||||
assert_eq!(record["truncated"], true);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_advice_lines_are_launcher_records_numbered_as_in_the_log() {
|
||||
let (_dir, mut log, log_path, journal_path) = open_in_tempdir();
|
||||
log.write("Runtime: cannot map 6080 MiB of guest memory (error 12)\n");
|
||||
log.finish(Some(1), Some("Close other programs and start again."));
|
||||
assert_eq!(
|
||||
std::fs::read_to_string(&log_path).unwrap(),
|
||||
"Runtime: cannot map 6080 MiB of guest memory (error 12)\n\nClose other programs and start again.\n"
|
||||
);
|
||||
let lines = line_records(&journal_path);
|
||||
let summary: Vec<(u64, &str, &str)> = lines
|
||||
.iter()
|
||||
.map(|r| {
|
||||
(
|
||||
r["n"].as_u64().unwrap(),
|
||||
r["source"].as_str().unwrap(),
|
||||
r["text"].as_str().unwrap(),
|
||||
)
|
||||
})
|
||||
.collect();
|
||||
assert_eq!(
|
||||
summary,
|
||||
[
|
||||
(
|
||||
1,
|
||||
"game",
|
||||
"Runtime: cannot map 6080 MiB of guest memory (error 12)"
|
||||
),
|
||||
(2, "launcher", ""),
|
||||
(3, "launcher", "Close other programs and start again."),
|
||||
]
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_advice_ends_a_line_the_game_left_open() {
|
||||
let (_dir, mut log, log_path, journal_path) = open_in_tempdir();
|
||||
log.write("cut off");
|
||||
log.finish(Some(1), Some("Advice."));
|
||||
// The advice starts with a newline, which ends the open line, as in the file.
|
||||
assert_eq!(
|
||||
std::fs::read_to_string(log_path).unwrap(),
|
||||
"cut off\nAdvice.\n"
|
||||
);
|
||||
let lines = line_records(&journal_path);
|
||||
let summary: Vec<(u64, &str, &str)> = lines
|
||||
.iter()
|
||||
.map(|r| {
|
||||
(
|
||||
r["n"].as_u64().unwrap(),
|
||||
r["source"].as_str().unwrap(),
|
||||
r["text"].as_str().unwrap(),
|
||||
)
|
||||
})
|
||||
.collect();
|
||||
assert_eq!(
|
||||
summary,
|
||||
[(1, "game", "cut off"), (2, "launcher", "Advice.")]
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_exit_record_has_the_code_and_the_advice() {
|
||||
let (_dir, mut log, _, journal_path) = open_in_tempdir();
|
||||
log.write("x\n");
|
||||
std::thread::sleep(Duration::from_millis(20));
|
||||
log.finish(Some(21), Some("Advice."));
|
||||
let all = records(&journal_path);
|
||||
let exit = all.last().unwrap();
|
||||
assert_eq!(exit["type"], "exit");
|
||||
assert_eq!(exit["code"], 21);
|
||||
assert_eq!(exit["advice"], "Advice.");
|
||||
assert!(seconds(exit) >= seconds(&all[1]));
|
||||
assert!(chrono::DateTime::parse_from_rfc3339(exit["time"].as_str().unwrap()).is_ok());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_exit_record_has_null_for_an_unknown_code_and_no_advice() {
|
||||
let (_dir, log, _, journal_path) = open_in_tempdir();
|
||||
log.finish(None, None);
|
||||
let all = records(&journal_path);
|
||||
assert_eq!(all.len(), 2, "{all:?}");
|
||||
assert_eq!(all[1]["code"], Value::Null);
|
||||
assert_eq!(all[1]["advice"], Value::Null);
|
||||
}
|
||||
|
||||
/// Accepts `allowed` writes, then fails every one.
|
||||
struct FailsAfter {
|
||||
allowed: usize,
|
||||
}
|
||||
|
||||
impl Write for FailsAfter {
|
||||
fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
|
||||
if self.allowed == 0 {
|
||||
return Err(std::io::Error::other("disk full"));
|
||||
}
|
||||
self.allowed -= 1;
|
||||
Ok(buf.len())
|
||||
}
|
||||
|
||||
fn flush(&mut self) -> std::io::Result<()> {
|
||||
Ok(())
|
||||
}
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_journal_write_error_leaves_the_run_log_intact() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let log_path = dir.path().join("last_run.log");
|
||||
let journal = RunJournal::new(Box::new(FailsAfter { allowed: 1 })).unwrap();
|
||||
let mut log = RunLog {
|
||||
file: File::create(&log_path).ok(),
|
||||
journal: Some(journal),
|
||||
};
|
||||
log.write("one\n");
|
||||
assert!(
|
||||
log.journal.is_none(),
|
||||
"the failed write disables the journal"
|
||||
);
|
||||
log.write("two\n");
|
||||
log.finish(Some(1), Some("Advice."));
|
||||
assert_eq!(
|
||||
std::fs::read_to_string(log_path).unwrap(),
|
||||
"one\ntwo\n\nAdvice.\n"
|
||||
);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_journal_that_cannot_be_created_leaves_the_run_log_working() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
std::fs::create_dir(dir.path().join("last_run.jsonl")).unwrap();
|
||||
let log_path = dir.path().join("last_run.log");
|
||||
let mut log = RunLog::open(&log_path);
|
||||
assert!(log.is_open());
|
||||
assert!(log.journal.is_none());
|
||||
log.write("kept\n");
|
||||
log.finish(Some(0), None);
|
||||
assert_eq!(std::fs::read_to_string(log_path).unwrap(), "kept\n");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_journal_keeps_going_when_the_run_log_cannot_be_created() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
std::fs::create_dir(dir.path().join("last_run.log")).unwrap();
|
||||
let mut log = RunLog::open(&dir.path().join("last_run.log"));
|
||||
assert!(!log.is_open());
|
||||
log.write(
|
||||
"only in the journal
|
||||
",
|
||||
);
|
||||
log.finish(Some(0), None);
|
||||
let lines = line_records(&dir.path().join("last_run.jsonl"));
|
||||
assert_eq!(lines.len(), 1, "{lines:?}");
|
||||
assert_eq!(lines[0]["text"], "only in the journal");
|
||||
}
|
||||
}
|
||||
@@ -294,7 +294,7 @@ pub fn relaunch_appimage(target: &Path, env: &IndexMap<String, String>) -> io::R
|
||||
}
|
||||
|
||||
/// Names the player owns: an update never copies them over, at any depth.
|
||||
pub const USER_FILES: [&str; 11] = [
|
||||
pub const USER_FILES: [&str; 12] = [
|
||||
"user",
|
||||
"out",
|
||||
"mods",
|
||||
@@ -305,6 +305,7 @@ pub const USER_FILES: [&str; 11] = [
|
||||
"mods_presets.json",
|
||||
"patches.json",
|
||||
"last_run.log",
|
||||
"last_run.jsonl",
|
||||
"gamecontrollerdb.txt",
|
||||
];
|
||||
|
||||
@@ -813,6 +814,7 @@ mod tests {
|
||||
"mods_presets.json",
|
||||
"patches.json",
|
||||
"last_run.log",
|
||||
"last_run.jsonl",
|
||||
"gamecontrollerdb.txt",
|
||||
]
|
||||
);
|
||||
|
||||
@@ -218,6 +218,88 @@ fn a_clean_exit_writes_no_advice() {
|
||||
assert_eq!(log, format!("{MEMORY_LINE}\n"));
|
||||
}
|
||||
|
||||
/// The records of the `last_run.jsonl` next to `log_path`.
|
||||
fn journal_records(log_path: &Path) -> Vec<serde_json::Value> {
|
||||
std::fs::read_to_string(log_path.with_extension("jsonl"))
|
||||
.unwrap()
|
||||
.lines()
|
||||
.map(|line| serde_json::from_str(line).unwrap())
|
||||
.collect()
|
||||
}
|
||||
|
||||
/// Runs the fake game with `args`, then returns `last_run.log` and the records of `last_run.jsonl`.
|
||||
fn run_and_read_both(args: &[&str]) -> (String, Vec<serde_json::Value>) {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let path = dir.path().join("last_run.log");
|
||||
let handle = start(args, RunLog::open(&path));
|
||||
collect(&handle);
|
||||
let log = std::fs::read_to_string(&path).unwrap();
|
||||
(log, journal_records(&path))
|
||||
}
|
||||
|
||||
/// The `n` and `text` of every `line` record.
|
||||
fn numbered_lines(records: &[serde_json::Value]) -> Vec<(u64, String)> {
|
||||
records
|
||||
.iter()
|
||||
.filter(|record| record["type"] == "line")
|
||||
.map(|record| {
|
||||
(
|
||||
record["n"].as_u64().unwrap(),
|
||||
record["text"].as_str().unwrap().to_string(),
|
||||
)
|
||||
})
|
||||
.collect()
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn the_journal_reproduces_the_run_log_line_by_line() {
|
||||
let (log, records) = run_and_read_both(&[
|
||||
"--say",
|
||||
"Texture cache: memory pressure, evicted 3 images",
|
||||
"--lines",
|
||||
"3",
|
||||
"--delay-ms",
|
||||
"0",
|
||||
"--exit",
|
||||
"0",
|
||||
]);
|
||||
let expected: Vec<(u64, String)> = log
|
||||
.lines()
|
||||
.enumerate()
|
||||
.map(|(index, line)| (index as u64 + 1, line.to_string()))
|
||||
.collect();
|
||||
assert_eq!(expected.len(), 4, "{log}");
|
||||
assert_eq!(numbered_lines(&records), expected);
|
||||
assert_eq!(records.first().unwrap()["type"], "start");
|
||||
let exit = records.last().unwrap();
|
||||
assert_eq!(exit["type"], "exit");
|
||||
assert_eq!(exit["code"], 0);
|
||||
assert_eq!(exit["advice"], serde_json::Value::Null);
|
||||
assert_eq!(records[1]["area"], "Texture cache");
|
||||
assert_eq!(records[1]["source"], "game");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_failed_run_puts_its_advice_and_code_in_the_journal() {
|
||||
let (log, records) = run_and_read_both(&["--say", MEMORY_LINE, "--exit", "1"]);
|
||||
let expected: Vec<(u64, String)> = log
|
||||
.lines()
|
||||
.enumerate()
|
||||
.map(|(index, line)| (index as u64 + 1, line.to_string()))
|
||||
.collect();
|
||||
assert_eq!(numbered_lines(&records), expected);
|
||||
let launcher_lines: Vec<&str> = records
|
||||
.iter()
|
||||
.filter(|record| record["source"] == "launcher")
|
||||
.map(|record| record["text"].as_str().unwrap())
|
||||
.collect();
|
||||
assert_eq!(launcher_lines, ["", advice()]);
|
||||
let exit = records.last().unwrap();
|
||||
assert_eq!(exit["type"], "exit");
|
||||
assert_eq!(exit["code"], 1);
|
||||
assert_eq!(exit["advice"], advice());
|
||||
}
|
||||
|
||||
/// The process group of `pid`, from `ps`.
|
||||
#[cfg(unix)]
|
||||
fn group_of(pid: u32) -> u32 {
|
||||
|
||||
@@ -1170,6 +1170,29 @@ fn play_writes_last_run_log_with_the_advice() {
|
||||
assert!(told.is_empty());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn play_writes_the_journal_next_to_the_run_log() {
|
||||
let dir = tempfile::tempdir().unwrap();
|
||||
let user = dir.path().join("saves");
|
||||
let settings = play_settings(dir.path(), &user);
|
||||
let line = "Runtime: cannot create 6080 MiB of guest memory (error 12)";
|
||||
let args = ["--say", line, "--exit", "21"];
|
||||
let (code, _, log, _) = played(&settings, dir.path(), &user, clean_environment(), &args);
|
||||
assert_eq!(code, 21, "{log}");
|
||||
let journal = fs::read_to_string(user.join("last_run.jsonl")).unwrap();
|
||||
let records: Vec<serde_json::Value> = journal
|
||||
.lines()
|
||||
.map(|record| serde_json::from_str(record).unwrap())
|
||||
.collect();
|
||||
assert_eq!(records.first().unwrap()["type"], "start");
|
||||
assert_eq!(records[1]["text"], line);
|
||||
assert_eq!(records[1]["area"], "Runtime");
|
||||
let exit = records.last().unwrap();
|
||||
assert_eq!(exit["type"], "exit");
|
||||
assert_eq!(exit["code"], 21);
|
||||
assert!(exit["advice"].as_str().is_some(), "{journal}");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn play_starts_the_game_with_the_saved_stream_memory() {
|
||||
// The saved choice, whatever the launcher inherited.
|
||||
|
||||
@@ -74,6 +74,8 @@ Problems
|
||||
set C: to 16384 MB initial, 24576 MB maximum -> Set -> OK, then restart your PC.
|
||||
- The game does not open: check Advanced -> Log, and send user\last_run.log with your report.
|
||||
With a custom Saves folder, last_run.log is in that folder instead.
|
||||
Next to it, last_run.jsonl has the same lines with the time, level and area of each one, for
|
||||
tools and for telling which event came first; attach both files when you report a bug.
|
||||
- Other known GPU, audio, crash and progress issues are tracked in the release notes and issues:
|
||||
https://github.com/FelipePrado0/SpartanPort/releases/latest
|
||||
https://github.com/FelipePrado0/SpartanPort/issues
|
||||
|
||||
@@ -50,7 +50,7 @@ cp gpu/third_party/fsr-vulkan/LICENSE.txt "$dest/LICENSES/FSR-Vulkan.txt"
|
||||
# No game files and nothing a player made (saves, shader caches built from the game's shaders,
|
||||
# settings, logs) may ship: stop when one is found.
|
||||
forbidden=$(find "$dest" -path "$dest/fsr4_shaders" -prune -o \( -iname eboot.bin -o -iname sce_module -o -iname sce_sys -o -iname savedata \
|
||||
-o -iname user -o -iname cache -o -iname '*.log' -o -iname spartanport.ini -o -iname settings.json \
|
||||
-o -iname user -o -iname cache -o -iname '*.log' -o -iname '*.jsonl' -o -iname spartanport.ini -o -iname settings.json \
|
||||
-o -iname game_icon.ico \
|
||||
-o -iname mods.json -o -iname patches.json \
|
||||
-o -iname '*.py' -o -iname _internal \
|
||||
|
||||
@@ -25,7 +25,7 @@ if ($env:SPARTAN_RELEASE_TAG) {
|
||||
}
|
||||
|
||||
# The same names package.sh refuses to ship: game files and anything a player makes.
|
||||
$forbidden = 'eboot.bin', 'sce_module', 'sce_sys', 'savedata', 'user', 'cache', '*.log', 'spartanport.ini',
|
||||
$forbidden = 'eboot.bin', 'sce_module', 'sce_sys', 'savedata', 'user', 'cache', '*.log', '*.jsonl', 'spartanport.ini',
|
||||
'settings.json', 'game_icon.ico', 'mods.json', 'patches.json', '*.spv', '*.pkg',
|
||||
'*.sprx', '*.prx', 'nvngx_dlss*.dll', 'spartanport_dlss.dll',
|
||||
'spartanport_streamline.dll', 'sl.*.dll'
|
||||
|
||||
Reference in new issue
Block a user