Plugin initialization is taking too long.

lucasmior commented 4 years ago

The proxyconf plugin is taking too long to configure the proxies everytime I need to start up my vagrant box. It is taking about 15-20 minutes to complete the following configuration:

==> devenv: Machine booted and ready!
==> devenv: Configuring proxy for Apt...
==> devenv: Configuring proxy for Docker...
==> devenv: Configuring proxy environment variables...
==> devenv: Configuring proxy for Git...
==> devenv: Skipping configuration of npm_proxy

Is there any reason to take all this time? Any misconfiguration on my side?

Appreciate any guidance.

Environment

$ vagrant version
Installed Version: 2.2.6
Latest Version: 2.2.6

$ vagrant plugin list
vagrant-cachier (1.2.1, global)
vagrant-proxyconf (2.0.6, global)
vagrant-vbguest (0.20.0, global)

Virtual Box
Versão 6.0.14 r133895 (Qt5.6.2)

OS: Windows 10

codylane commented 4 years ago

Hi @lucasmior,

Hmm, that is odd. Can you please share your Vagrantfile? Also what is your host OS and what version of virtualbox do you have installed?

codylane commented 4 years ago

For what it's worth and I'm not trying to point blame here but I do recall I couldn't test this plugin on recent versions of vagrant due to an upstream bug. I'll link that issue to this one just incase. #209

I know it might sound like a lot of work and this may not solve anything but I would try downgrading Vagrant if you can and see if that issue is fixed?

I have a feeling Vagrant is changing some of the plugin middleware and we will have to overhaul this plugin again. Ugh. I won't lie I'm no expert when it comes to ruby or how all the ins and outs work in the vagrant plugin ecosystem so this may take a while to fix if downgrading vagrant to < 2.2.5.

FWIW - This is the reason I mention downgrading only vagrant because I cannot test vagrant versions >= 2.2.5 due to a bug buried somewhere in the vagrant API. I've not had a lot of free time to figure out why.

lucasmior commented 4 years ago

Hi @codylane I updated the description with the OS and virtual box version. This is my Vagrantfile:

# -*- mode: ruby -*-
# vi: set ft=ruby :

use_proxy = true
use_proxy = ENV['use_proxy'].to_s == 'false' ? false : true  if ENV['use_proxy']
if use_proxy
    url_proxy = ENV['http_proxy'] || <proxies>
    not_proxy = ENV['no_proxy'] || <no_proxies>
else
    url_proxy = ''
    not_proxy = ''
end

extra_mappings = ENV['extra_mappings'] ? ENV['extra_mappings'].split('|') : Array.new

private_key = File.expand_path(File.join(Dir.home, '.ssh/id_rsa'))
public_key = File.expand_path(File.join(Dir.home, '.ssh/id_rsa.pub'))

