Bug 591750 - gnome-screensaver not auto-locking screen
Summary: gnome-screensaver not auto-locking screen
Keywords:
Status: CLOSED NEXTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: gnome-screensaver
Version: 12
Hardware: x86_64
OS: Linux
low
medium
Target Milestone: ---
Assignee: jmccann
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2010-05-12 23:54 UTC by Sean Sheedy
Modified: 2015-01-14 23:25 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2010-09-01 15:03:34 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
Output from strace on gnome-session (23.57 KB, text/plain)
2010-05-14 15:36 UTC, Sean Sheedy
no flags Details
Output from patched sync.c (3.89 KB, text/plain)
2010-06-03 21:52 UTC, Sean Sheedy
no flags Details
more debug msg on Xext/sync.c (3.70 KB, text/plain)
2010-06-22 03:02 UTC, Tim Taiwanese Liim
no flags Details
Output from latest patched sync.c (18.47 KB, text/plain)
2010-06-26 01:35 UTC, Sean Sheedy
no flags Details
debug code, ver 3. (2.47 KB, text/plain)
2010-07-01 22:46 UTC, Tim Taiwanese Liim
no flags Details
Output from debug code, ver 3. (6.33 KB, text/plain)
2010-07-02 23:57 UTC, Sean Sheedy
no flags Details
debug code, ver 4. (1.26 KB, text/plain)
2010-07-09 21:12 UTC, Tim Taiwanese Liim
no flags Details
Output from debug code, ver 4. (8.73 KB, text/plain)
2010-07-12 02:37 UTC, Sean Sheedy
no flags Details
debug code version 5, inside SIGIO handler. (1.44 KB, text/plain)
2010-08-04 04:05 UTC, Tim Taiwanese Liim
no flags Details

Description Sean Sheedy 2010-05-12 23:54:31 UTC
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

Comment 1 Tim Taiwanese Liim 2010-05-13 01:32:21 UTC
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.

Comment 2 Tim Taiwanese Liim 2010-05-13 02:40:08 UTC
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.

Comment 3 Sean Sheedy 2010-05-13 15:28:30 UTC
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

Comment 4 Tim Taiwanese Liim 2010-05-13 21:16:48 UTC
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                                       ....              |

Comment 5 Sean Sheedy 2010-05-14 15:36:43 UTC
Created attachment 414091 [details]
Output from strace on gnome-session

Comment 6 Tim Taiwanese Liim 2010-05-14 16:58:51 UTC
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. |

Comment 7 Sean Sheedy 2010-05-14 20:47:54 UTC
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?

Comment 8 Tim Taiwanese Liim 2010-05-14 21:16:31 UTC
> 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.

Comment 9 Sean Sheedy 2010-05-17 23:53:56 UTC
I've built xorg-x11-server-Xorg from source and it behaves the same.

Comment 10 Tim Taiwanese Liim 2010-05-19 02:40:24 UTC
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);

Comment 11 Tim Taiwanese Liim 2010-05-19 02:42:50 UTC
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.

Comment 12 Tim Taiwanese Liim 2010-05-19 02:46:29 UTC
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.

Comment 13 Sean Sheedy 2010-06-03 21:52:00 UTC
Created attachment 421048 [details]
Output from patched sync.c

Comment 14 Tim Taiwanese Liim 2010-06-09 02:57:31 UTC
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.

Comment 15 Sean Sheedy 2010-06-11 20:17:46 UTC
(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.

Comment 16 Tim Taiwanese Liim 2010-06-17 04:13:06 UTC
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.

Comment 17 Tim Taiwanese Liim 2010-06-22 03:02:12 UTC
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)

Comment 18 Tim Taiwanese Liim 2010-06-22 03:06:05 UTC
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

Comment 19 Sean Sheedy 2010-06-26 01:35:45 UTC
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.

Comment 20 Tim Taiwanese Liim 2010-07-01 22:46:28 UTC
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.

Comment 21 Sean Sheedy 2010-07-02 23:57:51 UTC
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.

Comment 22 Tim Taiwanese Liim 2010-07-09 21:12:12 UTC
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

Comment 23 Sean Sheedy 2010-07-12 02:37:00 UTC
Created attachment 431051 [details]
Output from  debug code, ver 4.

Comment 24 Tim Taiwanese Liim 2010-07-12 03:13:13 UTC
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.

Comment 25 Tim Taiwanese Liim 2010-08-04 04:05:27 UTC
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

Comment 26 Tim Taiwanese Liim 2010-08-13 04:22:46 UTC
Sean,
By any chance do you have update on this bug?  Thanks.

Comment 27 Sean Sheedy 2010-08-13 04:42:31 UTC
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

Comment 28 Tim Taiwanese Liim 2010-08-13 19:03:14 UTC
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.

Comment 29 Sean Sheedy 2010-09-01 15:02:37 UTC
I haven't seen this bug since I upgraded to Fedora 13 over a month ago.  I'd consider this closed.


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