Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add debug mode to ShellExtension #355

Closed
AndydeCleyre opened this issue Jul 9, 2020 · 38 comments
Closed

Add debug mode to ShellExtension #355

AndydeCleyre opened this issue Jul 9, 2020 · 38 comments
Labels
RFNR Ready to be shipped in next release

Comments

@AndydeCleyre
Copy link
Contributor

Sometimes when writing a match that uses the shell plugin, there will be a problem that interferes with proper replacement, but the nature of the problem is difficult to ascertain. The yaml syntax can be valid, the match can be triggered, but the replacement is missing.

Adding -vvv (up to how many makes a difference?) to the espanso worker command doesn't reveal if any error happened during the command run, or what the output/error was, if any.

I encountered this debugging difficulty as I tried to add a trigger for local IP address, 2 ways:

  - trigger: :local
    replace: "{{address}}"
    vars:
      - name: address
        type: shell
        params:
          cmd: 'nmcli device show wlan0 | pcre2grep -M -O ''$1'' ''^IP4.ADDRESS\[1\]: *(.*)/.*'''
          # cmd: 'ip addr | pcre2grep -M -O ''$2'' ''^\d: wlan0: (.*\n[^\d])*.* inet ((\d+\.){3}\d+)/'''

Neither of the two cmd values above produced a replacement. There are a lot of symbols, and maybe the command being run isn't what I think it is, and it would help if I could find out if it is, and anything else about the commands being run.

@federico-terzi
Copy link
Collaborator

Hey @AndydeCleyre,

Which version of espanso are you using?

Cheers :)

@federico-terzi federico-terzi added the enhancement New feature or request label Jul 9, 2020
@AndydeCleyre
Copy link
Contributor Author

I'm using the current release, 0.6.3, via the AUR.

@federico-terzi
Copy link
Collaborator

That's strange then! Since version 0.6.0, if you run a shell command and it returns an error, that is logged.
So if that command is not working, you could check espanso log to see the error.
Let me know if that works, otherwise, I'll make sure to check myself :)

@AndydeCleyre
Copy link
Contributor Author

Yes, that works, as I changed the cmd to cat nonexistentfile and espanso log shows

15:06:38 [ WARN] Shell command reported error:
cat: nonexistentfile: No such file or directory

So the example commands from the issue report are running "successfully" but not as expected. So it would be really helpful to be able to verify the exact command being run, and what its stdout and stderr are.

@federico-terzi
Copy link
Collaborator

All right, thank you @AndydeCleyre. I'll make sure to add an option to log the complete cmd line that is being executed. That should solve the problem right?

@AndydeCleyre
Copy link
Contributor Author

Thanks!

That should solve the problem right?

Maybe, if it turns out that the command is not run as expected due to yaml parsing or something. But if the command is exactly as expected, I'd still want to know what its out and err are, because I still won't have a clue why the replacement is not successful.