Vagrant.configure('2') do |config|
  # Proxy configuration:
  #
  if use_proxy
    if Vagrant.has_plugin?('vagrant-proxyconf')
      config.proxy.http     = url_proxy
      config.proxy.https    = url_proxy
      config.proxy.no_proxy = not_proxy
      config.proxy.enabled  = { npm: false }
    else
      puts '.'
      puts 'ERROR: Could not find vagrant-proxyconf plugin.'
      puts 'INFO: This plugin is required to use this box inside company network.'
      puts 'INFO: $ vagrant plugin install vagrant-proxyconf'
      puts 'ERROR: Bailing out.'
      puts '.'
      exit 1
    end
  end

  # VB Guest Additions configuration:
  #
  if Vagrant.has_plugin?('vagrant-vbguest')
    config.vbguest.auto_reboot = true
    # Do **NOT** force update if image already has pre-installed vbguest
    # - https://forums.virtualbox.org/viewtopic.php?f=7&t=86819
    # - https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1783267
    # - https://stackoverflow.com/questions/37556968/vagrant-disable-guest-additions
    # 
    config.vbguest.auto_update = false
  else
    puts '.'
    puts 'WARN: Could not find vagrant-vbguest plugin.'
    puts 'INFO: This plugin is highly recommended as it ensures that your VB guest additions are up-to-date.'
    puts 'INFO: $ vagrant plugin install vagrant-vbguest'
    puts '.'
  end

  # Cache configuration:
  #
  if Vagrant.has_plugin?('vagrant-cachier')
    config.cache.scope = :machine
    config.cache.auto_detect = false
    config.cache.enable :apt_lists
    config.cache.enable :apt
  else
    puts '.'
    puts 'WARN: Could not find vagrant-cachier plugin.'
    puts 'INFO: This plugin is highly recommended as it reduces the time required to provision the devenv.'
    puts 'INFO: $ vagrant plugin install vagrant-cachier'
    puts '.'
  end

  config.vm.box = "ubuntu/bionic64"
  config.vm.define 'devenv'
  config.vm.hostname = 'devenv'

  # SSH configuration:
  # Ensures the vagrant user is configured to use your keypair.
  #
  if File.exist?(private_key) && File.exist?(public_key)
    config.ssh.insert_key = false
    config.ssh.private_key_path = [private_key, '~/.vagrant.d/insecure_private_key']
    config.vm.provision 'file', source: public_key, destination: '~/.ssh/authorized_keys'
    config.vm.provision 'file', source: private_key, destination: '~/.ssh/id_rsa'
  else
    puts '.'
    puts 'WARN: Could not find either your private or public keys in the default locations.'
    puts "INFO: * [private key]: #{private_key}"
    puts "INFO: * [public  key]: #{public_key}"
    puts 'WARN: The vagrant box is going to be configured with its own self-created keypair.'
    puts '.'
  end

  # Port Forwarding:
  # Use ~/.vagrant.d/Vagrantfile for adding your service custom ports.
  #
  config.vm.network :forwarded_port, guest: 8000,  host: 8000,  auto_correct: true # debug
  config.vm.network :forwarded_port, guest: 8001,  host: 8001,  auto_correct: true # kubectl proxy
  config.vm.network :forwarded_port, guest: 8080,  host: 8080,  auto_correct: true # http
  config.vm.network :forwarded_port, guest: 8443,  host: 8443,  auto_correct: true # https
  config.vm.network :forwarded_port, guest: 30000, host: 30000, auto_correct: true # localkube dashboard

  # System setup
  config.vm.provision :shell, path: 'scripts/folders.sh', name: 'folders'
  config.vm.provision :shell, path: 'scripts/ssh-config.sh', name: 'ssh-config'
  config.vm.provision :shell, path: 'scripts/vagrant-ssh-key.sh', name: 'vagrant-ssh-key', privileged: false
  config.vm.provision :shell, path: 'scripts/sudo-setup.sh', name: 'sudo-setup'
  config.vm.provision :shell, path: 'scripts/apt-setup.sh', name: 'apt-setup'
  config.vm.provision :shell, path: 'scripts/apt-deps.sh', name: 'apt-deps'
  config.vm.provision :shell, path: 'scripts/ntp.sh', name: 'ntp'
  config.vm.provision :shell, path: 'scripts/kernel.sh', name: 'kernel'

  # Applications setup
  config.vm.provision :shell, path: 'scripts/aws-cli.sh', name: 'aws-cli'
  config.vm.provision :shell, path: 'scripts/docker.sh', name: 'docker'
  config.vm.provision :shell, path: 'scripts/golang.sh', name: 'golang'
  config.vm.provision :shell, path: 'scripts/kubernetes.sh', name: 'kubernetes'
  config.vm.provision :shell, path: 'scripts/aws-iam-authenticator.sh', name: 'aws-iam-authenticator'
  config.vm.provision :shell, path: 'scripts/minikube.sh', name: 'minikube' if ENV['minikube']
  config.vm.provision :shell, path: 'scripts/vim-plug.sh', name: 'vim-plug', privileged: false

  # Last provisionner is bootstrap
  config.vm.provision :shell, path: 'bootstrap.sh', name: 'bootstrap'

  # User's additional tools
  ext_devenv_provision = File.expand_path('~/.ext_devenv_provision')
  ext_bash_profile = File.expand_path('~/.ext_bash_profile')
  config.vm.provision :shell, path: ext_devenv_provision if File.exists?(ext_devenv_provision)
  config.vm.provision 'file', source: ext_bash_profile, destination: '~/.devenv_profile' if File.exists?(ext_bash_profile)
  config.vm.provision 'file', source: 'bash_profile', destination: '~/.bash_profile'

  config.vm.synced_folder Dir.home, '/home/vagrant/shared', create: true
  config.vm.synced_folder './bin', '/home/vagrant/bin', create: true

  # Map extra folder into the Guest
  extra_mappings.each do |value|
    sync_folder = value.split ','
    host_dir = sync_folder[0].strip
    guest_dir = sync_folder[1].strip
    puts "INFO: Mapping #{host_dir} to #{guest_dir}"
    config.vm.synced_folder host_dir, guest_dir, create: true
  end

  config.vm.network :public_network, bridge: 'eth0'

  config.vm.provider :virtualbox do |vb|
    vb.name = 'devenv'
    vb.customize ['modifyvm', :id, '--memory', '2048']
    vb.customize ['modifyvm', :id, '--cpus', '1']
    vb.customize ['modifyvm', :id, '--ioapic', 'on']
    vb.customize ['modifyvm', :id, '--cableconnected1', 'on']
  end
end

lucasmior commented 4 years ago

For downgrade vagrant, the version 2.2.4 looks good?

codylane commented 4 years ago

hi @lucasmior - Thank you for the very detailed info. I'll attempt in the next day or so to try you vagrantfile in my test environment and see what I can turn up. That is some Vagrantfile BTW. Holy geez. 🥇

