Fixes #34812 - add logging of script runner shell cmd at debug level #79

jhoblitt · 2022-04-25T18:04:44Z

I have been manually adding debug logging into my foreman-proxy instances when there is a problem with REX. It seems worth while for the default debug log to contain a trace of shell commands run.

theforeman-bot · 2022-04-25T18:04:45Z

Can one of the admins verify this patch?

adamruzicka · 2022-04-26T10:40:49Z

While I like the general notion, it gets way too chatty to my liking with certain bits being logged multiple times from different places.

2022-04-26T12:25:15  [D] start runner 8075400c-a4b9-4e90-a6ef-0178f7f32c25
2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes true
2022-04-26T12:25:15  [D] copying script to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/test:
  | #!/bin/sh
  | exec true
2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes mkdir -p /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25
2022-04-26T12:25:15  [D] Sending data to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/test on remote host:
#!/bin/sh
exec true
2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/test >/dev/null && chmod 555 /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-017
8f7f32c25/test
2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/test
2022-04-26T12:25:15  [D] copying script to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script:
  | ls -la /
2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes mkdir -p /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25
2022-04-26T12:25:15  [D] Sending data to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script on remote host:
ls -la /
2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script >/dev/null && chmod 555 /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0
178f7f32c25/script
2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes mkdir -p /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25
2022-04-26T12:25:15  [D] Sending data to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script-wrapper on remote host:
echo $$ > /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/pid; exec "$@";
2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script-wrapper >/dev/null && chmod 555 /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e9
0-a6ef-0178f7f32c25/script-wrapper
2022-04-26T12:25:15  [D] executing script:
  | sh <<EOF | /usr/bin/tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/output
  | /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script-wrapper /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script < /dev/null
  | echo \$?>/var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/exit_code
  | EOF
  | exit $(cat /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/exit_code)

2022-04-26T12:25:15  [D] running command: /usr/bin/ssh localhost -tt -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes sh <<EOF | /usr/bin/tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/output
/var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script-wrapper /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script < /dev/null
echo \$?>/var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/exit_code
EOF
exit $(cat /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/exit_code)

As a counter proposal, the whole ssh command that gets repeated every time should be the same every time we try to do something with the remote host. How about we log the common part (/usr/bin/ssh localhost -tt ...) at the beginning and then just log the part that gets executed on the remote end? Something like

2022-04-26T12:25:15  [D] start runner 8075400c-a4b9-4e90-a6ef-0178f7f32c25
2022-04-26T12:25:15  [D] runner 8075400c-a4b9-4e90-a6ef-0178f7f32c25 ssh command:
  | /usr/bin/ssh localhost -o User=root -o Port=10022 -o IdentityFile=~/.ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=no -o PreferredAuthentications=publickey -o NumberOfPasswordPrompts=1 -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/foreman-proxy/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/socket -o ControlPersist=yes

2022-04-26T12:25:15  [D] running remote command: true
2022-04-26T12:25:15  [D] copying script to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/test:
  | #!/bin/sh
  | exec true
2022-04-26T12:25:15  [D] running remote command: mkdir -p /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25
2022-04-26T12:25:15  [D] Sending data to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/test on remote host:
#!/bin/sh
exec true
2022-04-26T12:25:15  [D] running remote command: tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/test >/dev/null && chmod 555 /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-017
8f7f32c25/test
2022-04-26T12:25:15  [D] running remote command: /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/test
2022-04-26T12:25:15  [D] copying script to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script:
  | ls -la /
2022-04-26T12:25:15  [D] running remote command: mkdir -p /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25
2022-04-26T12:25:15  [D] Sending data to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script on remote host:
ls -la /
2022-04-26T12:25:15  [D] running remote command: tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script >/dev/null && chmod 555 /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0
178f7f32c25/script
2022-04-26T12:25:15  [D] running remote command: mkdir -p /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25
2022-04-26T12:25:15  [D] Sending data to /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script-wrapper on remote host:
echo $$ > /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/pid; exec "$@";
2022-04-26T12:25:15  [D] running remote command: tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script-wrapper >/dev/null && chmod 555 /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e9
0-a6ef-0178f7f32c25/script-wrapper
2022-04-26T12:25:15  [D] executing script:
  | sh <<EOF | /usr/bin/tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/output
  | /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script-wrapper /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script < /dev/null
  | echo \$?>/var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/exit_code
  | EOF
  | exit $(cat /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/exit_code)

2022-04-26T12:25:15  [D] running remote command: sh <<EOF | /usr/bin/tee /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/output
/var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script-wrapper /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/script < /dev/null
echo \$?>/var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/exit_code
EOF
exit $(cat /var/tmp/foreman-ssh-cmd-8075400c-a4b9-4e90-a6ef-0178f7f32c25/exit_code)

jhoblitt · 2022-04-26T20:45:17Z

My goal was to be able to cut'n'paste the command lines for debugging. Splitting it up means I would just end up editing the source on disk again so I don't have to try to manually work out what command was actually executed.

