Unable to re-provision FreeBSD-12 VM

[James E Keenan]

Background

For the past year a colleague and I have been running in an application
inside a FreeBSD-11 VM (virtualbox) sitting on a FreeBSD host. We put
in considerable time and effort writing a Vagrantfile that would
provision the VM with dozens of FreeBSD packages and Perl modules from
CPAN. Once we had the configuration we wanted, we left the Vagrantfile
and only needed to run 'vagrant up', 'vagrant reload --provision' or
'vagrant provision' a handful of times over a 12-month period.

Current Problem

We now want to update our application and run it on FreeBSD-12. With a
certain amount of effort we managed to install the VM and provision it
with a Vagrantfile very similar to the one we used in our FreeBSD-11 VM.
So we've already got many packages and Perl modules installed in the VM.

But now we want to add a few FreeBSD packages to the provisions. We are
finding that when we *re-run* 'vagrant provision' (or similar commands
that effect provisioning), we are fairly consistently failing with this
message:

#####
$ vagrant provision
==> default: Running provisioner: shell...
default: Running: inline script
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.
#####

As a diagnostic, I completely gutted the shell script inside the
Vagrantfile that was doing the provisioning.

#####
$ cat Vagrantfile.diagnostic
# -*- mode: ruby -*-
# vi: set ft=ruby :

# All Vagrant configuration is done below. The "2" in Vagrant.configure
# configures the configuration version (we support older styles for
# backwards compatibility). Please don't change it unless you know what
# you're doing.
Vagrant.configure("2") do |config|
config.vm.box = "freebsd/FreeBSD-12.0-RELEASE"


# 2019-06-09 19:04:00
config.vm.synced_folder ".", "/vagrant", disabled: true

# 2019-05-22 10:00:00
# per
https://forums.freebsd.org/threads/official-vagrant-freebsd-images.52717/
config.vm.base_mac = "080027D14C66"

# 2019-06-09 18:43:00
# First attempt at configuring with same packages
# used in perl-reporter-03 during 5.29 dev cycle

config.vm.provision "shell", inline: <<-SHELL

SHELL
end

#####

But now, whenever I get to 'config.vm.provision "shell", inline:
<<-SHELL' the shell script apparently exits non-zero and I get the error
message cited above. I've also tried:

#####
config.vm.provision "shell", inline: <<-SHELL
true
SHELL
#####

... and ...

#####
config.vm.provision "shell", inline: <<-SHELL
exit 0
SHELL
#####

... land in each case gotten the same error message.

I should note that these command failures are *not* preventing us from
entering the VM. 'vagrant ssh' works.

Summary

Why is this shell script used inside a Vagrantfile apparently exiting
non-zero today when it was working fine just two days ago?

Thank you very much.
Jim Keenan

[Brian Cain]

Hey there,

Do you have a full debug log showing this provisioning behavior when you run Vagrant up or vagrant provision? Thanks!

--
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 vagrant-up+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/vagrant-up/e09c3e3e-8112-2d67-8a7c-e29335046705%40pobox.com.
For more options, visit https://groups.google.com/d/optout.

--

Brian Cain

[James E Keenan]

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?

Thank you very much.
Jim Keenan

>

> <mailto:vagrant-up%2Bunsu...@googlegroups.com>.

> To view this discussion on the web visit
> https://groups.google.com/d/msgid/vagrant-up/e09c3e3e-8112-2d67-8a7c-e29335046705%40pobox.com.
> For more options, visit https://groups.google.com/d/optout.
>
>
>
> --
> Brian Cain
>

> --
> 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 vagrant-up+...@googlegroups.com

> <mailto:vagrant-up+...@googlegroups.com>.

> To view this discussion on the web visit

> https://groups.google.com/d/msgid/vagrant-up/CADHESCV%3DzepJ51JUwgg-31ez67LFmVZnmrfHg5Mt6aLAxkjBNg%40mail.gmail.com
> <https://groups.google.com/d/msgid/vagrant-up/CADHESCV%3DzepJ51JUwgg-31ez67LFmVZnmrfHg5Mt6aLAxkjBNg%40mail.gmail.com?utm_medium=email&utm_source=footer>.

[Brian Cain]

On Wed, Jun 12, 2019 at 10:57 PM James E Keenan <jke...@pobox.com> 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.

 

To unsubscribe from this group and stop receiving emails from it, send an email to vagrant-up+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/vagrant-up/997d08b9-5e65-e051-0fc0-1db63ecfdc08%40pobox.com.

For more options, visit https://groups.google.com/d/optout.

--

Brian Cain

[James E Keenan]

On 6/13/19 11:15 AM, Brian Cain wrote:
>
>
> On Wed, Jun 12, 2019 at 10:57 PM James E Keenan <jke...@pobox.com
> <mailto:jke...@pobox.com>> 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?

