virtualbox-iso: Step "StepOutputDir" failed, aborting.

[mike....@solidfire.com]

We're using packer in a build process and it's generating the error listed in the subject.  I've run with

export PACKER_LOG=1
export PACKER_LOG_PATH="/tmp/packerlog.txt"

but there is no additional information in the log:

2017/09/27 11:45:29 packer: 2017/09/27 11:45:29 Acquiring lock to download: file:///<path>.iso
2017/09/27 11:45:29 packer: 2017/09/27 11:45:29 Parsed URL: &url.URL{Scheme:"file", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/<path>.iso", RawPath:"", ForceQuery:false, RawQuery:"", Fragment:""}
2017/09/27 11:45:29 packer: 2017/09/27 11:45:29 [DEBUG] Using local file: /<path>.iso
2017/09/27 11:45:29 packer: 2017/09/27 11:45:29 Verifying checksum of /<path>.iso
2017/09/27 11:45:32 ui error: ==> virtualbox-iso: Step "StepOutputDir" failed, aborting...
2017/09/27 11:45:32 /usr/local/bin/packer: plugin process exited

where <path> was changed for posting here.

I'm looking for a way of identifying what might be causing this.  Note that a first pass gives a different error, but from that point on I get this error.  Rerunning the first pass takes a loooong time so I'm trying to debug back-to-front.

Any tips?

[Matthew Hooker]

hmm, definitely hard to tell from the log. I looked at the StepOutputDir step, and it should report any errors it runs in to. Could you upload your entire log to gist.github.com and post it here?

--
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/packer/issues
IRC: #packer-tool on Freenode
---
You received this message because you are subscribed to the Google Groups "Packer" group.
To unsubscribe from this group and stop receiving emails from it, send an email to packer-tool...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/packer-tool/4751ff77-e863-4a1f-8ddb-58756ef48bf5%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[mike....@solidfire.com]

https://gist.github.com/anonymous/8940245d6e5988ed99f898dea7e01c4c

[Alvaro Miranda Aguilera]

can you add the packer template to the gist ?

On Wed, Sep 27, 2017 at 8:32 PM, <mike....@solidfire.com> wrote:

https://gist.github.com/anonymous/8940245d6e5988ed99f898dea7e01c4c

--
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/packer/issues
IRC: #packer-tool on Freenode
---
You received this message because you are subscribed to the Google Groups "Packer" group.

To unsubscribe from this group and stop receiving emails from it, send an email to packer-tool+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/packer-tool/994c6531-b85c-4368-9039-b2455c2af9b9%40googlegroups.com.

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

--

Alvaro

[mike....@solidfire.com]

https://gist.github.com/anonymous/a5f03015c019d22de35223cc9132ff4e#file-gistfile1-txt

[mike....@solidfire.com]

I ran packer with strace to generate trace files for each child process.  I get lots of them, 36 of which end with "exited with 1".  I suspect lots of these are because of a child that exited badly.  I started looking at each of these logs to see if I could find the culprit.

I see this in one process log:

[00000000004fde14] write(4</tmp/packer-log213347499>, "2017/09/27 13:04:29 packer: 2017/09/27 13:04:29 [INFO] Packer version: 0.12.1\n", 78) = 78
 > /usr/local/bin/packer(syscall.Syscall+0x24) [0xfde14]
 > /usr/local/bin/packer(syscall.Write+0x49) [0xf8039]
 > /usr/local/bin/packer(os.(*File).write+0x78) [0x9ddf8]
 > /usr/local/bin/packer(os.(*File).Write+0x5f) [0x9b39f]
 > /usr/local/bin/packer(io.(*multiWriter).Write+0x72) [0xc0032]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/mitchellh/panicwrap.trackPanic+0x34f) [0xef1cf]

After which I get many calls to panicwrap.  There are 6 logs with panicwrap in them.  1 starts with an execve(packer, build).  4 start with getting their thread id, probably children of that first one.  1 starts by changing stdout to /dev/null.

The execve() trace has a panicwrap here:

 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]
[00000000004fde8a] openat(AT_FDCWD, "/tmp/packer-log213347499", O_RDWR|O_CREAT|O_EXCL|O_CLOEXEC, 0600) = 4</tmp/packer-log213347499>
 > /usr/local/bin/packer(syscall.Syscall6+0x2a) [0xfde8a]
 > /usr/local/bin/packer(syscall.Open+0x50) [0xf56b0]
 > /usr/local/bin/packer(os.OpenFile+0x80) [0x9cf40]
 > /usr/local/bin/packer(io/ioutil.TempFile+0x159) [0xd57b9]
 > /usr/local/bin/packer(main.realMain+0x150) [0x4500]
 > /usr/local/bin/packer(main.main+0x22) [0x4392]
 > /usr/local/bin/packer(runtime.main+0x1f4) [0x31b74]
 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]