adamruzicka · 2022-04-27T10:00:35Z

lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb

@@ -300,7 +300,9 @@ def run_async(command)
      raise 'Async command already in progress' if @process_manager&.started?

      @user_method.reset
-      initialize_command(*get_args(command, true))
+      full_cmd = get_args(command, true)
+      @logger.debug("running command: #{full_cmd.join(' ')}")


The first element of full_cmd might contain a hash where there might be effective user password under SSHPASS key. That should never end up in the logs, no matter the level

Absolutely agree. This PR started as a local hack I've made debugging several times over the last few years and wasn't deeply though through.

I realize that ultimately the interface of Process#spawn has to be satisfied but it is a bit unsettling to have secrets mixed into the same array as the command arguments. It feels like there should be a standard-ish secret or confidential string type that returns something like <SECRET> or raises an exception on #to_s but a brief search of rubygems hasn't found such a thing... is there such a thing?

One option would be to filter the args array and remove any hashes as part of the interpolation in the debug statement. How would you feel about splitting the env vars and command line args up into independent data structures that are either merged before being passed to Proxy::Dynflow::ProcessManager#initialize or changing the interface of that constructor?

is there such a thing?

I'm not aware of any standard solution for this, although a custom one should be fairly straightforward to implement.

How would you feel about splitting the env vars and command line args up into independent data structures that are either merged before being passed

I would be fine with this

or changing the interface of that constructor?

I'd like to avoid this. I'd say coordinating changes landing in three different projects and breaking the standard interface ala spawn just to make something, that can be done in a single project with minimal amount of effort, slightly easier is not worth it.

adamruzicka · 2022-07-26T11:00:06Z

@jhoblitt Do you deem the logging changes implemented in #82 sufficient or do we still need this?

jhoblitt · 2022-07-26T13:05:39Z

@adamruzicka Yes, the new debug output is great. Thank you.

theforeman-bot added Waiting on contributor Needs testing Not yet reviewed labels Apr 25, 2022

jhoblitt force-pushed the feature/debug-cmd branch from e56e115 to b03a798 Compare April 25, 2022 18:09

theforeman-bot added Waiting on contributor and removed Waiting on contributor labels Apr 25, 2022

jhoblitt changed the title ~~add logging of script runner shell commands at debug level~~ Fixes #34811 - add logging of script runner shell cmd at debug level Apr 25, 2022

jhoblitt force-pushed the feature/debug-cmd branch from b03a798 to 042460e Compare April 25, 2022 18:10

theforeman-bot added Waiting on contributor and removed Waiting on contributor labels Apr 25, 2022

jhoblitt changed the title ~~Fixes #34811 - add logging of script runner shell cmd at debug level~~ Fixes #34812 - add logging of script runner shell cmd at debug level Apr 25, 2022

jhoblitt force-pushed the feature/debug-cmd branch from 042460e to 9eaf69d Compare April 25, 2022 18:13

theforeman-bot added Waiting on contributor and removed Waiting on contributor labels Apr 25, 2022

jhoblitt mentioned this pull request Apr 25, 2022

add foreman::shell param theforeman/puppet-foreman_proxy#742

Merged

Fixes #34812 - add logging of script runner shell cmd at debug level

736cb4a

jhoblitt force-pushed the feature/debug-cmd branch from 9eaf69d to 736cb4a Compare April 25, 2022 19:07

theforeman-bot added Waiting on contributor and removed Waiting on contributor labels Apr 25, 2022

adamruzicka reviewed Apr 27, 2022

View reviewed changes

jhoblitt closed this Jul 26, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fixes #34812 - add logging of script runner shell cmd at debug level #79

Fixes #34812 - add logging of script runner shell cmd at debug level #79

jhoblitt commented Apr 25, 2022

theforeman-bot commented Apr 25, 2022

adamruzicka commented Apr 26, 2022

jhoblitt commented Apr 26, 2022

adamruzicka Apr 27, 2022

jhoblitt Apr 28, 2022 •

edited

Loading

adamruzicka Apr 29, 2022

adamruzicka commented Jul 26, 2022

jhoblitt commented Jul 26, 2022

Fixes #34812 - add logging of script runner shell cmd at debug level #79

Fixes #34812 - add logging of script runner shell cmd at debug level #79

Conversation

jhoblitt commented Apr 25, 2022

theforeman-bot commented Apr 25, 2022

adamruzicka commented Apr 26, 2022

jhoblitt commented Apr 26, 2022

adamruzicka Apr 27, 2022

Choose a reason for hiding this comment

jhoblitt Apr 28, 2022 • edited Loading

Choose a reason for hiding this comment

adamruzicka Apr 29, 2022

Choose a reason for hiding this comment

adamruzicka commented Jul 26, 2022

jhoblitt commented Jul 26, 2022

jhoblitt Apr 28, 2022 •

edited

Loading