Further, sometimes knowing the specific error code (rather than just whether or not it's 0) can be helpful.

It's hard to debug when there's so much separation from the bash process. So I'd still hope for more logging details, or some debug subcommand to simply run a shell-type match in the foreground.

@federico-terzi
Copy link
Collaborator

Seems like a great idea. To sum up, the proposal would be:

Add a debug: true option to the ShellExtension to help when experiencing problems.
Turning on the debug option, will force espanso to print the following information to the logs:

  • Exit code
  • Stdout
  • Stderr
  • Complete cmd line fed to the shell

An example usage would be:

  - trigger: :local
    replace: "{{address}}"
    vars:
      - name: address
        type: shell
        params:
          cmd: 'nmcli device show wlan0 | pcre2grep -M -O ''$1'' ''^IP4.ADDRESS\[1\]: *(.*)/.*'''
          debug: true

@AndydeCleyre would you like to change anything to this proposal?

@AndydeCleyre
Copy link
Contributor Author

AndydeCleyre commented Jul 9, 2020

That's excellent, thank you! Nothing to change.

Implementing as a param to the shell var item is a smart improvement over using espanso process flags, much more convenient, and targeted. 👍 👍

EDIT: Thanks for your continued work on this project, I really enjoy using it.

@federico-terzi
Copy link
Collaborator

@AndydeCleyre Great! Thanks for the help, I'll add it to the roadmap :)

@federico-terzi federico-terzi added Feature and removed enhancement New feature or request labels Jul 9, 2020
@federico-terzi federico-terzi changed the title Request: In debug logging, include stdout, stderr, return code, and run-command-string of shell plugin actions Add debug mode to ShellExtension Jul 9, 2020
@deckarep
Copy link
Contributor

I'd like to take a crack at this since it seems pretty straightforward.

@AndydeCleyre
Copy link
Contributor Author

I tried the current state of #359, and it is indeed helpful. Is the following behavior to be expected (am I using improper syntax), or is this demonstrating a bug, for which I should open a new issue?

yaml:

cmd: 'nmcli device show wlan0 | pcre2grep -M -O ''$1'' ''^IP4.ADDRESS\[1\]: *(.*)/.*'''

expected cmd string:

nmcli device show wlan0 | pcre2grep -M -O '$1' '^IP4.ADDRESS\[1\]: *(.*)/.*'

actual cmd string:

nmcli device show wlan0 | pcre2grep -M -O '' '^IP4.ADDRESS\[1\]: *(.*)/.*'

yaml:

cmd: 'ip addr | pcre2grep -M -O ''$2'' ''^\d: wlan0: (.*\n[^\d])*.* inet ((\d+\.){3}\d+)/'''

expected cmd string:

ip addr | pcre2grep -M -O '$2' '^\d: wlan0: (.*\n[^\d])*.* inet ((\d+\.){3}\d+)/'

actual cmd string:

ip addr | pcre2grep -M -O '' '^\d: wlan0: (.*\n[^\d])*.* inet ((\d+\.){3}\d+)/'

@deckarep
Copy link
Contributor

Hmmm, I would call this a bug, there might be some additional escaping going on. Let me see what I can do.

@AndydeCleyre
Copy link
Contributor Author

I've confirmed that the missing argument gets removed during this bit:

        // Render positional parameters in args
        let cmd = POS_ARG_REGEX
            .replace_all(&cmd, |caps: &Captures| {
                let position_str = caps.name("pos").unwrap().as_str();
                let position = position_str.parse::<i32>().unwrap_or(-1);
                if position >= 0 && position < args.len() as i32 {
                    args[position as usize].to_owned()
                } else {
                    "".to_owned()
                }
            })
            .to_string();

But what exactly that means to do, I'm not sure. Removing it breaks test_shell_args_unix.

@AndydeCleyre
Copy link
Contributor Author

My current guess is that it's argument parsing for passive mode, but if that's so, it should probably only be done if the match has passive_only: true.

@federico-terzi
Copy link
Collaborator

Hey,
This problem is indeed due to the way passive arguments are rendered!

it should probably only be done if the match has passive_only: true.

That would be problematic for matches that work for both the active and passive modes :)

The best solution would be to support an escaping sequence, but due to the way Rust implements regexes (there is no backward check), that is not easy to do (but things might have changed since then).

I'd rather add an option like skip_arguments: true, what do you think about it?

@AndydeCleyre
Copy link
Contributor Author

From the docs, I wouldn't expect to have to worry about working around the passive mode parsing, because:

  1. passive mode has to be globally, explicitly enabled
  2. how can a match work for both active and passive modes -- won't it be actively replaced before passive mode gets its hands on it? I guess that idea is: disable espanso, type, enable espanso, activate passive replacement.

Sure, if skip_arguments: true will do the trick, I'll be grateful. I just don't love that to use the "basic" mode without surprises we have to learn about and explicitly bypass an "advanced" feature that we may have not enabled at all in the first place.

@deckarep
Copy link
Contributor

@AndydeCleyre - why don't you try the latest push of this PR. I noticed that the original cmd variable gets shadowed, so now instead of logging the shadowed final result (after the regex code), I am now logging out the original cmd as it was directly represented via the yaml, ie no transformation.

