misleading errors when running on nfs and overlay

[smoser]

overlayfs does not work on nfs. When using stacker, the failure path is quite non-obvious there.
Below is output of stacker current tip on nfs build.

Reasons why I lost time debugging this:

• There isn't anything in the output that even mentions mounts failing
• you're left with the non-fatal 'error' in the output.
• --debug is even worse as it gives you a stack trace on the non-fatal main.doCheckAAProfile debug-log.txt .

I'd like to suggest that:

1. stack traces of "information finding" sub-commands should not be shown. they are really hard to ignore.
2. the message error: write /proc/30031/attr/current: invalid argument that is a result of that information subcommand (check-aa-profile) should not be written to output.

# this is centos 7.9 kernel from https://centos.pkgs.org/7/elrepo-kernel-x86_64/
$ uname -r
5.17.5-1.el7.elrepo.x86_64

$ /tmp/stacker-bins/stacker-v0.20.1-14-g8bcaa49 build
preparing image build-env...
loading docker://aci-docker-reg.cisco.com/c3/minbase:1.0.7
Copying blob 0dab16140ba4 skipped: already exists
Copying blob 6754ae8b4482 skipped: already exists
Copying config 7fe0fbc9f6 done
Writing manifest to image destination
Storing signatures
error: write /proc/30031/attr/current: invalid argument
couldn't find AppArmor profile lxc-container-default-cgns
failed to start container build-env
error: run commands failed: execute failed: exit status 1
error: exit status 1

