Lua debug output? about clink HOT 12 CLOSED

For debugger improvements, try the build from this auto workflow build.

And to help with converting scripts, build the latest docs via premake5 docs, and then start .build\docs\clink.html. There's a lot of updated info, and out of date sections are clearly marked with a "TODO" callout. Search for "deprecated" to find conversion info and examples for converting from old to new API.

Three things:

1. I added some Lua debugger improvements in c93174f after the 1.1.2-alpha release. Among other things, now you can turn on clink set lua.traceback 1 to get a stack trace on every error. Once you get a stack trace from the lua.traceback setting, then it's easy enough to manually inject a pause() to break into the debugger -- or for that matter to set a breakpoint on the file+line.

2. Today I believe I got backward compatibility working for all the major things -- except for match display filtering, which is essentially just gone and was a niche capability anyway. It's still worth updating scripts to use the new API because the Clink schema changed significantly enough that 1:1 compatibility support isn't really possible, and I expect there are edge cases where the behavior won't be quite the same as before. I'll investigate any cases that are found, and will fix ones that don't involve too much effort. At this point, I don't expect to add more compatibility shims, only potentially fix some issues in the existing shims.

3. The Lua API Reference section in the docs is mostly done (argmatcher and clink.generator still need filled out). The backward compatibility APIs are documented as deprecated and include sample code for the general pattern of how to convert scripts from the old API to the new API. (I haven't started on the Extending Clink how-to section yet; that'll come after the Reference section is finished.)

I would love feedback on the documentation -- anything that isn't clear, or that doesn't quite connect the dots enough, or any other thoughts, etc.

Also, I hope to eventually hook up a setting to automatically break into the debugger on every error, but something's not working right with it and I was getting nowhere on it so I gave up for now. That's ok; given the new traceback ability, automatically breaking to the debugger would only be a convenience to avoid manually injecting a pause().

from clink.

I'm not seeing any errors in the logs even when the scripts are obviously failing. How can I get better debug information on where the lua scripts are failing?

Also, just double checking -- If you're seeing nothing at all, how do you know scripts are failing? What if they aren't even getting loaded in the first place, due to maybe some issue with the --scripts argument or the way that Cmder tries to override and redirect Clink's script loading.

Lua errors should be emitted to stdout. Of course, it's possible for code to misbehave without actually triggering any errors, in which case debugging is needed (or inject some print() statements into scripts).

• clink set lua.debug 1 enables the Lua debugger. Put a pause() in a script, and it will break to the debugger.
• clink set lua.traceback 1 enables printing a stack trace on any error.

Also, if the debugger is enabled, then if a prompt filter or match generator fail (not sure yet exactly what kinds of failures) then it'll print a stack trace and break to the debugger. I might stop it from breaking to the debugger, though -- it seems like Just Too Late™ debugging. 😜

from clink.

Interesting. Clink's error output is getting eaten somehow while running inside Cmder/ConEmu. It doesn't get eaten for 0.4.9, so I assume it's a problem in Clink itself.

A few things:

• Clink no longer has a clink.lua file; the scripts are built into the program now.
• Cmder has a vendor\clink.lua file, which tries to load vendor\clink\clink.lua. I deleted the latter file, since that's the right thing to do -- trying to load it would go Very Wrong.
• Then vendor\clink.lua hits a fatal error because dofile() failed.
• Lua reports the error... but the text never reaches the console!

Commenting out the dofile() call at the top of vendor\clink.lua lets it continue.
And then it seems like it's working. 🤷‍♂️

But obviously I have to figure out why the output is getting eaten...

from clink.

I injected a syntax error into one Lua script, and a print("hello") call into another Lua script, and then I invoked each of them in three configurations: cmder with clink 0.4.9, cmder with clink 1.1.2, and ConEmu with clink 1.1.2.

I stepped through the assembly language for most of the cases.
Lua inside Clink calls luaB_error() and luaB_print() to print the error and message, respectively.
All end up calling fwrite() which ends up calling WriteFile() with the expected output strings.

The hooked WriteFile implementation seems to be OnWriteFile() in src/ConEmuHk/hkStdIO.cpp.

But ConEmuHk64.dll hooked WriteFile and intercepts the calls.
With Clink 0.4.9, Cmder/ConEmu for some reason lets the output strings reach the screen.
With Clink 1.1.2, Cmder/ConEmu for some reason doesn't let the output strings reach the screen.
With Clink 1.1.2 and raw, stock ConEmu, the output strings reach the screen.

So it seems that only Cmder is suppressing output from Clink; stock ConEmu seems to work fine.

from clink.

• Clink no longer has a clink.lua file; the scripts are built into the program now.

D'oh. I was specifically copying that file too. After trying the steps you listed, it works now. In fact, I think that's why I wasn't seeing anything.

Interesting. Clink's error output is getting eaten somehow while running inside Cmder/ConEmu. It doesn't get eaten for 0.4.9, so I assume it's a problem in Clink itself.

