machinectl clone: access denied

[jernst]

# machinectl import-tar ... foo
# machinectl list-images
NAME     TYPE      RO  USAGE  CREATED                     MODIFIED
foo subvolume no  896.9M Wed 2015-07-01 21:40:54 UTC n/a
# machinectl clone foo bar
Could not clone image: Access denied

It's unclear what is going wrong here. The image otherwise can be renamed or deleted. Nothing particular in the journal.

[poettering]

Hmm, weird. Any chance you can run "strace -s 500 -o /tmp/strace.log -p $PID" right before issuing the clone command, replacing $PID by the PID of machined. Then, afterwards terminate strace with C-c, and attach the output it generated in /tmp/strace.log here. That should give us a hint, what precisely fails due to access control issues.

Is this maybe a system with selinux enabled? If so, if you turn off selinux, do things start to work then?

[jernst]

This is plain vanilla Arch installation; no selinux.

> ps aux | grep machine
root      5706  0.0  0.0   8876  1880 ?        Ss   01:37   0:00 /usr/lib/systemd/systemd-machined
> sudo strace -s 500 -o /tmp/strace.log -p 5706 &
> sudo machinectl clone depot test
> sudo ls -al /var/lib/machines/
total 0
drwx------ 1 root        root         10 Jul  6 22:00 .
drwxr-xr-x 1 root        root        258 Jul  7 00:00 ..
drwxr-xr-x 1 buildmaster buildmaster 142 Jul  1 21:20 depot

produces:

