Add optional logging to track down completion issues.

Author: chrisant996

TODO.md

@@ -13,6 +13,19 @@ _This todo list describes ChrisAnt996's current intended roadmap for Clink's fut
   - ~~Maybe the repro is to queue up typing before the prompt, so that when the prompt shows it starts a coroutine to generate matches (e.g. for suggestions) but then typing and `TAB` is processed while the matches coroutine is already running?~~
   - I tried forcing several different race conditions, and none of them could reproduce the issue.  It happens only very rarely, so until I can find more detailed context, I can't even tell if it's a recent regression or if it only occurs in a certain configuration.  But my guess is it's either a recent regression, or an issue exposed/exacerbated by recent features.
   - I just hit it again.  I'll have to try to build optional logging to track it down.
+  - Does not seem to be related to coroutine generators superceding main routine generators (tried injecting os.sleep into coroutine generators to make them take longer, and was unable to repro).
+  - **What to log:**
+    - context that triggered running generators
+    - context that skips generating, and why
+    - context that cancels generating, and why
+    - context of timeout of generating (suggestionlist has some kind of timeout IIRC)
+    - context of reset generate matches
+    - begin generating
+    - coroutine or ismain
+    - volatile
+    - matches
+    - generation id
+    - finish generating
 - Some way for `io.popen`, `io.popenyield`, `os.execute`, etc to run without a console window.  `clink.execute` exists, but has quirks and doesn't support yielding.  This is a problem for any match generators that want to run Powershell, because Powershell insists on changing the window title.  Either they have to accept asynchronous window title changes, or they block until the Powershell command finishes.  For example, the `pid_complete.lua` module is impacted by this.
 - Some way for input hints to show up when the suggestion list is active?
 - Make a documentation section that lists all the CLINK environment variables.

clink/lib/include/lib/matches.h

@@ -267,7 +267,8 @@ class match_builder
 
     void                    set_deprecated_mode();
     void                    set_matches_are_files(bool files=true);
-    void                    set_input_line(const char* text);
+    void                    set_input_line(const char* text, int32 generation_id);
+    int32                   get_generation_id() const;
 
 private:
     matches&                m_matches;

clink/lib/src/line_editor_impl.cpp

@@ -31,6 +31,7 @@
 #include <core/str_iter.h>
 #include <core/str_tokeniser.h>
 #include <core/settings.h>
+#include <core/log.h>
 #include <terminal/terminal_in.h>
 #include <terminal/terminal_out.h>
 #include <terminal/input_idle.h>
@@ -570,13 +571,37 @@ bool line_editor_impl::notify_matches_ready(int32 generation_id, matches* matche
         m_matches.transfer(static_cast<matches_impl&>(*matches));
         m_matches.done_building();
         clear_flag(flag_generate);
+        if (dbg_get_env_int("CLINK_LOG_GENERATORS"))
+        {
+            str<> tmp;
+            int32 i = 0;
+            for (matches_iter iter = m_matches.get_iter(); iter.next(); i++)
+            {
+                if (i >= 5)
+                {
+                    tmp.concat(", ...");
+                    break;
+                }
+                else if (i > 0)
+                    tmp.concat(", ");
+                else
+                    tmp.concat(" -> ");
+                tmp.concat(iter.get_match());
+            }
+            assert(generation_id == m_matches.get_generation_id());
+            LOG("TRANSFERED MATCHES: %u matches, gen %d%s%s", m_matches.get_match_count(), m_matches.get_generation_id(), m_matches.is_volatile() ? ", *VOLATILE*" : "", tmp.c_str());
+        }
     }
     else
     {
         // There's a newer generation id, so force a new suggestion, since the
         // newer generation id's autosuggest will have been canceled due to the
         // match generator coroutine that was already running, and which has
         // just now signaled its completion.
+        if (dbg_get_env_int("CLINK_LOG_GENERATORS"))
+        {
+            LOG("CLEAR MATCHES: matches gen %d vs editor gen %d", generation_id, m_matches_generation_id);
+        }
         clear_suggestion();
     }
 
@@ -1704,6 +1729,11 @@ void line_editor_impl::try_suggest()
             // cannot work with wildcards or substrings.
             rollback<int32> rb_completion_type(rl_completion_type, TAB);
 
