Bug 1419501

Summary: "machinectl" fails when virtual machine/container is running
Product: [Fedora] Fedora Reporter: Vít Ondruch <vondruch>
Component: systemdAssignee: systemd-maint
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 26CC: Frodox, jdisnard, johannbg, jsynacek, lnykryn, mebrown, msekleta, msimacek, msuchy, muadda, praiskup, riehecky, ssahani, s, systemd-maint, williams, zbyszek
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: systemd-232-14.fc26 systemd-233-3.fc26 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-04-01 17:09:21 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
$ strace -f -s 128 -o strace.log machinectl list none

Description Vít Ondruch 2017-02-06 11:15:46 UTC
Description of problem:
I am using Vagrant with vagrant-libvirt backend. I did "vagrant up" but since the vagrant initialization takes some time, I switched to other task involving mock. But it doesn't work:

~~~
$ mock -r fedora-rawhide-x86_64 --scrub all
INFO: mock.py version 1.3.3 starting (python version = 3.6.0)...
Start: init plugins
INFO: selinux disabled
Finish: init plugins
Start: run
Start: scrub ['all']
INFO: removing +mock.fedora-rawhide-x86_64.head volume
Finish: scrub ['all']
ERROR: Command '['/usr/bin/machinectl', 'list', '--no-pager']' returned non-zero exit status 1.
Traceback (most recent call last):
  File "/usr/libexec/mock/mock", line 701, in main
    run_command(options, args, config_opts, commands, buildroot, state)
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/libexec/mock/mock", line 732, in run_command
    commands.scrub(options.scrub)
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/backend.py", line 87, in scrub
    self.plugins.call_hooks('scrub', scrub)
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/plugin.py", line 69, in call_hooks
    hook(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/mockbuild/plugins/lvm_root.py", line 345, in hook_scrub
    lvm_do(['lvremove', '-f', self.vg_name + '/' + name])
  File "/usr/lib/python3.6/site-packages/mockbuild/plugins/lvm_root.py", line 20, in lvm_do
    output = util.do(*args, returnOutput=True, env=env, **kwargs)
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/util.py", line 576, in do
    raise exception.Error("Command failed: \n # %s\n%s" % (command, output), child.returncode)
mockbuild.exception.Error: Command failed: 
 # lvremove -f vg_fedora/+mock.fedora-rawhide-x86_64.head
  Logical volume vg_fedora/+mock.fedora-rawhide-x86_64.head contains a filesystem in use.


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/libexec/mock/mock", line 885, in <module>
    main()
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/libexec/mock/mock", line 704, in main
    buildroot.finalize()
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/buildroot.py", line 544, in finalize
    util.orphansKill(self.make_chroot_path())
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/util.py", line 198, in orphansKill
    vm_list = subprocess.check_output(["/usr/bin/machinectl", "list", "--no-pager"])
  File "/usr/lib64/python3.6/subprocess.py", line 336, in check_output
    **kwargs).stdout
  File "/usr/lib64/python3.6/subprocess.py", line 418, in run
    output=stdout, stderr=stderr)
subprocess.CalledProcessError: Command '['/usr/bin/machinectl', 'list', '--no-pager']' returned non-zero exit status 1.
~~~

and indeed, trying just "machinectl", it fails without any explanation unfortunately :/

~~~
$ sudo machinectl list --no-pager
$ echo $?
1
~~~

Version-Release number of selected component (if applicable):
$ rpm -q mock
mock-1.3.3-1.fc26.noarch

$ rpm -qf `which machinectl`
systemd-container-232-12.fc26.x86_64

$ rpm -q vagrant
vagrant-1.8.7-1.fc26.noarch

$ rpm -q vagrant-libvirt
vagrant-libvirt-0.0.36-2.fc26.noarch

$ rpm -q libvirt-libs 
libvirt-libs-3.0.0-1.fc26.x86_64


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:
`mock --scrub all` does not work.


Expected results:
`mock --scrub all` works.


Additional info:

Comment 1 Vít Ondruch 2017-02-10 15:46:06 UTC
So here is the log I got with "debug" on kernel cmdline running plain "machinectl":


~~~
$ LANG=C.utf-8 journalctl -u systemd-machined -b -f -x

... snip ...

