Bug 1408457

Summary: power.sh fails to list processes and so will always shut down the computer
Product: [Fedora] Fedora Reporter: Oliver Henshaw <oliver.henshaw>
Component: acpidAssignee: Jaroslav Škarvada <jskarvad>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 25CC: jskarvad, systemd-maint, ted
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: acpid-2.0.28-2.fc25 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-01-27 19:21:50 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:

Description Oliver Henshaw 2016-12-23 13:31:14 UTC
Description of problem:

On F25 with kde plasma and acpid.service enabled, pushing the power button always shuts down the machine, and the logged in user does not logout cleanly. I haven't tested, but I expect that this will fail in the same way with gnome sessions.

This happens because the /etc/acpi/actions/power.sh script is activated on the power button event but it fails to detect that a kde plasma session is running - in fact it fails to enumerate the processes in the active session.


With
--- /etc/acpi/actions/power.sh	2016-12-23 12:17:00.897786166 +0000
+++ /home/test/power.sh	2016-12-23 12:15:59.898361085 +0000
@@ -6,7 +6,7 @@
 session_ids=$(loginctl list-sessions 2>/dev/null | awk '{print $1}')
 for session in ${session_ids} ; do
 	session_status=$(loginctl session-status ${session})
-	echo "${session_status}" | grep -e '\(Active: yes\|State: active\)' &> /dev/null &&
+	echo "${session_status}" | grep -e '\(Active: yes\|State: active\)' &> /dev/null && logger "${session_status}" &&
 		echo "${session_status}" | grep -e '\(gnome-settings-daemon\|cinnamon-settings-daemon\|kded[4-5]\|plasmashell\|xfce4-power-manager\|mate-power-manager\)' &> /dev/null && exit 0
 done
 
I see in 'journalctl -b -1':
Dec 23 11:58:33 localhost.localdomain audit[2005]: AVC avc:  denied  { read } for  pid=2005 comm="loginctl" name="user-1000.j
Dec 23 11:58:33 localhost.localdomain audit[2005]: AVC avc:  denied  { read } for  pid=2005 comm="loginctl" name="system.jour
Dec 23 11:58:33 localhost.localdomain root[2008]: 2 - test (1000)
                                                             Since: Fri 2016-12-23 11:54:32 GMT; 4min 0s ago
                                                            Leader: 964 (sddm-helper)
                                                              Seat: seat0; vc1
                                                           Display: :0
                                                           Service: sddm; type x11; class user
                                                           Desktop: KDE
                                                             State: active
                                                              Unit: session-2.scope