[Brian Cain]

I think this is a fairly common issue, and might just be an issue with how that box has setup the root account? I believe this error

is essentially saying that it's trying to run the script as root but there is no configured shell to be used on the root account. I'm guessing maybe

if you update the root account to be able to allocate a shell, the error should go away?

 

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 vagrant-up+...@googlegroups.com.

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.

--

Brian Cain

[James E Keenan]

On 6/13/19 6:09 PM, Brian Cain wrote:
>
>
> On Thu, Jun 13, 2019 at 12:49 PM James E Keenan <jke...@pobox.com
> <mailto:jke...@pobox.com>> wrote:
>
> On 6/13/19 11:15 AM, Brian Cain wrote:
> >
> >
> > On Wed, Jun 12, 2019 at 10:57 PM James E Keenan
> <jke...@pobox.com <mailto:jke...@pobox.com>

This is what I have for the key users on each of 2 VMs. FreeBSD-12 is
not working. FreeBSD-13 is working.

#####
$ uname -mrs;grep -E '^(root|vagrant)' /etc/passwd | cut -d ':' -f1,7
FreeBSD 12.0-RELEASE-p4 amd64
root:/bin/csh
vagrant:/usr/local/bin/bash

% uname -mrs;grep -E '^(root|vagrant)' /etc/passwd | cut -d ':' -f1,7
FreeBSD 13.0-CURRENT amd64
root:/bin/csh
vagrant:/bin/csh
######

Could it be that the vagrant user's shell must be /bin/csh?

[James E Keenan]

Well, in the faulty FreeBSD-12 VM, I changed user 'vagrant's shell to
/bin/csh. I then exited the VM and called 'vagrant provision --debug'
and logged the output.

I got no improvement. Once again I got:

#####
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:

#####

[Brian Cain]

So I pulled down the FreeBSD-12-RELEASE box myself and noticed this line when I tried to run this simple provisioner:

freebsd.vm.provision "shell", inline: "echo 'hi'"

DEBUG ssh: Re-using SSH connection.

 INFO ssh: Execute:  (sudo=false)

DEBUG ssh: stderr: bash: Command not found.

DEBUG ssh: Exit status: 1

 INFO ssh: SSH not ready: #<Vagrant::Errors::SSHInvalidShell: The configured shell (config.ssh.shell) is invalid and unable

to properly execute commands. The most common cause for this is

using a shell that is unavailable on the system. Please verify

you're using the full path to the shell and that the shell is

executable by the SSH user.>

ERROR warden: Error occurred: The configured shell (config.ssh.shell) is invalid and unable

to properly execute commands. The most common cause for this is

using a shell that is unavailable on the system. Please verify

you're using the full path to the shell and that the shell is

executable by the SSH user.

I'm not 100% sure, but I think perhaps bash is a hard requirement for the shell provisioner? Seems like this might be the issue

you are running into as well? Do the other FreeBSD boxes that are working have bash installed?

--
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 vagrant-up+...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/vagrant-up/5f1746c1-f749-934d-b772-0c688f2a2768%40pobox.com.

For more options, visit https://groups.google.com/d/optout.

--

Brian Cain

[James E Keenan]

On 6/14/19 4:36 PM, Brian Cain wrote:
> So I pulled down the FreeBSD-12-RELEASE box myself and noticed this line
> when I tried to run this simple provisioner:
>
> freebsd.vm.provision "shell", inline: "echo 'hi'"
>
>
> DEBUG ssh: Re-using SSH connection.
>  INFO ssh: Execute:  (sudo=false)
> DEBUG ssh: stderr: bash: Command not found.
>
> DEBUG ssh: Exit status: 1
>  INFO ssh: SSH not ready: #<Vagrant::Errors::SSHInvalidShell: The
> configured shell (config.ssh.shell) is invalid and unable
> to properly execute commands. The most common cause for this is
> using a shell that is unavailable on the system. Please verify
> you're using the full path to the shell and that the shell is
> executable by the SSH user.>
> ERROR warden: Error occurred: The configured shell
> (config.ssh.shell) is invalid and unable
> to properly execute commands. The most common cause for this is
> using a shell that is unavailable on the system. Please verify
> you're using the full path to the shell and that the shell is
> executable by the SSH user.
>
>
> I'm not 100% sure, but I think perhaps bash is a hard requirement for
> the shell provisioner? Seems like this might be the issue
> you are running into as well? Do the other FreeBSD boxes that are
> working have bash installed?
>

We have 3 FreeBSD VMs of various ages. One for 11.2, one for 12, one
for 13. Each has /usr/local/bin/bash. For some reason I can't
remember, on the FreeBSD-11.2 machine (which is where we have been
running an application for a year that we would now like to run on
FreeBSD-12) has this:

#####
$ which bash
/bin/bash