Feb 10 16:40:28 localhost.localdomain systemd-machined[3304]: Got message type=method_call sender=:1.106 destination=org.freedesktop.machine1 object=/org/freedesktop/machine1 interface=org.freedesktop.machine1.Manager member=ListMachines cookie=2 reply_cookie=0 error=n/a
Feb 10 16:40:28 localhost.localdomain systemd-machined[3304]: Sent message type=method_return sender=n/a destination=:1.106 object=n/a interface=n/a member=n/a cookie=20 reply_cookie=2 error=n/a
Feb 10 16:40:28 localhost.localdomain systemd-machined[3304]: Got message type=method_call sender=:1.106 destination=org.freedesktop.machine1 object=/org/freedesktop/machine1 interface=org.freedesktop.machine1.Manager member=GetMachineOSRelease cookie=3 reply_cookie=0 error=n/a
Feb 10 16:40:28 localhost.localdomain systemd-machined[3304]: Sent message type=error sender=n/a destination=:1.106 object=n/a interface=n/a member=n/a cookie=21 reply_cookie=3 error=Requesting OS release data is only supported on container machines.
Feb 10 16:40:28 localhost.localdomain systemd-machined[3304]: Failed to process message [type=method_call sender=:1.106 path=/org/freedesktop/machine1 interface=org.freedesktop.machine1.Manager member=GetMachineOSRelease signature=s]: Requesting OS release data is only supported on container machines.
Feb 10 16:40:28 localhost.localdomain systemd[1]: systemd-machined.service: Got notification message from PID 3304 (WATCHDOG=1)
~~~

I don't understand why machinectl does not report this error and why is this error at all.

Comment 2 Miroslav Suchý 2017-02-13 07:35:06 UTC
I cannot reproduce it. On my machine:
$ machinectl
MACHINE             CLASS SERVICE     
qemu-1-coprfrontend vm    libvirt-qemu
qemu-2-coprdistgit  vm    libvirt-qemu
qemu-3-coprbackend  vm    libvirt-qemu

3 machines listed.

(This is on F25 thou).
Anyway this seems to be problem of machinectl and not mock.

Comment 4 Vít Ondruch 2017-02-16 09:56:36 UTC
systemd-232-14.fc26 seems to fex the issues for me. Thx.

Comment 5 Vit Ry 2017-02-16 11:23:17 UTC
I faced exactly same issue. On F26 (rawhide), systemd-232-12.fc26.x86_64

[builder@f26-kvm ~]$ mock -r epel-7-x86_64 --init --resultdir test-fm2
INFO: mock.py version 1.3.3 starting (python version = 3.6.0)...
Start: init plugins
INFO: selinux disabled
Finish: init plugins
Start: run
Start: clean chroot
ERROR: Command '['/usr/bin/machinectl', 'list', '--no-pager']' returned non-zero exit status 1.
Traceback (most recent call last):
  File "/usr/libexec/mock/mock", line 701, in main
    run_command(options, args, config_opts, commands, buildroot, state)
[builder@niger-f26-kvm ~]$ mock -r epel-7-x86_64 --init --resultdir test-fm2
INFO: mock.py version 1.3.3 starting (python version = 3.6.0)...
Start: init plugins
INFO: selinux disabled
Finish: init plugins
Start: run
Start: clean chroot
ERROR: Command '['/usr/bin/machinectl', 'list', '--no-pager']' returned non-zero exit status 1.
Traceback (most recent call last):
  File "/usr/libexec/mock/mock", line 701, in main
    run_command(options, args, config_opts, commands, buildroot, state)
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/libexec/mock/mock", line 725, in run_command
    commands.clean()
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/backend.py", line 74, in clean
    self.buildroot.delete()
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/buildroot.py", line 560, in delete
    util.orphansKill(p)
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/util.py", line 198, in orphansKill
    vm_list = subprocess.check_output(["/usr/bin/machinectl", "list", "--no-pager"])
  File "/usr/lib64/python3.6/subprocess.py", line 336, in check_output
    **kwargs).stdout
  File "/usr/lib64/python3.6/subprocess.py", line 418, in run
    output=stdout, stderr=stderr)
subprocess.CalledProcessError: Command '['/usr/bin/machinectl', 'list', '--no-pager']' returned non-zero exit status 1.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/libexec/mock/mock", line 885, in <module>
    main()
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/libexec/mock/mock", line 704, in main
    buildroot.finalize()
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/buildroot.py", line 544, in finalize
    util.orphansKill(self.make_chroot_path())
  File "/usr/lib/python3.6/site-packages/mockbuild/trace_decorator.py", line 89, in trace
    result = func(*args, **kw)
  File "/usr/lib/python3.6/site-packages/mockbuild/util.py", line 198, in orphansKill
    vm_list = subprocess.check_output(["/usr/bin/machinectl", "list", "--no-pager"])
  File "/usr/lib64/python3.6/subprocess.py", line 336, in check_output
    **kwargs).stdout
  File "/usr/lib64/python3.6/subprocess.py", line 418, in run
    output=stdout, stderr=stderr)
subprocess.CalledProcessError: Command '['/usr/bin/machinectl', 'list', '--no-pager']' returned non-zero exit status 1.

---

$ /usr/bin/machinectl list --no-pager
$ echo $?
1

and stopping qemu-kvm machine - solves the issue.

$ /usr/bin/machinectl list --no-pager
No machines.
$ echo $?
0

---