But from a terminal I would get e.g.:
# loginctl session-status 2
2 - test (1000)
	   Since: Fri 2016-12-23 11:59:18 GMT; 20min ago
	  Leader: 964 (sddm-helper)
	    Seat: seat0; vc1
	 Display: :0
	 Service: sddm; type x11; class user
	 Desktop: KDE
	   State: active
	    Unit: session-2.scope
		  ├─ 964 /usr/libexec/sddm-helper --socket /tmp/sddm-auth521bbc66-d461-4e3c-abed-50a5f525449d --id 1 --start /usr/bin/startkde --user test
		  ├─ 986 /usr/bin/kwalletd5 --pam-login 14 17
		  ├─ 988 /usr/bin/kwalletd --pam-login 14 18 --nofork
		  ├─ 989 /bin/sh /usr/bin/startkde
		  ├─1012 /usr/bin/ssh-agent /bin/sh -c exec -l /bin/bash -c "/usr/bin/startkde"
		  ├─1056 /usr/libexec/kf5/start_kdeinit --kded +kcminit_startup
		  ├─1057 kdeinit5: Running...
		  ├─1058 /usr/libexec/kf5/klauncher --fd=9
		  ├─1061 kded5 [kdeinit5]
		  ├─1077 kwrapper5 /usr/bin/ksmserver
		  ├─1078 /usr/bin/ksmserver
		  ├─1106 /usr/bin/kaccess
		  ├─1153 kwin_x11 -session 1028c1d320b210000148103492100000010970008_1482494029_976984
		  ├─1155 /usr/bin/baloo_file
		  ├─1156 /usr/libexec/kdeconnectd
		  ├─1157 /usr/bin/krunner
		  ├─1159 /usr/bin/plasmashell --shut-up
		  ├─1162 /usr/libexec/kf5/polkit-kde-authentication-agent-1
		  ├─1163 /usr/bin/xembedsniproxy
		  ├─1179 /usr/libexec/gam_server
		  ├─1185 /usr/bin/pulseaudio --start --log-target=syslog
		  ├─1197 konsole [kdeinit5] -session 1028c1d320b210000148103561700000010970014_1482494029_797246 -name konsole
		  ├─1203 /usr/lib64/firefox/firefox --sm-client-id 1028c1d320b210000148103575500000010970016
		  ├─1222 /usr/libexec/org_kde_powerdevil -session 1028c1d320b210000148103492200000010970010_1482494029_797740
		  ├─1246 /usr/bin/kactivitymanagerd start-daemon
		  ├─1248 /usr/bin/korgac -session 1028c1d320b210000148103492900000010970011_1482494029_796472
		  ├─1278 /usr/bin/abrt-applet
		  ├─1284 /usr/bin/spice-vdagent
		  ├─1382 /bin/bash
		  ├─1409 /usr/bin/akonadi_control
		  ├─1414 akonadiserver
		  ├─1418 /usr/libexec/mysqld --defaults-file=/home/test/.local/share/akonadi/mysql.conf --datadir=/home/test/.local/share/akonadi/db_data/ --socket=/tmp/akonadi-test.3c4Gwu/mysql.socket
		  ├─1464 /usr/bin/akonadi_akonotes_resource --identifier akonadi_akonotes_resource_0
		  ├─1465 /usr/bin/akonadi_archivemail_agent --identifier akonadi_archivemail_agent
		  ├─1466 /usr/bin/akonadi_birthdays_resource --identifier akonadi_birthdays_resource
		  ├─1467 /usr/bin/akonadi_contacts_resource --identifier akonadi_contacts_resource_0
		  ├─1468 /usr/bin/akonadi_followupreminder_agent --identifier akonadi_followupreminder_agent
		  ├─1469 /usr/bin/akonadi_ical_resource --identifier akonadi_ical_resource_0
		  ├─1470 /usr/bin/akonadi_indexing_agent --identifier akonadi_indexing_agent
		  ├─1471 /usr/bin/akonadi_maildir_resource --identifier akonadi_maildir_resource_0
		  ├─1472 /usr/bin/akonadi_maildispatcher_agent --identifier akonadi_maildispatcher_agent
		  ├─1473 /usr/bin/akonadi_mailfilter_agent --identifier akonadi_mailfilter_agent
		  ├─1474 /usr/bin/akonadi_migration_agent --identifier akonadi_migration_agent
		  ├─1475 /usr/bin/akonadi_newmailnotifier_agent --identifier akonadi_newmailnotifier_agent
		  ├─1476 /usr/bin/akonadi_notes_agent --identifier akonadi_notes_agent
		  ├─1477 /usr/bin/akonadi_sendlater_agent --identifier akonadi_sendlater_agent
		  ├─1702 su -
		  ├─1709 -bash
		  ├─1729 journalctl -b -1
		  ├─1730 less
		  ├─1840 /bin/bash
		  ├─1889 /bin/bash
		  ├─1908 su -
		  ├─1915 -bash
		  ├─2232 less /etc/acpi/actions/power.sh
		  ├─2240 loginctl session-status 2
		  └─2241 xclip -i

