Add parser tracing, fix 629 (#638)

Cargo.lock

@@ -841,6 +841,7 @@ dependencies = [
  "crossterm_winapi",
  "ctrlc",
  "dialoguer",
+ "log",
  "miette",
  "nu-ansi-term",
  "nu-cli",
@@ -859,10 +860,24 @@ dependencies = [
  "nu_plugin_gstat",
  "nu_plugin_inc",
  "pretty_assertions",
+ "pretty_env_logger",
  "reedline",
  "tempfile",
 ]
 
+[[package]]
+name = "env_logger"
+version = "0.7.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36"
+dependencies = [
+ "atty",
+ "humantime",
+ "log",
+ "regex",
+ "termcolor",
+]
+
 [[package]]
 name = "erased-serde"
 version = "0.3.16"
@@ -1166,6 +1181,15 @@ version = "0.3.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "e9025058dae765dee5070ec375f591e2ba14638c63feff74f13805a72e523163"
 
+[[package]]
+name = "humantime"
+version = "1.3.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f"
+dependencies = [
+ "quick-error",
+]
+
 [[package]]
 name = "ical"
 version = "0.7.0"
@@ -1672,6 +1696,7 @@ dependencies = [
 name = "nu-cli"
 version = "0.1.0"
 dependencies = [
+ "log",
  "miette",
  "nu-ansi-term",
  "nu-color-config",
@@ -1787,6 +1812,7 @@ dependencies = [
 name = "nu-parser"
 version = "0.1.0"
 dependencies = [
+ "log",
  "miette",
  "nu-path",
  "nu-plugin",
@@ -2382,6 +2408,16 @@ dependencies = [
  "output_vt100",
 ]
 
+[[package]]
+name = "pretty_env_logger"
+version = "0.4.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d"
+dependencies = [
+ "env_logger",
+ "log",
+]
+
 [[package]]
 name = "prettytable-rs"
 version = "0.8.0"
@@ -2405,6 +2441,12 @@ dependencies = [
  "unicode-xid",
 ]
 
+[[package]]
+name = "quick-error"
+version = "1.2.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0"
+
 [[package]]
 name = "quick-xml"
 version = "0.19.0"
@@ -3063,6 +3105,15 @@ dependencies = [
  "winapi",
 ]
 
+[[package]]
+name = "termcolor"
+version = "1.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4"
+dependencies = [
+ "winapi-util",
+]
+
 [[package]]
 name = "terminal_size"
 version = "0.1.17"

Cargo.toml

@@ -40,6 +40,8 @@ nu-color-config = { path = "./crates/nu-color-config" }
 miette = "3.0.0"
 ctrlc = "3.2.1"
 crossterm_winapi = "0.9.0"
+log = "0.4"
+pretty_env_logger = "0.4.0"
 # mimalloc = { version = "*", default-features = false }
 
 

crates/nu-cli/Cargo.toml

@@ -15,3 +15,4 @@ nu-color-config = { path = "../nu-color-config" }
 miette = { version = "3.0.0", features = ["fancy"] }
 thiserror = "1.0.29"
 reedline = { git = "https://github.com/nushell/reedline", branch = "main" }
+log = "0.4"

crates/nu-cli/src/syntax_highlight.rs

@@ -1,3 +1,4 @@
+use log::trace;
 use nu_ansi_term::Style;
 use nu_color_config::get_shape_color;
 use nu_parser::{flatten_block, parse, FlatShape};
@@ -12,6 +13,8 @@ pub struct NuHighlighter {
 
 impl Highlighter for NuHighlighter {
     fn highlight(&self, line: &str) -> StyledText {
+        trace!("highlighting: {}", line);
+
         let (shapes, global_span_offset) = {
             let mut working_set = StateWorkingSet::new(&self.engine_state);
             let (block, _) = parse(&mut working_set, None, line.as_bytes(), false);

crates/nu-parser/Cargo.toml

@@ -10,6 +10,7 @@ serde_json = "1.0"
 nu-path = {path = "../nu-path"}
 nu-protocol = { path = "../nu-protocol"}
 nu-plugin = { path = "../nu-plugin", optional = true }
+log = "0.4"
 
 [features]
 plugin = ["nu-plugin"]

crates/nu-parser/src/parser.rs

@@ -20,6 +20,7 @@ use crate::parse_keywords::{
     parse_alias, parse_def, parse_def_predecl, parse_hide, parse_let, parse_module, parse_use,
 };
 
+use log::trace;
 use std::collections::HashSet;
 
 #[cfg(feature = "plugin")]
@@ -417,12 +418,15 @@ pub fn parse_multispan_value(
 
     match shape {
         SyntaxShape::VarWithOptType => {
+            trace!("parsing: var with opt type");
+
             let (arg, err) = parse_var_with_opt_type(working_set, spans, spans_idx);
             error = error.or(err);
 
             (arg, error)
         }
         SyntaxShape::RowCondition => {
+            trace!("parsing: row condition");
             let (arg, err) = parse_row_condition(working_set, &spans[*spans_idx..]);
             error = error.or(err);
             *spans_idx = spans.len() - 1;
@@ -430,6 +434,8 @@ pub fn parse_multispan_value(
             (arg, error)
         }
         SyntaxShape::Expression => {
+            trace!("parsing: expression");
+
             let (arg, err) = parse_expression(working_set, &spans[*spans_idx..], true);
             error = error.or(err);
             *spans_idx = spans.len() - 1;
@@ -437,6 +443,11 @@ pub fn parse_multispan_value(
             (arg, error)
         }
         SyntaxShape::Keyword(keyword, arg) => {
+            trace!(
+                "parsing: keyword({}) {:?}",
+                String::from_utf8_lossy(keyword),
+                arg
+            );
             let arg_span = spans[*spans_idx];
 
             let arg_contents = working_set.get_span_contents(arg_span);
@@ -507,6 +518,8 @@ pub fn parse_internal_call(
     spans: &[Span],
     decl_id: usize,
 ) -> (Box<Call>, Option<ParseError>) {
+    trace!("parsing: internal call (decl id: {})", decl_id);
+
     let mut error = None;
 
     let mut call = Call::new();
@@ -657,6 +670,8 @@ pub fn parse_call(
     expand_aliases: bool,
     head: Span,
 ) -> (Expression, Option<ParseError>) {
+    trace!("parsing: call");
+
     if spans.is_empty() {
         return (
             garbage(head),
@@ -686,6 +701,8 @@ pub fn parse_call(
         if expand_aliases {
             // If the word is an alias, expand it and re-parse the expression
             if let Some(expansion) = working_set.find_alias(name) {
+                trace!("expanding alias");
+
                 let orig_span = spans[pos];
                 let mut new_spans: Vec<Span> = vec![];
                 new_spans.extend(&spans[0..pos]);
@@ -745,6 +762,8 @@ pub fn parse_call(
             let test_equal = working_set.get_span_contents(spans[1]);
 
             if test_equal == [b'='] {
+                trace!("incomplete statement");
+
                 return (
                     garbage(span(spans)),
                     Some(ParseError::UnknownState(
@@ -755,6 +774,8 @@ pub fn parse_call(
             }
         }
 
+        trace!("parsing: internal call");
+
         // parse internal command
         let (call, err) = parse_internal_call(
             working_set,
@@ -774,12 +795,16 @@ pub fn parse_call(
     } else {
         // We might be parsing left-unbounded range ("..10")
         let bytes = working_set.get_span_contents(spans[0]);
+        trace!("parsing: range {:?} ", bytes);
         if let (Some(b'.'), Some(b'.')) = (bytes.get(0), bytes.get(1)) {
+            trace!("-- found leading range indicator");
             let (range_expr, range_err) = parse_range(working_set, spans[0]);
             if range_err.is_none() {
+                trace!("-- successfully parsed range");
                 return (range_expr, range_err);
             }
         }
+        trace!("parsing: external call");
 
         // Otherwise, try external command
         parse_external_call(working_set, spans)
@@ -904,6 +929,8 @@ pub fn parse_range(
     working_set: &mut StateWorkingSet,
     span: Span,
 ) -> (Expression, Option<ParseError>) {
+    trace!("parsing: range");
+
     // Range follows the following syntax: [<from>][<next_operator><next>]<range_operator>[<to>]
     //   where <next_operator> is ".."
     //   and  <range_operator> is ".." or "..<"
@@ -994,6 +1021,8 @@ pub fn parse_range(
         }
     };
 
+    trace!("-- from: {:?} to: {:?}", from, to);
+
     if let (None, None) = (&from, &to) {
         return (
             garbage(span),
@@ -1352,6 +1381,8 @@ pub fn parse_full_cell_path(
     if let Some(head) = tokens.peek() {
         let bytes = working_set.get_span_contents(head.span);
         let (head, expect_dot) = if bytes.starts_with(b"(") {
+            trace!("parsing: paren-head of full cell path");
+
             let head_span = head.span;
             let mut start = head.span.start;
             let mut end = head.span.end;
@@ -1392,6 +1423,8 @@ pub fn parse_full_cell_path(
                 true,
             )
         } else if bytes.starts_with(b"[") {
+            trace!("parsing: table head of full cell path");
+
             let (output, err) = parse_table_expression(working_set, head.span);
             error = error.or(err);
 
@@ -1399,6 +1432,7 @@ pub fn parse_full_cell_path(
 
             (output, true)
         } else if bytes.starts_with(b"{") {
+            trace!("parsing: record head of full cell path");
             let (output, err) = parse_record(working_set, head.span);
             error = error.or(err);
 
@@ -1406,6 +1440,8 @@ pub fn parse_full_cell_path(
 
             (output, true)
         } else if bytes.starts_with(b"$") {
+            trace!("parsing: $variable head of full cell path");
+
             let (out, err) = parse_variable_expr(working_set, head.span);
             error = error.or(err);
 
@@ -1469,10 +1505,13 @@ pub fn parse_filepath(
 ) -> (Expression, Option<ParseError>) {
     let bytes = working_set.get_span_contents(span);
     let bytes = trim_quotes(bytes);
+    trace!("parsing: filepath");
 
     if let Ok(token) = String::from_utf8(bytes.into()) {
         let filepath = nu_path::expand_path(token);
         let filepath = filepath.to_string_lossy().to_string();
+        trace!("-- found {}", filepath);
+
         (
             Expression {
                 expr: Expr::Filepath(filepath),
@@ -1495,6 +1534,8 @@ pub fn parse_duration(
     working_set: &mut StateWorkingSet,
     span: Span,
 ) -> (Expression, Option<ParseError>) {
+    trace!("parsing: duration");
+
     fn parse_decimal_str_to_number(decimal: &str) -> Option<i64> {
         let string_to_parse = format!("0.{}", decimal);
         if let Ok(x) = string_to_parse.parse::<f64>() {
@@ -1547,6 +1588,8 @@ pub fn parse_duration(
         };
 
         if let Some(x) = value {
+            trace!("-- found {} {:?}", x, unit_to_use);
+
             let lhs_span = Span::new(span.start, span.start + lhs.len());
             let unit_span = Span::new(span.start + lhs.len(), span.end);
             return (
@@ -1587,6 +1630,8 @@ pub fn parse_filesize(
     working_set: &mut StateWorkingSet,
     span: Span,
 ) -> (Expression, Option<ParseError>) {
+    trace!("parsing: duration");
+
     fn parse_decimal_str_to_number(decimal: &str) -> Option<i64> {
         let string_to_parse = format!("0.{}", decimal);
         if let Ok(x) = string_to_parse.parse::<f64>() {
@@ -1642,6 +1687,8 @@ pub fn parse_filesize(
         };
 
         if let Some(x) = value {
+            trace!("-- found {} {:?}", x, unit_to_use);
+
             let lhs_span = Span::new(span.start, span.start + lhs.len());
             let unit_span = Span::new(span.start + lhs.len(), span.end);
             return (
@@ -1681,10 +1728,14 @@ pub fn parse_glob_pattern(
     working_set: &mut StateWorkingSet,
     span: Span,
 ) -> (Expression, Option<ParseError>) {
+    trace!("parsing: glob pattern");
+
     let bytes = working_set.get_span_contents(span);
     let bytes = trim_quotes(bytes);
 
     if let Ok(token) = String::from_utf8(bytes.into()) {
+        trace!("-- found {}", token);
+
         let filepath = nu_path::expand_path(token);
         let filepath = filepath.to_string_lossy().to_string();
 
@@ -1709,10 +1760,14 @@ pub fn parse_string(
     working_set: &mut StateWorkingSet,
     span: Span,
 ) -> (Expression, Option<ParseError>) {
+    trace!("parsing: string");
+
     let bytes = working_set.get_span_contents(span);
     let bytes = trim_quotes(bytes);
 
     if let Ok(token) = String::from_utf8(bytes.into()) {
+        trace!("-- found {}", token);
+
         (
             Expression {
                 expr: Expr::String(token),
@@ -1734,6 +1789,8 @@ pub fn parse_string_strict(
     working_set: &mut StateWorkingSet,
     span: Span,
 ) -> (Expression, Option<ParseError>) {
+    trace!("parsing: string, with required delimiters");
+
     let bytes = working_set.get_span_contents(span);
     let (bytes, quoted) = if (bytes.starts_with(b"\"") && bytes.ends_with(b"\"") && bytes.len() > 1)
         || (bytes.starts_with(b"\'") && bytes.ends_with(b"\'") && bytes.len() > 1)
@@ -1744,6 +1801,8 @@ pub fn parse_string_strict(
     };
 
     if let Ok(token) = String::from_utf8(bytes.into()) {
+        trace!("-- found {}", token);
+
         if quoted {
             (
                 Expression {
@@ -2621,6 +2680,8 @@ pub fn parse_block_expression(
     shape: &SyntaxShape,
     span: Span,
 ) -> (Expression, Option<ParseError>) {
+    trace!("parsing: block expression");
+
     let bytes = working_set.get_span_contents(span);
     let mut error = None;
 
@@ -2768,16 +2829,23 @@ pub fn parse_value(
     // which might result in a value that fits other shapes (and require the variable to already be
     // declared)
     if shape == &SyntaxShape::Variable {
+        trace!("parsing: variable");
+
         return parse_variable_expr(working_set, span);
     } else if bytes.starts_with(b"$") {
+        trace!("parsing: dollar expression");
+
         return parse_dollar_expr(working_set, span);
     } else if bytes.starts_with(b"(") {
+        trace!("parsing: range or full path");
+
         if let (expr, None) = parse_range(working_set, span) {
             return (expr, None);
         } else {
             return parse_full_cell_path(working_set, None, span);
         }
     } else if bytes.starts_with(b"{") {
+        trace!("parsing: block or full path");
         if !matches!(shape, SyntaxShape::Block(..)) {
             if let (expr, None) = parse_full_cell_path(working_set, None, span) {
                 return (expr, None);
@@ -2822,6 +2890,8 @@ pub fn parse_value(
         SyntaxShape::String => parse_string(working_set, span),
         SyntaxShape::Block(_) => {
             if bytes.starts_with(b"{") {
+                trace!("parsing value as a block expression");
+
                 parse_block_expression(working_set, shape, span)
             } else {
                 (
@@ -3347,6 +3417,8 @@ pub fn parse_block(
     lite_block: &LiteBlock,
     scoped: bool,
 ) -> (Block, Option<ParseError>) {
+    trace!("parsing block: {:?}", lite_block);
+
     if scoped {
         working_set.enter_scope();
     }
@@ -3667,6 +3739,8 @@ pub fn parse(
     contents: &[u8],
     scoped: bool,
 ) -> (Block, Option<ParseError>) {
+    trace!("starting top-level parse");
+
     let mut error = None;
 
     let span_offset = working_set.next_span_start();

crates/nu-protocol/src/config.rs

@@ -53,6 +53,7 @@ pub struct Config {
     pub env_conversions: HashMap<String, EnvConversion>,
     pub edit_mode: String,
     pub max_history_size: i64,
+    pub log_level: String,
 }
 
 impl Default for Config {
@@ -71,6 +72,7 @@ impl Default for Config {
             env_conversions: HashMap::new(), // TODO: Add default conversoins
             edit_mode: "emacs".into(),
             max_history_size: 1000,
+            log_level: String::new(),
         }
     }
 }
@@ -186,6 +188,9 @@ impl Value {
                 "max_history_size" => {
                     config.max_history_size = value.as_i64()?;
                 }
+                "log_level" => {
+                    config.log_level = value.as_string()?;
+                }
                 _ => {}
             }
         }

src/logger.rs

@@ -0,0 +1,49 @@
+use log::LevelFilter;
+use nu_protocol::ShellError;
+use pretty_env_logger::env_logger::Builder;
+
+pub fn logger(f: impl FnOnce(&mut Builder) -> Result<(), ShellError>) -> Result<(), ShellError> {
+    let mut builder = pretty_env_logger::formatted_builder();
+    f(&mut builder)?;
+    let _ = builder.try_init();
+    Ok(())
+}
+
+pub fn configure(level: &str, logger: &mut Builder) -> Result<(), ShellError> {
+    let level = match level {
+        "error" => LevelFilter::Error,
+        "warn" => LevelFilter::Warn,
+        "info" => LevelFilter::Info,
+        "debug" => LevelFilter::Debug,
+        "trace" => LevelFilter::Trace,
+        _ => LevelFilter::Warn,
+    };
+
+    logger.filter_module("nu", level);
+
+    if let Ok(s) = std::env::var("RUST_LOG") {
+        logger.parse_filters(&s);
+    }
+
+    Ok(())
+}
+
+// pub fn trace_filters(app: &App, logger: &mut Builder) -> Result<(), ShellError> {
+//     if let Some(filters) = app.develop() {
+//         filters.into_iter().filter_map(Result::ok).for_each(|name| {
+//             logger.filter_module(&name, LevelFilter::Trace);
+//         })
+//     }
+
+//     Ok(())
+// }
+
+// pub fn debug_filters(app: &App, logger: &mut Builder) -> Result<(), ShellError> {
+//     if let Some(filters) = app.debug() {
+//         filters.into_iter().filter_map(Result::ok).for_each(|name| {
+//             logger.filter_module(&name, LevelFilter::Debug);
+//         })
+//     }
+
+//     Ok(())
+// }

src/main.rs

@@ -5,6 +5,7 @@ use dialoguer::{
     theme::ColorfulTheme,
     Select,
 };
+use log::trace;
 use miette::{IntoDiagnostic, Result};
 use nu_cli::{CliError, NuCompleter, NuHighlighter, NuValidator, NushellPrompt};
 use nu_color_config::get_color_config;
@@ -21,7 +22,6 @@ use reedline::{
 };
 use std::{
     io::Write,
-    path::Path,
     sync::{
         atomic::{AtomicBool, Ordering},
         Arc,
@@ -31,6 +31,8 @@ use std::{
 #[cfg(test)]
 mod tests;
 
+mod logger;
+
 // Name of environment variable where the prompt could be stored
 const PROMPT_COMMAND: &str = "PROMPT_COMMAND";
 
@@ -114,6 +116,8 @@ fn main() -> Result<()> {
 
         let (block, delta) = {
             let mut working_set = StateWorkingSet::new(&engine_state);
+            trace!("parsing file: {}", path);
+
             let (output, err) = parse(&mut working_set, Some(&path), &file, false);
             if let Some(err) = err {
                 report_error(&working_set, &err);
@@ -297,6 +301,16 @@ fn main() -> Result<()> {
             }
         };
 
+        use logger::{configure, logger};
+
+        logger(|builder| {
+            configure(&config.log_level, builder)?;
+            // trace_filters(self, builder)?;
+            // debug_filters(self, builder)?;
+
+            Ok(())
+        })?;
+
         // Translate environment variables from Strings to Values
         if let Some(e) = convert_env_values(&engine_state, &mut stack, &config) {
             let working_set = StateWorkingSet::new(&engine_state);
@@ -417,18 +431,18 @@ fn main() -> Result<()> {
 
             let input = line_editor.read_line(prompt);
             match input {
-                Ok(Signal::Success(mut s)) => {
+                Ok(Signal::Success(s)) => {
+                    let tokens = lex(s.as_bytes(), 0, &[], &[], false);
                     // Check if this is a single call to a directory, if so auto-cd
                     let path = nu_path::expand_path(&s);
                     let orig = s.clone();
-                    s = path.to_string_lossy().to_string();
 
-                    let path = Path::new(&s);
                     if (orig.starts_with('.')
                         || orig.starts_with('~')
                         || orig.starts_with('/')
                         || orig.starts_with('\\'))
                         && path.is_dir()
+                        && tokens.0.len() == 1
                     {
                         // We have an auto-cd
                         let _ = std::env::set_current_dir(&path);
@@ -446,6 +460,8 @@ fn main() -> Result<()> {
                         continue;
                     }
 
+                    trace!("eval source: {}", s);
+
                     eval_source(
                         &mut engine_state,
                         &mut stack,
@@ -754,6 +770,8 @@ fn eval_source(
     source: &str,
     fname: &str,
 ) -> bool {
+    trace!("eval_source");
+
     let (block, delta) = {
         let mut working_set = StateWorkingSet::new(engine_state);
         let (output, err) = parse(