Bug 1461989 - Cannot create virtual machines in KVM, systemd-machined.service entered failed state
Cannot create virtual machines in KVM, systemd-machined.service entered faile...
Status: NEW
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: systemd (Show other bugs)
7.3
x86_64 Linux
high Severity urgent
: rc
: ---
Assigned To: systemd-maint
qe-baseos-daemons
:
Depends On:
Blocks: 1420851
  Show dependency treegraph
 
Reported: 2017-06-15 16:36 EDT by Robert McSwain
Modified: 2017-11-01 08:21 EDT (History)
13 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Robert McSwain 2017-06-15 16:36:49 EDT
Description of problem:
ERROR    Activation of org.freedesktop.machine1 timed out
While doing some troubleshooting, I came across some information that indicated that the systemd-machine service needed to be restarted.  When I attempt to restart that service I get:
journalctl -xe
-- 
-- Unit NetworkManager-dispatcher.service has finished starting up.
-- 
-- The start-up result is done.
Jun 13 12:46:52 rh7dev01.domain.com nm-dispatcher[30563]: req:1 'down' [vnet0]: new request (4 scripts)
Jun 13 12:46:52 rh7dev01.domain.com nm-dispatcher[30563]: req:1 'down' [vnet0]: start running ordered scripts...
Jun 13 12:47:15 rh7dev01.domain.com sshd[30606]: Connection closed by 10.28.59.175 [preauth]
Jun 13 12:50:01 rh7dev01.domain.com systemd[1]: Started Session 9741 of user root.
-- Subject: Unit session-9741.scope has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit session-9741.scope has finished starting up.
-- 
-- The start-up result is done.
Jun 13 12:50:01 rh7dev01.domain.com CROND[30777]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Jun 13 12:50:01 rh7dev01.domain.com systemd[1]: Starting Session 9741 of user root.
-- Subject: Unit session-9741.scope has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit session-9741.scope has begun starting up.
Jun 13 12:50:15 rh7dev01.domain.com sshd[30802]: Connection closed by 10.28.59.175 [preauth]
Jun 13 12:52:40 rh7dev01.domain.com polkitd[30459]: Registered Authentication Agent for unix-process:31109:312248526 (system bus name :1.27516 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en
Jun 13 12:52:40 rh7dev01.domain.com systemd[1]: Starting Virtual Machine and Container Registration Service...
-- Subject: Unit systemd-machined.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit systemd-machined.service has begun starting up.
Jun 13 12:52:40 rh7dev01.domain.com systemd[31126]: Failed at step NAMESPACE spawning /usr/lib/systemd/systemd-machined: Invalid argument
-- Subject: Process /usr/lib/systemd/systemd-machined could not be executed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- The process /usr/lib/systemd/systemd-machined could not be executed and failed.
-- 
-- The error number returned by this process is 22.
Jun 13 12:52:40 rh7dev01.domain.com systemd[1]: systemd-machined.service: main process exited, code=exited, status=226/NAMESPACE
Jun 13 12:52:40 rh7dev01.domain.com systemd[1]: Failed to start Virtual Machine and Container Registration Service.
-- Subject: Unit systemd-machined.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit systemd-machined.service has failed.
-- 
-- The result is failed.
Jun 13 12:52:40 rh7dev01.domain.com systemd[1]: Unit systemd-machined.service entered failed state.
Jun 13 12:52:40 rh7dev01.domain.com systemd[1]: systemd-machined.service failed.
Jun 13 12:52:40 rh7dev01.domain.com polkitd[30459]: Unregistered Authentication Agent for unix-process:31109:312248526 (system bus name :1.27516, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
Jun 13 12:52:48 rh7dev01.domain.com polkitd[30459]: Registered Authentication Agent for unix-process:31141:312249301 (system bus name :1.27517 [/usr/bin/pkttyagent --notify-fd 5 --fallback], object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en
Jun 13 12:52:48 rh7dev01.domain.com systemd[1]: Starting Virtual Machine and Container Registration Service...
-- Subject: Unit systemd-machined.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit systemd-machined.service has begun starting up.
Jun 13 12:52:48 rh7dev01.domain.com systemd[31158]: Failed at step NAMESPACE spawning /usr/lib/systemd/systemd-machined: Invalid argument
-- Subject: Process /usr/lib/systemd/systemd-machined could not be executed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- The process /usr/lib/systemd/systemd-machined could not be executed and failed.
-- 
-- The error number returned by this process is 22.
Jun 13 12:52:48 rh7dev01.domain.com systemd[1]: systemd-machined.service: main process exited, code=exited, status=226/NAMESPACE
Jun 13 12:52:48 rh7dev01.domain.com systemd[1]: Failed to start Virtual Machine and Container Registration Service.
-- Subject: Unit systemd-machined.service has failed
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit systemd-machined.service has failed.
-- 
-- The result is failed.
Jun 13 12:52:48 rh7dev01.domain.com systemd[1]: Unit systemd-machined.service entered failed state.
Jun 13 12:52:48 rh7dev01.domain.com systemd[1]: systemd-machined.service failed.
Jun 13 12:52:48 rh7dev01.domain.com polkitd[30459]: Unregistered Authentication Agent for unix-process:31141:312249301 (system bus name :1.27517, object path /org/freedesktop/PolicyKit1/AuthenticationAgent, locale en_US.UTF-8) (disconnected from bus)
Jun 13 12:53:15 rh7dev01.domain.com sshd[31188]: Connection closed by 10.28.59.175 [preauth]


Version-Release number of selected component (if applicable):
RHEL 7.3
kernel-3.10.0-514.10.2.el7.x86_64
systemd-219-30.el7_3.9.x86_64

How reproducible:
Unknown, as no changes have been made recently

How resolvable:
Bugzilla 1381666 had a similar issue, so investigating the local systemd-machined.service file shows:

# cat /lib/systemd/system/systemd-machined.service
...
[Service]
ExecStart=/usr/lib/systemd/systemd-machined
BusName=org.freedesktop.machine1
CapabilityBoundingSet=CAP_KILL CAP_SYS_PTRACE CAP_SYS_ADMIN CAP_SETGID CAP_SYS_CHROOT CAP_DAC_READ_SEARCH
WatchdogSec=3min
PrivateTmp=yes
PrivateDevices=yes
PrivateNetwork=yes
ProtectSystem=full
ProtectHome=yes

Commenting out PrivateDevices=yes allows the service to start and VMs can be made


Actual results:
KVM not allowing for VMs to be made, systemd-machined fails to start.

Expected results:
KVM allows for VMs to be made, systemd-machined starts without issue.
Comment 2 Michal Sekletar 2017-06-18 12:56:53 EDT
Does customer know what change they applied to the system before they encountered the error?

At the first glance this looks like selinux-policy bug. Does selinux-policy downgrade alleviate  the issue?
Comment 3 Robert McSwain 2017-06-23 15:53:40 EDT
Michal, could you confirm exactly which selinux-policy version he'd want to be running. Per the customer, he's only odne regular system updates and hasn't made other changes beyond that.
Comment 4 Lukas Vrabec 2017-06-30 04:13:12 EDT
Hi Robert, 

Personally, I think this is more selinux-policy issue then bug systemd. Are you able to reproduce it? If yes please do following: 

Switch to permissive mode
# setenforce 0  

Reproduce the scenario. 

And then attach output of:
# ausearch -m AVC,USER_AVC,SELINUX_ERR -ts today


We think there is some SELinux denial when systemd-machined is trying to communicate via DBUS. 


Thanks,
Lukas.
Comment 5 Michal Sekletar 2017-07-03 03:45:37 EDT
Since the issue seems to be selinux-policy problem I am reassigning the bug to respective component.
Comment 8 Robert McSwain 2017-07-05 20:37:49 EDT
I've not been able to reproduce this but the customer was able to provide the following output regarding their selinux output: 

# ausearch -m AVC,USER_AVC,SELINUX_ERR -ts today
----
time->Wed Jul  5 12:44:27 2017
type=USER_AVC msg=audit(1499283867.150:339776): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  received setenforce notice (enforcing=0)  exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
Comment 9 chen zhen 2017-08-03 05:21:08 EDT
the issue has appeared in my environment and my selinux config is Disabled.

version:
kernel-3.10.0-514.16.1.el7.x86_64
systemd-219-30.el7_3.9.x86_64

[root@cloud~]# getenforce 
Disabled


[root@cloud~]#  cat /lib/systemd/system/systemd-machined.service
 

[Unit]
Description=Virtual Machine and Container Registration Service
Documentation=man:systemd-machined.service(8)
Documentation=http://www.freedesktop.org/wiki/Software/systemd/machined
Wants=machine.slice
After=machine.slice

[Service]
ExecStart=/usr/lib/systemd/systemd-machined
BusName=org.freedesktop.machine1
CapabilityBoundingSet=CAP_KILL CAP_SYS_PTRACE CAP_SYS_ADMIN CAP_SETGID CAP_SYS_CHROOT CAP_DAC_READ_SEARCH
WatchdogSec=3min
PrivateTmp=yes
PrivateDevices=yes
PrivateNetwork=yes
ProtectSystem=full
ProtectHome=yes
Comment 10 Lukas Vrabec 2017-09-05 08:07:27 EDT
Michal, 

Please see comment#9, SELinux is disabled and issue appeared. Could you look on it?
Comment 11 Michal Sekletar 2017-09-06 05:44:23 EDT
Can you provide journal from the machine where you encountered the issue with disabled SELinux? Is there anything interesting in audit.log?
Comment 12 Nirav Dave 2017-10-04 06:40:07 EDT
I have received a ticket with the similar issue:

Please find below the details:


$ sudo virsh list --all
 Id    Name                           State
----------------------------------------------------
 -     VM1                 shut off
 -     VM2                 shut off

$ sudo virsh start VM1
error: Failed to start domain VM1
error: Activation of org.freedesktop.machine1 timed out

The issue was resolved after rebooting the host.

I will be attaching additional logs shortly.

Thanks & Regards,
Nirav Dave
Comment 14 Nirav Dave 2017-10-24 05:09:39 EDT
Please do let know if more information is needed over the issue, please do let know the further progress, as Customer is facing issue in production.

Thanks & Regards,
Nirav Dave

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