Using env_logger for logging

added testing

Signed-off-by: faldor20 <eli.jambu@yahoo.com>

Cargo.lock

@@ -844,6 +844,19 @@ version = "1.0.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "5443807d6dff69373d433ab9ef5378ad8df50ca6298caf15de6e52e24aaf54d5"
 
+[[package]]
+name = "env_logger"
+version = "0.10.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "95b3f3e67048839cb0d0781f445682a35113da7121f7c949db0e2be96a4fbece"
+dependencies = [
+ "humantime",
+ "is-terminal",
+ "log",
+ "regex",
+ "termcolor",
+]
+
 [[package]]
 name = "errno"
 version = "0.3.5"
@@ -1151,6 +1164,12 @@ version = "1.0.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "df3b46402a9d5adb4c86a0cf463f42e19994e3ee891101b1841f30a545cb49a9"
 
+[[package]]
+name = "humantime"
+version = "2.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4"
+
 [[package]]
 name = "hyper"
 version = "0.14.27"
@@ -1327,6 +1346,17 @@ version = "2.8.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "28b29a3cd74f0f4598934efe3aeba42bae0eb4680554128851ebbecb02af14e6"
 
+[[package]]
+name = "is-terminal"
+version = "0.4.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "cb0889898416213fab133e1d33a0e5858a48177452750691bde3666d0fdbaf8b"
+dependencies = [
+ "hermit-abi 0.3.3",
+ "rustix",
+ "windows-sys 0.48.0",
+]
+
 [[package]]
 name = "itertools"
 version = "0.9.0"
@@ -1922,7 +1952,7 @@ version = "1.0.3"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "588f6378e4dd99458b60ec275b4477add41ce4fa9f64dcba6f15adccb19b50d6"
 dependencies = [
- "env_logger",
+ "env_logger 0.8.4",
  "log",
  "rand",
 ]
