GNOME Bugzilla – Bug 311868
weird focus behavior
Last modified: 2008-03-23 23:45:19 UTC
I have two non-gnome applications open in a workspace (JabRef and acroread). Acroread is on the top with focus. I leave the workspace and come back - JabRef comes on top for no apparent reason. This is an annoying behavoir when you are using references in acrobat reader to work in another workspace. I have no idea if this is metacity's fault, or the pager, or even JabRef (a java application, if that helps).
Actually, the first time I come back to the original workspace acroread is still on top, but the focus has been given to JabRef (according to the window title colors). The second time I leave and come back to the workspace, JabRef comes on top.
Do you use focus-follows-mouse? How do you switch between workspaces? Using a keyboard shortcut?
No, I use the usual focus method. I can reproduce the behavior by switching with the mouse (pager applet) or keyboard shortcuts. I was also able to reproduce the same behavior with JabRef and evince (evince on top with focus, switch, switch back, focus goes to JabRef, switch, switch back, JabRef on top). So I guess the real bug comes from JabRef, but maybe something in gnome workspace switching triggers it...
Can you patch metacity with http://www.gnome.org/~newren/temp/development/debug-focus-2.11.1.patch, restart metacity from a terminal (use the '--replace' command line option), reproduce the bug, and attach the output here? (Also, Olav: It's better to ask for focus method, as there are two mouse-oriented focus policies--sloppy and mouse. And yes, I have seen bugs for each of the three focus policies (click being the non-mouse-oriented one) that affected none of the others. The questions you asked were definitely the right ones, though)
There you go. The evince window was entitled "PSC paper", the JabRef window "JabRef", both are on the second workspace. The "noel@miro" that appear is a terminal window I have on the first workspace. Window manager warning: window 0x3400003 (PSC-paper.) focused, last_focus_time set to 82859005 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82589259 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x3400003 (PSC-paper.) fw->net_wm_user_time : 82853195 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82831628 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x3400003 (PSC-paper.) fw->net_wm_user_time : 82853195 Window manager warning: COMPARISON: net_wm_user_time_set : 0 net_wm_user_time : 0 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x3400003 (PSC-paper.) fw->net_wm_user_time : 82853195 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 81613747 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x3400003 (PSC-paper.) fw->net_wm_user_time : 82853195 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82827610 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0xa00033 (JabRef) fw->net_wm_user_time : 0 Window manager warning: window 0x22027b1 (noel@miro:) focused, last_focus_time set to 82860522 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82589259 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82831628 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82789253 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82407826 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 81613747 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 0 net_wm_user_time : 0 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82589259 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0xa00033 (JabRef) fw->net_wm_user_time : 0 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82831628 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0xa00033 (JabRef) fw->net_wm_user_time : 0 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82853195 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0xa00033 (JabRef) fw->net_wm_user_time : 0 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 81613747 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0xa00033 (JabRef) fw->net_wm_user_time : 0 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82827610 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0xa00033 (JabRef) fw->net_wm_user_time : 0 Window manager warning: window 0x22027b1 (noel@miro:) focused, last_focus_time set to 82864461 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82589259 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82831628 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82789253 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 82407826 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: COMPARISON: net_wm_user_time_set : 1 net_wm_user_time : 81613747 initial_timestamp_set: 0 initial_timestamp : 0 Window manager warning: COMPARISON (continued): focus_window : 0x22027b1 (noel@miro:) fw->net_wm_user_time : 82827610 Window manager warning: Window 0x22027b1 (noel@miro:) has _NET_WM_USER_TIME of 82866558
Ugh...I forgot that I didn't have anything saying "Window X is being mapped" which makes that output not as useful unless you try to watch it at the same time you're interacting with all the windows so you know what's happening via different means. Sorry. Let's go for the big hammer instead of trying to whittle the output prematurely. Can you get a verbose debugging log? (go ahead and undo that patch I provided first) To do so: 1. Reduce your desktop to as few windows as possible to reproduce the bug 2. Run METACITY_VERBOSE=1 METACITY_USE_LOGFILE=1 metacity --replace 3. On stdout metacity will print the name of the logfile 4. Reproduce the bug as quickly as possible 5. Kill the metacity you started above to stop the logfile from growing any longer then attach the logfile here.
Created attachment 49892 [details] logfile Ok, here is the logfile. Boy that thing fills up really fast :-) I reproduced the bug with only two windows opened, one terminal (to relaunch metacity) and JabRef.
Do this: Run 'xprop | grep _NET_WM_USER_TIME', click on your terminal Run 'xprop | grep _NET_WM_USER_TIME', click on that JabRef program Click on the terminal (updates it's _NET_WM_USER_TIME) Run 'xprop | grep _NET_WM_USER_TIME', click on your terminal Click on the JabRef program Run 'xprop | grep _NET_WM_USER_TIME', click on that JabRef program _NET_WM_USER_TIME measures the xserver timestamp (milliseconds since X started, ignoring wraparound) of the last time you interacted with the program. From the log, it looks like you used JabRef at timestamp 1078080753 whereas you had last used your terminal at timestamp 84748613. Later in the same file, the _NET_WM_USER_TIME of the terminal gets updated to 84753916. So, at the time it was mapping JabRef on your workspace switch, your terminal had last been used about a day after X started on your machine. The later update of the terminal in the log file is about 5 seconds after that. Since that's an update and the terminal isn't a funky program, we can pretty reliably trust that as the correct time. JabRef's timestamp is about 12 and a half days after your X server started. Naturally, since you used JabRef eleven and a half days into the future, you had used it more recently than the terminal. Is there any chance that you have had your Xserver up for about 51 days or so (1 day + how long it takes timestamps to wrap around) and that you haven't used the JabRef program for the last 40 of them? I'm guessing no, so the question is--how did it get such a timestamp? ('xprop -spy' might be useful in figuring it out...) Since it's almost certainly an app bug, do we need to be able to detect such apps better and workaround them? *sigh*
When I run xprop | grep _NET_WM_USER_TIME and click on the terminal, I get stuff like _NET_WM_USER_TIME(CARDINAL) = 1441047 When I run the same command and click on JabRef, I get nothing. I tried xprop -spy on JabRef, here is the output : _MOTIF_DRAG_RECEIVER_INFO(_MOTIF_DRAG_RECEIVER_INFO) = 0x6c, 0x0, 0x5, 0x0, 0x33 , 0x0, 0xc0, 0x2, 0x0, 0x0, 0x0, 0x0, 0x10, 0x0, 0x0, 0x0 XdndAware(ATOM) = BITMAP _NET_WM_ICON_GEOMETRY(CARDINAL) = 423, 936, 191, 24 XKLAVIER_STATE(INTEGER) = 0, 0 WM_STATE(WM_STATE): window state: Normal icon window: 0x0 _NET_FRAME_EXTENTS(CARDINAL) = 5, 5, 22, 5 _NET_WM_DESKTOP(CARDINAL) = 1 _MOTIF_WM_HINTS(_MOTIF_WM_HINTS) = 0x3, 0x1, 0x1, 0x0, 0x18 WM_ICON_NAME(STRING) = "JabRef" _NET_WM_STATE(ATOM) = WM_HINTS(WM_HINTS): Client accepts input or input focus: False Initial state is Normal State. bitmap id # to use for icon: 0x2c00037 window id # to use for icon: 0x2c00039 WM_NORMAL_HINTS(WM_SIZE_HINTS): user specified location: 258, 25 program specified location: 258, 25 program specified size: 864 by 851 window gravity: NorthWest WM_PROTOCOLS(ATOM): protocols WM_DELETE_WINDOW, WM_TAKE_FOCUS WM_CLASS(STRING) = "sun-awt-X11-XFramePeer", "net-sf-jabref-JabRef" WM_CLIENT_LEADER(WINDOW): window id # 0x2c00007 WM_NAME(STRING) = "JabRef" I'm not really sure what to make out of this.
I am puzzled to report that the exact same behavior (even the xprop thing) happens with JDiskReport (available at http://www.jgoodies.com/) and jEdit (www.jedit.org). The latter is a pretty popular program. JabRef and JDiskReport are both java applications, contained in a jar file (launched with java -jar jdiskreport-1.2.1.jar, for example). So I guess this is a bug common to java applications which do not set their timestamp.
[Mid-air collision] No, apps are supposed to update their own _NET_WM_USER_TIME but not all apps yet support the spec. And, this bug shouldn't happen just because apps don't update their _NET_WM_USER_TIME. Since some apps don't, Metacity tries to update it's internal variable for this when it can so things can work as well as possible. There are basically three ways that Metacity's internal timestamp variable (window->net_wm_user_time) can be updated right now--metacity detects that you click on the app, the app updates its own time, or a _NET_ACTIVE_WINDOW message is sent. Since the app isn't updating its own time, it must be that someone is sending a _NET_ACTIVE_WINDOW message for your JabRef program with a retarded timestamp. But, it kind of puzzles me because I just realized/remembered that sanity_check_timestamps is supposed to be checking for this already for us in quite a few circumstances. Are there just a lot of _NET_ACTIVE_WINDOW messages being sent? Hmmm...I'll have to provide you with a patch to help me debug; I'll try to get something before too long.
We should change the user time stuff to have a cutoff; i.e. let apps steal focus if the timestamp difference is large. Cause you're really not going to be upset when an app steals focus when you haven't typed into your gnome terminal for (say) 30 seconds.
Created attachment 57499 [details] [review] Add some debugging information Sorry for disappearing off the face of the planet there. Anyway, can you try again after patching metacity with this patch? (If the display.h parts of the patch conflict, it means another patch in bugzilla was accepted that had part of the same patch and you can just ignore the conflict) Run it with 'metacity --replace' in a terminal so that you can watch for warnings there. There will be some warnings when metacity restarts (1 per unused window in the last minute that you have open), which you can ignore. The interesting warnings will be the ones that occur after it's done restarting and you start interacting with other apps. Thanks for your patience...
(Something that just occurred to me that we might want to also check later: It may be that the app is being really stupid and generating ButtonPresses through XSendEvent but with bogus timestamps -- much like another bug report in here with a command line program called xse or something)
(patch isn't meant to be applied, just used for testing; kicking it off the unreviewed list...)
Was this bug fixed by this patch 2006-08-07 Elijah Newren <newren gmail com> * src/window.c (intervening_user_event_occurred): Vytautus Liuolia totally rocks; he tested and debugged and tracked down where we were using the focus window's net_wm_user_time even when it was uninitialized. This may fix bug 311868 and others I've heard about (with Valknut, IIRC). It definitely fixes the issues Vytas was seeing with his single instance library. :-) Just applied today? (You'll need CVS HEAD; or wait until 2.15.34 or later is released)
(In reply to comment #12) > We should change the user time stuff to have a cutoff; i.e. let apps steal focus > if the timestamp difference is large. Cause you're really not going to be upset > when an app steals focus when you haven't typed into your gnome terminal for > (say) 30 seconds. What about if I'm watching a movie in Totem? Or maybe I'm watching an ASCII movie in G-T? :P
Vincent: this bug has been in NEEDINFO for two years asking whether you're still seeing the bug with the patch that Elijah thought would fix it. I'm closing the bug as obsolete; if you're still seeing it, please do reopen.