diff --git a/AGENTS.md b/AGENTS.md index 5ea7526..351ff11 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -212,3 +212,7 @@ any crate. - Adding/changing diagnostics or schema content: update the affected `tests/spec/*.spec.toml` (and drop any `xfail` a change now satisfies), then review the diff. +- Server logging uses `window/logMessage` for concise user-facing lifecycle + events and `tracing` for developer detail. Keep stdout protocol-only, put + paths/URIs at Debug or Trace, never log source text or INI values, and use + structured `snake_case` fields with unit suffixes such as `_ms` and `_bytes`. diff --git a/crates/server/src/backend.rs b/crates/server/src/backend.rs index 44dacef..7c7657f 100644 --- a/crates/server/src/backend.rs +++ b/crates/server/src/backend.rs @@ -10,7 +10,7 @@ use std::collections::{HashMap, VecDeque}; use std::path::PathBuf; use std::sync::atomic::{AtomicBool, AtomicU64, AtomicUsize, Ordering}; use std::sync::{Arc, Mutex, OnceLock, RwLock}; -use std::time::Duration; +use std::time::{Duration, Instant}; use base64::Engine; use dashmap::DashMap; @@ -19,7 +19,7 @@ use ropey::Rope; use serde::Deserialize; use tower_lsp::lsp_types::*; use tower_lsp::{jsonrpc::Result, Client, LanguageServer}; -use zerosyntax_analysis::diagnostics::DiagnosticsCache; +use zerosyntax_analysis::diagnostics::{DiagnosticsCache, Severity as AnalysisSeverity}; use zerosyntax_analysis::index::{ definitions_in, module_tags_in, object_models_in, object_parents_in, references_in, ModelMemberStrictness, WorkspaceIndex, @@ -29,7 +29,7 @@ use zerosyntax_analysis::nav::{ HoverInfo, ModuleTagReferenceAt, ReferenceAt, }; use zerosyntax_analysis::{actions, completion, diagnostics, format, outline, semantic, Analyzer}; -use zerosyntax_syntax::{Edit, Parse}; +use zerosyntax_syntax::{Edit, Parse, Strategy}; use crate::convert::{self, PositionEnc}; use crate::scan::{ @@ -318,10 +318,13 @@ fn load_schema(path: &str) -> std::result::Result { fn load_schema_or_embedded(path: &str) -> (Analyzer, Option) { match load_schema(path) { Ok(analyzer) => (analyzer, None), - Err(error) => ( - Analyzer::embedded(), - Some(format!("ZeroSyntax: {error}; using the built-in schema.")), - ), + Err(error) => { + tracing::debug!(schema_path = path, %error, "custom schema load failed"); + ( + Analyzer::embedded(), + Some(format!("ZeroSyntax: {error}; using the built-in schema.")), + ) + } } } @@ -394,6 +397,7 @@ async fn refresh_document( uri: Url, options: RefreshOptions, ) { + let started = Instant::now(); let analyzer = analyzer.read().expect("analyzer lock poisoned").clone(); let Some((rope, parse, version)) = docs.get(&uri).and_then(|d| { if options @@ -405,6 +409,11 @@ async fn refresh_document( Some((d.rope.clone(), d.parse.clone(), d.version)) } }) else { + tracing::trace!( + uri = %uri, + expected_version = ?options.expected_version, + "document refresh skipped because the document closed or changed" + ); return; }; @@ -417,8 +426,17 @@ async fn refresh_document( // Keep this document guard through the short index commit so didChange // cannot advance the document and then be overwritten by this snapshot. - let Some(entry) = docs.get(&uri) else { return }; + let Some(entry) = docs.get(&uri) else { + tracing::trace!(uri = %uri, version, "document refresh superseded before index commit"); + return; + }; if entry.version != version { + tracing::trace!( + uri = %uri, + version, + current_version = entry.version, + "document refresh superseded before index commit" + ); return; } if let Ok(mut idx) = index.write() { @@ -434,15 +452,22 @@ async fn refresh_document( // Take the cache only after the versioned index commit. Expensive work // above never empties the live document's cache when an edit supersedes it. let Some(mut entry) = docs.get_mut(&uri) else { + tracing::trace!(uri = %uri, version, "document refresh superseded before diagnostics"); return; }; if entry.version != version { + tracing::trace!( + uri = %uri, + version, + current_version = entry.version, + "document refresh superseded before diagnostics" + ); return; } let mut cache = std::mem::take(&mut entry.diag_cache); drop(entry); - let lsp_diags: Vec = { + let (lsp_diags, error_count, warning_count, hint_count) = { let idx = index.read().ok(); let mut diags = diagnostics::diagnose_with_cache( &analyzer, @@ -455,24 +480,51 @@ async fn refresh_document( &mut diags, map_ordering_diagnostics.load(Ordering::Relaxed), ); - diags + let (mut errors, mut warnings, mut hints) = (0, 0, 0); + for diagnostic in &diags { + match diagnostic.severity { + AnalysisSeverity::Error => errors += 1, + AnalysisSeverity::Warning => warnings += 1, + AnalysisSeverity::Hint => hints += 1, + } + } + let converted: Vec = diags .iter() .map(|d| convert::to_lsp_diagnostic(&rope, d, options.enc)) - .collect() + .collect(); + (converted, errors, warnings, hints) }; let Some(mut entry) = docs.get_mut(&uri) else { + tracing::trace!(uri = %uri, version, "document refresh superseded before cache commit"); return; }; if entry.version != version { + tracing::trace!( + uri = %uri, + version, + current_version = entry.version, + "document refresh superseded before cache commit" + ); return; } entry.diag_cache = cache; drop(entry); + let diagnostic_count = lsp_diags.len(); client - .publish_diagnostics(uri, lsp_diags, Some(version)) + .publish_diagnostics(uri.clone(), lsp_diags, Some(version)) .await; + tracing::debug!( + uri = %uri, + version, + diagnostic_count, + error_count, + warning_count, + hint_count, + elapsed_ms = started.elapsed().as_millis() as u64, + "document diagnostics published" + ); } impl Backend { @@ -555,6 +607,12 @@ impl Backend { let enc = self.enc(); let map_ordering_diagnostics = self.map_ordering_diagnostics.clone(); let delay = Duration::from_millis(self.analysis_debounce_ms.load(Ordering::Relaxed)); + tracing::trace!( + uri = %uri, + version, + delay_ms = delay.as_millis() as u64, + "document refresh scheduled" + ); tokio::spawn(async move { tokio::time::sleep(delay).await; refresh_document( @@ -621,10 +679,11 @@ impl Backend { .await }; if let Err(error) = result { + tracing::error!(%error, enabled, "formatting capability update failed"); self.client .log_message( MessageType::ERROR, - format!("failed to update formatting capability: {error}"), + format!("ZeroSyntax: failed to update formatting capability: {error}"), ) .await; } @@ -637,6 +696,7 @@ impl Backend { return; }; if *current == settings { + tracing::trace!("configuration notification made no changes"); return; } let previous = current.clone(); @@ -661,6 +721,54 @@ impl Backend { previous.map_ordering_diagnostics != settings.map_ordering_diagnostics; let preview_changed = previous.preview_image_width != settings.preview_image_width || previous.preview_zoom_percent != settings.preview_zoom_percent; + let debounce_changed = previous.debounce_ms != settings.debounce_ms; + let format_changed = previous.format_enabled != settings.format_enabled; + let mut changed = Vec::new(); + if format_changed { + changed.push("format.enable"); + } + if schema_changed { + changed.push("schemaPath"); + } + if roots_changed { + changed.push("baseIniRoots"); + } + if strictness_changed { + changed.push("analysis.modelMemberStrictness"); + } + if bare_changed { + changed.push("analysis.allowPercentagesWithoutSign"); + } + if map_ordering_changed { + changed.push("analysis.mapOrderingDiagnostics"); + } + if debounce_changed { + changed.push("analysis.debounceMs"); + } + if preview_changed { + changed.push("preview"); + } + self.client + .log_message( + MessageType::INFO, + format!( + "ZeroSyntax: settings updated ({}) — formatting={}, schema={}, base roots={}, model strictness={:?}, bare percentages={}, map ordering={}, debounce={} ms.", + changed.join(", "), + settings.format_enabled, + if settings.schema_path.is_empty() { "built-in" } else { "custom" }, + settings.base_ini_roots.len(), + settings.model_member_strictness, + settings.allow_bare_percentages, + settings.map_ordering_diagnostics, + settings.debounce_ms, + ), + ) + .await; + tracing::debug!( + schema_path = settings.schema_path, + base_roots = ?settings.base_ini_roots, + "configuration paths updated" + ); if preview_changed { if let Ok(mut cache) = self.preview_cache.lock() { @@ -678,7 +786,8 @@ impl Backend { } else if bare_changed { (Analyzer::new(self.analyzer().schema().clone()), None) } else { - self.scan_workspace(self.analyzer(), false).await; + self.scan_workspace(self.analyzer(), false, "configuration_changed") + .await; self.refresh_all().await; return; }; @@ -690,11 +799,18 @@ impl Backend { } } if let Some(warning) = warning { + self.client + .log_message( + MessageType::WARNING, + "ZeroSyntax: custom schema could not be loaded; using the built-in schema.", + ) + .await; self.client .show_message(MessageType::WARNING, warning) .await; } - self.scan_workspace(analyzer, schema_changed).await; + self.scan_workspace(analyzer, schema_changed, "configuration_changed") + .await; self.refresh_all().await; return; } @@ -732,9 +848,8 @@ impl Backend { .lock() .map(|settings| settings.base_ini_roots.is_empty()) .unwrap_or(true); - if roots_empty && self.client_base_ini_hint.get().copied().unwrap_or(false) { - return; - } + let client_handles_hint = + roots_empty && self.client_base_ini_hint.get().copied().unwrap_or(false); if self .base_roots_hint_shown .compare_exchange(false, true, Ordering::Relaxed, Ordering::Relaxed) @@ -742,6 +857,15 @@ impl Backend { { return; } + self.client + .log_message( + MessageType::WARNING, + "ZeroSyntax: map/solo.ini diagnostics are limited because no base game or mod data is configured.", + ) + .await; + if client_handles_hint { + return; + } self.client .show_message( MessageType::WARNING, @@ -757,8 +881,13 @@ impl Backend { /// client as `$/progress` (a status-bar spinner with a `done/total` /// counter in VS Code) so users can tell "still indexing" apart from /// "nothing was found". - async fn scan_workspace(&self, analyzer: Arc, replace_analyzer: bool) { - let progress_token = self.begin_scan_progress().await; + async fn scan_workspace( + &self, + analyzer: Arc, + replace_analyzer: bool, + reason: &'static str, + ) { + let started = Instant::now(); let roots = self.roots.lock().map(|r| r.clone()).unwrap_or_default(); let (base_roots, model_member_strictness) = self .settings @@ -770,6 +899,24 @@ impl Backend { ) }) .unwrap_or_default(); + self.client + .log_message( + MessageType::INFO, + format!( + "ZeroSyntax: indexing started (reason={reason}, workspace roots={}, base roots={}).", + roots.len(), + base_roots.len() + ), + ) + .await; + tracing::debug!( + reason, + workspace_roots = ?roots, + base_roots = ?base_roots, + replace_analyzer, + "workspace indexing paths" + ); + let progress_token = self.begin_scan_progress().await; // The blocking scan streams (done, total) over a channel; forward // each update as a progress report while waiting for the results. let (tx, mut rx) = tokio::sync::mpsc::unbounded_channel::<(usize, usize)>(); @@ -793,7 +940,21 @@ impl Backend { self.report_scan_progress(&progress_token, done, total) .await; } - let scanned = handle.await.unwrap_or_default(); + let scanned = match handle.await { + Ok(scanned) => scanned, + Err(error) => { + tracing::error!(reason, %error, "workspace indexing worker failed"); + self.client + .log_message( + MessageType::ERROR, + format!( + "ZeroSyntax: indexing worker failed (reason={reason}); the index may be incomplete." + ), + ) + .await; + Vec::new() + } + }; if replace_analyzer { if let Ok(mut current) = self.analyzer.write() { *current = analyzer.clone(); @@ -885,6 +1046,15 @@ impl Backend { texture_total, ) .await; + self.client + .log_message( + MessageType::INFO, + format!( + "ZeroSyntax: indexing completed (reason={reason}) — {ini_total} INI files, {model_total} W3D models, {audio_total} audio files, {texture_total} textures in {} ms.", + started.elapsed().as_millis() + ), + ) + .await; } /// Ask the client to show an indexing spinner. Returns the token to end @@ -1210,13 +1380,51 @@ impl LanguageServer for Backend { } async fn initialized(&self, _: InitializedParams) { + let roots = self + .roots + .lock() + .map(|roots| roots.clone()) + .unwrap_or_default(); + let settings = self + .settings + .lock() + .map(|settings| settings.clone()) + .unwrap_or_default(); + self.client + .log_message( + MessageType::INFO, + format!( + "ZeroSyntax: initializing v{} (encoding={:?}, workspace roots={}, base roots={}, schema={}, work progress={}, snippets={}, dynamic formatting={}).", + env!("CARGO_PKG_VERSION"), + self.enc(), + roots.len(), + settings.base_ini_roots.len(), + if settings.schema_path.is_empty() { "built-in" } else { "custom" }, + self.progress_support.get().copied().unwrap_or(false), + self.snippet_support.get().copied().unwrap_or(false), + self.formatting_dynamic_registration.get().copied().unwrap_or(false), + ), + ) + .await; + tracing::debug!( + workspace_roots = ?roots, + base_roots = ?settings.base_ini_roots, + schema_path = settings.schema_path, + "server initialization paths" + ); if let Some(error) = self.schema_error.lock().ok().and_then(|mut e| e.take()) { + self.client + .log_message( + MessageType::WARNING, + "ZeroSyntax: custom schema could not be loaded; using the built-in schema.", + ) + .await; self.client.show_message(MessageType::WARNING, error).await; } if self.format_enabled() { self.set_formatting_enabled(true).await; } - self.scan_workspace(self.analyzer(), false).await; + self.scan_workspace(self.analyzer(), false, "startup").await; // Re-publish diagnostics for any already-open docs now that the index // is populated (so cross-file references resolve). The cached parse is // still valid — only the index changed. @@ -1252,7 +1460,7 @@ impl LanguageServer for Backend { .log_message( MessageType::INFO, format!( - "zerosyntax language server ready ({ini} base INI files, {models} W3D models, {audio} audio files, {textures} textures indexed)" + "ZeroSyntax: language server ready ({ini} base INI files, {models} W3D models, {audio} audio files, {textures} textures indexed)." ), ) .await; @@ -1277,18 +1485,34 @@ impl LanguageServer for Backend { .lock() .map(|settings| settings.base_ini_roots.clone()) .unwrap_or_default(); - let cleared = clear_index_cache(&roots, &base_roots).map_err(|error| { - tracing::warn!(%error, "could not clear asset index cache"); - tower_lsp::jsonrpc::Error::internal_error() - })?; + let cleared = match clear_index_cache(&roots, &base_roots) { + Ok(cleared) => cleared, + Err(error) => { + tracing::error!(%error, "asset index cache clear failed"); + self.client + .log_message( + MessageType::ERROR, + "ZeroSyntax: failed to clear the index cache.", + ) + .await; + return Err(tower_lsp::jsonrpc::Error::internal_error()); + } + }; if params.command == REBUILD_INDEX_CACHE_COMMAND { self.scan_finished.store(false, Ordering::Relaxed); self.base_indexed_count.store(0, Ordering::Relaxed); - self.scan_workspace(self.analyzer(), false).await; + self.scan_workspace(self.analyzer(), false, "manual_cache_rebuild") + .await; let open: Vec = self.docs.iter().map(|entry| entry.key().clone()).collect(); for uri in open { self.refresh(&uri, None).await; } + self.client + .log_message( + MessageType::INFO, + format!("ZeroSyntax: index cache rebuilt (previous cache cleared={cleared})."), + ) + .await; self.client .show_message(MessageType::INFO, "ZeroSyntax index cache rebuilt.") .await; @@ -1301,11 +1525,18 @@ impl LanguageServer for Backend { } else { "ZeroSyntax index cache is already clear." }; + self.client.log_message(MessageType::INFO, message).await; self.client.show_message(MessageType::INFO, message).await; Ok(Some(serde_json::json!({ "cleared": cleared }))) } async fn shutdown(&self) -> Result<()> { + self.client + .log_message( + MessageType::INFO, + "ZeroSyntax: language server shutting down.", + ) + .await; Ok(()) } @@ -1320,6 +1551,12 @@ impl LanguageServer for Backend { let rope = Rope::from_str(&text); let parse = Arc::new(self.analyzer().parse(&text)); let version = params.text_document.version; + tracing::debug!( + uri = %uri, + version, + text_bytes = text.len(), + "document opened" + ); self.docs.insert( uri.clone(), DocumentState { @@ -1339,8 +1576,24 @@ impl LanguageServer for Backend { let version = params.text_document.version; let enc = self.enc(); let analyzer = self.analyzer(); + let change_count = params.content_changes.len(); + let incoming_bytes = params + .content_changes + .iter() + .map(|change| change.text.len()) + .sum::(); + let all_ranged = params + .content_changes + .iter() + .all(|change| change.range.is_some()); + let mut spliced_count = 0; + let mut full_fallback_count = 0; + let mut full_replacement = false; + let parse_strategy; + let text_bytes; { let Some(mut entry) = self.docs.get_mut(&uri) else { + tracing::trace!(uri = %uri, version, "document change ignored because it is not open"); return; }; let entry = entry.value_mut(); @@ -1354,21 +1607,16 @@ impl LanguageServer for Backend { // format edits can each carry kilobytes). const BULK_CHANGE_THRESHOLD: usize = 8; const BULK_TEXT_BYTES: usize = 32 * 1024; - let bulk = params.content_changes.len() > BULK_CHANGE_THRESHOLD - || (params.content_changes.len() > 1 - && params - .content_changes - .iter() - .map(|c| c.text.len()) - .sum::() - > BULK_TEXT_BYTES); - if bulk && params.content_changes.iter().all(|c| c.range.is_some()) { + let bulk = change_count > BULK_CHANGE_THRESHOLD + || (change_count > 1 && incoming_bytes > BULK_TEXT_BYTES); + if bulk && all_ranged { for change in params.content_changes { convert::apply_change(&mut entry.rope, change.range, &change.text, enc); } entry.text = entry.rope.to_string().into(); entry.parse = Arc::new(analyzer.parse(&entry.text)); entry.version = version; + parse_strategy = "bulk_full_parse"; } else { // Each change applies to the text produced by the previous // one. The parse is kept in lockstep via incremental reparse, @@ -1386,8 +1634,12 @@ impl LanguageServer for Backend { old_end: old_end as usize, new_len: change.text.len(), }; - let (parse, _strategy) = + let (parse, strategy) = analyzer.reparse(&entry.parse, &entry.text, &new_text, edit); + match strategy { + Strategy::Spliced => spliced_count += 1, + Strategy::Full => full_fallback_count += 1, + } entry.parse = Arc::new(parse); entry.text = new_text; } @@ -1396,11 +1648,20 @@ impl LanguageServer for Backend { entry.rope = Rope::from_str(&change.text); entry.text = change.text.into(); entry.parse = Arc::new(analyzer.parse(&entry.text)); + full_replacement = true; } } } entry.version = version; + parse_strategy = if full_replacement { + "full_document_replacement" + } else if full_fallback_count > 0 { + "incremental_full_fallback" + } else { + "incremental_splice" + }; } + text_bytes = entry.text.len(); // Definition names power reference completions and are cheap to // extract. Commit them while the document guard preserves version // order; the expensive index passes wait for the debounce. @@ -1409,13 +1670,26 @@ impl LanguageServer for Backend { idx.set_file(uri.as_str(), defs); } } + tracing::debug!( + uri = %uri, + version, + change_count, + incoming_bytes, + text_bytes, + parse_strategy, + spliced_count, + full_fallback_count, + "document changed" + ); self.schedule_refresh(uri, version); } async fn did_close(&self, params: DidCloseTextDocumentParams) { // Keep the file's symbols in the index (it still exists on disk); just // drop the in-memory buffer. - self.docs.remove(&canonical_uri(params.text_document.uri)); + let uri = canonical_uri(params.text_document.uri); + let removed = self.docs.remove(&uri).is_some(); + tracing::debug!(uri = %uri, removed, "document closed"); } async fn completion(&self, params: CompletionParams) -> Result> { @@ -1531,11 +1805,13 @@ impl LanguageServer for Backend { Arc::::from(markdown) } Ok(Err(error)) => { - tracing::warn!(%error, model = %data.model, "could not render W3D completion preview"); + tracing::debug!(%error, "W3D completion preview render details"); + tracing::warn!("could not render W3D completion preview"); Arc::::from("_Preview unavailable: unsupported or malformed W3D data._") } Err(error) => { - tracing::warn!(%error, model = %data.model, "W3D preview task failed"); + tracing::debug!(%error, "W3D completion preview task details"); + tracing::warn!("W3D preview task failed"); Arc::::from("_Preview unavailable: unsupported or malformed W3D data._") } }; diff --git a/crates/server/src/main.rs b/crates/server/src/main.rs index f9b3e9a..0dfebf3 100644 --- a/crates/server/src/main.rs +++ b/crates/server/src/main.rs @@ -19,9 +19,10 @@ async fn main() -> std::process::ExitCode { // Log to stderr (stdout is reserved for the LSP wire protocol). tracing_subscriber::fmt() .with_writer(std::io::stderr) + .with_ansi(false) .with_env_filter( tracing_subscriber::EnvFilter::try_from_default_env() - .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info")), + .unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("warn")), ) .init(); diff --git a/crates/server/src/scan.rs b/crates/server/src/scan.rs index 5d8cee9..39f4da5 100644 --- a/crates/server/src/scan.rs +++ b/crates/server/src/scan.rs @@ -5,7 +5,7 @@ use std::hash::{Hash, Hasher}; use std::io::{Read, Seek, SeekFrom}; use std::path::{Path, PathBuf}; use std::sync::Arc; -use std::time::UNIX_EPOCH; +use std::time::{Instant, UNIX_EPOCH}; use anyhow::{Context, Result}; use percent_encoding::percent_decode_str; @@ -406,6 +406,7 @@ pub(crate) fn collect_scan_paths_checked(roots: &[PathBuf]) -> Result Result> { let mut out = Vec::new(); + let mut skipped = 0; for root in roots { let root_start = out.len(); if root.is_file() @@ -421,7 +422,11 @@ fn collect_paths(roots: &[PathBuf], checked: bool) -> Result> { let entry = match entry { Ok(entry) => entry, Err(error) if checked => return Err(error.into()), - Err(_) => continue, + Err(error) => { + skipped += 1; + tracing::debug!(root = %root.display(), %error, "workspace walk entry skipped"); + continue; + } }; let path = entry.path(); if !path.is_file() { @@ -464,6 +469,12 @@ fn collect_paths(roots: &[PathBuf], checked: bool) -> Result> { }) }); } + if skipped > 0 { + tracing::warn!( + skipped_count = skipped, + "workspace walk skipped inaccessible entries" + ); + } Ok(out) } @@ -493,28 +504,61 @@ pub(crate) fn scan_with_cache( base_roots: &[PathBuf], progress: &mut impl FnMut(usize, usize), ) -> Vec<(bool, ScanEntry)> { + let started = Instant::now(); let cache_path = index_cache_path(workspace_roots, base_roots); let expected_schema_hash = schema_hash(); - let mut cache = std::fs::read(&cache_path) - .ok() - .and_then(|bytes| serde_json::from_slice::(&bytes).ok()) - .filter(|cache| { - cache.version == INDEX_CACHE_VERSION && cache.schema_hash == expected_schema_hash - }) - .unwrap_or(IndexCache { - version: INDEX_CACHE_VERSION, - schema_hash: expected_schema_hash, - files: HashMap::new(), - }); + let empty_cache = || IndexCache { + version: INDEX_CACHE_VERSION, + schema_hash: expected_schema_hash, + files: HashMap::new(), + }; + let (mut cache, cache_state) = match std::fs::read(&cache_path) { + Err(error) if error.kind() == std::io::ErrorKind::NotFound => (empty_cache(), "absent"), + Err(error) => { + tracing::debug!(path = %cache_path.display(), %error, "index cache could not be read"); + (empty_cache(), "corrupt") + } + Ok(bytes) => match serde_json::from_slice::(&bytes) { + Err(error) => { + tracing::debug!(path = %cache_path.display(), %error, "index cache could not be parsed"); + (empty_cache(), "corrupt") + } + Ok(cache) + if cache.version != INDEX_CACHE_VERSION + || cache.schema_hash != expected_schema_hash => + { + tracing::debug!( + path = %cache_path.display(), + cache_version = cache.version, + expected_version = INDEX_CACHE_VERSION, + "index cache is stale" + ); + (empty_cache(), "stale") + } + Ok(cache) => (cache, "valid"), + }, + }; + let mut discovered_inputs = 0; + let mut fingerprint_failures = 0; + let mut cache_hits = 0; + let mut cache_misses = 0; + let mut scan_failures = 0; let mut seen = HashSet::new(); let mut paths = Vec::new(); for (roots, is_base) in [(base_roots, true), (workspace_roots, false)] { for path in collect_scan_paths(roots) { let key = path_key(&path); if seen.insert(key.clone()) { + discovered_inputs += 1; if let Some(fingerprint) = fingerprint(&path) { paths.push((path, key, fingerprint, is_base)); + } else { + fingerprint_failures += 1; + tracing::debug!( + path = %path.display(), + "workspace input skipped because it could not be fingerprinted" + ); } } } @@ -526,9 +570,20 @@ pub(crate) fn scan_with_cache( for (done, (path, key, fingerprint, is_base)) in paths.into_iter().enumerate() { let entries = match cache.files.remove(&key) { Some(cached) if cached.fingerprint == fingerprint => { + cache_hits += 1; cached.entries.into_iter().map(ScanEntry::from).collect() } - _ => scan_path(analyzer, &path).unwrap_or_default(), + _ => { + cache_misses += 1; + match scan_path(analyzer, &path) { + Ok(entries) => entries, + Err(error) => { + scan_failures += 1; + tracing::debug!(path = %path.display(), %error, "workspace input could not be indexed"); + Vec::new() + } + } + } }; next.insert( key, @@ -545,15 +600,42 @@ pub(crate) fn scan_with_cache( schema_hash: expected_schema_hash, files: next, }; + let mut cache_written = false; if let Some(parent) = cache_path.parent() { if let Err(error) = std::fs::create_dir_all(parent).and_then(|()| { serde_json::to_vec(&cache) .map_err(std::io::Error::other) .and_then(|bytes| std::fs::write(&cache_path, bytes)) }) { - tracing::warn!(%error, path = %cache_path.display(), "could not write asset index cache"); + tracing::debug!(path = %cache_path.display(), %error, "asset index cache write failed"); + tracing::warn!(%error, "could not write asset index cache"); + } else { + cache_written = true; } } + let skipped_count = fingerprint_failures + scan_failures; + if skipped_count > 0 { + tracing::warn!( + skipped_count, + fingerprint_failures, + scan_failures, + "workspace indexing skipped inputs" + ); + } + tracing::debug!( + path = %cache_path.display(), + cache_state, + discovered_inputs, + cache_hits, + cache_misses, + reparsed_files = cache_misses, + fingerprint_failures, + scan_failures, + produced_entries = scanned.len(), + cache_written, + elapsed_ms = started.elapsed().as_millis() as u64, + "workspace scan completed" + ); scanned } diff --git a/crates/server/tests/e2e.py b/crates/server/tests/e2e.py index 7f926c4..577c62a 100644 --- a/crates/server/tests/e2e.py +++ b/crates/server/tests/e2e.py @@ -10,6 +10,7 @@ """ import json import base64 +import os import subprocess import sys import threading @@ -51,6 +52,11 @@ def reader(stream, q: "queue.Queue"): q.put({"_parse_error": str(e)}) +def line_reader(stream, lines): + for line in iter(stream.readline, b""): + lines.append(line.decode("utf-8", "replace").rstrip()) + + def main() -> int: exe = sys.argv[1] @@ -130,13 +136,21 @@ def write_big(path, entries): [exe, "--stdio"], stdin=subprocess.PIPE, stdout=subprocess.PIPE, - stderr=subprocess.DEVNULL, + stderr=subprocess.PIPE, bufsize=0, + env={**os.environ, "RUST_LOG": "zerosyntax_lsp=debug"}, ) q: "queue.Queue" = queue.Queue() threading.Thread(target=reader, args=(proc.stdout, q), daemon=True).start() + stderr_lines = [] + stderr_thread = threading.Thread( + target=line_reader, args=(proc.stderr, stderr_lines), daemon=True + ) + stderr_thread.start() server_requests = [] indexing_begins = [] + indexing_ends = [] + log_messages = [] def send(obj): proc.stdin.write(frame(obj)) @@ -153,6 +167,7 @@ def wait_for(pred, what, timeout=15.0): break if msg is None: break + assert "_parse_error" not in msg, msg if msg.get("method") in { "client/registerCapability", "client/unregisterCapability", @@ -163,6 +178,11 @@ def wait_for(pred, what, timeout=15.0): if (msg.get("method") == "$/progress" and msg.get("params", {}).get("value", {}).get("kind") == "begin"): indexing_begins.append(msg) + if (msg.get("method") == "$/progress" + and msg.get("params", {}).get("value", {}).get("kind") == "end"): + indexing_ends.append(msg) + if msg.get("method") == "window/logMessage": + log_messages.append(msg) if pred(msg): return msg print(f"TIMEOUT waiting for {what}", file=sys.stderr) @@ -212,6 +232,29 @@ def configure(): print("OK: initialize advertised capabilities (incremental sync, utf-16)") send({"jsonrpc": "2.0", "method": "initialized", "params": {}}) + ready = wait_for( + lambda m: m.get("method") == "window/logMessage" + and "language server ready" in m.get("params", {}).get("message", ""), + "startup logging", + ) + assert ready and ready["params"]["type"] == 3, ready + startup_logs = [message["params"]["message"] for message in log_messages] + assert any("initializing v" in message for message in startup_logs), startup_logs + assert any( + "indexing started (reason=startup" in message for message in startup_logs + ), startup_logs + completed = next( + message + for message in startup_logs + if "indexing completed (reason=startup" in message + ) + assert "INI files" in completed and "W3D models" in completed, completed + startup_progress = indexing_ends[0]["params"]["value"]["message"] + assert startup_progress.removesuffix(" indexed") in completed, ( + startup_progress, + completed, + ) + print("OK: startup emits initialization, indexing, and ready logs") # 2) didOpen with a Weapon block: bad bool + unknown field. uri = "file:///test/Weapon.ini" @@ -673,6 +716,13 @@ def latest_burst_diag(message): and m.get("params", {}).get("value", {}).get("kind") == "end", "base-root indexing", ) + reindexed = wait_for( + lambda m: m.get("method") == "window/logMessage" + and "indexing completed (reason=configuration_changed" + in m.get("params", {}).get("message", ""), + "base-root indexing log", + ) + assert reindexed and "audio files" in reindexed["params"]["message"], reindexed assert len(indexing_begins) == progress_before + 1, ( f"expected one base-root scan, got {len(indexing_begins) - progress_before}" ) @@ -849,6 +899,27 @@ def completion_labels(doc_uri, line, character): "custom-schema diagnostics", ) assert "unknown-block" not in [d.get("code") for d in custom["params"]["diagnostics"]] + runtime_settings["schema"]["path"] = str(workspace / "missing-schema.json") + configure() + schema_warning_log = wait_for( + lambda m: m.get("method") == "window/logMessage" + and m.get("params", {}).get("type") == 2 + and "custom schema could not be loaded" in m.get("params", {}).get("message", ""), + "invalid-schema warning log", + ) + schema_warning_popup = wait_for( + lambda m: m.get("method") == "window/showMessage" + and m.get("params", {}).get("type") == 2 + and "built-in schema" in m.get("params", {}).get("message", ""), + "invalid-schema warning popup", + ) + assert schema_warning_log and schema_warning_popup + custom = wait_for( + lambda m: m.get("method") == "textDocument/publishDiagnostics" + and m["params"]["uri"] == custom_uri, + "invalid-schema fallback diagnostics", + ) + assert "unknown-block" in [d.get("code") for d in custom["params"]["diagnostics"]] runtime_settings["schema"]["path"] = "" configure() custom = wait_for( @@ -857,7 +928,7 @@ def completion_labels(doc_uri, line, character): "embedded-schema diagnostics", ) assert "unknown-block" in [d.get("code") for d in custom["params"]["diagnostics"]] - print("OK: schema hot-reload reparses already-open documents") + print("OK: schema hot-reload logs invalid fallback and reparses open documents") runtime_settings["format"]["enable"] = True configure() @@ -882,14 +953,42 @@ def completion_labels(doc_uri, line, character): configure() wait_for(lambda m: m.get("method") == "client/registerCapability", "dynamic formatting re-registration") + wait_for( + lambda m: m.get("method") == "window/logMessage" + and "settings updated (format.enable)" in m.get("params", {}).get("message", ""), + "dynamic formatting settings log", + ) + + send({"jsonrpc": "2.0", "id": 30, "method": "workspace/executeCommand", + "params": {"command": "zerosyntax.rebuildIndexCache", "arguments": []}}) + rebuild_started = wait_for( + lambda m: m.get("method") == "window/logMessage" + and "indexing started (reason=manual_cache_rebuild" + in m.get("params", {}).get("message", ""), + "manual cache rebuild start log", + ) + rebuild_completed = wait_for( + lambda m: m.get("method") == "window/logMessage" + and "indexing completed (reason=manual_cache_rebuild" + in m.get("params", {}).get("message", ""), + "manual cache rebuild completion log", + ) + rebuild = wait_for(lambda m: m.get("id") == 30 and "result" in m, + "manual cache rebuild response") + assert rebuild_started and rebuild_completed and rebuild["result"]["rebuilt"] is True + print("OK: manual cache rebuild logs its reason and completion") requests_before = len(server_requests) progress_before = len(indexing_begins) + logs_before = len(log_messages) configure() import time time.sleep(0.25) while not q.empty(): pending = q.get_nowait() + assert "_parse_error" not in pending, pending + if pending.get("method") == "window/logMessage": + log_messages.append(pending) assert pending.get("method") not in { "client/registerCapability", "client/unregisterCapability" }, pending @@ -897,6 +996,7 @@ def completion_labels(doc_uri, line, character): and pending.get("params", {}).get("value", {}).get("kind") == "begin"), pending assert len(server_requests) == requests_before assert len(indexing_begins) == progress_before + assert len(log_messages) == logs_before print("OK: formatting hot-registers; identical settings are a no-op") # 9) Phase-6 batch 2: semanticTokens delta, formatting, code actions. @@ -980,6 +1080,17 @@ def pos_off(text, pos): # ASCII docs: utf-16 char == byte offset proc.wait(timeout=5) except Exception: proc.kill() + stderr_thread.join(timeout=2) + developer_logs = "\n".join(stderr_lines) + assert "workspace scan completed" in developer_logs, developer_logs + assert "document changed" in developer_logs, developer_logs + assert "document diagnostics published" in developer_logs, developer_logs + assert "parse_strategy=" in developer_logs, developer_logs + assert uri in developer_logs, developer_logs + assert workspace.name in developer_logs, developer_logs + assert "ScaleWeaponSpeed = Maybe" not in developer_logs, developer_logs + assert "Bogus = 1" not in developer_logs, developer_logs + print("OK: RUST_LOG debug records decisions and paths without document contents") # 10) a default-initialized server (no initializationOptions) must not # advertise formatting and must answer the request with null. diff --git a/docs/language-server.md b/docs/language-server.md index 06e90af..045b024 100644 --- a/docs/language-server.md +++ b/docs/language-server.md @@ -15,6 +15,38 @@ over stdio. The server writes protocol messages to stdout, so clients must launch it using stdio rather than a TCP port. +## Logging and troubleshooting + +The server sends concise lifecycle, configuration, indexing, and command +outcomes through LSP `window/logMessage`. In VS Code these appear under +**Output → ZeroSyntax v2 Language Server** at their proper Info, Warning, or +Error level. Long scans also keep their existing status-bar progress report. + +Developer detail uses structured `tracing` records on stderr and is controlled +with the standard `RUST_LOG` filter. The default is `warn`; enable server Debug +or Trace records before starting the editor: + +```powershell +$env:RUST_LOG = "zerosyntax_lsp=debug" # or zerosyntax_lsp=trace +code . +``` + +```sh +RUST_LOG=zerosyntax_lsp=debug code . # or zerosyntax_lsp=trace +``` + +The same filter works when launching `zerosyntax-lsp --stdio` from another LSP +client. Debug records include paths, document URIs, versions, timings, cache +decisions, parse strategies, and diagnostic counts. Info logs contain counts +instead of paths. Source text, INI values, completion contents, and document +excerpts are never logged. + +`zerosyntax.trace.server = verbose` is separate: it records the LSP requests +and responses themselves, while `RUST_LOG` explains internal server decisions. +Raw stderr can be decorated as an error by VS Code's language-client transport; +the level printed inside each tracing record is authoritative. Stdout is always +reserved for LSP framing and must never receive logs. + ## Command-line diagnostics Use the `check` subcommand to run the same parser, schema, workspace index, and diff --git a/editors/vscode/README.md b/editors/vscode/README.md index 20398df..2c39db3 100644 --- a/editors/vscode/README.md +++ b/editors/vscode/README.md @@ -88,8 +88,11 @@ Use the language selector in VS Code's status bar to change an individual file. - If map references are reported as missing, configure `zerosyntax.baseIniRoots` and check that the paths point to the required INI folders or `.big` archives. -- For detailed logs, set `zerosyntax.trace.server` to `messages` or `verbose`, - reproduce the problem, then open **Output → ZeroSyntax v2 Language Server**. +- Start with the operational log under **Output → ZeroSyntax v2 Language + Server**. Set `zerosyntax.trace.server` to `verbose` for protocol traffic. + For internal cache, parse, and diagnostic decisions, launch VS Code with + `RUST_LOG=zerosyntax_lsp=debug` (PowerShell: + `$env:RUST_LOG = "zerosyntax_lsp=debug"; code .`). Report reproducible problems through [GitHub Issues](https://github.com/ViTeXFTW/ZeroSyntaxV2/issues) with a minimal