Description of problem: gnome-screensaver does not automatically lock the screen. Version-Release number of selected component (if applicable): 2.28.3-1.fc12.x86_64 How reproducible: Always Steps to Reproduce: 1. Wait for the idle time to expire Actual results: The screensaver does not start, and the display does not lock. Expected results: The screensaver should start and lock the display. Additional info: I set the idle time to 1 minute, and ran: gnome-screensaver --no-daemon --debug I let the computer idle, without any keyboard or mouse input, for several minutes. The results: [gs_debug_init] gs-debug.c:106 (09:32:16): Debugging enabled [main] gnome-screensaver.c:87 (09:32:16): initializing gnome-screensaver 2.28.3 [init_session_id] gs-listener-dbus.c:1979 (09:32:16): Got session-id: /org/freedesktop/ConsoleKit/Session2 [gs_fade_init] gs-fade.c:881 (09:32:17): Fade type: 3 [set_status] gs-watcher-x11.c:345 (09:32:17): GSWatcher: not active, ignoring status changes [gs_watcher_set_active] gs-watcher-x11.c:275 (09:32:17): turning watcher: ON [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:17): obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameAcquired destination=:1.282 [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:17): obj_path=(null) interface=(null) method=(null) destination=:1.282 [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:17): obj_path=(null) interface=(null) method=(null) destination=:1.282 [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:17): obj_path=(null) interface=(null) method=(null) destination=:1.282 [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:17): obj_path=(null) interface=(null) method=(null) destination=:1.282 [on_bg_changed] gs-manager.c:949 (09:32:17): background changed [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:17): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:17): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:18): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:18): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:18): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:18): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:19): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:19): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:19): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:20): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:20): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:20): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:21): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:21): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:21): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:21): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:22): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:22): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:22): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:23): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:23): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:23): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:24): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:24): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:24): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:24): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:25): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:25): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:25): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:26): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:32:26): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [watcher_idle_notice_cb] gs-monitor.c:125 (09:33:27): Idle notice signal detected: 1 [gs_grab_grab_offscreen] gs-grab-x11.c:540 (09:33:27): Grabbing an offscreen window [gs_grab_get_keyboard] gs-grab-x11.c:171 (09:33:27): Grabbing keyboard widget=3A00003 [gs_grab_get_mouse] gs-grab-x11.c:206 (09:33:27): Grabbing mouse widget=3A00003 [_gs_watcher_set_session_idle_notice] gs-watcher-x11.c:202 (09:33:28): Changing idle notice state: 1 [watcher_idle_notice_cb] gs-monitor.c:125 (09:33:28): Idle notice signal detected: 0 [watcher_idle_notice_cb] gs-monitor.c:149 (09:33:28): manager not active, performing fade cancellation [gs_fade_reset] gs-fade.c:826 (09:33:28): Resetting fade [_gs_watcher_set_session_idle_notice] gs-watcher-x11.c:202 (09:33:28): Changing idle notice state: 0 [listener_dbus_handle_system_message] gs-listener-dbus.c:1404 (09:33:28): obj_path=/org/freedesktop/Hal/devices/computer_logicaldev_input_0 interface=org.freedesktop.Hal.Device method=Condition destination=(null) [gs_grab_release] gs-grab-x11.c:418 (09:33:29): Releasing all grabs [gs_grab_release_mouse] gs-grab-x11.c:267 (09:33:29): Ungrabbing pointer [gs_grab_release_keyboard] gs-grab-x11.c:244 (09:33:29): Ungrabbing keyboard [xorg_lock_smasher_set_active] gs-grab-x11.c:124 (09:33:29): No XFree86-Misc extension present
Repost bug505915 Comment #82 for event timeline in Comment #0: 09:32:16 g-ss started 09:33:27 Idle notice signal detected: 1 [start gamma fading (10 sec)] 09:33:28 Idle notice signal detected: 0 manager not active, performing fade cancellation In bug505915 Comment #84 Sean clarified that no mouse/keyboard was touched until long after these msg printed, so we need to find out who produced the "no longer idle" msg.
Sean, We need to have debug msg from gnome-session ("g-s", gnome session manager), because g-ss (gnome-screensaver) registers with g-s for idle notice. Ultimately the idle notice comes from Xorg (Xserver), which g-s registers with for idle notice, so the msg flow is Xorg --> g-s --> g-ss To be precise, between g-s and g-ss there is a dbus-daemon, which acts as an event channel, to which different processes can register as event producer (eg. g-s produces "idle notice" event) or event consumer (eg. g-ss consumes "idle notice" event). But since dbus does not produce event itself, we can ignore dbus for this debugging. Could you try the following as root? - create gnome-session.sh, with these content: #!/bin/bash exec gnome-session.bin --debug "$@" - do these b=/usr/bin/gnome-session mv $b $b.bin cp gnome-session.sh $b ls -lZ $b* chcon system_u:object_r:bin_t:s0 $b chmod +x $b ls -lZ $b* Then logout and login again. The debug output of g-s now goes to /var/log/messages, so as root do tail -f /var/log/messages | grep gnome-session.bin Now we know what g-s is thinking. Here is an example of idle=1 from g-s (portion of msg editted out to improve readability): May 12 22:29:40 ... Searching for 16777229 in 16777229,16777230 May 12 22:29:40 ... Watch 4 fired, idle time = 60000 May 12 22:29:40 ... GsmPresence: setting idle: 1 May 12 22:29:40 ... Updating ConsoleKit idle status: 1 Here is an example of idle=0 from g-s, when gamma fading is interrupted by key event: May 12 22:29:46 ... Searching for 16777230 in 16777229,16777230 May 12 22:29:46 ... Watch 4 fired, idle time = 0 May 12 22:29:46 ... GsmPresence: setting idle: 0 May 12 22:29:46 ... Updating ConsoleKit idle status: 0 If you don't touch kbd/mouse but g-s says "setting idle: 0", then we know g-ss is innocent, and we need to find out why g-s thinks so. Sorry to have you go through these trouble; but as I am unable to reproduce this issue I need your help to gather info.
Output (edited for readability): May 13 08:15:48 Searching for 12582917 in 12582917,12582918 May 13 08:15:48 Watch 1 fired, idle time = 60002 May 13 08:15:48 GsmPresence: setting idle: 1 May 13 08:15:48 Updating ConsoleKit idle status: 1 May 13 08:15:48 Searching for 12582918 in 12582917,12582918 May 13 08:15:48 Watch 1 fired, idle time = 51 May 13 08:15:48 GsmPresence: setting idle: 0 May 13 08:15:48 Updating ConsoleKit idle status: 0
Sean, Thanks for getting back. You proved that, in your system, g-ss is just following order from g-s, as evidenced by these two lines from Comment #3: May 13 08:15:48 GsmPresence: setting idle: 1 May 13 08:15:48 GsmPresence: setting idle: 0 Next we need to check why g-s is making that decision. Could you run strace on gnome-session, like this? strace -tt -e read=all -e write=all -p $(pgrep gnome-session) Here is a sample output (edited). - idled for 60 sec #11 Xorg send idle notice to g-s. #12 g-s send debug msg to sys log (/var/log/messages) #13 g-s send idle notice to g-ss (via dbus-daemon) - the user hit a key to stop gamma fading. #11 Xorg send idle=0 to g-s. #12 g-s send debug msg to sys log (/var/log/messages) #13 g-s send idle=0 to g-ss (via dbus-daemon) #11 12:27:45.574340 read(3, "`\1\304\0...", 4096) = 32 | 00000 60 01 c4 00 0b 00 c0 00 00 00 00 00 61 ea 00 00 `....... ....a... | | 00010 00 00 00 00 60 ea 00 00 09 45 34 10 00 42 21 08 ....`... .E4..B!. | ... #12 12:27:45.591363 send(6, "<28>May 13 12:27:45 gnome-"..., 85, MSG_NOSIGNAL) = 85 | 00000 3c 32 38 3e 4d 61 79 20 31 33 20 31 32 3a 32 37 <28>May 13 12:27 | | 00010 3a 34 35 20 67 6e 6f 6d 65 2d 73 65 73 73 69 6f :45 gnom e-sessio | | 00020 6e 2e 62 69 6e 5b 31 39 37 32 39 5d 3a 20 44 45 n.bin[19 729]: DE | | 00030 42 55 47 28 2b 29 3a 20 47 73 6d 50 72 65 73 65 BUG(+): GsmPrese | | 00040 6e 63 65 3a 20 73 65 74 74 69 6e 67 20 69 64 6c nce: set ting idl | | 00050 65 3a 20 31 0a e: 1. | #13 12:27:45.593508 writev(9, [{"l\4\1\1..."..., 144}, {"\3\0\0\0", 4}], 2) = 148 | 00000 6c 04 01 01 04 00 00 00 47 00 00 00 7f 00 00 00 l....... G....... | | 00010 01 01 6f 00 22 00 00 00 2f 6f 72 67 2f 67 6e 6f ..o."... /org/gno | | 00020 6d 65 2f 53 65 73 73 69 6f 6e 4d 61 6e 61 67 65 me/Sessi onManage | | 00030 72 2f 50 72 65 73 65 6e 63 65 00 00 00 00 00 00 r/Presen ce...... | | 00040 02 01 73 00 21 00 00 00 6f 72 67 2e 67 6e 6f 6d ..s.!... org.gnom | | 00050 65 2e 53 65 73 73 69 6f 6e 4d 61 6e 61 67 65 72 e.Sessio nManager | | 00060 2e 50 72 65 73 65 6e 63 65 00 00 00 00 00 00 00 .Presenc e....... | | 00070 03 01 73 00 0d 00 00 00 53 74 61 74 75 73 43 68 ..s..... StatusCh | | 00080 61 6e 67 65 64 00 00 00 08 01 67 00 01 75 00 00 anged... ..g..u.. | | 00000 03 00 00 00 .... | ... #21 12:27:50.381930 read(3, "`\1\304\0\f\0\300\0...", 4096) = 32 | 00000 60 01 c4 00 0c 00 c0 00 00 00 00 00 01 00 00 00 `....... ........ | | 00010 00 00 00 00 60 ea 00 00 d0 57 34 10 00 42 21 08 ....`... .W4..B!. | ... #22 12:27:50.405836 send(6, "<28>May 13 12:27:50 gnome-"..., 85, MSG_NOSIGNAL) = 85 | 00000 3c 32 38 3e 4d 61 79 20 31 33 20 31 32 3a 32 37 <28>May 13 12:27 | | 00010 3a 35 30 20 67 6e 6f 6d 65 2d 73 65 73 73 69 6f :50 gnom e-sessio | | 00020 6e 2e 62 69 6e 5b 31 39 37 32 39 5d 3a 20 44 45 n.bin[19 729]: DE | | 00030 42 55 47 28 2b 29 3a 20 47 73 6d 50 72 65 73 65 BUG(+): GsmPrese | | 00040 6e 63 65 3a 20 73 65 74 74 69 6e 67 20 69 64 6c nce: set ting idl | | 00050 65 3a 20 30 0a e: 0. | #23 12:27:50.407495 writev(9, [{"l\4\1\1\4"..., 144}, {"\0\0\0\0", 4}], 2) = 148 | 00000 6c 04 01 01 04 00 00 00 48 00 00 00 7f 00 00 00 l....... H....... | | 00010 01 01 6f 00 22 00 00 00 2f 6f 72 67 2f 67 6e 6f ..o."... /org/gno | | 00020 6d 65 2f 53 65 73 73 69 6f 6e 4d 61 6e 61 67 65 me/Sessi onManage | | 00030 72 2f 50 72 65 73 65 6e 63 65 00 00 00 00 00 00 r/Presen ce...... | | 00040 02 01 73 00 21 00 00 00 6f 72 67 2e 67 6e 6f 6d ..s.!... org.gnom | | 00050 65 2e 53 65 73 73 69 6f 6e 4d 61 6e 61 67 65 72 e.Sessio nManager | | 00060 2e 50 72 65 73 65 6e 63 65 00 00 00 00 00 00 00 .Presenc e....... | | 00070 03 01 73 00 0d 00 00 00 53 74 61 74 75 73 43 68 ..s..... StatusCh | | 00080 61 6e 67 65 64 00 00 00 08 01 67 00 01 75 00 00 anged... ..g..u.. | | 00000 00 00 00 00 .... |
Created attachment 414091 [details] Output from strace on gnome-session
So the problem is with Xorg. What release is your Xorg? Eg. I have [timliim@taiwan ~]$ rpm -qf /usr/bin/Xorg xorg-x11-server-Xorg-1.7.6-4.fc12.i686 In your strace we have #11 Xorg tells g-s: idle=1 #21 168ms later, Xorg tells g-s: idle=0 The problem then is, why would Xorg immediately send "idle=0" immediately after "idle=1." #11 08:25:12.831258 read(3, "`\1\253\0\5\0"..., 4096) = 32 | 00000 60 01 ab 00 05 00 c0 00 00 00 00 00 64 ea 00 00 `....... ....d... | | 00010 00 00 00 00 60 ea 00 00 4d fb 2f 00 00 7f 00 00 ....`... M./..... | #12 08:25:12.832841 writev(2, [{"gnome-session.bin[2927]: DEBUG"..., 64}], 1) = 64 | 00000 67 6e 6f 6d 65 2d 73 65 73 73 69 6f 6e 2e 62 69 gnome-se ssion.bi | | 00010 6e 5b 32 39 32 37 5d 3a 20 44 45 42 55 47 28 2b n[2927]: DEBUG(+ | | 00020 29 3a 20 47 73 6d 50 72 65 73 65 6e 63 65 3a 20 ): GsmPr esence: | | 00030 73 65 74 74 69 6e 67 20 69 64 6c 65 3a 20 31 0a setting idle: 1. | #21 08:25:12.999021 read(3, "`\1\253\0\6\0\300\", 4096) = 32 | 00000 60 01 ab 00 06 00 c0 00 00 00 00 00 33 00 00 00 `....... ....3... | | 00010 00 00 00 00 60 ea 00 00 f5 fb 2f 00 00 7f 00 00 ....`... ../..... | #22 08:25:13.001562 writev(2, [{"gnome-session.bin[2927]: DEBUG"..., 64}], 1) = 64 | 00000 67 6e 6f 6d 65 2d 73 65 73 73 69 6f 6e 2e 62 69 gnome-se ssion.bi | | 00010 6e 5b 32 39 32 37 5d 3a 20 44 45 42 55 47 28 2b n[2927]: DEBUG(+ | | 00020 29 3a 20 47 73 6d 50 72 65 73 65 6e 63 65 3a 20 ): GsmPr esence: | | 00030 73 65 74 74 69 6e 67 20 69 64 6c 65 3a 20 30 0a setting idle: 0. |
My version of Xorg is: xorg-x11-server-Xorg-1.7.6-3.fc12.x86_64 I'm now wondering if this is related to another display bug I have open that manifests on the same machine: bug580276 I filed it against the kernel driver, but I'm wondering if there might be a problem with the X driver for Intel?
> I'm now wondering if this is related to ... bug580276 ... might be a > problem with the X driver for Intel? Maybe, but we have no evidence yet. Could you build xorg-x11-server-Xorg from source rpm and see if it behaves the same? If so, we can put in a few debug msgs.
I've built xorg-x11-server-Xorg from source and it behaves the same.
Good, we can debug Xorg then. In Xorg source tree, Xext/sync.c, add these debug msgs [1] [2]. Then cd ~/rpmbuild/BUILD/xorg-server-1.7.6 make [1] aux methods, add near top of sync.c, wherever you feel right. #include <time.h> #include <sys/time.h> const char* timestamp(void); const char* timestamp(void) { static char buf[200]; struct timeval tv; struct tm tm; buf[0] = 0; gettimeofday(&tv, NULL); localtime_r(&tv.tv_sec, &tm); snprintf(buf, 200, "%02d/%02d %02d:%02d:%02d.%03lu", tm.tm_mon, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, tv.tv_usec / 1000); return buf; } const char* testType2str(int testType); const char* testType2str(int testType) { const char* b = "unknown"; switch (testType) { case XSyncPositiveTransition: b = "XSyncPositiveTransition"; break; case XSyncNegativeTransition: b = "XSyncNegativeTransition"; break; case XSyncPositiveComparison: b = "XSyncPositiveComparison"; break; case XSyncNegativeComparison: b = "XSyncNegativeComparison"; break; } return b; } [2] debug msgs, add to these 4 methods #1 ProcSyncCreateAlarm /* add right before "return Success;" */ fprintf(stderr, "%s #1 ProcSyncCreateAlarm alarm id 0x%08x, type=%s, value=%8u\n", timestamp(), (unsigned int) pAlarm->alarm_id, testType2str( pTrigger->test_type), XSyncValueLow32(pTrigger->wait_value)); #2 ProcSyncChangeAlarm /* add right before "return Success;" */ fprintf(stderr, "%s #2 ProcSyncChangeAlarm alarm id 0x%08x, type=%s, value=%8u\n", timestamp(), (unsigned int) pAlarm->alarm_id, testType2str( pAlarm->trigger.test_type), XSyncValueLow32(pAlarm->trigger.wait_value)); #3 ProcSyncDestroyAlarm /* add right before "FreeResource()" */ fprintf(stderr, "%s #3 ProcSyncDestroyAlarm alarm id 0x%08x\n", timestamp(), (unsigned int)pAlarm->alarm_id); #4 SyncAlarmTriggerFired /* add right before "SyncSendAlarmNotifyEvents()" */ fprintf(stderr, "%s #4 SyncAlarmTriggerFired alarm id 0x%08x\n", timestamp(), (unsigned int)pAlarm->alarm_id);
After modifying sync.c and build with "make" as regular user: as root, do d=/home/xxx/rpmbuild/BUILD/xorg-server-1.7.6 # ^^^ where your rpmbuild is i=hw/xfree86/Xorg b=/usr/bin/Xorg c=system_u:object_r:xserver_exec_t:s0 mv -f $b $b.orig cp $d/$i $b ls -lZ $b*; ls -l $b* chmod og-r,u+s $b chcon $c $b ls -lZ $b*; ls -l $b* So we replace /usr/bin/Xorg with our debug version. Logout and login gnome; then as root, log=/var/log/gdm/:0.log tail -n 500 -f $log | grep "#" Now we can observe what sync.c is doing.
When I set g-ss to activate in 1 minute, I have (output edited; there are other alarms from gnome-power-manager and from other sources) #11 22:24:36.106 #1 alarm id 0x00c00005, type=+Trans, value= 60000 #12 22:24:36.106 #1 alarm id 0x00c00006, type=-Trans, value= 60000 #13 22:26:02.076 #4 alarm id 0x00c00005 #14 22:26:12.524 #3 alarm id 0x00c00005 #15 22:26:12.524 #3 alarm id 0x00c00006 The pair of alarm #11, #12 were created by g-s for the 60 sec idle notice. My last key stroke was at 22:25:02, so #13 kicks in after 60 sec. Another 10 sec later (22:26:12) gamma fading completed and g-s destroyed the pair of alarms (#14, #15). When I touched the keyboard, this cycle repeats. Let's see if the same happens to you.
Created attachment 421048 [details] Output from patched sync.c
Sean, Thanks for info. In your log file (Comment #13) we have 14:42:38.037 #4 alarm id 0x00c00005 <== idle notice to g-s (II) intel(0): EDID for output LVDS1 ... 14:42:38.199 #4 alarm id 0x00c00006 <== no-longer idle to g-s Why I single out 0x00c00005,0x00c00006? For idle notice from Xorg, g-s registers a pair of alarm, one for positive transition, one negative. For example, in Comment #12 we have 0x00c00005 (c5 for short), type=+Trans, value= 60000 ^^ when idle count grows to be >60000ms, send alarm 0x00c00006 (c6 for short), type=-Trans, value= 60000 ^^ when idle count drops below 60000ms, send alarm alarm c5 is for idle notice, c6 is for no-longer-idle notice. g-s uses the alarm pair only once before destroying them and create new ones, ie. after the current idle cycle, g-s destroys c5, c6 and create a new pair c7, c8, and so on. So in Comment #13 your Xorg send idle notice at 14:42:38.037 #4 alarm id 0x00c00005 and immediately (in 162ms) followed by no-longer-idle notice: 14:42:38.199 #4 alarm id 0x00c00006 Our goal now becomes: find out why c6 is consistently triggered immediately. In Comment #13 you also have (II) intel(0): EDID for output LVDS1 ... right before c6 triggering. Is this always the case in your system? On my system I do see similar msg from time to time, but I don't see any obvious pattern between "EDID for output xxx" and c6 (-trans alarm for g-s). If you see some pattern between the two, maybe we can dive towards that direction. Otherwise, we need to guess what triggered alarm c6.
(In reply to comment #14) > In Comment #13 you also have > (II) intel(0): EDID for output LVDS1 > ... > right before c6 triggering. Is this always the case in your > system? Yes, this occurs every time.
Looks like I made a wrong guess on the relevance of the EDID msg, (II) intel(0): EDID for output LVDS1 because on one of my machines I also see this msg every time after c5 triggering, yet no spurious c6 trigger, and the screen locks properly if I don't touch mouse/kbd. I'll trace Xext/sync.c further to find out possible cause for the spurious no-longer-idle msg. But since I haven't traced this portion before, it will take some time; plus I am also involved in the preparation of an upcoming Taiwanese American Conference (http://tacec.org) on Independence day, so my response time will be slow until then. Thanks for your patience.
Created attachment 425805 [details] more debug msg on Xext/sync.c Sean, Could you try adding more debug info, as in the attachment? Thanks. Summary of changes: 1. fix bug in previous debug msgs const char* timestamp(void) snprintf(buf, 200, "%02d/%02d %02d:%02d:%02d.%03lu", tm.tm_mon + 1, /* fix bug in counting months */ 2. enhance previous debug msg #4 to include current counter value fprintf(stderr, "%s #4 SyncAlarmTriggerFired alarm id 0x%08x, counter=%8u\n", timestamp(), (unsigned int)pAlarm->alarm_id, XSyncValueLow32(pAlarm->trigger.pCounter->value) ); 3. add new debug msgs to #5 SyncChangeCounter (invoked when Xorg server handles an event) #6 IdleTimeQueryValue (updates the idle counter)
A sample output (edited) where the idle timer kicks in properly, and the user interrupted the gamma fading after 9 sec: 06/21 22:55:40.876 #1 alarm id 0x00c00005, type=XSync+Trans, value= 60000 06/21 22:55:40.881 #1 alarm id 0x00c00006, type=XSync-Trans, value= 60000 ### ^^ the pair of alarms for g-s are created. 06/21 22:55:57.218 #6 now=480685932, last event time=480685931, diff= 1 06/21 22:55:57.315 #6 now=480686029, last event time=480686029, diff= 0 ### ^^ user hit and release a key to reset idle time 06/21 22:56:57.316 #5 newval= 60001 06/21 22:56:57.316 #4 alarm id 0x00c00005, counter= 60001 ### ^^ idle alarm triggered after idling for 60sec (II) intel(0): EDID for output LVDS1 06/21 22:57:06.779 #6 now=480755493, last event time=480755493, diff= 0 ### ^^ after 9 sec user hit a key to stop gamma fading. 06/21 22:57:06.779 #5 newval= 0 06/21 22:57:06.779 #4 alarm id 0x00c00006, counter= 0 ### ^^ Xorg sends no-longer-idle msg to g-s
Created attachment 427026 [details] Output from latest patched sync.c Starting a couple of seconds before the 60 second timeout, and ending a couple of seconds afterwards.
Created attachment 428574 [details] debug code, ver 3. Good, these lines showed we are on the right track: 06/25 18:13:29.364 #6 now=26429023, last event time=26369017, diff= 60006 06/25 18:13:29.522 #6 now=26429182, last event time=26429127, diff= 55 Note that "last event time" changed, so Xorg considered itself no longer idle. The "last event time" (lastDeviceEventTime) is changed in NoticeTime() (dix/events.c), which is is invoked by NoticeEventTime(). User input (kbd, mouse) are processed in ProcessOtherEvent() (Xi/exevents.c), so let's add some debug code there, as the attached debug msg ver. 3, and see if we catch anyone modifying lastDeviceEventTime.
Created attachment 429196 [details] Output from debug code, ver 3. Note that no keys (or anything else, for that matter) were actually touched, despite what Xorg reports.
Created attachment 430761 [details] debug code, ver 4. > Note that no keys ... were actually touched, ... Yes, I believe you; the phantom "key event" reported by Xorg always came ~150-170ms after the initial idle alarm. You'd be a famous sports star :-) by now if you can keep up that reflex so consistently. So, yes, from your log, this phantom key event woke up Xorg, after 155ms. 07/02 16:38:08.136 #6 IdleTimeQueryValue now= 468489, ... 07/02 16:38:08.291 #9 ProcessOtherEvent type=2 (KeyPress) Let's add more debug code to see what the phantom key is, and if it comes in from the usual path. NOTE: please change your password to a temporary (but still hard to guess) one, because essentially this debug code becomes a key logger. The log file is readable only by root, true, but if you are as paranoid as I am, you don't want to tolerate any slim chance that the password might leak out to the world. Here is the log msg for a real key event (I hit the shift key): 07/09 11:41:20.790 #11 ProcessInputEvents 07/09 11:41:20.790 #10 ProcessKeyboardEvent 07/09 11:41:20.790 #9 ProcessOtherEvent type=2 (KeyPress) key=62 07/09 11:41:20.790 #8 NoticeEventTime 07/09 11:41:20.790 #7 NoticeTime event time=238886922 07/09 11:41:20.790 #10 ProcessKeyboardEvent 07/09 11:41:20.790 #9 ProcessOtherEvent type=2 (KeyPress) key=62 07/09 11:41:20.790 #8 NoticeEventTime 07/09 11:41:20.790 #7 NoticeTime event time=238886922 For the record, here is the stack trace leading to NoticeEventTime(). #0 NoticeEventTime at events.c:1085 #1 ProcessOtherEvent at exevents.c:1046 #2 XkbHandleActions at xkbActions.c:1196 #3 XkbProcessKeyboardEvent at xkbPrKeyEv.c:139 #4 AccessXFilterPressEvent at xkbAccessX.c:561 #5 ProcessKeyboardEvent at xkbPrKeyEv.c:174 #6 mieqProcessDeviceEvent at mieq.c:412 #7 mieqProcessInputEvents at mieq.c:471 #8 ProcessInputEvents at xf86Events.c:165 #9 Dispatch at dispatch.c:371 #10 main at main.c:285
Created attachment 431051 [details] Output from debug code, ver 4.
Is this on a laptop? Could you check which key produces key code 235? 07/11 19:16:24.695 #11 ProcessInputEvents 07/11 19:16:24.695 #9 ProcessOtherEvent type=2 (KeyPress) key=235 On my VAIO, key 235 is Fn + F7 (switch video to external display). In Comment #7 you mentioned bug580276 Screen flickering on Intel graphics If your key 235 also switches external display, this bug might be somehow related to bug580276. Do you still see the flickering with these debug code? If so, do you see key 235 in Xorg log where it should not appear? Hopefully around the time when the flickering occurs? At this point I am suspecting some driver that's specific to your video chip inserted the phantom key 235. I'll debug further to see how the key events are processed and then get back to you.
Created attachment 436428 [details] debug code version 5, inside SIGIO handler. Sean, Could you try more of these debug code? Thanks. In the following debug msg example, #15-#13 are inside SIGIO handler, while #12-#7 are inside main event loop handler. 08/03 23:51:27.192 #15 xf86SIGIO 08/03 23:51:27.192 #14 xf86PostKeyboardEvent 08/03 23:51:27.193 #13 mieqEnqueue tail=46 08/03 23:51:27.193 #13 mieqEnqueue tail=47 08/03 23:51:27.193 #12 Dispatch *icheck[0]=45 *icheck[1]=47 08/03 23:51:27.193 #11 ProcessInputEvents 08/03 23:51:27.193 #10 ProcessKeyboardEvent 08/03 23:51:27.193 #9 ProcessOtherEvent type=2 (KeyPress) key=62 08/03 23:51:27.193 #8 NoticeEventTime 08/03 23:51:27.193 #7 NoticeTime event time=2442693325
Sean, By any chance do you have update on this bug? Thanks.
I updated to Fedora 13 a couple of weeks ago, and the problem no longer manifests. Apparently the bug, whatever the root cause, has already been fixed. Versions that work, for the record: kernel-2.6.33.6-147.fc13.x86_64 xorg-x11-server-Xorg-1.8.2-3.fc13.x86_64 xorg-x11-drv-intel-2.11.0-5.fc13.x86_64
Sean, That's good to know, that the issue is fixed in F13. Since this is no longer an issue in F13, can we close this bug? Thanks.
I haven't seen this bug since I upgraded to Fedora 13 over a month ago. I'd consider this closed.