Add some logging messages

crates/red_knot/docs/tracing.md

@@ -47,6 +47,20 @@ RED_KNOT_LOG="red_knot_python_semantic::types"
 
 Note: Ensure that you use `-vvv` to see tracing spans.
 
+#### Show messages for a single file
+
+Shows all messages that are inside of a span for a specific file.
+
+```bash
+RED_KNOT_LOG=red_knot[{file=/home/micha/astral/test/x.py}]=trace
+```
+
+**Note**: Tracing still shows all spans because tracing can't know at the time of entering the span
+whether one if its children has the file `x.py`.
+
+**Note**: Salsa currently logs the entire memoized values. In our case, the source text and parsed AST.
+This very quickly leads to extremely long outputs.
+
 ## Tracing and Salsa
 
 Be mindful about using `tracing` in Salsa queries, especially when using `warn` or `error` because it isn't guaranteed

crates/red_knot/src/logging.rs

@@ -42,16 +42,16 @@ impl Verbosity {
 
 #[derive(Debug, Copy, Clone, Eq, PartialEq, Ord, PartialOrd)]
 pub(crate) enum VerbosityLevel {
-    /// Default output level. Only shows ruff and red knot events up to the [`LogLevel::Warn`].
+    /// Default output level. Only shows Ruff and Red Knot events up to the [`WARN`](tracing::Level::WARN).
     Default,
 
-    /// Enables verbose output. Emits ruff and red knot events up to the [`LogLevel::Info`]
+    /// Enables verbose output. Emits Ruff and Red Knot events up to the [`INFO`](tracing::Level::INFO)
     Verbose,
 
-    /// Enables a more verbose tracing format and emits ruff and red_knot events up to [`LogLevel::Debug`] Corresponds to `-vv`
+    /// Enables a more verbose tracing format and emits Ruff and Red Knot events up to [`DEBUG`](tracing::Level::DEBUG) Corresponds to `-vv`
     ExtraVerbose,
 
-    /// Enables all tracing events and uses a tree like output format. Corresponds to `-vvv`.
+    /// Enables all tracing events and uses a tree-like output format. Corresponds to `-vvv`.
     Trace,
 }
 
@@ -145,6 +145,7 @@ pub(crate) fn setup_tracing(level: VerbosityLevel) -> anyhow::Result<TracingGuar
     })
 }
 