+            if (dbg_get_env_int("CLINK_LOG_GENERATORS"))
+            {
+                LOG("try_suggest, update_matches");
+            }
+
             update_matches();
             matches = &m_matches;
         }

clink/lib/src/match_pipeline.cpp

@@ -15,6 +15,7 @@
 #include <core/str_compare.h>
 #include <core/str_unordered_set.h>
 #include <core/settings.h>
+#include <core/log.h>
 #include <terminal/ecma48_iter.h>
 
 extern "C" {
@@ -334,11 +335,32 @@ void match_pipeline::generate(
 
     m_matches.done_building();
 
+    if (dbg_get_env_int("CLINK_LOG_GENERATORS"))
+    {
+        str<> tmp;
+        int32 i = 0;
+        for (matches_iter iter = m_matches.get_iter(); iter.next(); i++)
+        {
+            if (i >= 5)
+            {
+                tmp.concat(", ...");
+                break;
+            }
+            else if (i > 0)
+                tmp.concat(", ");
+            else
+                tmp.concat(" -> ");
+            tmp.concat(iter.get_match());
+        }
+        LOG("GENERATED MATCHES: %u matches, gen %d%s%s", m_matches.get_match_count(), m_matches.get_generation_id(), m_matches.is_volatile() ? ", *VOLATILE*" : "", tmp.c_str());
+    }
+
 #ifdef DEBUG
     if (dbg_get_env_int("DEBUG_PIPELINE"))
     {
-        printf("GENERATE, %u matches, word break %u, file_comp %u %s --%s",
+        printf("GENERATE, %u matches, gen %d, word break %u, file_comp %u %s --%s",
                m_matches.get_match_count(),
+               m_matches.get_generation_id(),
                m_matches.get_word_break_position(),
                m_matches.is_filename_completion_desired().get(),
                m_matches.is_filename_completion_desired().is_explicit() ? "(exp)" : "(imp)",

clink/lib/src/matches_impl.cpp

@@ -334,9 +334,15 @@ void match_builder::set_volatile()
 }
 
 //------------------------------------------------------------------------------
-void match_builder::set_input_line(const char* text)
+void match_builder::set_input_line(const char* text, int32 generation_id)
 {
-    return ((matches_impl&)m_matches).set_input_line(text);
+    return ((matches_impl&)m_matches).set_input_line(text, generation_id);
+}
+
+//------------------------------------------------------------------------------
+int32 match_builder::get_generation_id() const
+{
+    return ((matches_impl&)m_matches).get_generation_id();
 }
 
 //------------------------------------------------------------------------------
@@ -563,8 +569,8 @@ matches_impl::store_impl::store_impl(uint32 size)
 
 
 //------------------------------------------------------------------------------
-matches_impl::matches_impl(uint32 store_size)
-: m_store(min(store_size, 0x10000u))
+matches_impl::matches_impl()
+: m_store(0x10000u)
 , m_filename_completion_desired(false)
 , m_filename_display_desired(false)
 {
@@ -931,6 +937,7 @@ void matches_impl::transfer(matches_impl& from)
 
     m_store = std::move(from.m_store);
     m_infos = std::move(from.m_infos);
+    m_generation_id = from.m_generation_id;
     m_count = from.m_count;
     m_any_none_type = from.m_any_none_type;
     m_deprecated_mode = from.m_deprecated_mode;
@@ -978,6 +985,7 @@ void matches_impl::copy(const matches_impl& from)
         m_infos.emplace_back(std::move(add));
     }
 
+    m_generation_id = from.m_generation_id;
     m_count = from.m_count;
     m_any_none_type = from.m_any_none_type;
     m_deprecated_mode = from.m_deprecated_mode;
@@ -1094,9 +1102,11 @@ void matches_impl::set_volatile()
 }
 
 //------------------------------------------------------------------------------
-void matches_impl::set_input_line(const char* text)
+void matches_impl::set_input_line(const char* text, int32 generation_id)
 {
+    assert(generation_id > 0);
     m_input_line = text;
+    m_generation_id = generation_id;
 }
 
 //------------------------------------------------------------------------------

clink/lib/src/matches_impl.h

@@ -62,7 +62,7 @@ class matches_impl
 public:
     typedef std::unordered_set<match_lookup, match_lookup_hasher, match_lookup_comparator> match_lookup_unordered_set;
 
-                            matches_impl(uint32 store_size=0x10000);
+                            matches_impl();
                             ~matches_impl();
     matches_iter            get_iter() const;
     matches_iter            get_iter(const char* pattern) const;
@@ -96,6 +96,7 @@ class matches_impl
     void                    set_regen_blocked();
     bool                    is_regen_blocked() const { return m_regen_blocked; }
     int32                   get_completion_type() const { return m_completion_type; }
+    int32                   get_generation_id() const { return m_generation_id; }
 
     void                    set_generator(match_generator* generator);
     void                    done_building();
@@ -127,7 +128,7 @@ class matches_impl
     void                    set_no_sort();
     void                    set_has_descriptions();
     void                    set_volatile();
-    void                    set_input_line(const char* text);
+    void                    set_input_line(const char* text, int32 generation_id);
     bool                    is_from_current_input_line();
     bool                    add_match(const match_desc& desc, bool already_normalised=false);
     uint32                  get_info_count() const;
@@ -150,6 +151,7 @@ class matches_impl
 
     store_impl              m_store;
     infos                   m_infos;
+    int32                   m_generation_id = -1;
     unsigned short          m_count = 0;
     bool                    m_any_none_type = false;
     bool                    m_deprecated_mode = false;

clink/lua/scripts/generator.lua

@@ -33,6 +33,29 @@ clink.match_display_filter = nil
 
 
 
+--------------------------------------------------------------------------------
+-- luacheck: globals NOSTK
+local nostk_cookie = {}
+NOSTK = nostk_cookie
+function clink._log_generators(...)
+    local co, ismain = coroutine.running()
+    local msg = (ismain and "*" or "")..tostring(co).."  ---"
+    local add_stack = true
+    for _, e in ipairs({...}) do
+        if e == nostk_cookie then
+            add_stack = false
+        else
+            msg = msg.."  "..tostring(e)
+        end
+    end
+    if add_stack and (tonumber(os.getenv("CLINK_LOG_GENERATORS")) or 0) > 1 then
+        msg = msg.."  ---  " .. debug.traceback()
+    end
+    log.info(msg)
+end
+
+
+
 --------------------------------------------------------------------------------
 local function advance_ignore_quotes(word, seek)
     if seek > 1 then
@@ -122,6 +145,10 @@ local function cancel_match_generate_coroutine()
     if ismain and _match_generate_state.coroutine then
         -- Make things (e.g. globbers) short circuit to faciliate coroutine
         -- completing as quickly as possible.
+        if os.getenv("CLINK_LOG_GENERATORS") then
+            clink._log_generators("cancel_match_generate_coroutine", _match_generate_state.coroutine,
+                                  "started", _match_generate_state.started and "true" or "false")
+        end
         clink._cancel_coroutine(_match_generate_state.coroutine)
         if not _match_generate_state.started then
             -- If it never started, remove it from the scheduler.
@@ -138,6 +165,8 @@ function clink._make_match_generate_coroutine(line, lines, matches, builder, gen
         return
     end
 
+    local do_log = os.getenv("CLINK_LOG_GENERATORS")
+
     -- Create coroutine to generate matches.  The coroutine is automatically
     -- scheduled for resume while waiting for input.
     coroutine.override_isgenerator()
@@ -146,6 +175,10 @@ function clink._make_match_generate_coroutine(line, lines, matches, builder, gen
         -- started, it can be removed from the scheduler.
         _match_generate_state.started = true
 
+        if do_log then
+            clink._log_generators("match_generate_coroutine", "BEGIN", "gen", generation_id)
+        end
+
         -- Generate matches.
         clink._generate(line, lines, builder)
 
@@ -166,13 +199,27 @@ function clink._make_match_generate_coroutine(line, lines, matches, builder, gen
             clink.runonmain(function()
                 -- PERF: This can potentially take some time, especially in
                 -- Debug builds.
-                builder:matches_ready(generation_id)
+                if do_log then
+                    clink._log_generators("_matches_ready", string.format("(FROM %s)", tostring(c)))
+                end
+                builder:_matches_ready(generation_id)
             end)
         else
-            builder:clear_toolkit()
+            if do_log then
+                clink._log_generators("_clear_toolkit", NOSTK)
+            end
+            builder:_clear_toolkit()
+        end
+
+        if do_log then
+            clink._log_generators("match_generate_coroutine", "END", NOSTK)
         end
     end)
 
+    if do_log then
+        clink._log_generators("_make_match_generate_coroutine", "->", c, NOSTK)
+    end
+
     clink.setcoroutinename(c, "generate matches")
     _match_generate_state.coroutine = c
     _match_generate_state.started = nil
@@ -255,7 +302,14 @@ function clink._generate(line_state, line_states, match_builder, old_filtering)
     prepare()
     clink.co_state._current_builder = match_builder
 
+    local do_log = os.getenv("CLINK_LOG_GENERATORS")
+    if do_log then
+        clink._log_generators("clink._generate", "BEGIN", "gen", match_builder:_get_generation_id())
+    end
     local ok, ret = xpcall(impl, _error_handler_ret)
+    if do_log then
+        clink._log_generators("clink._generate", "END", NOSTK)
+    end
     if not ok then
         print("")
         print("match generator failed:")
@@ -268,7 +322,7 @@ function clink._generate(line_state, line_states, match_builder, old_filtering)
     end
 
     if not clink._is_coroutine_canceled(coroutine.running()) then
-        match_builder:set_input_line(line_state:getline())
+        match_builder:_set_input_line(line_state:getline(), match_builder:_get_generation_id())
     end
 
     clink.co_state._current_builder = nil

clink/lua/src/match_builder_lua.cpp

@@ -26,9 +26,10 @@ const match_builder_lua::method match_builder_lua::c_methods[] = {
     { "deprecated_addmatch", &deprecated_add_match },
     { "setmatchesarefiles", &set_matches_are_files },
     // UNDOCUMENTED; internal use only.
-    { "clear_toolkit",      &clear_toolkit },
-    { "set_input_line",     &set_input_line },
-    { "matches_ready",      &matches_ready },
+    { "_clear_toolkit",     &clear_toolkit },
+    { "_set_input_line",    &set_input_line },
+    { "_matches_ready",     &matches_ready },
+    { "_get_generation_id", &get_generation_id },
     {}
 };
 
@@ -351,11 +352,14 @@ int32 match_builder_lua::clear_toolkit(lua_State* state)
 // UNDOCUMENTED; internal use only.
 int32 match_builder_lua::set_input_line(lua_State* state)
 {
+    if (!m_toolkit)
+        return 0;
+
     const char* text = checkstring(state, LUA_SELF + 1);
     if (!text)
         return 0;
 
-    m_builder->set_input_line(text);
+    m_builder->set_input_line(text, m_toolkit->get_generation_id());
     return 0;
 }
 
@@ -374,6 +378,23 @@ int32 match_builder_lua::matches_ready(lua_State* state)
     return 1;
 }
 
+//------------------------------------------------------------------------------
+// UNDOCUMENTED; internal use only.
+int32 match_builder_lua::get_generation_id(lua_State* state)
+{
+    if (m_toolkit)
+    {
+        lua_pushinteger(state, m_toolkit->get_generation_id());
+        lua_pushliteral(state, "toolkit");
+    }
+    else
+    {
+        lua_pushinteger(state, m_builder->get_generation_id());
+        lua_pushliteral(state, "builder");
+    }
+    return 2;
+}
+
 //------------------------------------------------------------------------------
 /// -name:  builder:addmatches
 /// -ver:   1.0.0

clink/lua/src/match_builder_lua.h

@@ -40,6 +40,7 @@ class match_builder_lua
     int32           clear_toolkit(lua_State* state);
     int32           set_input_line(lua_State* state);
     int32           matches_ready(lua_State* state);
+    int32           get_generation_id(lua_State* state);
 
 private:
     bool            add_match_impl(lua_State* state, int32 stack_index, match_type type);