[00000000004fdeef] pipe2([5<pipe:[275195825]>, 6<pipe:[275195825]>], O_CLOEXEC) = 0
 > /usr/local/bin/packer(syscall.RawSyscall+0x1f) [0xfdeef]
 > /usr/local/bin/packer(syscall.Pipe2+0x97) [0xf7707]
 > /usr/local/bin/packer(os.Pipe+0x6a) [0x9fa5a]
 > /usr/local/bin/packer(os/exec.(*Cmd).writerDescriptor+0x6d) [0xc247d]
 > /usr/local/bin/packer(os/exec.(*Cmd).stdout+0x3d) [0xc228d]
 > /usr/local/bin/packer(os/exec.(*Cmd).Start+0xfd) [0xc2d1d]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/mitchellh/panicwrap.Wrap+0x4d5) [0xee715]

One processes has panicwrap and StepOutputDir:

 > /usr/local/bin/packer(runtime.mcall+0x5b) [0x5d5fb]
[00000000004611c7] select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=3}) = 0 (Timeout)
 > /usr/local/bin/packer(runtime.usleep+0x37) [0x611c7]
 > /usr/local/bin/packer(runtime.runqgrab+0x11f) [0x3d25f]
 > /usr/local/bin/packer(runtime.runqsteal+0x57) [0x3d347]
 > /usr/local/bin/packer(runtime.findrunnable+0x718) [0x36c48]
 > /usr/local/bin/packer(runtime.schedule+0x14c) [0x372cc]
 > /usr/local/bin/packer(runtime.park_m+0x123) [0x37643]
 > /usr/local/bin/packer(runtime.mcall+0x5b) [0x5d5fb]
[00000000004615e3] futex(0xc420146510, FUTEX_WAKE, 1) = 1
 > /usr/local/bin/packer(runtime.futex+0x23) [0x615e3]
 > /usr/local/bin/packer(runtime.notewakeup+0x5b) [0x1467b]
 > /usr/local/bin/packer(runtime.startm+0xe0) [0x35b40]
 > /usr/local/bin/packer(runtime.wakep+0x57) [0x35fc7]
 > /usr/local/bin/packer(runtime.resetspinning+0x8b) [0x36f7b]
 > /usr/local/bin/packer(runtime.schedule+0x136) [0x372b6]
 > /usr/local/bin/packer(runtime.park_m+0x123) [0x37643]
 > /usr/local/bin/packer(runtime.mcall+0x5b) [0x5d5fb]
[00000000004fde14] read(7<pipe:[275195828]>, "2017/09/27 13:07:49 ui error: \33[1;31m==> virtualbox-iso: Step \"StepOutputDir\" failed, aborting...\33[0m\n", 32768) = 102
 > /usr/local/bin/packer(syscall.Syscall+0x24) [0xfde14]
 > /usr/local/bin/packer(syscall.Read+0x49) [0xf7fb9]
 > /usr/local/bin/packer(os.(*File).read+0x4f) [0x9dc9f]
 > /usr/local/bin/packer(os.(*File).Read+0x59) [0x9af19]
 > /usr/local/bin/packer(io.copyBuffer+0x147) [0xbf3a7]
 > /usr/local/bin/packer(io.Copy+0x68) [0xbf0e8]
 > /usr/local/bin/packer(os/exec.(*Cmd).writerDescriptor.func1+0x4d) [0xc5fbd]
 > /usr/local/bin/packer(os/exec.(*Cmd).Start.func1+0x27) [0xc6037]
 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]
[00000000004fde14] write(4</tmp/packer-log213347499>, "2017/09/27 13:07:49 ui error: \33[1;31m==> virtualbox-iso: Step \"StepOutputDir\" failed, aborting...\33[0m\n", 102) = 102
 > /usr/local/bin/packer(syscall.Syscall+0x24) [0xfde14]
 > /usr/local/bin/packer(syscall.Write+0x49) [0xf8039]
 > /usr/local/bin/packer(os.(*File).write+0x78) [0x9ddf8]
 > /usr/local/bin/packer(os.(*File).Write+0x5f) [0x9b39f]
 > /usr/local/bin/packer(io.(*multiWriter).Write+0x72) [0xc0032]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/mitchellh/panicwrap.trackPanic+0x34f) [0xef1cf]