I haven't systemd-232-14.fc26 in my rawhide repo =\

Comment 6 Vit Ry 2017-02-16 11:27:17 UTC
And 
/dev/sda3 on /var/lib/mock/epel-7-x86_64/root/var/cache/yum type xfs (rw,relatime,seclabel,attr2,inode64,noquota)

still mounted after this fail =\

Comment 7 Vít Ondruch 2017-02-16 12:02:38 UTC
Actually, I was too quick to judge :/ This appears to work (and did not worked previously):

~~~
$ /usr/bin/machinectl 'list' '--no-pager'
MACHINE        CLASS SERVICE      OS VERSION ADDRESSES
qemu-6-rawhide vm    libvirt-qemu -  -       -

1 machines listed.
~~~

as long as nobody checks the return code:

~~~
$ echo $?
1
~~~

Please note that the error message in journal is different this time:

~~~
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd-machined[3789]: Got message type=method_call sender=:1.133 destination=org.freedesktop.machine1 object=/org/freedesktop/machine1 interface=org.freedesktop.machine1.Manager member=ListMachines cookie=2 reply_cookie=0 error=n/a
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd-machined[3789]: Sent message type=method_return sender=n/a destination=:1.133 object=n/a interface=n/a member=n/a cookie=29 reply_cookie=2 error=n/a
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd[1]: systemd-machined.service: Got notification message from PID 3789 (WATCHDOG=1)
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd-machined[3789]: Got message type=method_call sender=:1.133 destination=org.freedesktop.machine1 object=/org/freedesktop/machine1 interface=org.freedesktop.machine1.Manager member=GetMachineOSRelease cookie=3 reply_cookie=0 error=n/a
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd-machined[3789]: Sent message type=error sender=n/a destination=:1.133 object=n/a interface=n/a member=n/a cookie=30 reply_cookie=3 error=Requesting OS release data is only supported on container machines.
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd-machined[3789]: Failed to process message [type=method_call sender=:1.133 path=/org/freedesktop/machine1 interface=org.freedesktop.machine1.Manager member=GetMachineOSRelease signature=s]: Requesting OS release data is only supported on container machines.
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd-machined[3789]: Got message type=method_call sender=:1.133 destination=org.freedesktop.machine1 object=/org/freedesktop/machine1 interface=org.freedesktop.machine1.Manager member=GetMachineAddresses cookie=4 reply_cookie=0 error=n/a
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd-machined[3789]: Sent message type=error sender=n/a destination=:1.133 object=n/a interface=n/a member=n/a cookie=31 reply_cookie=4 error=Requesting IP address data is only supported on container machines.
Feb 16 13:01:53 unused-4-134.brq.redhat.com systemd-machined[3789]: Failed to process message [type=method_call sender=:1.133 path=/org/freedesktop/machine1 interface=org.freedesktop.machine1.Manager member=GetMachineAddresses signature=s]: Requesting IP address data is only supported on container machines.
~~~

Comment 8 Vít Ondruch 2017-02-16 12:04:23 UTC
(In reply to Vit Ry from comment #5)
> I haven't systemd-232-14.fc26 in my rawhide repo =\

It is not yet in Rawhide compose ... You need to take it from Koji.

Comment 9 Vít Ondruch 2017-02-22 09:42:52 UTC
BTW not it fails even when other container (mock) is running :/

Comment 10 Fedora End Of Life 2017-02-28 11:11:20 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 26 development cycle.
Changing version to '26'.

Comment 11 Vít Ondruch 2017-03-13 14:03:41 UTC
This is still issue with recent systemd:

$ rpm -q systemd
systemd-233-2.fc27.x86_64

Therefore I reported it upstream.

Comment 12 Vít Ondruch 2017-03-13 14:16:21 UTC
Created attachment 1262463 [details]
$ strace -f -s 128 -o strace.log machinectl list

Comment 13 Vít Ondruch 2017-03-16 07:40:48 UTC
This was resovled upstream. Would it be possible to backport this, please?

https://github.com/systemd/systemd/pull/5587

Comment 14 Michal Sekletar 2017-03-16 09:11:35 UTC
(In reply to Vít Ondruch from comment #13)
> This was resovled upstream. Would it be possible to backport this, please?
> 
> https://github.com/systemd/systemd/pull/5587

I've backported the fix to F26 alongside with other bugfixes from upstream.

Comment 15 Fedora Update System 2017-03-16 12:23:03 UTC
systemd-233-3.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2017-27d711e213

Comment 16 Fedora Update System 2017-03-17 02:19:09 UTC
systemd-233-3.fc26 has been pushed to the Fedora 26 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-27d711e213

Comment 17 Fedora Update System 2017-04-01 17:09:21 UTC
systemd-233-3.fc26 has been pushed to the Fedora 26 stable repository. If problems still persist, please make note of it in this bug report.