Merge pull request #7676 from chrisroberts/en/cmd-pre-filter

Filter command output in SSH communicator

plugins/communicators/ssh/communicator.rb

@@ -19,8 +19,12 @@ module VagrantPlugins
   module CommunicatorSSH
     # This class provides communication with the VM via SSH.
     class Communicator < Vagrant.plugin("2", :communicator)
+      # Marker for start of PTY enabled command output
       PTY_DELIM_START = "bccbb768c119429488cfd109aacea6b5-pty"
+      # Marker for end of PTY enabled command output
       PTY_DELIM_END = "bccbb768c119429488cfd109aacea6b5-pty"
+      # Marker for start of regular command output
+      CMD_GARBAGE_MARKER = "41e57d38-b4f7-4e46-9c38-13873d338b86-vagrant-ssh"
 
       include Vagrant::Util::ANSIEscapeCodeRemover
       include Vagrant::Util::Retryable
@@ -490,16 +494,32 @@ module VagrantPlugins
             end
           end
 
+          marker_found = false
+          data_buffer = ''
+
           ch.exec(shell_cmd(opts)) do |ch2, _|
             # Setup the channel callbacks so we can get data and exit status
             ch2.on_data do |ch3, data|
               # Filter out the clear screen command
               data = remove_ansi_escape_codes(data)
-              @logger.debug("stdout: #{data}")
+
               if pty
                 pty_stdout << data
               else
-                yield :stdout, data if block_given?
+                if !marker_found
+                  data_buffer << data
+                  marker_index = data_buffer.index(CMD_GARBAGE_MARKER)
+                  if marker_index
+                    marker_found = true
+                    data_buffer.slice!(0, marker_index + CMD_GARBAGE_MARKER.size)
+                    data.replace data_buffer
+                    data_buffer = nil
+                  end
+                end
+
+                if block_given? && marker_found
+                  yield :stdout, data
+                end
               end
             end
 
@@ -516,7 +536,7 @@ module VagrantPlugins
 
               # Close the channel, since after the exit status we're
               # probably done. This fixes up issues with hanging.
-              channel.close
+              ch.close
             end
 
             # Set the terminal
@@ -563,7 +583,7 @@ module VagrantPlugins
               data = data.force_encoding('ASCII-8BIT')
               ch2.send_data data
             else
-              ch2.send_data "#{command}\n".force_encoding('ASCII-8BIT')
+              ch2.send_data "printf '#{CMD_GARBAGE_MARKER}'\n#{command}\n".force_encoding('ASCII-8BIT')
               # Remember to exit or this channel will hang open
               ch2.send_data "exit\n"
             end

test/unit/plugins/communicators/ssh/communicator_test.rb