Looks like someone is sending this child the error message through a pipe.  Three processes other than this one have StepOutputDir in them.

One looks like this:

[00000000004fde14] read(5<pipe:[275195825]>, "\n\33[1;32m==> virtualbox-iso: Downloading or copying ISO\33[0m\n\33[0;32m    virtualbox-iso: Downloading or copying: file:///home/mjham"..., 32768) = 238
 > /usr/local/bin/packer(syscall.Syscall+0x24) [0xfde14]
 > /usr/local/bin/packer(syscall.Read+0x49) [0xf7fb9]
 > /usr/local/bin/packer(os.(*File).read+0x4f) [0x9dc9f]
 > /usr/local/bin/packer(os.(*File).Read+0x59) [0x9af19]
 > /usr/local/bin/packer(io.copyBuffer+0x147) [0xbf3a7]
 > /usr/local/bin/packer(io.Copy+0x68) [0xbf0e8]
 > /usr/local/bin/packer(os/exec.(*Cmd).writerDescriptor.func1+0x4d) [0xc5fbd]
 > /usr/local/bin/packer(os/exec.(*Cmd).Start.func1+0x27) [0xc6037]
 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]
[00000000004615e3] futex(0xc42017a110, FUTEX_WAKE, 1) = 1
 > /usr/local/bin/packer(runtime.futex+0x23) [0x615e3]
 > /usr/local/bin/packer(runtime.notewakeup+0x5b) [0x1467b]
 > /usr/local/bin/packer(runtime.startm+0xe0) [0x35b40]
 > /usr/local/bin/packer(runtime.wakep+0x57) [0x35fc7]
 > /usr/local/bin/packer(runtime.ready+0x132) [0x333d2]
 > /usr/local/bin/packer(runtime.goready.func1+0x38) [0x57638]
 > /usr/local/bin/packer(runtime.systemstack+0x79) [0x5d699]
[00000000004615e3] futex(0xc42017a110, FUTEX_WAKE, 1) = 1
 > /usr/local/bin/packer(runtime.futex+0x23) [0x615e3]
 > /usr/local/bin/packer(runtime.notewakeup+0x5b) [0x1467b]
 > /usr/local/bin/packer(runtime.startm+0xe0) [0x35b40]
 > /usr/local/bin/packer(runtime.wakep+0x57) [0x35fc7]
 > /usr/local/bin/packer(runtime.ready+0x132) [0x333d2]
 > /usr/local/bin/packer(runtime.goready.func1+0x38) [0x57638]
 > /usr/local/bin/packer(runtime.systemstack+0x79) [0x5d699]
[00000000004fde14] read(5<pipe:[275195825]>, "\33[1;31m==> virtualbox-iso: Step \"StepOutputDir\" failed, aborting...\33[0m\n", 32768) = 72

Another looks like this:

[00000000004fde14] write(5<socket:[275228958]>, "\0\0\0\0\0\0\0\2\0\0\0O", 12) = 12
 > /usr/local/bin/packer(syscall.Syscall+0x24) [0xfde14]
 > /usr/local/bin/packer(syscall.Write+0x49) [0xf8039]
 > /usr/local/bin/packer(net.(*netFD).Write+0x12a) [0x37823a]
 > /usr/local/bin/packer(net.(*conn).Write+0x70) [0x3883d0]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Session).send+0x180) [0xca0270]
 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]
[00000000004fde14] write(5<socket:[275228958]>, "\202\243Seq\3\255ServiceMethod\254Cache.Unlock\331,517ece04011e1b38e184e296c95d ff7996580b8f.iso", 79) = 79
 > /usr/local/bin/packer(syscall.Syscall+0x24) [0xfde14]
 > /usr/local/bin/packer(syscall.Write+0x49) [0xf8039]
 > /usr/local/bin/packer(net.(*netFD).Write+0x12a) [0x37823a]
 > /usr/local/bin/packer(net.(*conn).Write+0x70) [0x3883d0]
 > /usr/local/bin/packer(bytes.(*Reader).WriteTo+0x86) [0x1b0d96]
 > /usr/local/bin/packer(io.copyBuffer+0x37b) [0xbf5db]
 > /usr/local/bin/packer(io.Copy+0x68) [0xbf0e8]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Session).send+0x32d) [0xca041d]
 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]