Yup, I would try re-installing vagrant 2.2.4 and leave the rest of the plugin versions the same and see if the problem exist You may also have to repair or reinstall your plugins but that should be pretty trivial since you already have them captured here.

Let me know if you still have this problem on vagrant 2.2.4?

tmatilai commented 4 years ago

Quite often these kind of delays are caused by DNS timeouts. Maybe the SSH server on the box is trying to do reverse lookup for the client's (i.e. Vagrant) IP, and failing. You could check the sshd logs on the finally started machine. And maybe also running Vagrant with --debug option (creates huge amount of output; you can gist it if you want us to take a look).

codylane commented 4 years ago

That could be a very good point about DNS causing a slow down. I've certainly seen it in the past and it's hard to troubleshoot. I've also not used much network bridges in Virtualbox but when I have in the past I feel like there was a pretty noticeable slow down.

There are a few additional things you might also try:

Here are some recommended settings that I have been using since 2014 and they seem to increase network performance for the first NAT device in VirtualBox. The one about --uartmode1 is a fix to the ubuntu vagrant base boxes because they are built with the UART console enabled when the images are built and that metadata is saved into the image. At one point a few years ago, I stopped using the official ubuntu base boxes and switched to using the Chef bento ubuntu boxes as the experience for me was way better or way more predictable. Also, the best thing about using Bento is that you have all the code there of how the image was built so you can build it on your own if you don't trust the public boxes.

    config.vm.provider "virtualbox" do |vb|
      # http://station.clancats.com/3-vagrant-settings-you-should-check-out-to-optimize-your-vm/
      vb.customize ["modifyvm",   :id, "--natdnshostresolver1", "on"]
      vb.customize ["modifyvm",   :id, "--natdnsproxy1", "on"]

      # https://github.com/hashicorp/vagrant/issues/10578
      vb.customize ["modifyvm",   :id, "--uart1", "off"] if config.vm.box =~ /xenial|bionic/
      vb.customize ["modifyvm",   :id, "--uartmode1", "disconnected" ] if config.vm.box =~ /xenial|bionic/
    end

I have a hunch here, no proof but I suspect the another source of your slow down is a side effect of all the things that this plugin auto detected during the provisioning process. The plugin has an auto-detect feature to search for binaries that this plugin supports. When it detects the presence of binary that this plugin supports it has to configure the proxy twice per run.

For example, if docker is detected it first has to make sure docker is installed, the proxy is configured after the last provisioning hook executes then our plugin takes over (this is the first pass).
(The second pass occurs) after Vagrant has run all the other provisioners and we hook into that and configure/unconfigure a proxy.
Both passes are needed because the first pass hooks into the first time the box is provisioned and the second pass is needed so that you can continue to configure/unconfigure a proxy each time vagrant provision is called.

codylane commented 4 years ago

Hi @lucasmior - Just curious any chance you have had time to try these recommendations? I'm eager to find out.

lucasmior commented 4 years ago

Updates: I did the rollback to use the vagrant 2.2.4 and I still have the same behavior. However, I notice the first start-up(vagrant up --provision) the plugin configured the proxies too fast, without any delay. At the second time(vagrant halt && vagrant up) it took ~10 minutes back to just configure that plugins. I'm Going to try the remain alternatives we have discussed.

codylane commented 4 years ago

Thanks for the update @lucasmior.

I know this may be a lot to ask but would you be able to capture the output of your initial VAGRANT_LOG=debug vagrant up. I'd like to see the entire chain of commands just to see how the box is provisioned upon first run.

After the box is up and running, I would also like to see the output of the following command:

VAGRANT_LOG=debug vagrant provision

The reason I ask is because I've not been able to reproduce this issue yet.

lucasmior commented 4 years ago

So, problem solved. We have a bash_profile file that we use to provision the vm: config.vm.provision 'file', source: 'bash_profile', destination: '~/.bash_profile' This script does a few operations when it runs.

We resolved the issue adding this condition here:

# Checking whether bash_profile is being run within an interactive shell
# Otherwise, the following block would be executed by vagrant as it issues commands to the VM
if [ -n "$PS1" ]; then
    // my bash_profile script
fi

So looks like it was been called everytime we had to install or configure a proxy settings, like these:

==> devenv: Configuring proxy for Apt...
==> devenv: Configuring proxy for Docker...
==> devenv: Configuring proxy environment variables...
==> devenv: Configuring proxy for Git...
==> devenv: Skipping configuration of npm_proxy

Well, our start up time decreased almost 10x with this fix 😄 kudos to Rafael Lopes which figure out that! 🎉 🍻

codylane commented 4 years ago

Excellent, I'm happy to hear that you were able to sort this out and had some help from a colleague as well.

🥇 🥇 🍻

I'm going go ahead and close this request.

tmatilai / vagrant-proxyconf

Plugin initialization is taking too long. #215

Environment