Dec 23 12:08:32 localhost.localdomain kscreenlocker_greet[1820]: No metadata file in the package, expected it at: "/usr/share/backgrounds/f25/default/standard/"
Dec 23 12:08:32 localhost.localdomain kscreenlocker_greet[1820]: No metadata file in the package, expected it at: "/usr/share/backgrounds/f25/default/standard/"
Dec 23 12:08:33 localhost.localdomain kscreenlocker_greet[1820]: file:///usr/share/plasma/look-and-feel/org.fedoraproject.fedora.desktop/contents/components/Battery.qml:39:18: Unable to assign [undefined] to int
Dec 23 12:10:22 localhost.localdomain kwin_x11[1153]: QXcbConnection: XCB error: 3 (BadWindow), sequence: 35121, resource id: 96469021, major code: 18 (ChangeProperty), minor code: 0
Dec 23 12:16:13 localhost.localdomain su[1908]: (to root) test on pts/3
Dec 23 12:16:13 localhost.localdomain su[1908]: pam_systemd(su-l:session): Cannot create session: Already running in a session
Dec 23 12:16:13 localhost.localdomain su[1908]: pam_unix(su-l:session): session opened for user root by test(uid=1000)
Dec 23 12:18:38 localhost.localdomain plasmashell[1159]: file:///usr/lib64/qt5/qml/QtQuick/Controls/Button.qml:99: TypeError: Cannot read property of null
Dec 23 12:19:06 localhost.localdomain plasmashell[1159]: file:///usr/lib64/qt5/qml/QtQuick/Controls/Button.qml:99: TypeError: Cannot read property of null
Dec 23 12:19:06 localhost.localdomain plasmashell[1159]: QXcbConnection: XCB error: 2 (BadValue), sequence: 6215, resource id: 52428820, major code: 141 (Unknown), minor code: 3

It looks loginctl fails to read the logs for the active session (due to selinux forbidding apmd_t processes from reading them) and so doesn't print the logs or the process tree. Then the power.sh script continues onwards and calls "shutdown -h now".


I'm not sure whether logind provides any convenient way to list processes belonging to a session without also showing logs.

However, it looks like systemd puts processes in a cgroup hierarchy of the form 
"/user.slice/user-${userid}.slice/session-{session}.scope" so you could grep
"ps -eo comm,cgroup" or "systemd-cgls"; or you could find the uid of the active session and do "systemd-cgls /user.slice/user-${userid}.slice/session-{session}.scope".


Another approach is to parse the reply from ListInhibitors() on the org.freedesktop.login1.Manager dbus interface and for every process with a "handle-power-key" block-inhibition check whether it's in the active session.


Version-Release number of selected component (if applicable):

systemd-231-10.fc25.x86_64
acpid-2.0.28-1.fc25.x86_64

Comment 1 Oliver Henshaw 2016-12-23 13:38:13 UTC
Sorry, the AVCs from the journal where truncated.

# journalctl -b -1 | grep apmd
Dec 23 11:58:33 localhost.localdomain audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  denied  { status } for auid=n/a uid=0 gid=0 path="/run/systemd/transient/session-2.scope" cmdline="loginctl session-status 2" scontext=system_u:system_r:apmd_t:s0 tcontext=system_u:object_r:init_var_run_t:s0 tclass=service
Dec 23 11:58:33 localhost.localdomain audit[2005]: AVC avc:  denied  { read } for  pid=2005 comm="loginctl" name="user-1000.journal" dev="dm-0" ino=32124 scontext=system_u:system_r:apmd_t:s0 tcontext=system_u:object_r:var_log_t:s0 tclass=file permissive=0
Dec 23 11:58:33 localhost.localdomain audit[2005]: AVC avc:  denied  { read } for  pid=2005 comm="loginctl" name="system.journal" dev="dm-0" ino=32073 scontext=system_u:system_r:apmd_t:s0 tcontext=system_u:object_r:var_log_t:s0 tclass=file permissive=0

Comment 2 Fedora Update System 2017-01-18 16:21:06 UTC
acpid-2.0.28-2.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-f83941c948

Comment 3 Fedora Update System 2017-01-19 09:12:05 UTC
acpid-2.0.28-2.fc25 has been pushed to the Fedora 25 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-f83941c948

Comment 4 Fedora Update System 2017-01-27 19:21:50 UTC
acpid-2.0.28-2.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.