On 6/13/19 11:15 AM, Brian Cain wrote:
On Wed, Jun 12, 2019 at 10:57 PM James E Keenan <[email protected]
<mailto:[email protected]>> wrote:
On 6/12/19 5:37 PM, Brian Cain wrote:
> Hey there,
>
> Do you have a full debug log showing this provisioning behavior
when you
> run Vagrant up or vagrant provision? Thanks!
I haven't been able to locate any logging for Vagrant (only for
VirtualBox). Where would I find that?
It's only enabled when you use the flag. So you'll need to rerun your
command with --debug then capture the output.
Thank you very much for that suggestion.
As a basis for comparison, I ran 'vagrant provision --debug' and logged
the output in each of *two* VMs: the first being the problematic
FreeBSD-12 VM, the second a FreeBSD-13 VM we have been using for several
months without incident. The Vagrantfiles in each are similarly
structured, i.e., each uses a shell script for provisioning. The
Vagrantfile for the FreeBSD-13VM has real content in its shell script
and completes successfully.
In each of the two log files, the following is the first 'ERROR' line to
appear:
#####
E, [datestamp #id] ERROR -- net.ssh.authentication.agent[404b67954]:
could not connect to ssh-agent: Agent not configured
#####
In the FreeBSD-13 VM, this is the *only* 'ERROR' message in the log.
Please see attachment freebsd13.following.ERROR.txt for how 'vagrant
provision' recovered from this. (The expected STDOUT begins at the end
of this excerpt.)
In the FreeBSD-12 VM, this is the first of 11 'ERROR' messages in the
log (though many of the instances are repeats). Please see attachment
freebsd12.following.ERROR.txt.
What seems to be the first instance of real failure is these lines from
the FreeBSD-12 debug log:
#####
INFO ssh: Execute: chown -R vagrant /tmp/vagrant-shell (sudo=true)
DEBUG ssh: stderr: sudo
DEBUG ssh: stderr: :
DEBUG ssh: stderr: no tty present and no askpass program specified
DEBUG ssh: stderr:
DEBUG ssh: Exit status: 1
#####
The corresponding lines in the FreeBSD-13 VM debug line are:
#####
DEBUG ssh: == Net-SSH connection debug-level log END ==
INFO ssh: Execute: chown -R vagrant /tmp/vagrant-shell (sudo=true)
DEBUG ssh: stderr: 41e57d38-b4f7-4e46-9c38-13873d338b86-vagrant-ssh
DEBUG ssh: Exit status: 0
DEBUG ssh: Uploading: /tmp/vagrant-shell20190613-60554-odqtcv.ps1 to
/tmp/vagrant-shell
DEBUG ssh: Re-using SSH connection.
#####
I can supply complete debug logs off-line upon request.
So, can you suggest what is going wrong in the FreeBSD-12 VM (taking
into consideration that several days ago I did achieve one successful
provisioning of this VM) and how to remedy it?
Thank you very much.
Jim Keenan
--
This mailing list is governed under the HashiCorp Community Guidelines -
https://www.hashicorp.com/community-guidelines.html. Behavior in violation of
those guidelines may result in your removal from this mailing list.
GitHub Issues: https://github.com/mitchellh/vagrant/issues
IRC: #vagrant on Freenode
---
You received this message because you are subscribed to the Google Groups "Vagrant" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/vagrant-up/b4fcc9a0-cf43-db38-f157-5518a93a13a1%40pobox.com.
For more options, visit https://groups.google.com/d/optout.
E, [2019-06-13T19:09:43.606577 #60554] ERROR --
net.ssh.authentication.agent[404b67954]: could not connect to ssh-agent: Agent
not configured
D, [2019-06-13T19:09:43.606711 #60554] DEBUG --
net.ssh.authentication.methods.publickey[404b6a014]: trying publickey
(14:80:f0:9a:20:18:e3:ec:0e:e2:7a:a9:f4:07:16:eb)
D, [2019-06-13T19:09:43.606801 #60554] DEBUG -- socket[404c2b368]: queueing
packet nr 5 type 50 len 348
D, [2019-06-13T19:09:43.606843 #60554] DEBUG -- socket[404c2b368]: sent 372
bytes
D, [2019-06-13T19:09:43.607972 #60554] DEBUG -- socket[404c2b368]: read 324
bytes
D, [2019-06-13T19:09:43.608074 #60554] DEBUG -- socket[404c2b368]: received
packet nr 5 type 60 len 300
D, [2019-06-13T19:09:43.610444 #60554] DEBUG -- socket[404c2b368]: queueing
packet nr 6 type 50 len 620
D, [2019-06-13T19:09:43.610482 #60554] DEBUG -- socket[404c2b368]: sent 644
bytes
D, [2019-06-13T19:09:43.621399 #60554] DEBUG -- socket[404c2b368]: read 36 bytes
D, [2019-06-13T19:09:43.621483 #60554] DEBUG -- socket[404c2b368]: received
packet nr 6 type 52 len 12
D, [2019-06-13T19:09:43.621529 #60554] DEBUG --
net.ssh.authentication.methods.publickey[404b6a014]: publickey succeeded
(14:80:f0:9a:20:18:e3:ec:0e:e2:7a:a9:f4:07:16:eb)
DEBUG ssh: == Net-SSH connection debug-level log END ==
INFO ssh: Execute: chown -R vagrant /tmp/vagrant-shell (sudo=true)
DEBUG ssh: stderr: 41e57d38-b4f7-4e46-9c38-13873d338b86-vagrant-ssh
DEBUG ssh: Exit status: 0
DEBUG ssh: Uploading: /tmp/vagrant-shell20190613-60554-odqtcv.ps1 to
/tmp/vagrant-shell
DEBUG ssh: Re-using SSH connection.
INFO interface: detail: Running: inline script
INFO interface: detail: default: Running: inline script
default: Running: inline script
DEBUG ssh: Re-using SSH connection.
INFO ssh: Execute: chmod +x '/tmp/vagrant-shell' && /tmp/vagrant-shell
(sudo=true)
DEBUG ssh: stderr: 41e57d38-b4f7-4e46-9c38-13873d338b86-vagrant-ssh
INFO interface: detail: Updating FreeBSD repository catalogue...
E, [2019-06-13T19:04:11.156773 #28692] ERROR --
net.ssh.authentication.agent[404cb02c0]: could not connect to ssh-agent: Agent
not configured
D, [2019-06-13T19:04:11.156931 #28692] DEBUG --
net.ssh.authentication.methods.publickey[404cb05f4]: trying publickey
(a6:aa:1c:67:55:ba:fe:e1:47:34:3b:76:2c:37:f2:75)
D, [2019-06-13T19:04:11.157039 #28692] DEBUG -- socket[404da8254]: queueing
packet nr 5 type 50 len 348
D, [2019-06-13T19:04:11.157076 #28692] DEBUG -- socket[404da8254]: sent 372
bytes
D, [2019-06-13T19:04:11.159547 #28692] DEBUG -- socket[404da8254]: read 324
bytes
D, [2019-06-13T19:04:11.159644 #28692] DEBUG -- socket[404da8254]: received
packet nr 5 type 60 len 300
D, [2019-06-13T19:04:11.162077 #28692] DEBUG -- socket[404da8254]: queueing
packet nr 6 type 50 len 620
D, [2019-06-13T19:04:11.162123 #28692] DEBUG -- socket[404da8254]: sent 644
bytes
D, [2019-06-13T19:04:11.175918 #28692] DEBUG -- socket[404da8254]: read 36 bytes
D, [2019-06-13T19:04:11.175982 #28692] DEBUG -- socket[404da8254]: received
packet nr 6 type 52 len 12
D, [2019-06-13T19:04:11.176025 #28692] DEBUG --
net.ssh.authentication.methods.publickey[404cb05f4]: publickey succeeded
(a6:aa:1c:67:55:ba:fe:e1:47:34:3b:76:2c:37:f2:75)
DEBUG ssh: == Net-SSH connection debug-level log END ==
INFO ssh: Execute: chown -R vagrant /tmp/vagrant-shell (sudo=true)
DEBUG ssh: stderr: sudo
DEBUG ssh: stderr: :
DEBUG ssh: stderr: no tty present and no askpass program specified
DEBUG ssh: stderr:
DEBUG ssh: Exit status: 1
DEBUG ssh: Uploading: /tmp/vagrant-shell20190613-28692-g7a1o9.ps1 to
/tmp/vagrant-shell
DEBUG ssh: Re-using SSH connection.
INFO interface: detail: Running: inline script
INFO interface: detail: default: Running: inline script
default: Running: inline script
DEBUG ssh: Re-using SSH connection.
INFO ssh: Execute: chmod +x '/tmp/vagrant-shell' && /tmp/vagrant-shell
(sudo=true)
DEBUG ssh: stderr: sudo
DEBUG ssh: stderr: :
DEBUG ssh: stderr: no tty present and no askpass program specified
DEBUG ssh: stderr:
DEBUG ssh: Exit status: 1
ERROR warden: Error occurred: The SSH command responded with a non-zero exit
status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
ERROR warden: Error occurred: The SSH command responded with a non-zero exit
status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
ERROR warden: Error occurred: The SSH command responded with a non-zero exit
status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
ERROR warden: Error occurred: The SSH command responded with a non-zero exit
status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
INFO warden: Beginning recovery process...
INFO warden: Calling recover:
#<Vagrant::Action::Builtin::Call:0x0000000809b84640>
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
INFO warden: Recovery complete.
ERROR warden: Error occurred: The SSH command responded with a non-zero exit
status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
ERROR warden: Error occurred: The SSH command responded with a non-zero exit
status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
INFO warden: Beginning recovery process...
INFO warden: Calling recover:
#<Vagrant::Action::Builtin::Call:0x0000000809ea0c70>
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
INFO warden: Recovery complete.
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
INFO warden: Beginning recovery process...
INFO warden: Recovery complete.
INFO environment: Released process lock:
machine-action-d1c5e81075dfcc7d84373fb436539c2d
INFO environment: Running hook: environment_unload
INFO runner: Preparing hooks for middleware sequence...
INFO runner: 1 hooks defined.
INFO runner: Running action: environment_unload
#<Vagrant::Action::Builder:0x000000080975ca68>
ERROR vagrant: Vagrant experienced an error! Details:
ERROR vagrant: #<Vagrant::Errors::VagrantError: The SSH command responded with
a non-zero exit status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.>
ERROR vagrant: The SSH command responded with a non-zero exit status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
ERROR vagrant:
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/communicators/ssh/communicator.rb:263:in
`execute'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/provisioners/shell/provisioner.rb:89:in
`block (2 levels) in provision_ssh'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/provisioners/shell/provisioner.rb:63:in
`tap'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/provisioners/shell/provisioner.rb:63:in
`block in provision_ssh'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/provisioners/shell/provisioner.rb:287:in
`with_script_file'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/provisioners/shell/provisioner.rb:61:in
`provision_ssh'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/provisioners/shell/provisioner.rb:27:in
`provision'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builtin/provision.rb:138:in
`run_provisioner'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:95:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:95:in
`block in finalize_action'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builder.rb:116:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/runner.rb:66:in
`block in run'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/util/busy.rb:19:in
`busy'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/runner.rb:66:in
`run'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/environment.rb:526:in
`hook'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builtin/provision.rb:126:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builtin/provision.rb:126:in
`block in call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builtin/provision.rb:103:in
`each'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builtin/provision.rb:103:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/providers/virtualbox/action/check_accessible.rb:18:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:95:in
`block in finalize_action'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builder.rb:116:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/runner.rb:66:in
`block in run'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/util/busy.rb:19:in
`busy'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/runner.rb:66:in
`run'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builtin/call.rb:53:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:95:in
`block in finalize_action'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builder.rb:116:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/runner.rb:66:in
`block in run'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/util/busy.rb:19:in
`busy'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/runner.rb:66:in
`run'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builtin/call.rb:53:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builtin/config_validate.rb:25:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/providers/virtualbox/action/check_virtualbox.rb:26:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/warden.rb:34:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/builder.rb:116:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/runner.rb:66:in
`block in run'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/util/busy.rb:19:in
`busy'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/action/runner.rb:66:in
`run'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/machine.rb:239:in
`action_raw'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/machine.rb:208:in
`block in action'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/environment.rb:614:in
`lock'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/machine.rb:194:in
`call'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/machine.rb:194:in
`action'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/commands/provision/command.rb:30:in
`block in execute'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/plugin/v2/command.rb:238:in
`block in with_target_vms'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/plugin/v2/command.rb:232:in
`each'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/plugin/v2/command.rb:232:in
`with_target_vms'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/plugins/commands/provision/command.rb:29:in
`execute'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/cli.rb:54:in
`execute'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/lib/vagrant/environment.rb:291:in
`cli'
/usr/local/lib/ruby/gems/2.4/gems/vagrant-2.1.5/bin/vagrant:167:in `<top
(required)>'
/usr/local/bin/vagrant:23:in `load'
/usr/local/bin/vagrant:23:in `<main>'
INFO interface: error: The SSH command responded with a non-zero exit status.
Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
The SSH command responded with a non-zero exit status. Vagrant
assumes that this means the command failed. The output for this command
should be in the log above. Please read the output to determine what
went wrong.
INFO interface: Machine: error-exit ["Vagrant::Errors::VagrantError", "The SSH
command responded with a non-zero exit status. Vagrant\nassumes that this means
the command failed. The output for this command\nshould be in the log above.
Please read the output to determine what\nwent wrong."]