@@ -2649,6 +2679,9 @@ name = "roc_lang_srv"
 version = "0.0.1"
 dependencies = [
  "bumpalo",
+ "env_logger 0.10.1",
+ "insta",
+ "log",
  "parking_lot",
  "roc_can",
  "roc_collections",

crates/lang_srv/Cargo.toml

@@ -7,6 +7,14 @@ edition = "2021"
 name = "roc_ls"
 path = "src/server.rs"
 
+[profile.dev.package]
+insta.opt-level = 3
+similar.opt-level = 3
+
+[dev-dependencies]
+insta = "1.34.0"
+
+
 [dependencies]
 roc_can = { path = "../compiler/can" }
 roc_collections = { path = "../compiler/collections" }
@@ -27,3 +35,5 @@ parking_lot.workspace = true
 
 tower-lsp = "0.17.0"
 tokio = { version = "1.20.1", features = [ "rt", "rt-multi-thread", "macros", "io-std" ] }
+log.workspace = true
+env_logger = "0.10.1"

crates/lang_srv/README.md

@@ -78,3 +78,7 @@ If you're using coc.nvim and want to use the configuration above, be sure to als
 
 If you want to debug the server, use [debug_server.sh](./debug_server.sh)
 instead of the direct binary.
+
+If you would like to enable debug logging set the `RUST_LOG` environment variable to `debug` or `trace` for even more logs. 
+eg: `RUST_LOG=debug`  
+

crates/lang_srv/debug_server.sh

@@ -1,4 +1,5 @@
 #!/usr/bin/bash
 
 SCRIPT_DIR=$(cd -- "$( dirname -- "${BASH_SOURCE[0]}" )" &> /dev/null && pwd)
+RUST_LOG=debug
 ${SCRIPT_DIR}/../../target/debug/roc_ls "$@" 2> /tmp/roc_ls.err

crates/lang_srv/src/analysis.rs

@@ -1,3 +1,4 @@
+use log::debug;
 use std::{
     collections::HashMap,
     path::{Path, PathBuf},
@@ -53,6 +54,9 @@ fn format_var_type(
     subs.rollback_to(snapshot);
     type_str
 }
+fn is_roc_identifier_char(char: &char) -> bool {
+    matches!(char,'a'..='z'|'A'..='Z'|'0'..='9'|'.')
+}
 ///Returns a closure that will run the global analysis and the docinfo for the provided source
 ///This means that you can get positions within the source code before the analysis completes
 pub(crate) fn global_analysis(
@@ -72,7 +76,7 @@ pub(crate) fn global_analysis(
     };
     //We will return this before the analysis has completed to enable completion
     let doc_info_return = doc_info.clone();
-    let documents_future = move || {
+    let perform_analysis = move || {
         let arena = Bump::new();
         let loaded = roc_load::load_and_typecheck_str(
             &arena,
@@ -141,7 +145,7 @@ pub(crate) fn global_analysis(
 
         documents
     };
-    (documents_future, doc_info_return)
+    (perform_analysis, doc_info_return)
 }
 
 fn find_src_dir(path: &Path) -> &Path {
@@ -311,22 +315,19 @@ pub struct DocInfo {
 impl DocInfo {
     #[cfg(debug_assertions)]
     #[allow(unused)]
-    fn debug_log_prefix(&self, offset: u32) {
+    fn debug_log_prefix(&self, offset: usize) {
-        eprintln!("prefix source{:?}", self.source);
+        debug!("prefix source{:?}", self.source);
 
-        let last_few = self
+        let last_few = self.source.get(offset - 5..offset + 5).unwrap();
-            .source
-            .split_at((offset - 5) as usize)
-            .1
-            .split_at((offset + 5) as usize)
-            .0;
-        let splitter = last_few.split_at(5);
 
-        eprintln!(
+        let (before, after) = last_few.split_at(5);
+
+        debug!(
             "starting to get completion items at offset:{:?} content:: '{:?}|{:?}'",
-            offset, splitter.0, splitter.1
+            offset, before, after
         );
     }
+
     fn whole_document_range(&self) -> Range {
         let start = Position::new(0, 0);
         let end = Position::new(self.line_info.num_lines(), 0);
@@ -334,18 +335,16 @@ impl DocInfo {
     }
     pub fn get_prefix_at_position(&self, position: Position) -> String {
         let position = position.to_roc_position(&self.line_info);
-        let offset = position.offset;
+        let offset = position.offset as usize;
-        let source = self.source.as_bytes().split_at(offset as usize).0;
+        let source = &self.source.as_bytes()[..offset];
-        let mut symbol = source
+        let symbol_len = source
             .iter()
             .rev()
-            //TODO proper regex here
+            .take_while(|&a| is_roc_identifier_char(&(*a as char)))
-            .take_while(|&&a| matches!(a as char,'a'..='z'|'A'..='Z'|'0'..='9'|'_'|'.'))
+            .count();
-            .map(|&a| a)
+        let symbol = &self.source[offset - symbol_len..offset];
-            .collect::<Vec<u8>>();
-        symbol.reverse();
 
-        String::from_utf8(symbol).unwrap()
+        String::from(symbol)
     }
     pub fn format(&self) -> Option<Vec<TextEdit>> {
         let source = &self.source;
@@ -473,7 +472,7 @@ impl AnalyzedDocument {
         latest_doc: &DocInfo,
     ) -> Option<Vec<CompletionItem>> {
         let symbol_prefix = latest_doc.get_prefix_at_position(position);
-        eprintln!(
+        debug!(
             "starting to get completion items for prefix: {:?} docVersion:{:?}",
             symbol_prefix, latest_doc.version
         );
@@ -483,7 +482,7 @@ impl AnalyzedDocument {
         //TODO: this is kind of a hack and should be removed once we can do some minimal parsing without full type checking
         let mut position = position.to_roc_position(&latest_doc.line_info);
         position.offset = (position.offset as i32 - len_diff - 1) as u32;
-        eprintln!("completion offset: {:?}", position.offset);
+        debug!("completion offset: {:?}", position.offset);
 
         let AnalyzedModule {
             module_id,
@@ -512,7 +511,6 @@ impl AnalyzedDocument {
                 module_id,
                 interns,
             );
-            eprintln!("got completions: ");
             Some(completions)
         }
     }

crates/lang_srv/src/analysis/completion.rs

@@ -1,3 +1,4 @@
+use log::{debug, trace, warn};
 use roc_can::{
     def::Def,
     expr::{Declarations, Expr, WhenBranch},
@@ -25,7 +26,6 @@ impl Visitor for CompletionVisitor<'_> {
 
     fn visit_expr(&mut self, expr: &Expr, region: Region, var: Variable) {
         if region.contains_pos(self.position) {
-            // self.region_typ = Some((region, var));
             let mut res = self.expression_defs(expr);
             self.found_decls.append(&mut res);
 
@@ -40,8 +40,8 @@ impl Visitor for CompletionVisitor<'_> {
                 loc_body: loc_expr, ..
             }
             | DeclarationInfo::Destructure { loc_expr, .. } => {
-                let mut res = self.decl_to_completion_item(&decl);
+                let res = self.decl_to_completion_item(&decl);
-                self.found_decls.append(&mut res);
+                self.found_decls.extend(res);
                 if loc_expr.region.contains_pos(self.position) {
                     walk_decl(self, decl);
                 };
@@ -53,14 +53,14 @@ impl Visitor for CompletionVisitor<'_> {
     }
 
     fn visit_def(&mut self, def: &Def) {
-        let mut res = self.extract_defs(def);
+        let res = self.extract_defs(def);
-        self.found_decls.append(&mut res);
+        self.found_decls.extend(res);
         walk_def(self, def);
     }
 }
 impl CompletionVisitor<'_> {
     fn extract_defs(&mut self, def: &Def) -> Vec<(Symbol, Variable)> {
-        eprintln!("completion begin");
+        trace!("completion begin");
         def.pattern_vars
             .iter()
             .map(|(symbol, var)| (symbol.clone(), var.clone()))
@@ -70,8 +70,18 @@ impl CompletionVisitor<'_> {
         match expr {
             Expr::When {
                 expr_var, branches, ..
-            } => {
+            } => self.when_is_expr(branches, expr_var),
-                let out: Vec<_> = branches
+            _ => vec![],
+        }
+    }
+
+    ///Extract any variables made available by the branch of a when_is expression that contains `self.position`
+    fn when_is_expr(
+        &self,
+        branches: &Vec<WhenBranch>,
+        expr_var: &Variable,
+    ) -> Vec<(Symbol, Variable)> {
+        branches
             .iter()
             .flat_map(
                 |WhenBranch {
@@ -80,27 +90,19 @@ impl CompletionVisitor<'_> {
                     if value.region.contains_pos(self.position) {
                         patterns
                             .iter()
-                                    .flat_map(|pattern| {
+                            .flat_map(|pattern| self.patterns(&pattern.pattern.value, expr_var))
-                                        //We use the expression var here because if the pattern is an identifier then it must have the type of the expession given to the when is block
-                                        self.patterns(&pattern.pattern.value, expr_var)
-                                    })
                             .collect()
                     } else {
                         vec![]
                     }
                 },
             )
-                    .collect();
+            .collect()
-                out
-            }
-            _ => vec![],
-        }
     }
 
-    fn record_destructs(&self, destructs: &Vec<Loc<RecordDestruct>>) -> Vec<(Symbol, Variable)> {
+    fn record_destructure(&self, destructs: &Vec<Loc<RecordDestruct>>) -> Vec<(Symbol, Variable)> {
         destructs
             .iter()
-            //TODO:I need to destructure value.typ here
             .flat_map(|a| match &a.value.typ {
                 roc_can::pattern::DestructType::Required
                 | roc_can::pattern::DestructType::Optional(_, _) => {
@@ -111,10 +113,9 @@ impl CompletionVisitor<'_> {
             .collect()
     }
 
-    fn tuple_destructs(&self, destructs: &Vec<Loc<TupleDestruct>>) -> Vec<(Symbol, Variable)> {
+    fn tuple_destructure(&self, destructs: &Vec<Loc<TupleDestruct>>) -> Vec<(Symbol, Variable)> {
         destructs
             .iter()
-            //TODO:I need to destructure value.typ here
             .flat_map(|a| {
                 let (var, pattern) = &a.value.typ;
                 self.patterns(&pattern.value, &var)
@@ -122,65 +123,62 @@ impl CompletionVisitor<'_> {
             .collect()
     }
 
-    fn list_destructure(
+    fn list_pattern(&self, list_elems: &ListPatterns, var: &Variable) -> Vec<(Symbol, Variable)> {
-        &self,
-        list_elems: &ListPatterns,
-        var: &Variable,
-    ) -> Vec<(Symbol, Variable)> {
         list_elems
             .patterns
             .iter()
-            //TODO:I need to destructure value.typ here
             .flat_map(|a| self.patterns(&a.value, var))
             .collect()
     }
-    fn tag_destructure(&self, arguments: &[(Variable, Loc<Pattern>)]) -> Vec<(Symbol, Variable)> {
+    fn tag_pattern(&self, arguments: &[(Variable, Loc<Pattern>)]) -> Vec<(Symbol, Variable)> {
         arguments
             .iter()
             .flat_map(|(var, pat)| self.patterns(&pat.value, var))
             .collect()
     }
 
-    fn as_pattern(&self, as_pat: &Pattern, as_symbol: Symbol) -> Option<(Symbol, Variable)> {
+    fn as_pattern(
-        let var = match as_pat {
+        &self,
-            Pattern::AppliedTag { whole_var, .. } => whole_var,
+        as_pat: &Pattern,
-            Pattern::UnwrappedOpaque { whole_var, .. } => whole_var,
+        as_symbol: Symbol,
-            Pattern::RecordDestructure { whole_var, .. } => whole_var,
+        var: &Variable,
-            Pattern::TupleDestructure { whole_var, .. } => whole_var,
+    ) -> Vec<(Symbol, Variable)> {
-            Pattern::List { list_var, .. } => list_var,
+        //Get the variables introduced within the pattern
-            _ => return None,
+        let mut patterns = self.patterns(as_pat, var);
-        };
+        //Add the "as" that wraps the whole pattern
-        Some((as_symbol, var.clone()))
+        patterns.push((as_symbol, var.clone()));
+        patterns
     }
+    ///Returns a list of symbols defined by this pattern.  
+    ///`pattern_var`: Variable type of the entire pattern. This will be returned if the pattern turns out to be an identifier
     fn patterns(
         &self,
         pattern: &roc_can::pattern::Pattern,
-        var: &Variable,
+        pattern_var: &Variable,
     ) -> Vec<(Symbol, Variable)> {
         match pattern {
             roc_can::pattern::Pattern::Identifier(symbol) => {
                 if self.is_match(symbol) {
-                    vec![(symbol.clone(), var.clone())]
+                    vec![(symbol.clone(), pattern_var.clone())]
                 } else {
                     vec![]
                 }
             }
-            Pattern::AppliedTag { arguments, .. } => self.tag_destructure(arguments),
+            Pattern::AppliedTag { arguments, .. } => self.tag_pattern(arguments),
             Pattern::UnwrappedOpaque { argument, .. } => {
                 self.patterns(&argument.1.value, &argument.0)
             }
             Pattern::List {
                 elem_var, patterns, ..
-            } => self.list_destructure(patterns, elem_var),
+            } => self.list_pattern(patterns, elem_var),
-            roc_can::pattern::Pattern::As(pat, symbol) => self
+            roc_can::pattern::Pattern::As(pat, symbol) => {
-                .as_pattern(&pat.value, symbol.clone())
+                self.as_pattern(&pat.value, symbol.clone(), pattern_var)
-                .map(|a| vec![a])
+            }
-                .unwrap_or(vec![]),
             roc_can::pattern::Pattern::RecordDestructure { destructs, .. } => {
-                self.record_destructs(destructs)
+                self.record_destructure(destructs)
             }
             roc_can::pattern::Pattern::TupleDestructure { destructs, .. } => {
-                self.tuple_destructs(destructs)
+                self.tuple_destructure(destructs)
             }
             _ => vec![],
         }
@@ -202,20 +200,20 @@ impl CompletionVisitor<'_> {
                 loc_body,
                 ..
             } => {
-                let mut out: Vec<_> = vec![];
+                let mut out = vec![];
-                //append the function declaration
+                //Append the function declaration itself for recursive calls
-                out.append(&mut self.patterns(pattern, expr_var));
+                out.extend(self.patterns(pattern, expr_var));
 
                 if loc_body.region.contains_pos(self.position) {
                     //also add the arguments if we are inside the function
-                    let mut args: Vec<_> = function
+                    let args: Vec<_> = function
                         .value
                         .arguments
                         .iter()
-                        .flat_map(|(var, _1, pat)| self.patterns(&pat.value, var))
+                        .flat_map(|(var, _, pat)| self.patterns(&pat.value, var))
                         //We add in the pattern for the function declaration
                         .collect();
-                    out.append(&mut args);
+                    out.extend(args);
                 }
                 out
             }
@@ -262,7 +260,7 @@ fn make_completion_item(
             _ => CompletionItemKind::VARIABLE,
         },
         a => {
-            eprintln!(
+            debug!(
                 "No specific completionKind for variable type :{:?} defaulting to 'Variable'",
                 a
             );
@@ -290,29 +288,17 @@ pub fn get_completion_items(
     interns: &Interns,
 ) -> Vec<CompletionItem> {
     let completions = get_completions(position, decls, prefix, interns);
-    make_completion_items(subs, module_id, interns, completions)
+    make_completion_items(
-}
-pub fn make_completion_items(
-    subs: &mut Subs,
-    module_id: &ModuleId,
-    interns: &Interns,
-    completions: Vec<(Symbol, Variable)>,
-) -> Vec<CompletionItem> {
-    completions
-        .into_iter()
-        .map(|(symbol, var)| {
-            make_completion_item(
         subs,
         module_id,
         interns,
-                symbol.as_str(interns).to_string(),
+        completions
-                var,
+            .into_iter()
+            .map(|(symb, var)| (symb.as_str(interns).to_string(), var))
+            .collect(),
     )
-        })
-        .collect()
 }
-
+fn make_completion_items(
-fn make_completion_items_string(
     subs: &mut Subs,
     module_id: &ModuleId,
     interns: &Interns,
@@ -324,43 +310,31 @@ fn make_completion_items_string(
         .collect()
 }
 
-///Gets completion items for a record field
+///Finds the types of and names of all the fields of a record
-///Uses
+///`var` should be a `Variable` that you know is a record's type or else it will return an empty list
 fn find_record_fields(var: Variable, subs: &mut Subs) -> Vec<(String, Variable)> {
     let content = subs.get(var);
     match content.content {
         roc_types::subs::Content::Structure(typ) => match typ {
             roc_types::subs::FlatType::Record(fields, ext) => {
                 let field_types = fields.unsorted_iterator(subs, ext);
-                let fields: Vec<_> = match field_types {
+
+                match field_types {
                     Ok(field) => field
-                        .map(|a| {
+                        .map(|a| (a.0.clone().into(), a.1.into_inner()))
-                            let var = match a.1 {
+                        .collect::<Vec<_>>(),
-                                roc_types::types::RecordField::Demanded(var)
-                                | roc_types::types::RecordField::Required(var)
-                                | roc_types::types::RecordField::Optional(var)
-                                | roc_types::types::RecordField::RigidRequired(var)
-                                | roc_types::types::RecordField::RigidOptional(var) => var,
-                            };
-                            (a.0.clone().into(), var)
-                        })
-                        .collect(),
                     Err(err) => {
-                        eprintln!(
+                        warn!("Error getting record field types for completion{:?}", err);
-                            "WARN:Error getting record field types for completion{:?}",
-                            err
-                        );
                         vec![]
                     }
-                };
+                }
-                fields
             }
             roc_types::subs::FlatType::Tuple(elems, ext) => {
                 let elems = elems.unsorted_iterator(subs, ext);
-                let elems: Vec<_> = match elems {
+                let elems = match elems {
                     Ok(elem) => elem.map(|(num, var)| (num.to_string(), var)).collect(),
                     Err(err) => {
-                        eprintln!("WARN:Error getting tuple elems for completion{:?}", err);
+                        warn!("Error getting tuple elems for completion{:?}", err);
                         vec![]
                     }
                 };
@@ -368,36 +342,48 @@ fn find_record_fields(var: Variable, subs: &mut Subs) -> Vec<(String, Variable)>
             }
 
             _ => {
-                eprintln!(
+                warn!("Trying to get field completion for a type that is not a record ",);
-                    "WARN: Trying to get field completion for a type that is not a record   ",
-                );
                 vec![]
             }
         },
         roc_types::subs::Content::Error => {
             //This is caused by typechecking our partially typed variable name causing the typechecking to be confused as the type of the parent variable
             //TODO! ideally i could recover using some previous typecheck result that isn't broken
-            eprintln!("ERROR: variable type of record was of type error cannot access field",);
+            warn!("Variable type of record was of type 'error', cannot access field",);
             vec![]
         }
-        a => {
+        _ => {
-            eprintln!("variable before field was unsuported type:{:?}", a);
+            warn!(
+                "Variable before field was unsuported type:{:?}",
+                subs.dbg(var)
+            );
             vec![]
         }
     }
 }
-///Splits a completion prefix for a field into it's components
-//eg a.b.c.d->("a",["b","c"],"d")
-fn get_field_completion_parts(symbol_prefix: &String) -> Option<(String, Vec<String>, String)> {
-    let parts: Vec<_> = symbol_prefix.split('.').collect();
-    let (variable, fields) = parts.split_first()?;
-
-    let (field, middle) = match fields.split_last() {
-        Some(a) => (a.0.to_string(), a.1.iter().map(|x| x.to_string()).collect()),
 
+struct FieldCompletion {
+    var: String,
+    field: String,
+    remaining_chain: Vec<String>,
+}
+///Splits a completion prefix for a field into its components
+///E.g. a.b.c.d->("a",["b","c"],"d")
+fn get_field_completion_parts(symbol_prefix: &str) -> Option<FieldCompletion> {
+    let mut parts = symbol_prefix.split('.');
+    let variable = parts.next()?;
+    let field = parts.next();
+    let remaining = parts;
+    let (field, remaining_chain) = match field {
+        Some(f) => (f.to_string(), remaining.map(ToString::to_string).collect()),
         None => ("".to_string(), vec![]),
     };
-    Some((variable.to_string(), middle, field))
+
+    Some(FieldCompletion {
+        var: variable.to_string(),
+        field,
+        remaining_chain,
+    })
 }
 pub fn field_completion(
     position: Position,
@@ -407,27 +393,30 @@ pub fn field_completion(
     subs: &mut Subs,
     module_id: &ModuleId,
 ) -> Option<Vec<CompletionItem>> {
-    eprintln!("getting record field completions: ");
+    let FieldCompletion {
-    let (variable, middle, field) = get_field_completion_parts(&symbol_prefix)?;
+        var,
+        field,
+        remaining_chain,
+    } = get_field_completion_parts(&symbol_prefix)?;
 
-    eprintln!(
+    debug!(
         "getting record field completions: variable:{:?} field{:?} middle{:?} ",
-        variable, field, middle
+        var, field, remaining_chain
     );
     //get the variable from within the region
     //TODO: this is kind of just a hack. We are gettting all the completions and seeing if any match the part before the dot as a way to get the Variable type of the variable before the dot. I imagine there are much faster ways to do this
-    let completion = get_completions(position, declarations, variable.to_string(), interns)
+    let completion = get_completions(position, declarations, var.to_string(), interns)
         .into_iter()
         .map(|a| (a.0.as_str(&interns).to_string(), a.1))
         .next()?;
 
     //We iterate through all the intermediate chunks eg var.field1.field2.field3 this iterates through fields until we get to field2, becuase it's second last
-    let second_last = middle.iter().fold(completion, |state, a| {
+    let second_last = remaining_chain.iter().fold(completion, |state, a| {
         let fields_vars = find_record_fields(state.1, subs);
-        match fields_vars.into_iter().find(|field| a == &field.0) {
+        fields_vars
-            None => state,
+            .into_iter()
-            Some(a) => a,
+            .find(|field| a == &field.0)
-        }
+            .unwrap_or(state)
     });
 
     let field_completions: Vec<_> = find_record_fields(second_last.1, subs)
@@ -435,7 +424,6 @@ pub fn field_completion(
         .filter(|(str, _)| str.starts_with(&field.to_string()))
         .collect();
 
-    let field_completions =
+    let field_completions = make_completion_items(subs, module_id, interns, field_completions);
-        make_completion_items_string(subs, module_id, interns, field_completions);
     Some(field_completions)
 }

crates/lang_srv/src/registry.rs

@@ -1,4 +1,5 @@
-use std::{collections::HashMap, sync::Arc};
+use log::{debug, info};
+use std::{collections::HashMap, future::Future, sync::Arc};
 
 use tokio::sync::{Mutex, MutexGuard, RwLock, RwLockWriteGuard};
 use tower_lsp::lsp_types::{
@@ -13,12 +14,15 @@ pub(crate) struct LatestDocument {
     pub info: DocInfo,
     analyzed: tokio::sync::RwLock<Option<Arc<AnalyzedDocument>>>,
 }
+
 impl LatestDocument {
     pub(crate) async fn get_latest(&self) -> Arc<AnalyzedDocument> {
         self.analyzed.read().await.as_ref().unwrap().clone()
     }
-    pub(crate) fn get_lock(&self) -> RwLockWriteGuard<Option<Arc<AnalyzedDocument>>> {
+    pub(crate) fn get_lock(
-        self.analyzed.blocking_write()
+        &self,
+    ) -> impl Future<Output = RwLockWriteGuard<Option<Arc<AnalyzedDocument>>>> {
+        self.analyzed.write()
     }
     pub(crate) fn new(doc_info: DocInfo) -> LatestDocument {
         let val = RwLock::new(None);
@@ -56,10 +60,9 @@ impl Registry {
     }
     fn update_document<'a>(
         documents: &mut MutexGuard<'a, HashMap<Url, DocumentPair>>,
-        document: AnalyzedDocument,
+        document: Arc<AnalyzedDocument>,
     ) {
         let url = document.url().clone();
-        let document = Arc::new(document);
         let latest_doc = Arc::new(LatestDocument::new_initialised(document.clone()));
         match documents.get_mut(&url) {
             Some(old_doc) => {
@@ -94,42 +97,34 @@ impl Registry {
         updating_url: Url,
     ) {
         let mut documents = self.documents.lock().await;
-        eprintln!(
+        debug!(
-            "finised doc analysis updating docs {:?}",
+            "finised doc analysis for doc: {:?}",
-            analysed_docs
+            updating_url.to_string()
-                .iter()
-                .map(|a| a.doc_info.url.to_string())
-                .collect::<Vec<_>>()
         );
-        let updates = analysed_docs.into_iter().filter_map(|a| {
-            if a.doc_info.url == updating_url {
-                *partial_writer = Some(Arc::new(a));
-                None
-            } else {
-                Some(a)
-            }
-        });
 
-        for document in updates {
+        for document in analysed_docs {
+            let document = Arc::new(document);
+            //Write the newly analysed document into the partial document that any request requiring the latest document will be waiting on
+            if document.doc_info.url == updating_url {
+                *partial_writer = Some(document.clone());
+            }
             Registry::update_document(&mut documents, document);
         }
     }
 
     pub async fn apply_doc_info_changes(&self, url: Url, partial: Arc<LatestDocument>) {
-        let mut lock = self.documents.lock().await;
+        let mut documents_lock = self.documents.lock().await;
-        let doc = lock.get_mut(&url);
+        let doc = documents_lock.get_mut(&url);
         match doc {
             Some(a) => {
-                eprintln!(
+                debug!(
                     "set the docInfo for {:?} to version:{:?}",
                     url.as_str(),
                     partial.info.version
                 );
-
                 a.latest_document = partial;
             }
-
+            None => debug!("no existing docinfo for {:?} ", url.as_str()),
-            None => (),
         }
     }
 
@@ -139,6 +134,7 @@ impl Registry {
             .get(url)
             .map(|a| a.latest_document.info.clone())
     }
+
     async fn latest_document_by_url(&self, url: &Url) -> Option<Arc<AnalyzedDocument>> {
         match self.documents.lock().await.get(url) {
             Some(a) => Some(a.latest_document.get_latest().await),
@@ -149,6 +145,7 @@ impl Registry {
     pub async fn diagnostics(&self, url: &Url) -> Vec<Diagnostic> {
         let Some( document) = self.latest_document_by_url(url).await else {
             return vec![];
+
         };
         document.diagnostics()
     }
@@ -185,9 +182,11 @@ impl Registry {
     ) -> Option<CompletionResponse> {
         let lock = self.documents.lock().await;
         let pair = lock.get(url)?;
-        eprintln!("got document");
         let latest_doc_info = &pair.latest_document.info;
-        eprintln!("latest version:{:?} ", latest_doc_info.version);
+        info!(
+            "using document version:{:?} for completion ",
+            latest_doc_info.version
+        );
 
         let completions = pair
             .last_good_document

crates/lang_srv/src/server.rs

@@ -1,4 +1,5 @@
 use analysis::HIGHLIGHT_TOKENS_LEGEND;
+use log::debug;
 use registry::Registry;
 use std::future::Future;
 use tokio::sync::RwLock;
@@ -18,10 +19,10 @@ mod registry;
 #[derive(Debug)]
 struct RocLs {
     pub inner: Arc<Inner>,
+    client: Client,
 }
 #[derive(Debug)]
 struct Inner {
-    client: Client,
     registry: RwLock<Registry>,
 }
 
@@ -30,10 +31,8 @@ impl std::panic::RefUnwindSafe for RocLs {}
 impl RocLs {
     pub fn new(client: Client) -> Self {
         Self {
-            inner: Arc::new(Inner {
+            inner: Arc::new(Inner::new()),
             client,
-                registry: RwLock::new(Registry::default()),
-            }),
         }
     }
     ///Wait for all the semaphores associated with an in-progress document_info update to be released
@@ -91,13 +90,52 @@ impl RocLs {
 
     /// Records a document content change.
     async fn change(&self, fi: Url, text: String, version: i32) {
-        eprintln!("starting change");
+        let updating_result = self.inner.change(&fi, text, version).await;
-        let registry_write_lock = self.inner.registry.write().await;
 
-        eprintln!("finished checking for cancellation");
+        //The analysis task can be cancelled by another change coming in which will update the watched variable
+        if let Err(e) = updating_result {
+            debug!("cancelled change. Reason:{:?}", e);
+            return;
+        }
+        debug!("applied_change getting and returning diagnostics");
+
+        let diagnostics = self.inner.registry().await.diagnostics(&fi).await;
+
+        self.client
+            .publish_diagnostics(fi, diagnostics, Some(version))
+            .await;
+    }
+}
+
+impl Inner {
+    pub fn new() -> Inner {
+        Self {
+            registry: RwLock::new(Registry::default()),
+        }
+    }
+
+    fn registry(&self) -> impl Future<Output = tokio::sync::RwLockReadGuard<Registry>> {
+        self.registry.read()
+    }
+
+    async fn close(&self, _fi: Url) {
+        ()
+    }
+
+    pub async fn change(
+        &self,
+        fi: &Url,
+        text: String,
+        version: i32,
+    ) -> std::result::Result<(), String> {
+        debug!("starting change");
+        let registry_write_lock = self.registry.write().await;
+
+        debug!("change aquired registry lock");
         let (results, partial) = global_analysis(fi.clone(), text, version);
         let partial_document = Arc::new(LatestDocument::new(partial.clone()));
-        let partial_doc_write_lock = partial_document.get_lock();
+        //TODO check if allowing context switching here is an issue
+        let partial_doc_write_lock = partial_document.get_lock().await;
 
         registry_write_lock
             .apply_doc_info_changes(fi.clone(), partial_document.clone())
@@ -105,29 +143,27 @@ impl RocLs {
         //Now that we've got our new partial document written and we hold the exclusive write_handle to its analysis we can allow other tasks to access the registry and the doc_info inside this partial document
         drop(registry_write_lock);
 
-        eprintln!("finished updating docinfo, starting analysis ",);
+        debug!("finished updating docinfo, starting analysis ",);
 
-        let inner_ref = self.inner.clone();
+        let inner_ref = self.clone();
         let updating_result = async {
             let results = match tokio::task::spawn_blocking(results).await {
-                Err(e) => return Err(format!("document analysis failed. reason:{:?}", e)),
+                Err(e) => return Err(format!("Document analysis failed. reason:{:?}", e)),
                 Ok(a) => a,
             };
-            let latest_version = inner_ref
+            let latest_version = inner_ref.registry.read().await.get_latest_version(fi).await;
-                .registry
-                .read()
-                .await
-                .get_latest_version(&fi)
-                .await;
 
             //if this version is not the latest another change must have come in and this analysis is useless
             //if there is no older version we can just proceed with the update
             if let Some(latest_version) = latest_version {
+                if latest_version != version {
                     return Err(format!(
                         "version {0} doesn't match latest: {1} discarding analysis  ",
                         version, latest_version
                     ));
                 }
+            }
+            debug!("finished updating documents returning ",);
 
             inner_ref
                 .registry
@@ -138,30 +174,8 @@ impl RocLs {
             Ok(())
         }
         .await;
-
+        debug!("finished updating documents returning ",);
-        //The analysis task can be cancelled by another change coming in which will update the watched variable
+        updating_result
-        if let Err(e) = updating_result {
-            eprintln!("cancelled change. Reason:{:?}", e);
-            return;
-        }
-        eprintln!("applied_change getting and returning diagnostics");
-
-        let diagnostics = self.inner.registry().await.diagnostics(&fi).await;
-
-        self.inner
-            .client
-            .publish_diagnostics(fi, diagnostics, Some(version))
-            .await;
-    }
-}
-
-impl Inner {
-    fn registry(&self) -> impl Future<Output = tokio::sync::RwLockReadGuard<Registry>> {
-        self.registry.read()
-    }
-
-    async fn close(&self, _fi: Url) {
-        ()
     }
 }
 
@@ -175,8 +189,7 @@ impl LanguageServer for RocLs {
     }
 
     async fn initialized(&self, _: InitializedParams) {
-        self.inner
+        self.client
-            .client
             .log_message(MessageType::INFO, "Roc language server initialized.")
             .await;
     }
@@ -283,11 +296,6 @@ impl LanguageServer for RocLs {
     }
     async fn completion(&self, params: CompletionParams) -> Result<Option<CompletionResponse>> {
         let doc = params.text_document_position;
-        eprintln!("starting completion");
-
-        //We need to wait untill any changes that were in progress when we requested completion have applied
-        eprintln!("waited for doc update to get sorted ");
-
         let res = panic_wrapper_async(|| async {
             self.inner
                 .registry()
@@ -296,8 +304,6 @@ impl LanguageServer for RocLs {
                 .await
         })
         .await;
-
-        eprintln!("finished completion");
         res
     }
 }
@@ -316,9 +322,152 @@ where
 
 #[tokio::main]
 async fn main() {
+    env_logger::init();
+
     let stdin = tokio::io::stdin();
     let stdout = tokio::io::stdout();
 
     let (service, socket) = LspService::new(RocLs::new);
     Server::new(stdin, stdout, socket).serve(service).await;
 }
+
+#[cfg(test)]
+mod tests {
+    use std::{
+        sync::{Once, OnceLock},
+        time::Duration,
+    };
+
+    use insta::assert_debug_snapshot;
+    use tokio::{join, spawn};
+
+    use super::*;
+    const DOC_LIT: &str = r#"
+app "fizz-buzz"
+    packages { pf: "https://github.com/roc-lang/basic-cli/releases/download/0.5.0/Cufzl36_SnJ4QbOoEmiJ5dIpUxBvdB3NEySvuH82Wio.tar.br" }
+    imports [pf.Stdout,pf.Task.{ Task, await },]
+    provides [main] to pf
+"#;
+    static INIT: Once = Once::new();
+    async fn test_setup(doc: String) -> (Inner, Url) {
+        INIT.call_once(|| {
+            env_logger::builder()
+                .is_test(true)
+                .filter_level(log::LevelFilter::Trace)
+                .init();
+        });
+        // static INNER_CELL: OnceLock<Inner> = OnceLock::new();
+        // INNER_CELL.set(Inner::new()).unwrap();
+        // static URL_CELL: OnceLock<Url> = OnceLock::new();
+        // URL_CELL.set().unwrap()).unwrap();
+
+        // let inner = INNER_CELL.get().unwrap();
+        let url = Url::parse("file:/test.roc").unwrap();
+
+        let inner = Inner::new();
+        //setup the file
+        inner.change(&url, doc, 0).await.unwrap();
+        (inner, url)
+    }
+
+    #[tokio::test]
+    async fn test_inner_change() {
+        let doc = DOC_LIT.to_string()
+            + r#"rec=\a,b->{one:{potato:\d->d,leak:59},two:b}
+rectest= 
+  value= rec 1 2
+  va"#;
+        let (inner, url) = test_setup(doc.clone()).await;
+        static INNER_CELL: OnceLock<Inner> = OnceLock::new();
+        INNER_CELL.set(inner).unwrap();
+        static URL_CELL: OnceLock<Url> = OnceLock::new();
+        URL_CELL.set(url).unwrap();
+
+        let inner = INNER_CELL.get().unwrap();
+        let url = URL_CELL.get().unwrap();
+        let position = Position::new(8, 8);
+        //setup the file
+        inner.change(&url, doc.clone(), 1).await.unwrap();
+
+        //apply a sequence of changes back to back
+        let a1 = spawn(inner.change(&url, doc.clone() + "l", 2));
+        let a2 = spawn(inner.change(&url, doc.clone() + "lu", 3));
+        let a3 = spawn(inner.change(&url, doc.clone() + "lue", 4));
+        let a4 = spawn(inner.change(&url, doc.clone() + "lue.", 5));
+        //start a completion that would only work if all changes have been applied
+        let comp = spawn(async move {
+            let url2 = url.clone();
+            let reg = inner.registry().await;
+            reg.completion_items(&url2, position).await
+        });
+        // Simulate two changes coming in with a slight delay
+        let a = spawn(inner.change(&url, doc.clone() + "lue.o", 6));
+        tokio::time::sleep(Duration::from_millis(100)).await;
+        let rest = spawn(inner.change(&url, doc.clone() + "lue.on", 7));
+
+        let done = join!(a1, a2, a3, a4, comp, a, rest);
+
+        assert_debug_snapshot!(done)
+    }
+    #[tokio::test]
+    async fn test_as_identifier() {
+        let suffix = DOC_LIT.to_string()
+            + r#"
+main =
+  when a is
+    inn as outer -> "#;
+        let (inner, url) = test_setup(suffix.clone()).await;
+        //test compltion for outer
+        let position = Position::new(8, 21);
+
+        let change = suffix.clone() + "o";
+        inner.change(&url, change, 1).await.unwrap();
+        let comp1 = inner
+            .registry()
+            .await
+            .completion_items(&url, position)
+            .await;
+
+        let c = suffix.clone() + "i";
+        inner.change(&url, c, 2).await.unwrap();
+        let comp2 = inner
+            .registry()
+            .await
+            .completion_items(&url, position)
+            .await;
+
+        let actual = [comp1, comp2];
+        assert_debug_snapshot!(actual)
+    }
+
+    #[tokio::test]
+    async fn test_as_record() {
+        let doc = DOC_LIT.to_string()
+            + r#"
+main =
+  when a is
+    {one,two} as outer -> "#;
+        let (inner, url) = test_setup(doc.clone()).await;
+        //test compltion for outer
+        let position = Position::new(8, 27);
+
+        let change = doc.clone() + "o";
+        inner.change(&url, change, 1).await.unwrap();
+        let comp1 = inner
+            .registry()
+            .await
+            .completion_items(&url, position)
+            .await;
+
+        let c = doc.clone() + "t";
+        inner.change(&url, c, 2).await.unwrap();
+        let comp2 = inner
+            .registry()
+            .await
+            .completion_items(&url, position)
+            .await;
+
+        let actual = [comp1, comp2];
+        assert_debug_snapshot!(actual);
+    }
+}

crates/lang_srv/src/snapshots/roc_ls__tests__as_identifier.snap

@@ -0,0 +1,87 @@
+---
+source: crates/lang_srv/src/server.rs
+expression: actual
+---
+[
+    Some(
+        Array(
+            [
+                CompletionItem {
+                    label: "outer",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+            ],
+        ),
+    ),
+    Some(
+        Array(
+            [
+                CompletionItem {
+                    label: "inn",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+                CompletionItem {
+                    label: "outer",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+            ],
+        ),
+    ),
+]

crates/lang_srv/src/snapshots/roc_ls__tests__as_record.snap

@@ -0,0 +1,156 @@
+---
+source: crates/lang_srv/src/server.rs
+expression: actual
+---
+[
+    Some(
+        Array(
+            [
+                CompletionItem {
+                    label: "one",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+                CompletionItem {
+                    label: "two",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+                CompletionItem {
+                    label: "outer",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+            ],
+        ),
+    ),
+    Some(
+        Array(
+            [
+                CompletionItem {
+                    label: "one",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+                CompletionItem {
+                    label: "two",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+                CompletionItem {
+                    label: "outer",
+                    kind: Some(
+                        Variable,
+                    ),
+                    detail: Some(
+                        "*",
+                    ),
+                    documentation: None,
+                    deprecated: None,
+                    preselect: None,
+                    sort_text: None,
+                    filter_text: None,
+                    insert_text: None,
+                    insert_text_format: None,
+                    insert_text_mode: None,
+                    text_edit: None,
+                    additional_text_edits: None,
+                    command: None,
+                    commit_characters: None,
+                    data: None,
+                    tags: None,
+                },
+            ],
+        ),
+    ),
+]

crates/lang_srv/src/snapshots/roc_ls__tests__inner_change.snap

@@ -0,0 +1,90 @@
+---
+source: crates/lang_srv/src/server.rs
+expression: done
+---
+(
+    Ok(
+        Err(
+            "version 2 doesn't match latest: 7 discarding analysis  ",
+        ),
+    ),
+    Ok(
+        Err(
+            "version 3 doesn't match latest: 7 discarding analysis  ",
+        ),
+    ),
+    Ok(
+        Err(
+            "version 4 doesn't match latest: 7 discarding analysis  ",
+        ),
+    ),
+    Ok(
+        Err(
+            "version 5 doesn't match latest: 7 discarding analysis  ",
+        ),
+    ),
+    Ok(
+        Some(
+            Array(
+                [
+                    CompletionItem {
+                        label: "one",
+                        kind: Some(
+                            Variable,
+                        ),
+                        detail: Some(
+                            "{ leak : Num *, potato : a -> a }",
+                        ),
+                        documentation: None,
+                        deprecated: None,
+                        preselect: None,
+                        sort_text: None,
+                        filter_text: None,
+                        insert_text: None,
+                        insert_text_format: None,
+                        insert_text_mode: None,
+                        text_edit: None,
+                        additional_text_edits: None,
+                        command: None,
+                        commit_characters: None,
+                        data: None,
+                        tags: None,
+                    },
+                    CompletionItem {
+                        label: "two",
+                        kind: Some(
+                            Variable,
+                        ),
+                        detail: Some(
+                            "Num *",
+                        ),
+                        documentation: None,
+                        deprecated: None,
+                        preselect: None,
+                        sort_text: None,
+                        filter_text: None,
+                        insert_text: None,
+                        insert_text_format: None,
+                        insert_text_mode: None,
+                        text_edit: None,
+                        additional_text_edits: None,
+                        command: None,
+                        commit_characters: None,
+                        data: None,
+                        tags: None,
+                    },
+                ],
+            ),
+        ),
+    ),
+    Ok(
+        Err(
+            "version 6 doesn't match latest: 7 discarding analysis  ",
+        ),
+    ),
+    Ok(
+        Ok(
+            (),
+        ),
+    ),
+)