@federico-terzi
Copy link
Collaborator

federico-terzi commented Jul 11, 2020

@AndydeCleyre Your point is definitely valid, indeed it might be better to explicitly enable argument injection rather than disabling it. So we should introduce a inject_args: true parameter (which defaults to false) in the shell extension.

@AndydeCleyre
Copy link
Contributor Author

Sounds good, but a couple questions:

  1. Can active replacements process args at all?

  2. Would it be more handy to take an integer for maximum number of arguments to parse, that defaults to zero?

@federico-terzi
Copy link
Collaborator

Can active replacements process args at all?

It might in the future once #257 is implemented, but not currently.

Would it be more handy to take an integer for maximum number of arguments to parse, that defaults to zero?

Could you expand a bit more on why this could be better compared to a flag to enable/disable?

Cheers :)

@AndydeCleyre
Copy link
Contributor Author

I hadn't used passive mode, so I thought maybe a shell match could process an arbitrary, variable number of args, but now I think that's not the case. But that does seem the case with script matches. So the idea would be to avoid treating things that look like more args as args, if we know we only want to handle a certain number of them.

Maybe that thought is pointless in practice. Here's a painfully contrived example:

  - trigger: :d
    passive_only: true
    replace: "{{output}}"
    vars:
      - name: output
        type: script
        params:
          inject_args: true
          args:
            - python
            - -c
            - >
              from sys import argv;
              print(
              "Dear",
              f"{', '.join(map(str.title, argv[1:-1]))}, and {argv[-1].title()}" if len(argv[1:]) > 2
              else f"{' and '.join(map(str.title, argv[1:]))}",
              end=",\n    ")
          trim: false

So that works on an arbitrary number of args, which is very nice, but let's say we only ever want this to work on 1, 2, or 3 args, so that the last result below changes.

:d/andy/HAPPY BIRTHDAY!

Dear Andy,
    HAPPY BIRTHDAY!
    
:d/andy/sam/HAPPY BIRTHDAY!

Dear Andy and Sam,
    HAPPY BIRTHDAY!

:d/andy/sam/josh/HAPPY BIRTHDAY!

Dear Andy, Sam, and Josh,
    HAPPY BIRTHDAY!

:d/andy/sam/josh//¡HAPPY BIRTHDAY!/ <-- Does that look like a banner to you?

Dear Andy, Sam, Josh, , and ¡Happy Birthday!,
     <-- Does that look like a banner to you?

If the match definition specified that only up to 3 args should be parsed, we might expect:

:d/andy/sam/josh//¡HAPPY BIRTHDAY!/ <-- Does that look like a banner to you?

Dear Andy, Sam, and Josh,
    /¡HAPPY BIRTHDAY!/ <-- Does that look like a banner to you?

That aside, if we do use argument injection in a shell match, does that mean we can't also use literal $<int>s in the cmd, for use with tools like pcregrep? It's a pretty corner case but I'm curious.

@AndydeCleyre
Copy link
Contributor Author

Another thought: if a match definition included maximum number of args, that could pave the way for actively completing them, triggering after that number of args.

@federico-terzi
Copy link
Collaborator

Hey,

Looking at your example, I get your point. But is it really worth the increase in complexity? I mean, that example seems like a pretty rare use-case, and moreover one could even customize the passive match regex if using the / character is needed.

Another thought: if a match definition included maximum number of args, that could pave the way for actively completing them, triggering after that number of args.

There are a number of problems with active argument detection, see: #292

Cheers :)

@AndydeCleyre
Copy link
Contributor Author

No, I guess it's not worth the complexity for those cases. It might be worth it if it enabled active args replacements. I'll have a look at #292 and #257.

If we do use argument injection in a shell match, does that mean we can't also use literal $<int>s in the cmd, for use with tools like pcregrep? Or is there a way to change the replacement variable strings?

@federico-terzi
Copy link
Collaborator

If we do use argument injection in a shell match, does that mean we can't also use literal $<int>s in the cmd, for use with tools like pcregrep? Or is there a way to change the replacement variable strings?