$ ls -l /bin/bash
lrwxr-xr-x 1 root wheel 19 May 31 2018 /bin/bash -> /usr/local/bin/bash
#####

Is there a possibility that the vagrant process wants a /bin/bash rather
than an /usr/local/bin/bash?

Thank you very much.
Jim Keenan

> On Thu, Jun 13, 2019 at 4:04 PM James E Keenan <jke...@pobox.com

> <mailto:jke...@pobox.com>> wrote:
>
> On 6/13/19 6:51 PM, James E Keenan wrote:
> > On 6/13/19 6:09 PM, Brian Cain wrote:
> >>
> >>
> >> On Thu, Jun 13, 2019 at 12:49 PM James E Keenan
> <jke...@pobox.com <mailto:jke...@pobox.com>

[James E Keenan]

Just now I explored this possibility, by creating symlink /bin/bash to
/usr/local/bin/bash inside the VM.

It made no difference. 'vagrant provision --debug' continues to include
this:

#####
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-shell20190615-6849-2kslno.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

[James E Keenan]

If /tmp/vagrant-shell already exists in the VM and if its owner is
'vagrant', then ...

> 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

... notwithstanding the non-zero exit status reported, I can
successfully upload the content of the SHELL heredoc to the VM (as in
the next line of output). However, if the owner is not 'vagrant' the
'chown' command does not work and the SHELL heredoc is not uploaded.

> DEBUG ssh: Uploading: /tmp/vagrant-shell20190615-6849-2kslno.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.

If the permissions on /tmp/vagrant-shell are, say, 0600, the following
'chmod +x' does not work. But if /tmp/vagrant-shell is already 0711 (as
it should be), we get past that ... but are unable to execute that program.

>  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:
> #####
>

So it seems as if the problem could be described as "When 'vagrant
provision' needs to execute one of the shell command, it always fails to
do so. If, however, execution of a shell command would have no effect,
the command is, in effect, bypassed, although the exit status is still
reported as non-zero."

Weird.

[Jim McGinness]

You've posed an interesting puzzle. My first guess was that there was just something missing from the box-building process for the 12.0 box.

I finally got my test enviroment back to the point where I could download the two boxes:

freebsd/FreeBSD-13.0-CURRENT

freebsd-FreeBSD-12.0-RELEASE

to see if I could reproduce your symptoms. As is the nature of things, I got different symptoms, but they are basically attributable to the fact that bash is not included in these boxes - a little strange for Vagrant boxes, since "bash -l" is the default value of config.ssh.shell. In order to use these boxes with vagrant, your Vagrantfile (or some other part of your environment) would have to specify a different shell - and I didn't see you doing this.

But these boxes do come with csh installed, so - if your provisioning script can be made compatible with csh - you could possibly get past your problem by adding the line:

   config.ssh.shell = "/bin/csh"

to your Vagrantfile.

As to why your v13 box worked and your v12 box didn't, I can't explain. The boxes on the vagrant cloud get updated from time to time, so I'd need to be sure I was more exactly getting the same boxes as you did, and a better characterization of your vagrant environment than you've given us so far, before I could expect to reproduce what you were seeing. The fact that you see /usr/local/bin/bash on your boxes is one indication that your boxes differ in important ways from the ones I just downloaded.

[James E Keenan]

Thanks for taking the time to investigate this problem. Here's what
we've done in the meantime.

I basically gave up on the FreeBSD-12 box. I went to vagrantup.com and
noticed that there was a newer box called 'generic/freebsd12'. I was
able to call 'vagrant init' on it, then successfully provision it, get
it up, and ssh into it.

This box I believe this box is created by a person whose handle is
'bazinga', as the default hostname for the box was something like
localhost.bazinga. For our application over the past year we used a box
called 'generic/freebsd11' that was also created by bazinga.

Both of his/her 11 and 12 boxes were much more ready-to-use than the
'freebsd/freebsd12' box we were struggling with. For example, bazinga's
boxes come with many ports already installed in /usr/local/bin that the
other box lacked (e.g., perl5). I've been able to provision and
re-provision 'generic/freebsd13' several times and run programs running
as much as 8 hours therein.

So as of now my judgment is that the box about which I posted at the
start of this thread was simply not up to the task. Once we've done a
bit more work on generic/freebsd13 and have started using it in
'production', we'll probably just get rid of the earlier FreeBSD-12 box.

[Jim McGinness]

Yes, the generic/ boxes or their brethren at roboxes/ seem to be a better set of starting points for vagrant use. I try to keep an up-to-date stable of selected roboxes on hand for my testing purposes (on-demand downloading of boxes takes too long on my slow DSL). I've seen "bazinga" as the pre-installed host name in various BSD boxes and have taken steps in my Vagrantfiles to deal with it. I didn't think it was someone's handle; more like it was just a new version of the old "amnesiac" default host name.