1419501 – "machinectl" fails when virtual machine/container is running

Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 1419501 - "machinectl" fails when virtual machine/container is running

Summary: "machinectl" fails when virtual machine/container is running

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	systemd
Sub Component:
Version:	26
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	systemd-maint
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2017-02-06 11:15 UTC by Vít Ondruch
Modified:	2017-04-01 17:09 UTC (History)
CC List:	17 users (show)
Fixed In Version:	systemd-232-14.fc26 systemd-233-3.fc26
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2017-04-01 17:09:21 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
$ strace -f -s 128 -o strace.log machinectl list (59.98 KB, text/plain) 2017-03-13 14:16 UTC, Vít Ondruch	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Github	systemd systemd issues 5581	0	None	closed	Make sense of machinectl return code (provide more debug info)	2020-08-19 12:46:27 UTC

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 3 Lukáš Nykrýn 2017-02-14 08:50:27 UTC

https://github.com/systemd/systemd/commit/4b2419165ce409ee55ce96a926302f89685f2293

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.

Note You need to log in before you can comment on or make changes to this bug.