In my testing with a build on your current master with Cmder, I ran into a bug in the npm completion script, and it output an error message to console:

...ools\Cmder/vendor/clink-completions/modules/matchers.lua:32: attempt to call field 'matches_are_files' (a nil value)
stack traceback:
        ...link/.build/vs2019/../../clink/lua/scripts/generator.lua:17: in function 'pcall_dispatch'
        ...link/.build/vs2019/../../clink/lua/scripts/generator.lua:49: in function <...link/.build/vs2019/../../clink/lua/scripts/generator.lua:36>

I thought this might have been because I'm not using the ConEmu that comes with Cmder (201011 vs. Cmder's 191012), so I tested it with that. It still output to console. Then, I made a new cmder directory with stock user settings to see if that was messing with it, and it still output to console. It's not my build; it still outputs an error message to console with the actions build, albiet with redacted stack traces. It's very strange that our positions are reversed now.

from clink.

I am on Windows Insider though, build 20251.

from clink.

1. Clink should probably include a clink.lua that contains just -- This file is intentionally blank. so that if/when people copy new Clink over top of old Clink there won't be a lingering old clink.lua file. 😁

2. A couple times now, I've seen WriteFile calls reach the screen in new-clink-in-cmder. It seems that if they work, then they'll work for the whole session. And if they don't, then they won't for the whole session. Something strange is going on. And I think -- cannot swear -- that I've now seen old-clink-in-cmder also have its output get suppressed once. I've opened/closed so many debugging sessions that maybe I got confused? I think I'm seeing inconsistent results, but I can't prove it conclusively.

from clink.

Interesting:

• The suppressed output seems to be caused by something in the init.bat script.
• The init.bat script is also what makes starting clink so slow in cmder: I removed all of the @echo off lines, and it's surprising how much work is happening in that script. Surely it can be pruned or optimized.
• In a given Cmder.exe session:
  • Launching the vendor\clink copy of clink with inject --quiet --profile "%CMDER_ROOT%\config" --scripts "%CMDER_ROOT%\vendor" always starts clink super fast, and output always works correctly.
  • But launching the same copy of clink and calling the %CMDER_ROOT%\vendor\init.bat script results in very slow startup, and also sometimes results in output getting suppressed in the associated clink tab.

It's looking like the problems are part of Cmder, but it could also be possible that the init.bat script is merely exposing an issue in Clink.

from clink.

This line in init.bat seems to significantly affected the likelihold that Clink output will end up getting suppressed:

%lib_git% get_user_git_version

With that line present, there's a 30-40% chance output will be suppressed in a particular instance of cmder/cmd/clink.
Without that line, I have to simultaneously start several instances of cmder/cmd/clink in order for 1 or 2 of them to have output suppressed.

Aha -- and Cmder causes the same output suppression in Clink 0.4.x as it does in Clink 1.x.

I copied ConEmu 200713 into the corresponding Cmder vendor directory, and 200713 also suppresses. But ConEmu by itself, or Cmder without init.bat don't suppress. Hm.

from clink.

Output is suppressed because the handle is invalid.
Next step is to track down where the invalid handle came from and why it's invalid.

Details:

• I cloned the ConEmu repo, built x64 Debug, and copied the binaries into the corresponding Cmder vendor directory.
• I launched Cmder and created new console tabs until output was suppressed.
• I attached the VS 2019 debugger to the cmd.exe instance and set a breakpoint on WriteFile.
• I pressed Enter in the console tab to trigger print() calls I added to one of the Lua scripts.
• I stepped through the OnWriteFile hook and through the assembly code for WriteFile.
• The handle being used yields INVALID_HANDLE_VALUE as the error code from WriteFile, and from GetConsoleMode, and from other APIs. So naturally anything written to it will get eaten.
• The C runtime thinks the stdout handle is one value, but GetStdHandle(STD_OUTPUT_HANDLE) returns a different value.

Maybe the handle was changed after the C runtime initialized? The C runtime doesn't support the underlying handle changing after the stdio FILE structs are initialized, which happens as one of the first things while the C runtime is initialized (e.g. see initialize_stdio_handles_nolock, which seems to be the only place that calls GetStdHandle(STD_OUTPUT_HANDLE)).

Some other interesting observations:

• The Debug build of ConEmu intermittently fires a few assertions.
• The assertions don't seem to correlate with the invalid handle issue.

from clink.

Closing since the original issue was a difference between how old and new Clink were installed (and new Clink now includes an intentionally blank clink.lua file to avoid that problem in the future), and the general issue of intermittent suppressed output occurs with both old and new Clink and is somehow being induced externally from Clink. Nothing further to do in Clink itself for this issue.

from clink.

Just adding a cross-reference:

Output is suppressed because the handle is invalid.

Issue #93 has the full information on stdout getting broken in Cmder.

from clink.