[00000000004fde14] stat("/home/mjhammel/src/netapp/bitbucket/ember2/src/work/minimal/virtualbox-output", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
 > /usr/local/bin/packer(syscall.Syscall+0x24) [0xfde14]
 > /usr/local/bin/packer(os.Stat+0x7d) [0x9d57d]
 > /usr/local/bin/packer(github.com/mitchellh/packer/builder/virtualbox/common.(*StepOutputDir).Run+0xd6) [0xa9c9e6]
 > /usr/local/bin/packer(github.com/mitchellh/packer/common.abortStep.Run+0x45) [0x517b45]
 > /usr/local/bin/packer(github.com/mitchellh/packer/common.(*abortStep).Run+0x81) [0x51fb41]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/mitchellh/multistep.(*BasicRunner).Run+0x207) [0x4f4f17]
 > /usr/local/bin/packer(github.com/mitchellh/packer/builder/virtualbox/iso.(*Builder).Run+0x128a) [0x29b20a]
 > /usr/local/bin/packer(github.com/mitchellh/packer/packer/rpc.(*BuilderServer).Run+0x218) [0x359098]
 > /usr/local/bin/packer(runtime.call64+0x4c) [0x5daac]
 > /usr/local/bin/packer(reflect.Value.call+0x5c8) [0x118738]
 > /usr/local/bin/packer(reflect.Value.Call+0xa4) [0x118054]
 > /usr/local/bin/packer(net/rpc.(*service).call+0x148) [0xb4d1f8]
 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]

And the last looks like this:

 > /usr/local/bin/packer(io.ReadFull+0x58) [0xbef08]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Session).recvLoop+0xf3) [0xca06d3]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Session).recv+0x2b) [0xca059b]
 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]
[00000000004fde14] read(5<socket:[275228957]>, 0xc420333000, 4096) = -1 EAGAIN (Resource temporarily unavailable)
 > /usr/local/bin/packer(syscall.Syscall+0x24) [0xfde14]
 > /usr/local/bin/packer(syscall.Read+0x49) [0xf7fb9]
 > /usr/local/bin/packer(net.(*netFD).Read+0x10f) [0x3774ff]
 > /usr/local/bin/packer(net.(*conn).Read+0x70) [0x3880f0]
 > /usr/local/bin/packer(bufio.(*Reader).fill+0x10c) [0x1bca8c]
 > /usr/local/bin/packer(bufio.(*Reader).Read+0x1bc) [0x1bd0ec]
 > /usr/local/bin/packer(io.(*LimitedReader).Read+0x6c) [0xbf68c]
 > /usr/local/bin/packer(bytes.(*Buffer).ReadFrom+0x155) [0x1ad3d5]
 > /usr/local/bin/packer(io.copyBuffer+0x323) [0xbf583]
 > /usr/local/bin/packer(io.Copy+0x68) [0xbf0e8]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Stream).readData+0x2ee) [0xca3d2e]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Session).handleStreamMessage+0x308) [0x
ca0f48]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Session).(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.handleStreamMessage)-fm+0x48) [0xca43d8]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Session).recvLoop+0x1b4) [0xca0794]
 > /usr/local/bin/packer(github.com/mitchellh/packer/vendor/github.com/hashicorp/yamux.(*Session).recv+0x2b) [0xca059b]
 > /usr/local/bin/packer(runtime.goexit+0x1) [0x60541]
[0000000000461779] epoll_wait(6<anon_inode:[eventpoll]>, [], 128, 0) = 0
 > /usr/local/bin/packer(runtime.epollwait+0x19) [0x61779]
 > /usr/local/bin/packer(runtime.findrunnable+0x832) [0x36d62]
 > /usr/local/bin/packer(runtime.schedule+0x14c) [0x372cc]
 > /usr/local/bin/packer(runtime.park_m+0x123) [0x37643]
 > /usr/local/bin/packer(runtime.mcall+0x5b) [0x5d5fb]
[0000000000461779] epoll_wait(6<anon_inode:[eventpoll]>, [{EPOLLIN|EPOLLOUT, {u32=4210577152, u64=139835460833024}}], 128, -1) = 1
 > /usr/local/bin/packer(runtime.epollwait+0x19) [0x61779]
 > /usr/local/bin/packer(runtime.findrunnable+0x28c) [0x367bc]
 > /usr/local/bin/packer(runtime.schedule+0x14c) [0x372cc]
 > /usr/local/bin/packer(runtime.park_m+0x123) [0x37643]
 > /usr/local/bin/packer(runtime.mcall+0x5b) [0x5d5fb]