epoll_wait(4, {{EPOLLIN, {u32=1698789472, u64=140271035709536}}}, 3, 30000) = 1
clock_gettime(CLOCK_BOOTTIME, {115758, 686778961}) = 0
socket(PF_LOCAL, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 8
sendmsg(8, {msg_name(21)={sa_family=AF_LOCAL, sun_path="/run/systemd/notify"}, msg_iov(1)=[{"WATCHDOG=1", 10}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 10
close(8)                                = 0
timerfd_settime(5, TFD_TIMER_ABSTIME, {it_interval={0, 0}, it_value={115801, 915748000}}, NULL) = 0
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"l\1\4\1\34\0\0\0\2\0\0\0\266\0\0\0\1\1o\0\31\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"/org/freedesktop/machine1\0\0\0\0\0\0\0\3\1s\0\n\0\0\0CloneImage\0\0\0\0\0\0\2\1s\0 \0\0\0org.freedesktop.machine1.Manager\0\0\0\0\0\0\0\0\6\1s\0\30\0\0\0org.freedesktop.machine1\0\0\0\0\0\0\0\0\10\1g\0\3ssb\0\0\0\0\0\0\0\0\7\1s\0\5\0\0\0:1.74\0\0\0\5\0\0\0depot\0\0\0\4\0\0\0test\0\0\0\0\0\0\0\0", 204}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 204
openat(AT_FDCWD, "/var/lib/machines", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 8
newfstatat(8, "depot", {st_mode=S_IFDIR|0755, st_size=142, ...}, 0) = 0
faccessat(8, "depot", W_OK)             = 0
openat(8, "depot", O_RDONLY|O_NOCTTY|O_DIRECTORY|O_CLOEXEC) = 9
fstatfs(9, {f_type="BTRFS_SUPER_MAGIC", f_bsize=4096, f_blocks=10485504, f_bfree=4416863, f_bavail=4297087, f_files=0, f_ffree=0, f_fsid={981067682, -1905873711}, f_namelen=255, f_frsize=4096}) = 0
fstatfs(9, {f_type="BTRFS_SUPER_MAGIC", f_bsize=4096, f_blocks=10485504, f_bfree=4416863, f_bavail=4297087, f_files=0, f_ffree=0, f_fsid={981067682, -1905873711}, f_namelen=255, f_frsize=4096}) = 0
ioctl(9, BTRFS_IOC_INO_LOOKUP, 0x7ffe54907640) = 0
ioctl(9, BTRFS_IOC_TREE_SEARCH, 0x7ffe54908680) = 0
fstatfs(9, {f_type="BTRFS_SUPER_MAGIC", f_bsize=4096, f_blocks=10485504, f_bfree=4416863, f_bavail=4297087, f_files=0, f_ffree=0, f_fsid={981067682, -1905873711}, f_namelen=255, f_frsize=4096}) = 0
ioctl(9, BTRFS_IOC_INO_LOOKUP, 0x7ffe54907620) = 0
ioctl(9, BTRFS_IOC_TREE_SEARCH, 0x7ffe54908670) = 0
ioctl(9, BTRFS_IOC_TREE_SEARCH, 0x7ffe54908670) = 0
close(9)                                = 0
close(8)                                = 0
sendmsg(6, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\n\0\0\0\10\0\0\0\207\0\0\0\1\1o\0\25\0\0\0/org/freedesktop/DBus\0\0\0\3\1s\0\25\0\0\0GetConnectionUnixUser\0\0\0\2\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\6\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\10\1g\0\1s\0\0", 152}, {"\5\0\0\0:1.74\0", 10}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 162
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{"l\2\1\1\4\0\0\0\t\0\0\0=\0\0\0\6\1s\0\5\0\0\0", 24}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 24
recvmsg(6, {msg_name(0)=NULL, msg_iov(1)=[{":1.72\0\0\0\5\1u\0\10\0\0\0\10\1g\0\1u\0\0\7\1s\0\24\0\0\0org.freedesktop.DBus\0\0\0\0\0\0\0\0", 60}], msg_controllen=0, msg_flags=MSG_CMSG_CLOEXEC}, MSG_DONTWAIT|MSG_NOSIGNAL|MSG_CMSG_CLOEXEC) = 60
getuid()                                = 0
stat("/run/systemd/nspawn", {st_mode=S_IFDIR|0755, st_size=80, ...}) = 0
mkdir("/run/systemd/nspawn/locks", 0700) = -1 EEXIST (File exists)
stat("/run/systemd/nspawn/locks", {st_mode=S_IFDIR|0700, st_size=40, ...}) = 0
open("/run/systemd/nspawn/locks/name-test", O_RDWR|O_CREAT|O_NOCTTY|O_NOFOLLOW|O_CLOEXEC, 0600) = 8
fcntl(8, 0x25 /* F_??? */, 0x7ffe54909550) = 0
fstat(8, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
openat(AT_FDCWD, "/var/lib/machines", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 9
newfstatat(9, "test", 0x7ffe549095b0, 0) = -1 ENOENT (No such file or directory)
newfstatat(9, "test.raw", 0x7ffe549095b0, 0) = -1 ENOENT (No such file or directory)
close(9)                                = 0
openat(AT_FDCWD, "/var/lib/container", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/lib/machines", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/lib/machines", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/var/lib/machines/depot", O_RDONLY|O_NOCTTY|O_DIRECTORY|O_CLOEXEC) = 9
fstat(9, {st_mode=S_IFDIR|0755, st_size=142, ...}) = 0
fstatfs(9, {f_type="BTRFS_SUPER_MAGIC", f_bsize=4096, f_blocks=10485504, f_bfree=4416863, f_bavail=4297087, f_files=0, f_ffree=0, f_fsid={981067682, -1905873711}, f_namelen=255, f_frsize=4096}) = 0
open("/var/lib/machines", O_RDONLY|O_NOCTTY|O_DIRECTORY|O_CLOEXEC) = 10
ioctl(10, BTRFS_IOC_SNAP_CREATE_V2, 0x7ffe54906650) = -1 EPERM (Operation not permitted)
close(10)                               = 0
close(9)                                = 0
unlink("/run/systemd/nspawn/locks/name-test") = 0
close(8)                                = 0
sendmsg(6, {msg_name(0)=NULL, msg_iov(2)=[{"l\3\1\1\34\0\0\0\t\0\0\0O\0\0\0\5\1u\0\2\0\0\0\6\1s\0\5\0\0\0:1.74\0\0\0\4\1s\0'\0\0\0org.freedesktop.DBus.Error.AccessDenied\0\10\1g\0\1s\0\0", 96}, {"\27\0\0\0Operation not permitted\0", 28}], msg_controllen=0, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 124
epoll_wait(4,  <detached ...>

[poettering]

Hmm. The snapshot creation ioctl fails on /var/lib/machines...

Does it work if you use the btrfs command line on the terminal?

Do you have selinux on? Consider turning it off.

[poettering]

Oops. Closed this by accident... Sorry!

Which systemd version is this?

[dvdhrm]

@jernst Any followup on this?

[jernst]

I don't know what is different now, but it seems to work now. It may be that I upgraded from 221 (?) to 224. So I'll close it.

[rickysarraf]

I have run into the same problem now on systemd 229. Details below

rrs@learner:~/.rrs-home/Community $ machinectl clone jessie jessied
Could not clone image: Access denied
2016-03-17 / 18:30:45 ♒♒♒  ☹  => 1  
rrs@learner:~/.rrs-home/Community $ machinectl list-images 
NAME               TYPE      RO  USAGE  CREATED                     MODIFIED
debTemplate        subvolume no  849.6M Mon 2015-09-21 20:34:50 IST n/a     
fedora22           subvolume no  1.2G   Tue 2016-03-15 22:36:20 IST n/a     
fedoraTemplate     subvolume no  1.3G   Mon 2015-09-21 20:36:40 IST n/a     
jessie             directory no  n/a    n/a                         n/a     
sanboot            subvolume no  1.2G   Fri 2016-03-04 16:19:18 IST n/a     
trustyTemplate     subvolume no  414.6M Mon 2015-09-21 20:37:15 IST n/a     
tumbleweedTemplate subvolume no  1.2G   Mon 2015-09-21 20:37:37 IST n/a     

7 images listed.
2016-03-17 / 18:32:30 ♒♒♒  ☺  

And here's the details of packages installed.

rrs@learner:~$ dpkg -l | grep -i systemd
ii  dbus-user-session                         1.10.6-1                            all          simple interprocess messaging system (systemd --user integration)
ii  dh-systemd                                1.29                                all          debhelper add-on to handle systemd unit files
ii  gnome-logs                                3.18.1-1                            amd64        viewer for the systemd journal.
ii  libpam-systemd:amd64                      229-2                               amd64        system and service manager - PAM module
ii  libsystemd0:amd64                         229-2                               amd64        systemd utility library
ii  libsystemd0:i386                          229-2                               i386         systemd utility library
ii  systemd                                   229-2                               amd64        system and service manager
ii  systemd-container                         229-2                               amd64        systemd container/nspawn tools
ii  systemd-sysv                              229-2                               amd64        system and service manager - SysV links
ii  systemd-ui                                3-4                                 amd64        graphical frontend for systemd
2016-03-17 / 18:33:18 ♒♒♒  ☺  

Can we re-open this bug or should I file a new one ?

[rickysarraf]

From the man page, it says that a directory based container images will be cloned into subvolume images. So as I understand, the command request is correct.

strace.log.zip