We can definitely design a parameter to change the inject_args format, for example it uses $1 on Unix and %1% on Windows. We could easily change it so that espanso looks for alternative strings, such as ##1## when injecting.

@AndydeCleyre
Copy link
Contributor Author

Nice! Being able to use ##1## or {{1}} would be very helpful in avoiding clashes with bash and some cli tools like pcregrep, rg, etc.

@federico-terzi
Copy link
Collaborator

Nice! Being able to use ##1## or {{1}} would be very helpful in avoiding clashes with bash and some cli tools like pcregrep, rg, etc.

Great! Could you please create a separate issue for that?

@AndydeCleyre
Copy link
Contributor Author

Yeah, sorry for abusing this issue for broader discussion. I'll be back in about 8hrs and open a proper one.

@AndydeCleyre
Copy link
Contributor Author

I'm testing now with 44322a7, which has #359 merged (thanks @deckarep and @federico-terzi!).

With the following match definition:

  - trigger: :local
    replace: "{{address}}"
    vars:
      - name: address
        type: shell
        params:
          debug: true
          cmd: 'ip addr | pcre2grep -M -O ''$2'' ''^\d: wlan0: (.*\n[^\d])*.* inet ((\d+\.){3}\d+)/'''

I get a nice log line:

17:09:27 [ INFO] debug for shell cmd 'ip addr | pcre2grep -M -O '$2' '^\d: wlan0: (.*\n[^\d])*.* inet ((\d+\.){3}\d+)/'', exit_status 'exit code: 0', stdout '', stderr ''

Note that since it only renders the original command in the log, it does not inform the user of the command actually being run, which would be very helpful. In this case the difference is, I think:

-ip addr | pcre2grep -M -O '$2' '^\d: wlan0: (.*\n[^\d])*.* inet ((\d+\.){3}\d+)/'
+ip addr | pcre2grep -M -O '' '^\d: wlan0: (.*\n[^\d])*.* inet ((\d+\.){3}\d+)/'

@federico-terzi
Copy link
Collaborator

@AndydeCleyre I see your point, indeed it might be better to print the cmd rather than `original_cmd``

@deckarep
Copy link
Contributor

deckarep commented Jul 15, 2020

@AndydeCleyre

So, isn’t that what I originally had? Previous to my last change I was indeed logging cmd.

It’s an easy enough change just want to make sure is all.

@AndydeCleyre
Copy link
Contributor Author

@deckarep

Yes, I think reverting the last change would be the improvement I'm hoping for. But I don't know what its rationale was.

@AndydeCleyre
Copy link
Contributor Author

@deckarep

I don't seem to be getting a debug log for this, can you spot anything off?

  - trigger: :in
    replace: "{{indented}}"
    passive_only: true
    vars:
      - name: indented
        type: shell
        params:
          debug: true
          cmd: sed "s/^/$(printf ' %.0s' {1..$0})/g" <<<"$(xclip -sel clip -o)"
          trim: false

@AndydeCleyre
Copy link
Contributor Author

@deckarep -- nevermind about that last comment, I think I was mistyping the trigger or something, sorry.

@deckarep
Copy link
Contributor

@AndydeCleyre - cool...the code was merged maybe this issue can be closed as resolved.

@AndydeCleyre
Copy link
Contributor Author

@deckarep I think the current state of dev is still logging the pre-processed cmd (only). I would prefer to have this closed once it logs the post-processed cmd (either additionally or instead).

@federico-terzi
Copy link
Collaborator

federico-terzi commented Jul 20, 2020

Let's keep this issue open for now so that I can keep track of it. As soon as I get my hands on this area of the code I'll make sure to change it 👍

Thank you both for the help :)

@federico-terzi federico-terzi added the RFNR Ready to be shipped in next release label Aug 15, 2020
@federico-terzi
Copy link
Collaborator

Closed as it's been added in 0.7.0 :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
RFNR Ready to be shipped in next release
Projects
None yet
Development

No branches or pull requests

3 participants