[00000000004fde14] read(5<socket:[275228957]>, "\202\243Seq\4\255ServiceMethod\250Ui.Error\331(Step \"StepOutputDir\" failed, aborting...", 4096) = 71

The 2nd of these has an "abortStep" in it and is the only one of the three which didn't read that error message from a socket, which makes me think this is the culprit.  Perhaps it failed when running StepOutputDir after a stat() that failed?

But that's as far as my debug takes me.

[mike....@solidfire.com]

Oh, and /home/mjhammel/src/netapp/bitbucket/ember2/src/work/minimal/virtualbox-output is a directory, it exists but it has nothing in it.  It may have been cleaned out by the original pass that had a different error (I'm rerunning that one now in a different tree to see if I can identify that error).

[mike....@solidfire.com]

The original error on the first pass is this (which I've not debugged beyond this because multiples runs cause the other error I have been debugging):

| Creating Vagrant Box
|
| • FLAVOR   :: "minimal"
| • ISO      :: "work/builds/ember-minimal-dev-0.149-3-g91fb1af-dirty.iso"
| • OUTPUT   :: "work/builds/ember-minimal-dev-0.149-3-g91fb1af-dirty.box"
| • VERSION  :: "dev-0.149-3-g91fb1af-dirty"
|
+------------------------------------------------------------------------------------------------------------------------------+
>> Removing any virtualbox knowledge of previous builds at this version.
>> Building image and testing installation process pwd=/home/mjhammel/src/netapp/bitbucket/ember3/src
Template validated successfully.
virtualbox-iso output will be in this color.

==> virtualbox-iso: Downloading or copying ISO

    virtualbox-iso: Downloading or copying: file:///home/mjhammel/src/netapp/bitbucket/ember3/src/work/builds/ember-minimal-dev-0.149-3-g91fb1af-dirty.iso
==> virtualbox-iso: Creating virtual machine...
==> virtualbox-iso: Error creating VM: VBoxManage error: VBoxManage: error: Runtime error opening '/home/mjhammel/src/netapp/bitbucket/ember/src/work/VirtualBox/VirtualBox.xml-tmp' for overwriting: -102(File not found.).
==> virtualbox-iso: VBoxManage: error: /builddir/build/BUILD/VirtualBox-5.1.26/src/VBox/Main/src-server/VirtualBoxImpl.cpp[4276] (nsresult VirtualBox::i_saveSettings())
==> virtualbox-iso: VBoxManage: error: Details: code NS_ERROR_FAILURE (0x80004005), component VirtualBoxWrap, interface IVirtualBox, callee nsISupports
==> virtualbox-iso: VBoxManage: error: Context: "RegisterMachine(machine)" at line 278 of file VBoxManageMisc.cpp
==> virtualbox-iso: Step "stepCreateVM" failed, aborting...
Build 'virtualbox-iso' errored: unexpected EOF

==> Some builds didn't complete successfully and had errors:
--> virtualbox-iso: unexpected EOF

==> Builds finished but no artifacts were created.

>> [UnhandledError pid=18315 cmd=wait ${pid}]
   :: make-vagrant-box:106 | main

>> [Caught SIGTERM pid=17931 cmd=( unset TMPDIR; cat /dev/null > "${WORK}/${flavor}/virtua...]
   :: make-vagrant-box:1   | main
make: *** [Makefile:309: work/builds/ember-minimal-dev-0.149-3-g91fb1af-dirty.box] Error 1

[Rickard von Essen]

You have to define *all* user variables is the "variables" block.

            "output_directory": "{{user `output_directory`}}",

but:

    "variables" : {

        "ssh_username": "root",

        "ssh_password": "solidfire",

        "headless": "true"

    },

--
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/packer/issues
IRC: #packer-tool on Freenode
---
You received this message because you are subscribed to the Google Groups "Packer" group.
To unsubscribe from this group and stop receiving emails from it, send an email to packer-tool+unsubscribe@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/packer-tool/d32ff681-ef86-4978-b0e8-a24de01f0a76%40googlegroups.com.

[mike....@solidfire.com]

I found the source of the problem.  A directory needed to be cleaned up before running packer.  Even if --force was used, the directory still needed to be cleaned up.  The wrapper script for our build that calls packer now properly cleans up previous builds that may have failed.

Thanks for the tips!