Permission Denied when compressing hart

Habitat Help
1

We’re seeing a strange issue where at the completion of the plan, the step where the created tarball is compressed is exiting with a permission denied. See the below set -x output from the generate_artifact step:

+ _generate_artifact
+ build_line 'Generating package artifact'
+ [[ '' == \t\r\u\e ]]
+ case "${TERM:-}" in
+ echo -e '   \033[1;36mREDACTED: \033[1;37mGenerating package artifact\033[0m'
   REDACTED: Generating package artifact
+ return 0
++ dirname /hab/cache/artifacts/ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.hart
++ basename /hab/cache/artifacts/ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar
+ local tarf=/hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar
+ local xzf=/hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar.xz
++ dirname /hab/cache/artifacts/ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.hart
+ mkdir -pv /hab/cache/artifacts
+ rm -fv /hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar /hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar.xz /hab/cache/artifacts/ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.hart
+ /hab/pkgs/core/tar/1.29/20170513213607/bin/tar -cf /hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar /hab/pkgs/ALSO_REDACTED/REDACTED/REDACTED36.3.0/20180717092652
/hab/pkgs/core/tar/1.29/20170513213607/bin/tar: Removing leading `/' from member names
+ /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz --verbose --compress -6 --threads=0 /hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar
/hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar (1/1)
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: /hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-20180717092652-x86_64-linux.tar: Permission denied
++ _on_exit
++ local exit_status=1
++ [[ 0 -gt 0 ]]
++ : REDACTED
++ elapsed=94
+++ echo 94
+++ awk '{printf "%dm%ds", $1/60, $1%60}'
++ elapsed=1m34s
++ [[ '' == \t\r\u\e ]]
++ case "${TERM:-}" in
++ echo -e '   \033[1;36mREDACTED: \033[1;37mBuild time: 1m34s\033[0m'
   REDACTED: Build time: 1m34s
++ [[ 1 -ne 0 ]]
++ [[ '' == \t\r\u\e ]]
++ case "${TERM:-}" in
++ echo -e '   \033[1;36mREDACTED: \033[1;31mExiting on error\033[0m'
   REDACTED: Exiting on error
++ exit 1

We are able to run the xz command manually in the studio, and it works.

We are using a stock studio in Docker, under Mac, and the UID is root.

Here is our plan:

pkg_name=REDACTED
pkg_origin=ALSO_REDACTED
pkg_version=${pkg_name}36.3.0
pkg_upstream_url=https://git.repo.io/ALSO_REDACTED/REDACTED
pkg_description="ALSO_REDACTED front-end Habitat package."
pkg_source=${pkg_upstream_url}
pkg_svc_user="root"
pkg_svc_group="root"
pkg_deps=(
  tm/php
  tm/httpd
  core/mysql-client
)

pkg_build_deps=(
  core/git
)
set -x
do_download() {

    build_line "Setting up git: username, email and other options"
    git config --global user.email "dev@null.sh"
    git config --global user.name "devnull"
    git config --global color.ui true
    git config --global core.autocrlf false
    git config --global core.filemode false

    pushd "$HAB_CACHE_SRC_PATH"
    rm -rf REDACTED
    git clone --branch $pkg_version --depth 1 "$pkg_source"
    popd
}

do_clean() {
  return 0
}

do_verify() {
  return 0
}

do_unpack() {
  return 0
}

do_build() {
  return 0
}

do_install() {
  cp -R ../${pkg_name} "$pkg_prefix/"
}

do_strip() {
  return 0
}

Has anyone seen something like this before? Any suggestions on finding the issue? We are puzzled…

2

What version of the Habitat CLI do you have installed? hab --version

After a failed build, could you run:

ls -la /hab/cache/artifacts/.ALSO_REDACTED-REDACTED-REDACTED36.3.0-TIMESTAMP-x86_64-linux.tar and ls -la /hab/cache/artifacts and paste the results here? (redacting as necessary)

It’s interesting to note that /hab/cache/artifacts is mounted from your MacOS host. It’s possible that there is something going on there as well. Are you seeing this with any other builds on that host?

3

Hey Mister,

thanks for reply.

[20][default:/src:1]# hab --version
hab 0.57.0/20180614230004

[30][default:/src:0]# ls -la /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718062959-x86_64-linux.tar && ls -la /hab/cache/artifacts/
-rw-r–r-- 1 root root 116592640 Jul 18 06:34 /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718062959-x86_64-linux.tar
total 115260
drwxr-xr-x 3 root root 96 Jul 18 06:34 .
drwxr-xr-x 1 root root 4096 Jul 18 06:25 …
-rw-r–r-- 1 root root 116592640 Jul 18 06:34 .REDACTED-REDACTED-36.3.0-20180718062959-x86_64-linux.tar

There are no issues with another builds.

One thing to note is that this package is quite heavy (from 100 to 400 megs of size), not sure if this can be the case ?

4

core/mongodb is ~650MB compressed, so that size package should be fine. Could you add the following code snippet to your plan, rebuild and paste the output of the failure, as you did in your initial post?

do_prepare() {
  export XZ_OPT="-v -v" 
}

This will enable extra verbose mode in xz which may give us more of a hint as to what is going on.

5

Hey,

thanks for reply. Here is the info you requested:

REDACTED: Generating package artifact

  • return 0
    ++ dirname /hab/cache/artifacts/REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.hart
    ++ basename /hab/cache/artifacts/REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar
  • local tarf=/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar
  • local xzf=/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar.xz
    ++ dirname /hab/cache/artifacts/REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.hart
  • mkdir -pv /hab/cache/artifacts
  • rm -fv /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar.xz /hab/cache/artifacts/REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.hart
  • /hab/pkgs/core/tar/1.29/20170513213607/bin/tar -cf /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar /hab/pkgs/REDACTED/REDACTED/36.3.0/20180718172820
    /hab/pkgs/core/tar/1.29/20170513213607/bin/tar: Removing leading `/’ from member names
  • /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz --verbose --compress -6 --threads=0 /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar
    /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Filter chain: --lzma2=dict=8MiB,lc=3,lp=0,pb=2,mode=normal,nice=64,mf=bt4,depth=0
    /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Using up to 4 threads.
    /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: 661 MiB of memory is required. The limiter is disabled.
    /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Decompression will need 9 MiB of memory.
    /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar (1/1)
    /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718172820-x86_64-linux.tar: Permission denied
    ++ _on_exit
    ++ local exit_status=1
    ++ [[ 0 -gt 0 ]]
    ++ : REDACTED
    ++ elapsed=198
    +++ echo 198
    +++ awk ‘{printf “%dm%ds”, $1/60, 1%60}' ++ elapsed=3m18s ++ [[ '' == \t\r\u\e ]] ++ case "{TERM:-}" in
    ++ echo -e ’ \033[1;36mREDACTED: \033[1;37mBuild time: 3m18s\033[0m’
    REDACTED: Build time: 3m18s
    ++ [[ 1 -ne 0 ]]
    ++ [[ ‘’ == \t\r\u\e ]]
    ++ case “${TERM:-}” in
    ++ echo -e ’ \033[1;36mREDACTED: \033[1;31mExiting on error\033[0m’
    REDACTED: Exiting on error
    ++ exit 1
    [5][default:/src:1]#

Thanks

6

Interesting, I’m still not seeing anything obvious. For troubleshooting purposes, let’s try and get an strace of the output for xz.

In your pkg_build_deps, please add core/strace. Then update do_prepare as follows:

do_prepare() {
  _xz_cmd="strace $_xz_cmd"
}

This should give us all of the system calls it’s attempting to make when it runs xz. This can be pretty verbose, but will hopefully tell us why it’s failing.

I was able to replicate the behavior locally by removing read permissions from a file, but that doesn’t appear to be the case for you.

7

Here you go:

   REDACTED: Generating package artifact
+ return 0
++ dirname /hab/cache/artifacts/REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.hart
++ basename /hab/cache/artifacts/REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar
+ local tarf=/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar
+ local xzf=/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar.xz
++ dirname /hab/cache/artifacts/REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.hart
+ mkdir -pv /hab/cache/artifacts
+ rm -fv /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar.xz /hab/cache/artifacts/REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.hart
+ /hab/pkgs/core/tar/1.29/20170513213607/bin/tar -cf /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar /hab/pkgs/REDACTED/REDACTED/36.3.0/20180718200817
/hab/pkgs/core/tar/1.29/20170513213607/bin/tar: Removing leading `/' from member names
+ strace /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz --verbose --compress -6 --threads=0 /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar
execve("/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz", ["/hab/pkgs/core/xz/5.2.2/20170513"..., "--verbose", "--compress", "-6", "--threads=0", "/hab/cache/artifacts/.REDACTED-REDACTED"...], 0x7ffee73e3268 /* 22 vars */) = 0
brk(NULL)                               = 0x10bb000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f39528ac000
access("/hab/pkgs/core/glibc/2.22/20170513201042/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/tls/x86_64/liblzma.so.5", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/tls/x86_64", 0x7fff35bb37d0) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/tls/liblzma.so.5", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/tls", 0x7fff35bb37d0) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/x86_64/liblzma.so.5", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/x86_64", 0x7fff35bb37d0) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/liblzma.so.5", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200/\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=208816, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f39528ab000
mmap(NULL, 2304000, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f3952459000
mprotect(0x7f395248b000, 2097152, PROT_NONE) = 0
mmap(0x7f395268b000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x32000) = 0x7f395268b000
close(3)                                = 0
open("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/glibc/2.22/20170513201042/lib/tls/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/hab/pkgs/core/glibc/2.22/20170513201042/lib/tls/x86_64", 0x7fff35bb37a0) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/glibc/2.22/20170513201042/lib/tls/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/hab/pkgs/core/glibc/2.22/20170513201042/lib/tls", 0x7fff35bb37a0) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/glibc/2.22/20170513201042/lib/x86_64/libpthread.so.0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
stat("/hab/pkgs/core/glibc/2.22/20170513201042/lib/x86_64", 0x7fff35bb37a0) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/glibc/2.22/20170513201042/lib/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\320`\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=101848, ...}) = 0
mmap(NULL, 2213040, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f395223c000
mprotect(0x7f3952254000, 2093056, PROT_NONE) = 0
mmap(0x7f3952453000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17000) = 0x7f3952453000
mmap(0x7f3952455000, 13488, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3952455000
close(3)                                = 0
open("/hab/pkgs/core/xz/5.2.2/20170513214327/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/hab/pkgs/core/glibc/2.22/20170513201042/lib/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\7\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1709608, ...}) = 0
mmap(NULL, 3816000, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f3951e98000
mprotect(0x7f3952032000, 2097152, PROT_NONE) = 0
mmap(0x7f3952232000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19a000) = 0x7f3952232000
mmap(0x7f3952238000, 14912, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3952238000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f39528aa000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f39528a9000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f39528a8000
arch_prctl(ARCH_SET_FS, 0x7f39528a9700) = 0
mprotect(0x7f3952232000, 16384, PROT_READ) = 0
mprotect(0x7f3952453000, 4096, PROT_READ) = 0
mprotect(0x7f39528ad000, 4096, PROT_READ) = 0
set_tid_address(0x7f39528a99d0)         = 1283
set_robust_list(0x7f39528a99e0, 24)     = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f3952241b70, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {sa_handler=0x7f3952241c00, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
fcntl(0, F_GETFD)                       = 0
fcntl(1, F_GETFD)                       = 0
fcntl(2, F_GETFD)                       = 0
geteuid()                               = 0
pipe([3, 4])                            = 0
fcntl(3, F_GETFL)                       = 0 (flags O_RDONLY)
fcntl(3, F_SETFL, O_RDONLY|O_NONBLOCK)  = 0
fcntl(4, F_GETFL)                       = 0x1 (flags O_WRONLY)
fcntl(4, F_SETFL, O_WRONLY|O_NONBLOCK)  = 0
brk(NULL)                               = 0x10bb000
brk(0x10dc000)                          = 0x10dc000
ioctl(2, TCGETS, {B38400 opost isig icanon echo ...}) = 0
rt_sigaction(SIGALRM, {sa_handler=0x40934f, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigaction(SIGUSR1, {sa_handler=0x40934f, sa_mask=[], sa_flags=SA_RESTORER, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
open("/proc/meminfo", O_RDONLY|O_CLOEXEC) = 5
fstat(5, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f39528a7000
read(5, "MemTotal:        2046652 kB\nMemF"..., 1024) = 1024
close(5)                                = 0
munmap(0x7f39528a7000, 4096)            = 0
open("/sys/devices/system/cpu/online", O_RDONLY|O_CLOEXEC) = 5
read(5, "0-3\n", 8192)                  = 4
close(5)                                = 0
rt_sigaction(SIGINT, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGINT, {sa_handler=0x40b900, sa_mask=[HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], sa_flags=SA_RESTORER, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigaction(SIGTERM, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGTERM, {sa_handler=0x40b900, sa_mask=[HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], sa_flags=SA_RESTORER, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigaction(SIGHUP, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGHUP, {sa_handler=0x40b900, sa_mask=[HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], sa_flags=SA_RESTORER, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=0x40b900, sa_mask=[HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], sa_flags=SA_RESTORER, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigaction(SIGXCPU, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGXCPU, {sa_handler=0x40b900, sa_mask=[HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], sa_flags=SA_RESTORER, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigaction(SIGXFSZ, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGXFSZ, {sa_handler=0x40b900, sa_mask=[HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], sa_flags=SA_RESTORER, sa_restorer=0x7f395224ccf0}, NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], NULL, 8) = 0
write(2, "/hab/cache/artifacts/.REDACTED-REDACTED"..., 79/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar (1/1)
) = 79
rt_sigprocmask(SIG_UNBLOCK, [HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], NULL, 8) = 0
rt_sigprocmask(SIG_BLOCK, [HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], NULL, 8) = 0
open("/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_NOFOLLOW) = -1 EACCES (Permission denied)
write(2, "/hab/pkgs/core/xz/5.2.2/20170513"..., 47/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: ) = 47
write(2, "/hab/cache/artifacts/.REDACTED-REDACTED"..., 91/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718200817-x86_64-linux.tar: Permission denied) = 91
write(2, "\n", 1
)                       = 1
rt_sigprocmask(SIG_UNBLOCK, [HUP INT USR1 PIPE ALRM TERM XCPU XFSZ], NULL, 8) = 0
exit_group(1)                           = ?
+++ exited with 1 +++
++ _on_exit
++ local exit_status=1
++ [[ 0 -gt 0 ]]
++ : REDACTED
++ elapsed=127
+++ echo 127
+++ awk '{printf "%dm%ds", $1/60, $1%60}'
++ elapsed=2m7s
++ [[ '' == \t\r\u\e ]]
++ case "${TERM:-}" in
++ echo -e '   \033[1;36mREDACTED: \033[1;37mBuild time: 2m7s\033[0m'
   REDACTED: Build time: 2m7s
++ [[ 1 -ne 0 ]]
++ [[ '' == \t\r\u\e ]]
++ case "${TERM:-}" in
++ echo -e '   \033[1;36mREDACTED: \033[1;31mExiting on error\033[0m'
   REDACTED: Exiting on error
++ exit 1
[5][default:/src:1]#

Thanks

8

This is incredibly odd. I’m kind of suspecting some strange interaction between the Docker VM and and the host filesystem. Could you verify that your filesystem isn’t almost full ( I highly doubt this is the issue, since it can’t open the file ) . Could you also try restarting Docker on your mac. I don’t think this is the problem either, since other builds are working for you. You could also try resetting your docker installation (The bomb icon in the top right of the docker preferences).

9

Hey,

my mate just managed to find the issue and we believe that this is somehow related to the number of files inside directory. If we limit number of files from almost 27k by about half, we can get successful build, otherwise it keeps failing with the same issue. My mate will post a full answer shortly.

10

Immediately on entering the studio, core/xz/5.2.2 is available and, by default, uses the below options:

[1][default:/src:0]# /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz -v -v /tmp       
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Filter chain: --lzma2=dict=8MiB,lc=3,lp=0,pb=2,mode=normal,nice=64,mf=bt4,depth=0
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: 94 MiB of memory is required. The limiter is disabled.
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Decompression will need 9 MiB of memory.

During a build in the studio, we see:

    REDACTED: Generating package artifact
/hab/pkgs/core/tar/1.29/20170513213607/bin/tar: Removing leading `/' from member names
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Filter chain: --lzma2=dict=8MiB,lc=3,lp=0,pb=2,mode=normal,nice=64,mf=bt4,depth=0
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Using up to 4 threads.
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: 661 MiB of memory is required. The limiter is disabled.
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Decompression will need 9 MiB of memory.

The only difference seems to be threads, which is set here https://github.com/habitat-sh/habitat/blob/0e0157ca440d119e92b9501fdd64e4933d1c21d5/components/plan-build/bin/hab-plan-build.sh#L2173 (where 0 actually means one-thread-per-cpu available).

I had some mixed results when updating my Docker settings to give studio only one CPU - and therefore disable threading - but still couldn’t reliably build the package:

    REDACTED: Generating package artifact
/hab/pkgs/core/tar/1.29/20170513213607/bin/tar: Removing leading `/' from member names
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Filter chain: --lzma2=dict=8MiB,lc=3,lp=0,pb=2,mode=normal,nice=64,mf=bt4,depth=0
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: 94 MiB of memory is required. The limiter is disabled.
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: Decompression will need 9 MiB of memory.
/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718215532-x86_64-linux.tar (1/1)
/hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz: /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718215532-x86_64-linux.tar: Permission denied
    REDACTED: Build time: 1m55s
    REDACTED: Exiting on error

Following the output above, immediately trying to run xz again using what-i-think-are the default build options seems to work, indicating the problem could be unique to the Habitat build process:

[2][default:/src:1]# /hab/pkgs/core/xz/5.2.2/20170513214327/bin/xz --verbose --compress -6 --threads=0 /hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718215532-x86_64-linux.tar
/hab/cache/artifacts/.REDACTED-REDACTED-36.3.0-20180718215532-x86_64-linux.tar (1/1)
  100 %        41.1 MiB / 181.4 MiB = 0.227   1.9 MiB/s       1:37

Finally, as iskorptix mentioned above, we are using rsync to move files from our repo into the package path during do_install. Experimenting with the --exclude option proved that if the overall number of files is reduced, compression will complete successfully. My testing wasn’t scientific enough to advise a ‘breaking point’, although the repo we are packaging has many nested directories, huge vendored libraries, etc.

We’ve found a sweet spot where we can exclude enough files that we actually don’t require, to allow compression to succeed, so for now we’re happy but I imagine this is certainly something that others may encounter in the future.

1 Like