+#[allow(clippy::type_complexity)]
 fn setup_profile<S>() -> (
     Option<tracing_flame::FlameLayer<S, BufWriter<File>>>,
     Option<tracing_flame::FlushGuard<BufWriter<File>>>,
@@ -208,7 +209,7 @@ where
                 let formatted_level = level.to_string();
                 match *level {
                     tracing::Level::TRACE => {
-                        write!(writer, "{} ", formatted_level.purple().bold())?
+                        write!(writer, "{} ", formatted_level.purple().bold())?;
                     }
                     tracing::Level::DEBUG => write!(writer, "{} ", formatted_level.blue().bold())?,
                     tracing::Level::INFO => write!(writer, "{} ", formatted_level.green().bold())?,

crates/red_knot/src/main.rs

@@ -13,7 +13,7 @@ use ruff_db::program::{ProgramSettings, SearchPathSettings};
 use ruff_db::system::{OsSystem, System, SystemPathBuf};
 use target_version::TargetVersion;
 
-use crate::logging::{setup_tracing, Verbosity, VerbosityLevel};
+use crate::logging::{setup_tracing, Verbosity};
 
 mod logging;
 mod target_version;
@@ -155,7 +155,7 @@ pub fn main() -> anyhow::Result<()> {
     //   cache and load the cache if it exists.
     let mut db = RootDatabase::new(workspace_metadata, program_settings, system);
 
-    let (main_loop, main_loop_cancellation_token) = MainLoop::new(verbosity);
+    let (main_loop, main_loop_cancellation_token) = MainLoop::new();
 
     // Listen to Ctrl+C and abort the watch mode.
     let main_loop_cancellation_token = Mutex::new(Some(main_loop_cancellation_token));
@@ -173,6 +173,8 @@ pub fn main() -> anyhow::Result<()> {
         main_loop.run(&mut db);
     };
 
+    tracing::trace!("Counts for entire CLI run :\n{}", countme::get_all());
+
     std::mem::forget(db);
 
     Ok(())
@@ -187,53 +189,52 @@ struct MainLoop {
 
     /// The file system watcher, if running in watch mode.
     watcher: Option<WorkspaceWatcher>,
-
-    verbosity: VerbosityLevel,
 }
 
 impl MainLoop {
-    fn new(verbosity: VerbosityLevel) -> (Self, MainLoopCancellationToken) {
+    fn new() -> (Self, MainLoopCancellationToken) {
         let (sender, receiver) = crossbeam_channel::bounded(10);
 
         (
             Self {
                 sender: sender.clone(),
                 receiver,
                 watcher: None,
-                verbosity,
             },
             MainLoopCancellationToken { sender },
         )
     }
 
     fn watch(mut self, db: &mut RootDatabase) -> anyhow::Result<()> {
+        tracing::debug!("Starting watch mode");
         let sender = self.sender.clone();
         let watcher = watch::directory_watcher(move |event| {
             sender.send(MainLoopMessage::ApplyChanges(event)).unwrap();
         })?;
 
         self.watcher = Some(WorkspaceWatcher::new(watcher, db));
 
-        let is_trace = self.verbosity.is_trace();
         self.run(db);
 
-        if is_trace {
-            eprintln!("Exit");
-            eprintln!("{}", countme::get_all());
-        }
-
         Ok(())
     }
 
-    #[allow(clippy::print_stderr)]
     fn run(mut self, db: &mut RootDatabase) {
-        // Schedule the first check.
         self.sender.send(MainLoopMessage::CheckWorkspace).unwrap();
+
+        self.main_loop(db);
+
+        tracing::debug!("Exiting main loop");
+    }
+
+    #[allow(clippy::print_stderr)]
+    fn main_loop(&mut self, db: &mut RootDatabase) {
+        // Schedule the first check.
+        tracing::debug!("Starting main loop");
+
         let mut revision = 0usize;
 
         while let Ok(message) = self.receiver.recv() {
-            tracing::trace!("Main Loop: Tick");
-
             match message {
                 MainLoopMessage::CheckWorkspace => {
                     let db = db.snapshot();
@@ -257,15 +258,15 @@ impl MainLoop {
                 } => {
                     if check_revision == revision {
                         eprintln!("{}", result.join("\n"));
-
-                        if self.verbosity.is_trace() {
-                            eprintln!("{}", countme::get_all());
-                        }
+                    } else {
+                        tracing::debug!("Discarding check result for outdated revision: current: {revision}, result revision: {check_revision}");
                     }
 
                     if self.watcher.is_none() {
                         return;
                     }
+
+                    tracing::trace!("Counts after last check:\n{}", countme::get_all());
                 }
 
                 MainLoopMessage::ApplyChanges(changes) => {
@@ -281,6 +282,8 @@ impl MainLoop {
                     return;
                 }
             }
+
+            tracing::debug!("Waiting for next main loop message.");
         }
     }
 }

crates/red_knot_module_resolver/src/resolver.rs

@@ -32,10 +32,18 @@ pub(crate) fn resolve_module_query<'db>(
     let name = module_name.name(db);
     let _span = tracing::trace_span!("resolve_module", %name).entered();
 
-    let (search_path, module_file, kind) = resolve_name(db, name)?;
+    let Some((search_path, module_file, kind)) = resolve_name(db, name) else {
+        tracing::debug!("Module '{name}' not found in the search paths.");
+        return None;
+    };
 
     let module = Module::new(name.clone(), kind, search_path, module_file);
 
+    tracing::debug!(
+        "Resolved module '{name}' to '{path}'.",
+        path = module_file.path(db)
+    );
+
     Some(module)
 }
 

crates/red_knot_python_semantic/src/semantic_index.rs

@@ -34,7 +34,7 @@ type SymbolMap = hashbrown::HashMap<ScopedSymbolId, (), ()>;
 /// Prefer using [`symbol_table`] when working with symbols from a single scope.
 #[salsa::tracked(return_ref, no_eq)]
 pub(crate) fn semantic_index(db: &dyn Db, file: File) -> SemanticIndex<'_> {
-    let _span = tracing::trace_span!("semantic_index", file=?file.path(db)).entered();
+    let _span = tracing::trace_span!("semantic_index", file = %file.path(db)).entered();
 
     let parsed = parsed_module(db.upcast(), file);
 
@@ -50,7 +50,7 @@ pub(crate) fn semantic_index(db: &dyn Db, file: File) -> SemanticIndex<'_> {
 pub(crate) fn symbol_table<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> Arc<SymbolTable> {
     let file = scope.file(db);
     let _span =
-        tracing::trace_span!("symbol_table", scope=?scope.as_id(), file=?file.path(db)).entered();
+        tracing::trace_span!("symbol_table", scope=?scope.as_id(), file=%file.path(db)).entered();
     let index = semantic_index(db, file);
 
     index.symbol_table(scope.file_scope_id(db))
@@ -65,7 +65,7 @@ pub(crate) fn symbol_table<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> Arc<Sym
 pub(crate) fn use_def_map<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> Arc<UseDefMap<'db>> {
     let file = scope.file(db);
     let _span =
-        tracing::trace_span!("use_def_map", scope=?scope.as_id(), file=?file.path(db)).entered();
+        tracing::trace_span!("use_def_map", scope=?scope.as_id(), file=%file.path(db)).entered();
     let index = semantic_index(db, file);
 
     index.use_def_map(scope.file_scope_id(db))
@@ -74,7 +74,7 @@ pub(crate) fn use_def_map<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> Arc<UseD
 /// Returns the module global scope of `file`.
 #[salsa::tracked]
 pub(crate) fn global_scope(db: &dyn Db, file: File) -> ScopeId<'_> {
-    let _span = tracing::trace_span!("global_scope", file=?file.path(db)).entered();
+    let _span = tracing::trace_span!("global_scope", file = %file.path(db)).entered();
 
     FileScopeId::global().to_scope_id(db, file)
 }

crates/red_knot_python_semantic/src/types/infer.rs

@@ -50,7 +50,7 @@ use crate::Db;
 pub(crate) fn infer_scope_types<'db>(db: &'db dyn Db, scope: ScopeId<'db>) -> TypeInference<'db> {
     let file = scope.file(db);
     let _span =
-        tracing::trace_span!("infer_scope_types", scope=?scope.as_id(), file=?file.path(db))
+        tracing::trace_span!("infer_scope_types", scope=?scope.as_id(), file=%file.path(db))
             .entered();
 
     // Using the index here is fine because the code below depends on the AST anyway.
@@ -83,7 +83,7 @@ pub(crate) fn infer_definition_types<'db>(
     let _span = tracing::trace_span!(
         "infer_definition_types",
         definition = ?definition.as_id(),
-        file = ?file.path(db)
+        file = %file.path(db)
     )
     .entered();
 
@@ -104,7 +104,7 @@ pub(crate) fn infer_expression_types<'db>(
 ) -> TypeInference<'db> {
     let file = expression.file(db);
     let _span =
-        tracing::trace_span!("infer_expression_types", expression=?expression.as_id(), file=?file.path(db))
+        tracing::trace_span!("infer_expression_types", expression=?expression.as_id(), file=%file.path(db))
             .entered();
 
     let index = semantic_index(db, file);

crates/red_knot_workspace/src/lint.rs

@@ -2,7 +2,7 @@ use std::cell::RefCell;
 use std::ops::Deref;
 use std::time::Duration;
 
-use tracing::trace_span;
+use tracing::debug_span;
 
 use red_knot_module_resolver::ModuleName;
 use red_knot_python_semantic::types::Type;
@@ -76,7 +76,7 @@ fn lint_lines(source: &str, diagnostics: &mut Vec<String>) {
 #[allow(unreachable_pub)]
 #[salsa::tracked(return_ref)]
 pub fn lint_semantic(db: &dyn Db, file_id: File) -> Diagnostics {
-    let _span = trace_span!("lint_semantic", file=?file_id.path(db)).entered();
+    let _span = debug_span!("lint_semantic", file=%file_id.path(db)).entered();
 
     let source = source_text(db.upcast(), file_id);
     let parsed = parsed_module(db.upcast(), file_id);

crates/red_knot_workspace/src/site_packages.rs

@@ -117,6 +117,10 @@ fn site_packages_dir_from_sys_prefix(
 
         let site_packages_candidate = path.join("site-packages");
         if system.is_directory(&site_packages_candidate) {
+            tracing::debug!(
+                "Resoled site-packages directory: {}",
+                site_packages_candidate
+            );
             return Ok(site_packages_candidate);
         }
     }

crates/red_knot_workspace/src/watch/watcher.rs

@@ -109,13 +109,17 @@ struct WatcherInner {
 impl Watcher {
     /// Sets up file watching for `path`.
     pub fn watch(&mut self, path: &SystemPath) -> notify::Result<()> {
+        tracing::debug!("Watching path: {path}.");
+
         self.inner_mut()
             .watcher
             .watch(path.as_std_path(), RecursiveMode::Recursive)
     }
 
     /// Stops file watching for `path`.
     pub fn unwatch(&mut self, path: &SystemPath) -> notify::Result<()> {
+        tracing::debug!("Unwatching path: {path}.");
+
         self.inner_mut().watcher.unwatch(path.as_std_path())
     }
 
@@ -125,6 +129,7 @@ impl Watcher {
     ///
     /// The call blocks until the watcher has stopped.
     pub fn stop(mut self) {
+        tracing::debug!("Stop file watcher");
         self.set_stop();
     }
 
@@ -173,8 +178,8 @@ struct Debouncer {
 }
 
 impl Debouncer {
-    #[tracing::instrument(level = "trace", skip(self))]
     fn add_result(&mut self, result: notify::Result<notify::Event>) {
+        tracing::trace!("Handling file watcher event: {result:?}.");
         match result {
             Ok(event) => self.add_event(event),
             Err(error) => self.add_error(error),

crates/red_knot_workspace/src/workspace.rs

@@ -176,6 +176,8 @@ impl Workspace {
     /// Checks all open files in the workspace and its dependencies.
     #[tracing::instrument(level = "debug", skip_all)]
     pub fn check(self, db: &dyn Db) -> Vec<String> {
+        tracing::debug!("Checking workspace");
+
         let mut result = Vec::new();
 
         if let Some(open_files) = self.open_files(db) {
@@ -274,6 +276,8 @@ impl Package {
 
     #[tracing::instrument(level = "debug", skip(db))]
     pub(crate) fn check(self, db: &dyn Db) -> Vec<String> {
+        tracing::debug!("Checking package {}", self.root(db));
+
         let mut result = Vec::new();
         for file in &self.files(db).read() {
             let diagnostics = check_file(db, file);
@@ -327,6 +331,10 @@ impl Package {
 }
 
 pub(super) fn check_file(db: &dyn Db, file: File) -> Diagnostics {
+    let path = file.path(db);
+    let _span = tracing::debug_span!("check_file", file=%path).entered();
+    tracing::debug!("Checking file {path}");
+
     let mut diagnostics = Vec::new();
     diagnostics.extend_from_slice(lint_syntax(db, file));
     diagnostics.extend_from_slice(lint_semantic(db, file));

crates/ruff_db/src/files/path.rs

@@ -2,6 +2,7 @@ use crate::files::{system_path_to_file, vendored_path_to_file, File};
 use crate::system::{SystemPath, SystemPathBuf, SystemVirtualPath, SystemVirtualPathBuf};
 use crate::vendored::{VendoredPath, VendoredPathBuf};
 use crate::Db;
+use std::fmt::{Display, Formatter};
 
 /// Path to a file.
 ///
@@ -209,3 +210,13 @@ impl PartialEq<FilePath> for VendoredPathBuf {
         other == self
     }
 }
+
+impl Display for FilePath {
+    fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+        match self {
+            FilePath::System(path) => std::fmt::Display::fmt(path, f),
+            FilePath::SystemVirtual(path) => std::fmt::Display::fmt(path, f),
+            FilePath::Vendored(path) => std::fmt::Display::fmt(path, f),
+        }
+    }
+}

crates/ruff_db/src/parsed.rs

@@ -22,7 +22,7 @@ use crate::Db;
 /// for determining if a query result is unchanged.
 #[salsa::tracked(return_ref, no_eq)]
 pub fn parsed_module(db: &dyn Db, file: File) -> ParsedModule {
-    let _span = tracing::trace_span!("parsed_module", file = ?file.path(db)).entered();
+    let _span = tracing::trace_span!("parsed_module", file = %file.path(db)).entered();
 
     let source = source_text(db, file);
     let path = file.path(db);

crates/ruff_db/src/source.rs

@@ -14,7 +14,7 @@ use crate::Db;
 #[salsa::tracked]
 pub fn source_text(db: &dyn Db, file: File) -> SourceText {
     let path = file.path(db);
-    let _span = tracing::trace_span!("source_text", file=?path).entered();
+    let _span = tracing::trace_span!("source_text", file = %path).entered();
 
     let is_notebook = match path {
         FilePath::System(system) => system.extension().is_some_and(|extension| {