$ cat .stacker/lxc.log
lxc 20220506130812.376 TRACE    lxccontainer - lxccontainer.c:do_lxcapi_save_config:2672 - Saved config file "/tmp/stacker_build-env_run2594949720"
lxc build-env 20220506130817.794 TRACE    commands - commands.c:lxc_server_init:2078 - Created abstract unix socket "/home/scmoser/test/roots/build-env/command"
lxc build-env 20220506130817.794 TRACE    start - start.c:lxc_init_handler:757 - Unix domain socket 3 for command server is ready
lxc build-env 20220506130817.795 TRACE    execute - execute.c:lxc_execute:49 - Doing lxc_execute
lxc build-env 20220506130817.795 INFO     lsm - lsm/lsm.c:lsm_init_static:38 - Initialized LSM security driver nop
lxc build-env 20220506130817.795 TRACE    start - start.c:lxc_init:781 - Initialized LSM
lxc build-env 20220506130817.795 TRACE    start - start.c:lxc_serve_state_clients:486 - Set container state to STARTING
lxc build-env 20220506130817.795 TRACE    start - start.c:lxc_serve_state_clients:489 - No state clients registered
lxc build-env 20220506130817.795 INFO     utils - utils.c:get_rundir:260 - XDG_RUNTIME_DIR isn't set in the environment
lxc build-env 20220506130817.795 TRACE    start - start.c:lxc_init:787 - Set container state to "STARTING"
lxc build-env 20220506130817.795 TRACE    start - start.c:lxc_init:843 - Set environment variables
lxc build-env 20220506130817.795 TRACE    start - start.c:lxc_init:848 - Ran pre-start hooks
lxc build-env 20220506130817.795 TRACE    start - start.c:setup_signal_fd:373 - Created signal file descriptor 6
lxc build-env 20220506130817.795 TRACE    start - start.c:lxc_init:861 - Set up signal fd
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.795 INFO     cgfsng - cgroups/cgfsng.c:legacy_hierarchy_delegated:3092 - Permission denied - Legacy hierarchy not writable, skipping
lxc build-env 20220506130817.796 TRACE    cgroup - cgroups/cgroup.c:cgroup_init:40 - Initialized cgroup driver cgfsng
lxc build-env 20220506130817.796 TRACE    cgroup - cgroups/cgroup.c:cgroup_init:47 - Unified cgroup layout
lxc build-env 20220506130817.796 TRACE    start - start.c:lxc_init:868 - Initialized cgroup driver
lxc build-env 20220506130817.796 TRACE    start - start.c:lxc_init:875 - Read seccomp policy
lxc build-env 20220506130817.796 TRACE    start - start.c:lxc_init:882 - Initialized LSM
lxc build-env 20220506130817.796 INFO     start - start.c:lxc_init:884 - Container "build-env" is initialized
lxc build-env 20220506130817.796 DEBUG    storage - storage/storage.c:get_storage_by_name:209 - Detected rootfs type "overlay"
lxc build-env 20220506130817.796 TRACE    conf - conf.c:lxc_rootfs_init:560 - Invalid argument - Not pinning on stacking filesystem
lxc build-env 20220506130817.796 TRACE    sync - sync.c:lxc_sync_init:139 - Initialized synchronization infrastructure
lxc build-env 20220506130817.796 TRACE    start - start.c:lxc_spawn:1745 - Cloned child process 30039
lxc build-env 20220506130817.796 TRACE    start - start.c:core_scheduling:1563 - No new core scheduling domain requested
lxc build-env 20220506130817.796 TRACE    utils - utils.c:lxc_can_use_pidfd:1819 - Kernel supports pidfds
lxc build-env 20220506130817.796 INFO     start - start.c:lxc_spawn:1765 - Cloned CLONE_NEWNS
lxc build-env 20220506130817.796 INFO     start - start.c:lxc_spawn:1765 - Cloned CLONE_NEWPID
lxc build-env 20220506130817.796 INFO     start - start.c:lxc_spawn:1765 - Cloned CLONE_NEWUTS
lxc build-env 20220506130817.796 INFO     start - start.c:lxc_spawn:1765 - Cloned CLONE_NEWIPC
lxc build-env 20220506130817.796 INFO     start - start.c:lxc_spawn:1765 - Cloned CLONE_NEWCGROUP
lxc build-env 20220506130817.797 DEBUG    start - start.c:lxc_try_preserve_namespace:139 - Preserved mnt namespace via fd 13 and stashed path as mnt:/proc/30038/fd/13
lxc build-env 20220506130817.797 DEBUG    start - start.c:lxc_try_preserve_namespace:139 - Preserved pid namespace via fd 14 and stashed path as pid:/proc/30038/fd/14
lxc build-env 20220506130817.797 DEBUG    start - start.c:lxc_try_preserve_namespace:139 - Preserved uts namespace via fd 15 and stashed path as uts:/proc/30038/fd/15
lxc build-env 20220506130817.797 DEBUG    start - start.c:lxc_try_preserve_namespace:139 - Preserved ipc namespace via fd 16 and stashed path as ipc:/proc/30038/fd/16
lxc build-env 20220506130817.797 DEBUG    start - start.c:lxc_try_preserve_namespace:139 - Preserved cgroup namespace via fd 17 and stashed path as cgroup:/proc/30038/fd/17
lxc build-env 20220506130817.797 TRACE    sync - sync.c:lxc_sync_barrier_child:97 - Parent waking child with sequence startup and waiting with sequence configure
lxc build-env 20220506130817.797 TRACE    sync - sync.c:lxc_sync_wait_parent:110 - Child waiting for parent with sequence startup
lxc build-env 20220506130817.797 TRACE    sync - sync.c:lxc_sync_wake_parent:104 - Child waking parent with sequence configure
lxc build-env 20220506130817.797 TRACE    conf - conf.c:lxc_set_environment:5753 - Set environment variable: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
lxc build-env 20220506130817.797 DEBUG    start - start.c:lxc_try_preserve_namespace:139 - Preserved net namespace via fd 4 and stashed path as net:/proc/30038/fd/4
lxc build-env 20220506130817.797 TRACE    conf - conf.c:lxc_set_environment:5753 - Set environment variable: TERM=xterm
lxc build-env 20220506130817.797 TRACE    conf - conf.c:lxc_set_environment:5753 - Set environment variable: STACKER_LAYER_NAME=build-env
lxc build-env 20220506130817.797 TRACE    sync - sync.c:lxc_sync_wait_parent:110 - Child waiting for parent with sequence post-configure
lxc build-env 20220506130817.797 WARN     start - start.c:lxc_spawn:1835 - Operation not permitted - Failed to allocate new network namespace id
lxc build-env 20220506130817.797 TRACE    sync - sync.c:lxc_sync_wake_child:122 - Parent waking child with sequence post-configure
lxc build-env 20220506130817.797 TRACE    sync - sync.c:lxc_sync_wait_child:116 - Parent waiting for child with sequence idmapped-mounts
lxc build-env 20220506130817.798 TRACE    conf - conf.c:turn_into_dependent_mounts:3923 - Turned all mount table entries into dependent mount
lxc build-env 20220506130817.811 INFO     overlay - storage/overlay.c:ovl_mount:481 - Permission denied - Failed to mount "/home/scmoser/test/roots/sha256_6754ae8b4482caf0381ba778a105a956a9dd703193ecf25de47a3c8c258528cd/overlay:/home/scmoser/test/roots/sha256_0dab16140ba45e4d16857a1c36b0ba23da0e4df9eab34617591baf0f714e0744/overlay" on "/home/scmoser/test/.stacker/rootfsPivot" with options "upperdir=/home/scmoser/test/roots/build-env/overlay,lowerdir=/home/scmoser/test/roots/sha256_6754ae8b4482caf0381ba778a105a956a9dd703193ecf25de47a3c8c258528cd/overlay:/home/scmoser/test/roots/sha256_0dab16140ba45e4d16857a1c36b0ba23da0e4df9eab34617591baf0f714e0744/overlay,workdir=/home/scmoser/test/roots/build-env/work". Retrying without workdir
lxc build-env 20220506130817.813 ERROR    overlay - storage/overlay.c:ovl_mount:490 - Invalid argument - Failed to mount "/home/scmoser/test/roots/sha256_6754ae8b4482caf0381ba778a105a956a9dd703193ecf25de47a3c8c258528cd/overlay:/home/scmoser/test/roots/sha256_0dab16140ba45e4d16857a1c36b0ba23da0e4df9eab34617591baf0f714e0744/overlay" on "/home/scmoser/test/.stacker/rootfsPivot" with options "upperdir=/home/scmoser/test/roots/build-env/overlay,lowerdir=/home/scmoser/test/roots/sha256_6754ae8b4482caf0381ba778a105a956a9dd703193ecf25de47a3c8c258528cd/overlay:/home/scmoser/test/roots/sha256_0dab16140ba45e4d16857a1c36b0ba23da0e4df9eab34617591baf0f714e0744/overlay"
lxc build-env 20220506130817.813 ERROR    conf - conf.c:lxc_mount_rootfs:1432 - Failed to mount rootfs "overlayfs:/home/scmoser/test/roots/sha256_6754ae8b4482caf0381ba778a105a956a9dd703193ecf25de47a3c8c258528cd/overlay:/home/scmoser/test/roots/sha256_0dab16140ba45e4d16857a1c36b0ba23da0e4df9eab34617591baf0f714e0744/overlay:/home/scmoser/test/roots/build-env/overlay" onto "/home/scmoser/test/.stacker/rootfsPivot" with options "(null)"
lxc build-env 20220506130817.814 ERROR    conf - conf.c:lxc_setup_rootfs_prepare_root:3964 - Failed to setup rootfs for
lxc build-env 20220506130817.814 ERROR    conf - conf.c:lxc_setup:4331 - Failed to setup rootfs
lxc build-env 20220506130817.814 ERROR    start - start.c:do_start:1275 - Failed to setup container "build-env"
lxc build-env 20220506130817.814 TRACE    sync - sync.c:lxc_sync_wake_parent:104 - Child waking parent with sequence error
lxc build-env 20220506130817.814 ERROR    sync - sync.c:sync_wait:34 - An error occurred in another process (expected sequence number 3)
lxc build-env 20220506130817.814 TRACE    start - start.c:lxc_serve_state_clients:486 - Set container state to ABORTING
lxc build-env 20220506130817.814 TRACE    start - start.c:lxc_serve_state_clients:489 - No state clients registered
lxc build-env 20220506130817.814 INFO     utils - utils.c:get_rundir:260 - XDG_RUNTIME_DIR isn't set in the environment
lxc build-env 20220506130817.816 ERROR    start - start.c:__lxc_start:2074 - Failed to spawn container "build-env"
lxc build-env 20220506130817.816 TRACE    start - start.c:lxc_serve_state_clients:486 - Set container state to ABORTING
lxc build-env 20220506130817.816 TRACE    start - start.c:lxc_serve_state_clients:489 - No state clients registered
lxc build-env 20220506130817.816 INFO     utils - utils.c:get_rundir:260 - XDG_RUNTIME_DIR isn't set in the environment
lxc build-env 20220506130817.816 WARN     start - start.c:lxc_abort:1039 - No such process - Failed to send SIGKILL via pidfd 12 for process 30039
lxc build-env 20220506130817.816 TRACE    start - start.c:lxc_serve_state_clients:486 - Set container state to STOPPING
lxc build-env 20220506130817.816 TRACE    start - start.c:lxc_serve_state_clients:489 - No state clients registered
lxc build-env 20220506130817.816 INFO     utils - utils.c:get_rundir:260 - XDG_RUNTIME_DIR isn't set in the environment
lxc build-env 20220506130817.816 TRACE    start - start.c:lxc_end:966 - Closed command socket
lxc build-env 20220506130817.816 INFO     utils - utils.c:get_rundir:260 - XDG_RUNTIME_DIR isn't set in the environment
lxc build-env 20220506130817.816 TRACE    start - start.c:lxc_end:977 - Set container state to "STOPPED"

$ cat stacker.yaml
build-env:
  build_only: true
  from:
    type: docker
    url: docker://docker-repo/c3/minbase:1.0.7
  run: |
    echo HELLO WORLD

[smoser]

and other ideas for debugability:
a.) stacker mention "check /path/to/lxc.log for more information" (possibly even copying ERROR lines from it to stderr?)
b.) determine if you're on nfs and just fail as "not gonna work dood!"

[rchincha]

statfs() so b)?