Bug 1408457 - power.sh fails to list processes and so will always shut down the computer
Summary: power.sh fails to list processes and so will always shut down the computer
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: acpid
Version: 25
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Jaroslav Škarvada
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-12-23 13:31 UTC by Oliver Henshaw
Modified: 2017-01-27 19:21 UTC (History)
3 users (show)

Fixed In Version: acpid-2.0.28-2.fc25
Clone Of:
Environment:
Last Closed: 2017-01-27 19:21:50 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

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.


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