@@ -0,0 +1,512 @@
+require File.expand_path("../../../../base", __FILE__)
+
+require Vagrant.source_root.join("plugins/communicators/ssh/communicator")
+
+describe VagrantPlugins::CommunicatorSSH::Communicator do
+  include_context "unit"
+
+  # SSH configuration information mock
+  let(:ssh) do
+    double("ssh",
+      timeout: 1,
+      host: nil,
+      port: 5986,
+      guest_port: 5986,
+      pty: false,
+      keep_alive: false,
+      insert_key: false,
+      shell: 'bash -l'
+    )
+  end
+  # Configuration mock
+  let(:config) { double("config", ssh: ssh) }
+  # Provider mock
+  let(:provider) { double("provider") }
+  # UI mock
+  let(:ui) { double("ui") }
+  # Machine mock built with previously defined
+  let(:machine) do
+    double("machine",
+      config: config,
+      provider: provider,
+      ui: ui
+    )
+  end
+  # Subject instance to test
+  let(:communicator){ @communicator ||= described_class.new(machine) }
+  # Underlying net-ssh connection mock
+  let(:connection) { double("connection") }
+  # Base net-ssh connection channel mock
+  let(:channel) { double("channel") }
+  # net-ssh connection channel mock for running commands
+  let(:command_channel) { double("command_channel") }
+  # Default exit data for commands run
+  let(:exit_data) { double("exit_data", read_long: 0) }
+  # Core shell command used when starting command connection
+  let(:core_shell_cmd) { "bash -l" }
+  # Marker used for flagging start of output
+  let(:command_garbage_marker) { communicator.class.const_get(:CMD_GARBAGE_MARKER) }
+  # Start marker output when PTY is enabled
+  let(:pty_delim_start) { communicator.class.const_get(:PTY_DELIM_START) }
+  # End marker output when PTY is enabled
+  let(:pty_delim_end) { communicator.class.const_get(:PTY_DELIM_END) }
+  # Command output returned on stdout
+  let(:command_stdout_data) { '' }
+  # Command output returned on stderr
+  let(:command_stderr_data) { '' }
+  # Mock for net-ssh scp
+  let(:scp) { double("scp") }
+
+  # Setup for commands using the net-ssh connection. This can be reused where needed
+  # by providing to `before`
+  connection_setup = proc do
+    allow(connection).to receive(:closed?).and_return false
+    allow(connection).to receive(:open_channel).
+      and_yield(channel).and_return(channel)
+    allow(channel).to receive(:wait).and_return true
+    allow(channel).to receive(:close)
+    allow(command_channel).to receive(:send_data)
+    allow(command_channel).to receive(:eof!)
+    allow(command_channel).to receive(:on_data).
+      and_yield(nil, command_stdout_data)
+    allow(command_channel).to receive(:on_extended_data).
+      and_yield(nil, nil, command_stderr_data)
+    allow(machine).to receive(:ssh_info).and_return(host: '10.1.2.3', port: 22)
+    expect(channel).to receive(:exec).with(core_shell_cmd).
+      and_yield(command_channel, '').and_return channel
+    expect(command_channel).to receive(:on_request).with('exit-status').
+      and_yield(nil, exit_data)
+    # Return mocked net-ssh connection during setup
+    allow(communicator).to receive(:retryable).and_return(connection)
+  end
+
+  describe ".wait_for_ready" do
+    before(&connection_setup)
+    context "with no static config (default scenario)" do
+      before do
+        allow(ui).to receive(:detail)
+      end
+
+      context "when ssh_info requires a multiple tries before it is ready" do
+        before do
+          expect(machine).to receive(:ssh_info).
+            and_return(nil).ordered
+          expect(machine).to receive(:ssh_info).
+            and_return(host: '10.1.2.3', port: 22).ordered
+        end
+
+        it "retries ssh_info until ready" do
+          # retries are every 0.5 so buffer the timeout just a hair over
+          expect(communicator.wait_for_ready(0.6)).to eq(true)
+        end
+      end
+    end
+  end
+
+  describe ".ready?" do
+    before(&connection_setup)
+    it "returns true if shell test is successful" do
+      expect(communicator.ready?).to be_true
+    end
+
+    context "with an invalid shell test" do
+      before do
+        expect(exit_data).to receive(:read_long).and_return 1
+      end
+
+      it "returns raises SSHInvalidShell error" do
+        expect{ communicator.ready? }.to raise_error Vagrant::Errors::SSHInvalidShell
+      end
+    end
+  end
+
+  describe ".execute" do
+    before(&connection_setup)
+    it "runs valid command and returns successful status code" do
+      expect(command_channel).to receive(:send_data).with(/ls \/\n/)
+      expect(communicator.execute("ls /")).to eq(0)
+    end
+
+    it "prepends UUID output to command for garbage removal" do
+      expect(command_channel).to receive(:send_data).
+        with("printf '#{command_garbage_marker}'\nls /\n")
+      expect(communicator.execute("ls /")).to eq(0)
+    end
+
+    context "with command returning an error" do
+      let(:exit_data) { double("exit_data", read_long: 1) }
+
+      it "raises error when exit-code is non-zero" do
+        expect(command_channel).to receive(:send_data).with(/ls \/\n/)
+        expect{ communicator.execute("ls /") }.to raise_error(Vagrant::Errors::VagrantError)
+      end
+
+      it "returns exit-code when exit-code is non-zero and error check is disabled" do
+        expect(command_channel).to receive(:send_data).with(/ls \/\n/)
+        expect(communicator.execute("ls /", error_check: false)).to eq(1)
+      end
+    end
+
+    context "with garbage content prepended to command output" do
+      let(:command_stdout_data) do
+        "Line of garbage\nMore garbage\n#{command_garbage_marker}bin\ntmp\n"
+      end
+
+      it "removes any garbage output prepended to command output" do
+        stdout = ''
+        expect(
+          communicator.execute("ls /") do |type, data|
+            stdout << data
+          end
+        ).to eq(0)
+        expect(stdout).to eq("bin\ntmp\n")
+      end
+    end
+
+    context "with pty enabled" do
+      before do
+        expect(ssh).to receive(:pty).and_return true
+        expect(channel).to receive(:request_pty).and_yield(command_channel, true)
+        expect(command_channel).to receive(:send_data).
+          with(/#{Regexp.escape(pty_delim_start)}/)
+      end
+
+      let(:command_stdout_data) do
+        "#{pty_delim_start}bin\ntmp\n#{pty_delim_end}"
+      end
+
+      it "requests pty for connection" do
+        expect(communicator.execute("ls")).to eq(0)
+      end
+
+      context "with sudo enabled" do
+        let(:core_shell_cmd){ 'sudo bash -l' }
+
+        before do
+          expect(ssh).to receive(:sudo_command).and_return 'sudo %c'
+        end
+
+        it "wraps command in elevated shell when sudo is true" do
+          expect(communicator.execute("ls", sudo: true)).to eq(0)
+        end
+      end
+    end
+
+    context "with sudo enabled" do
+      let(:core_shell_cmd){ 'sudo bash -l' }
+
+      before do
+        expect(ssh).to receive(:sudo_command).and_return 'sudo %c'
+      end
+
+      it "wraps command in elevated shell when sudo is true" do
+        expect(communicator.execute("ls", sudo: true)).to eq(0)
+      end
+    end
+  end
+
+  describe ".test" do
+    before(&connection_setup)
+    context "with exit code as zero" do
+      it "returns true" do
+        expect(communicator.test("ls")).to be_true
+      end
+    end
+
+    context "with exit code as non-zero" do
+      before do
+        expect(exit_data).to receive(:read_long).and_return 1
+      end
+
+      it "returns false" do
+        expect(communicator.test("/bin/false")).to be_false
+      end
+    end
+  end
+
+  describe ".upload" do
+    before do
+      expect(communicator).to receive(:scp_connect).and_yield(scp)
+    end
+
+    it "uploads a directory if local path is a directory" do
+      Dir.mktmpdir('vagrant-test') do |dir|
+        expect(scp).to receive(:upload!).with(dir, '/destination', recursive: true)
+        communicator.upload(dir, '/destination')
+      end
+    end
+
+    it "uploads a file if local path is a file" do
+      file = Tempfile.new('vagrant-test')
+      begin
+        expect(scp).to receive(:upload!).with(instance_of(File), '/destination/file')
+        communicator.upload(file.path, '/destination/file')
+      ensure
+        file.delete
+      end
+    end
+
+    it "raises custom error on permission errors" do
+      file = Tempfile.new('vagrant-test')
+      begin
+        expect(scp).to receive(:upload!).with(instance_of(File), '/destination/file').
+          and_raise("Permission denied")
+        expect{ communicator.upload(file.path, '/destination/file') }.to(
+          raise_error(Vagrant::Errors::SCPPermissionDenied)
+        )
+      ensure
+        file.delete
+      end
+    end
+
+    it "does not raise custom error on non-permission errors" do
+      file = Tempfile.new('vagrant-test')
+      begin
+        expect(scp).to receive(:upload!).with(instance_of(File), '/destination/file').
+          and_raise("Some other error")
+        expect{ communicator.upload(file.path, '/destination/file') }.to raise_error(RuntimeError)
+      ensure
+        file.delete
+      end
+    end
+  end
+
+  describe ".download" do
+    before do
+      expect(communicator).to receive(:scp_connect).and_yield(scp)
+    end
+
+    it "calls scp to download file" do
+      expect(scp).to receive(:download!).with('/path/from', '/path/to')
+      communicator.download('/path/from', '/path/to')
+    end
+  end
+
+  describe ".connect" do
+
+    it "cannot be called directly" do
+      expect{ communicator.connect }.to raise_error(NoMethodError)
+    end
+
+    context "with default configuration" do
+
+      before do
+        expect(machine).to receive(:ssh_info).and_return(
+          host: nil,
+          port: nil,
+          private_key_path: nil,
+          username: nil,
+          password: nil,
+          keys_only: true,
+          paranoid: false
+        )
+      end
+
+      it "has keys_only enabled" do
+        expect(Net::SSH).to receive(:start).with(
+          nil, nil, hash_including(
+            keys_only: true
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "has paranoid disabled" do
+        expect(Net::SSH).to receive(:start).with(
+          nil, nil, hash_including(
+            paranoid: false
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "does not include any private key paths" do
+        expect(Net::SSH).to receive(:start).with(
+          nil, nil, hash_excluding(
+            keys: anything
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "includes `none` and `hostbased` auth methods" do
+        expect(Net::SSH).to receive(:start).with(
+          nil, nil, hash_including(
+            auth_methods: ["none", "hostbased"]
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+    end
+
+    context "with keys_only disabled and paranoid enabled" do
+
+      before do
+        expect(machine).to receive(:ssh_info).and_return(
+          host: nil,
+          port: nil,
+          private_key_path: nil,
+          username: nil,
+          password: nil,
+          keys_only: false,
+          paranoid: true
+        )
+      end
+
+      it "has keys_only enabled" do
+        expect(Net::SSH).to receive(:start).with(
+          nil, nil, hash_including(
+            keys_only: false
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "has paranoid disabled" do
+        expect(Net::SSH).to receive(:start).with(
+          nil, nil, hash_including(
+            paranoid: true
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+    end
+
+    context "with host and port configured" do
+
+      before do
+        expect(machine).to receive(:ssh_info).and_return(
+          host: '127.0.0.1',
+          port: 2222,
+          private_key_path: nil,
+          username: nil,
+          password: nil,
+          keys_only: true,
+          paranoid: false
+        )
+      end
+
+      it "specifies configured host" do
+        expect(Net::SSH).to receive(:start).with("127.0.0.1", anything, anything)
+        communicator.send(:connect)
+      end
+
+      it "has port defined" do
+        expect(Net::SSH).to receive(:start).with("127.0.0.1", anything, hash_including(port: 2222))
+        communicator.send(:connect)
+      end
+    end
+
+    context "with private_key_path configured" do
+      before do
+        expect(machine).to receive(:ssh_info).and_return(
+          host: '127.0.0.1',
+          port: 2222,
+          private_key_path: ['/priv/key/path'],
+          username: nil,
+          password: nil,
+          keys_only: true,
+          paranoid: false
+        )
+      end
+
+      it "includes private key paths" do
+        expect(Net::SSH).to receive(:start).with(
+          anything, anything, hash_including(
+            keys: ["/priv/key/path"]
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "includes `publickey` auth method" do
+        expect(Net::SSH).to receive(:start).with(
+          anything, anything, hash_including(
+            auth_methods: ["none", "hostbased", "publickey"]
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+    end
+
+    context "with username and password configured" do
+
+      before do
+        expect(machine).to receive(:ssh_info).and_return(
+          host: '127.0.0.1',
+          port: 2222,
+          private_key_path: nil,
+          username: 'vagrant',
+          password: 'vagrant',
+          keys_only: true,
+          paranoid: false
+        )
+      end
+
+      it "has username defined" do
+        expect(Net::SSH).to receive(:start).with(anything, 'vagrant', anything).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "has password defined" do
+        expect(Net::SSH).to receive(:start).with(
+          anything, anything, hash_including(
+            password: 'vagrant'
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "includes `password` auth method" do
+        expect(Net::SSH).to receive(:start).with(
+          anything, anything, hash_including(
+            auth_methods: ["none", "hostbased", "password"]
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+    end
+
+    context "with password and private_key_path configured" do
+
+      before do
+        expect(machine).to receive(:ssh_info).and_return(
+          host: '127.0.0.1',
+          port: 2222,
+          private_key_path: ['/priv/key/path'],
+          username: 'vagrant',
+          password: 'vagrant',
+          keys_only: true,
+          paranoid: false
+        )
+      end
+
+      it "has password defined" do
+        expect(Net::SSH).to receive(:start).with(
+          anything, anything, hash_including(
+            password: 'vagrant'
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "includes private key paths" do
+        expect(Net::SSH).to receive(:start).with(
+          anything, anything, hash_including(
+            keys: ["/priv/key/path"]
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+
+      it "includes `publickey` and `password` auth methods" do
+        expect(Net::SSH).to receive(:start).with(
+          anything, anything, hash_including(
+            auth_methods: ["none", "hostbased", "publickey", "password"]
+          )
+        ).and_return(true)
+        communicator.send(:connect)
+      end
+    end
+  end
+end