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.
--
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 [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/packer-tool/b3e492d0-7323-4e7c-bf9b-5d5754f1e98f%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
