Created attachment 145446 [details]
Debug output from gnome-screensaver leading up to the crash

We've just committed a change in Ubuntu which fixes this issue: http://bazaar.launchpad.net/~ubuntu-desktop/gnome-screensaver/ubuntu/revision/42#debian/patches/08_gs_dialog_request_to_exit.patch

Basically, what is happening is that gnome-screensaver-dialog exits after the 5th failed attempt at unlocking the screen, but before the shake animation finishes. If the timing is slightly unlucky, this results in gnome-screensaver accessing X resources that have already been destroyed (I ran it through xtrace, and that showed this happening)

My patch fixes this by making gnome-screensaver-dialog request to gnome-screensaver that it be terminated after the 5th failed attempt (rather than exitting straight away, although there is a fallback timeout too). gnome-screensaver then terminates the dialog after it is finished with the shake animation, to avoid the race condition that is currently making it crash.

Wouldn't it be much simpler to just ignore X errors in the shaker ?

It would be simpler - but you still occasionally end up with quite a few g_critical messages on the console if you do it this way (although I can't tell you exactly what they are yet until I trigger it again).

The method I've used avoids this, and also means that the dialog only disappears after the shaker has finished (although that is mainly cosmetic)

Can you please attach the patch here for review.  It doesn't look quite right to me.

don't you need to queue a SIGTERM after the shake finishes if the request comes in while the shake is happening?  Also, I don't think this makes sense:

+ g_timeout_add (5000, (GSourceFunc)quit_timeout_cb, NULL);

There's no reason to second guess the daemon.

Also, we should have the gdk_error_trap_push/gdk_display_sync/gdk_error_trap_pop calls comment 3 alluded to regardless for general robustness reasons.

Created attachment 146788 [details] [review]
gs_dont_crash_on_invalid_password.patch

Here is the version of the patch which is currently applied in Ubuntu.

+ g_timeout_add (5000, (GSourceFunc)quit_timeout_cb, NULL);

This part was added to handle upgrades where the user might be running the old daemon but have a new gnome-screensaver-dialog process. Without this, the user is left with a hung dialog if they enter their password incorrectly 5 times after they upgraded, but before restarting their session.

I agree that we should probably have the gdk_error_trap_push/gdk_display_sync/gdk_error_trap_pop in addition to the change I've already made.

I removed the SIGTERM handler in our Ubuntu patch, as that caused other issues (such as the dialog hanging when it times out)

So looking at this further, I think we may be missing the boat here.  Or at least, not entirely understanding the problem.

Trace 218314

shows the BadDrawable is a locally created pixmap that's internal to gtk, used for its expose handling.

Also, if you look at the more complete trace in launchpad (http://paste.ubuntu.com/293307/):

+ Trace 219456

it shows the pixmap being passed to XFreePixmap is bogus

That leads me to think we're dealing with some sort of memory corruption here.

Note I've spent some time trying to reproduce and have been unable to do so, so far.  

I also tried to induce the original race condition by adding sleep statements in the expose handler, by removing the sleeps in the shake function, by making it shaking indefinitly instead of 9 times, and by making the lock dialog exit after 1 failure instead of 5.

I also ran the screensaver through valgrind and haven't hit any issues yet.  Chris, can you:

1) try backing out your patch
2) make sure you can still reproduce the problem
3) export G_SLICE=always-malloc
4) run valgrind --log-file=/tmp/screensaver.log gnome-scrensaver --no-daemon
5) reproduce

and see if the valgrind log shows anything?

Created attachment 149284 [details]
xtrace log

As discussed on IRC, here is a xtrace log I saved when initially debugging this issue some time ago. It's quite big, so I'll pick out the interesting bits here (and sorry for the compression, but it was the only way I could get it to below 100kB):

The errors that make it crash can be seen at the end of the file:

000:<:06be: 16: Request(53): CreatePixmap depth=0x18 pid=0x02e000fe drawable=0x05400020 width=550 height=362
000:<:06bf:  8: Request(54): FreePixmap drawable=0x02e000fe
000:<:06c0: 16: Request(2): ChangeWindowAttributes window=0x02e00024  value-list={cursor=None(0x00000000)}
000:<:06c1: 16: Request(2): ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=None(0x00000000)}
000:<:06c2:  8: Request(10): UnmapWindow window=0x02e00060
000:<:06c3: 16: Request(2): ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=0x02e0004e}
000:<:06c4: 16: Request(2): ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=None(0x00000000)}
000:<:06c5:  8: Request(10): UnmapWindow window=0x02e00060
000:<:06c6: 16: Request(2): ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=0x02e0004e}
000:<:06c7: 16: Request(2): ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=None(0x00000000)}
000:<:06c8: 16: SHAPE-Request(141,1): ShapeRectangles operation=Set(0x00) destination kind=Bounding(0x00) ordering=YXBanded(0x03) destination window=0x02e00060 x-offset=0 y-offset=0 rectangles=;
000:<:06c9: 16: Request(2): ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=0x02e0004e}
000:<:06ca:  8: Request(4): DestroyWindow window=0x02e00060
000:<:06cb: 16: Request(53): CreatePixmap depth=0x18 pid=0x02e000ff drawable=0x02e00024 width=1680 height=1050
000:<:06cc: 28: Request(55): CreateGC cid=0x02e00100 drawable=0x02e000ff  values={fill-style=Tiled(0x01) tile=0x02e0004e graphics-exposures=false(0x00)}
000:<:06cd: 20: Request(59): SetClipRectangles ordering=YXBanded(0x03) gc=0x02e00100 clip-x-origin=0 clip-y-origin=0 rectangles ={x=0 y=0 w=1680 h=1050};
000:<:06ce: 20: Request(70): PolyFillRectangle drawable=0x02e000ff gc=0x02e00100 rectangles={x=0 y=0 w=1680 h=1050};
000:<:06cf:  8: Request(60): FreeGC gc=0x02e00100
000:<:06d0: 16: Request(2): ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=0x02e0004e}
000:<:06d1: 28: Request(55): CreateGC cid=0x02e00101 drawable=0x02e000ff  values={fill-style=Tiled(0x01) tile=0x02e0004e graphics-exposures=false(0x00)}
000:<:06d2: 20: Request(59): SetClipRectangles ordering=YXBanded(0x03) gc=0x02e00101 clip-x-origin=0 clip-y-origin=0 rectangles ={x=0 y=0 w=1680 h=1050};
000:<:06d3: 20: Request(70): PolyFillRectangle drawable=0x02e000ff gc=0x02e00101 rectangles={x=0 y=0 w=1680 h=1050};
000:<:06d4:  8: Request(60): FreeGC gc=0x02e00101
000:<:06d5: 20: Request(59): SetClipRectangles ordering=YXBanded(0x03) gc=0x02e00056 clip-x-origin=0 clip-y-origin=0 rectangles ={x=0 y=0 w=1680 h=1050};
000:<:06d6: 28: Request(62): CopyArea src-drawable=0x02e000ff dst-drawable=0x02e00024 gc=0x02e00056 src-x=0 src-y=0 dst-x=0 dst-y=0 width=1680 height=1050
000:<:06d7: 16: Request(56): ChangeGC gc=0x02e00056  values={clip-mask=None(0x00000000)}
000:<:06d8:  8: Request(54): FreePixmap drawable=0x02e000ff
000:>:6be:Error 9=Drawable: major=0, minor=53, bad=88080416
000:>:6bf:Error 4=Pixmap: major=0, minor=54, bad=48234750

The first bad call is a CreatePixmap, which passes drawable=0x05400020. If you look above this in the log file, you will see that the server already sent out a DestroyNotify for this drawable:

000:>:06af: Event UnmapNotify(18) event=0x05400020 window=0x05400020 from-configure=false(0x00)
000:>:06af: Event UnmapNotify(18) event=0x02e00060 window=0x05400020 from-configure=false(0x00)
000:>:06af: Event Expose(12) window=0x02e00060 x=0 y=0 width=550 height=362 count=0x0000
000:>:06af: Event EnterNotify(7) detail=Inferior(0x02) mode=Normal(0x00) flags=same-screen time=0x02809425 root=0x0000013c event=0x02e00060 child=None(0x00000000) root-x=921 root-y=685 event-x=371 event-y=341 state=Mod2
000:>:06af: Event DestroyNotify(17) event=0x05400020 window=0x05400020
000:>:06af: Event DestroyNotify(17) event=0x02e00060 window=0x05400020

Looking further up in the log file, this particular drawable was created here:

003:<:00cc:  8: Request(17): GetAtomName atom=0xc7(unrecognized atom)
003:>:00cc:44: Reply to GetAtomName:  name='Mouse Keys'
003:<:00cd: 52: Request(1): CreateWindow depth=0x18 window=0x05400020 parent=0x0000013c x=0 y=0 width=1 height=1 border-width=0 class=InputOutput(0x0001) visual=0x00000021  value-list={background-pixel=0x00000000 border-pixel=0x00000000 bit-gravity=NorthWest(0x01) event-mask=KeyPress,KeyRelease,ButtonPress,ButtonRelease,EnterWindow,LeaveWindow,PointerMotion,Exposure,VisibilityChange,StructureNotify,PropertyChange colormap=0x00000020}
003:<:00ce: 48: Request(18): ChangeProperty mode=Replace(0x00) window=0x05400020 property=0x100("_NET_WM_NAME") type=0xf1("UTF8_STRING")     data=0x67,0x6e,0x6f,0x6d,0x65,0x2d,0x73,0x63,0x72,0x65,0x65,0x6e,0x73,0x61,0x76,0x65,0x72,0x2d,0x64,0x69,0x61,0x6c,0x6f,0x67;
003:<:00cf: 48: Request(18): ChangeProperty mode=Replace(0x00) window=0x05400020 property=0x27("WM_NAME") type=0x1f("STRING")    data='gnome-screensaver-dialog'
003:<:00d0: 48: Request(18): ChangeProperty mode=Replace(0x00) window=0x05400020 property=0xff("_NET_WM_ICON_NAME") type=0xf1("UTF8_STRING")     data=0x67,0x6e,0x6f,0x6d,0x65,0x2d,0x73,0x63,0x72,0x65,0x65,0x6e,0x73,0x61,0x76,0x65,0x72,0x2d,0x64,0x69,0x61,0x6c,0x6f,0x67;

The numbers on the left there indicate that these calls were from a different process, and the ChangeProperty calls show that gnome-screensaver-dialog created this window.

Basically, what seems to be happening is that the GdkWindow passed to gdk_window_process_updates_internal() is actually the newly destroyed foreign window belonging to gnome-screensaver-dialog, and this is where the 2 failed calls shown in the xtrace log come from (CreatePixmap in gdk_window_begin_implicit_paint, and FreePixmap in gdk_window_end_implicit_paint).

> CreateWindow depth=0x18 window=0x02e00024 parent=0x0000013c x=0 y=0 width=1680 height=1050 border-width=0 class=InputOutput(0x0001) visual=0x00000021  value-list={background-pixel=0x00000000 border-pixel=0x00000000 bit-gravity=NorthWest(0x01) override-redirect=true(0x01) save-under=true(0x01) event-mask=KeyPress,KeyRelease,ButtonPress,ButtonRelease,EnterWindow,LeaveWindow,PointerMotion,Exposure,VisibilityChange,StructureNotify,FocusChange,PropertyChange colormap=0x02e00023}
> ChangeProperty mode=Replace(0x00) window=0x02e00024 property=0x100("_NET_WM_NAME") type=0xf1("UTF8_STRING")     data=0x67,0x6e,0x6f,0x6d,0x65,0x2d,0x73,0x63,0x72,0x65,0x65,0x6e,0x73,0x61,0x76,0x65,0x72;
> ChangeProperty mode=Replace(0x00) window=0x02e00024 property=0x27("WM_NAME") type=0x1f("STRING")    data='gnome-screensaver'

So 0x02e00024 is the fullscreen screensaver window

[...]
> CreateWindow depth=0x18 window=0x05400020 parent=0x0000013c x=0 y=0 width=1 height=1 border-width=0 class=InputOutput(0x0001) visual=0x00000021  value-list={background-pixel=0x00000000 border-pixel=0x00000000 bit-gravity=NorthWest(0x01) event-mask=KeyPress,KeyRelease,ButtonPress,ButtonRelease,EnterWindow,LeaveWindow,PointerMotion,Exposure,VisibilityChange,StructureNotify,PropertyChange colormap=0x00000020}
[...]
> ChangeProperty mode=Replace(0x00) window=0x05400020 property=0x27("WM_NAME") type=0x1f("STRING")    data='gnome-screensaver-dialog'
And 0x05400020 is the lock dialog running in a subprocess.

[...]
> CreateWindow depth=0x18 window=0x02e00060 parent=0x02e00024 x=-1 y=-1 width=1 height=1 border-width=0 class=InputOutput(0x0001) visual=0x00000021  value-list={background-pixel=0x00e6ddd5 border-pixel=0x00000000 bit-gravity=NorthWest(0x01) event-mask=EnterWindow,LeaveWindow,Exposure,VisibilityChange,StructureNotify,FocusChange,PropertyChange colormap=0x02e00023}
Here we create a child of the fullscreen screensaver window

[...]
> ReparentWindow window=0x05400020 parent=0x02e00060 x=0 y=0
> InternAtom only-if-exists=false(0x00)  name='_XEMBED_INFO'
And here we reparent the lock dialog from the subprocess into that child of the fullscreen window.
This means the child of the fullscreen screensaver window (0x02e00060) is a gtk socket.

So now we know who the players are:
0x02e00024 - fullscreen screensaver window
0x02e00060 - gtk socket in the parent
0x05400020 - lock dialog plug

[...]
> CreatePixmap depth=0x18 pid=0x02e000fb drawable=0x02e00024 width=1680 height=1050
Here we create a backing pixmap 0x02e000fb for the fullscreen screensaver window

[...]
> PolyFillRectangle drawable=0x02e000fb gc=0x02e000fc rectangles={x=0 y=0 w=1680 h=1050};
[...]
> PolyFillRectangle drawable=0x02e000fb gc=0x02e000fd rectangles={x=0 y=0 w=1680 h=1050};
Here we fill the backing pixmap with data

[...]
> CopyArea src-drawable=0x02e000fb dst-drawable=0x02e00024 gc=0x02e00056 src-x=0 src-y=0 dst-x=0 dst-y=0 width=1680 height=1050
[...]
> FreePixmap drawable=0x02e000fb
Here we copy the data from the backing pixmap to the fullscreen screensaver window and then free
the backing pixmap, so this was just a bit of double buffered drawing.

[...]
> CreatePixmap depth=0x18 pid=0x02e0004e drawable=0x02e00024 width=1 height=1
> CreateGC cid=0x02e0004f drawable=0x02e0004e  values={graphics-exposures=false(0x00)}
> PolyPoint coordinate-mode=Origin(0x00) drawable=0x02e0004e gc=0x02e0004f points={x=0 y=0};
Here we create a 1x1 solid tile pixmap that gets used later

[...]
> CreatePixmap depth=0x18 pid=0x02e000fe drawable=0x05400020 width=550 height=362
Here we create (from the parent process) a backing pixmap 0x2e000fe for the
lock dialog plug (which is running in the child process)

> FreePixmap drawable=0x02e000fe
Here we immediately free the backing pixmap.  Note we did no double buffered drawing,
at all.  This sort of makes sense.  The child is doing the drawing not us.  GTK+ probably
shouldn't have made the back pixmap in the first place, though.

[...]
> ChangeWindowAttributes window=0x02e00024  value-list={cursor=None(0x00000000)}
> ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=None(0x00000000)}
Here we're messing around with the screensaver window again, not fooling with the lock dialog anymore
> UnmapWindow window=0x02e00060
> ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=0x02e0004e}
> ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=None(0x00000000)}
Here we unmap the socket.  We must have gotten a lock-plug-removed signal.
The handler for that does:

        gtk_widget_hide (widget);

which would ultimately cause an UnmapWindow.

> UnmapWindow window=0x02e00060
> ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=0x02e0004e}
> ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=None(0x00000000)}
rinse and repeat? Huh?

> ShapeRectangles operation=Set(0x00) destination kind=Bounding(0x00) ordering=YXBanded(0x03) destination window=0x02e00060 x-offset=0 y-offset=0 rectangles=;
Then we set the shape of the socket window to be empty (no rectangles in the list),
even though it's unmapped.  I think this means if it were mapped again it wouldn't show up
at all.  That's sort of strange, but it's probably some subtle toolkit magic to
prevent some misbehavior from happening or something.  Maybe it's a workaround for a
buggy window manager.  I'm not sure.  I dont' think it's related to our problem, though.

> ChangeWindowAttributes window=0x02e00024  value-list={background-pixmap=0x02e0004e}
> DestroyWindow window=0x02e00060
We now explicitly destroy the socket window.  That's probably from this line in the
lock-plugin-removed handler:

        gtk_container_remove (GTK_CONTAINER (window->priv->vbox),
                              GTK_WIDGET (window->priv->lock_box));

We remove the socket from the parent window, which drops the socket's ref count to 0, causing
the socket to get destroyed.

> CreatePixmap depth=0x18 pid=0x02e000ff drawable=0x02e00024 width=1680 height=1050
[...]
> PolyFillRectangle drawable=0x02e000ff gc=0x02e00100 rectangles={x=0 y=0 w=1680 h=1050};
[...]
> PolyFillRectangle drawable=0x02e000ff gc=0x02e00101 rectangles={x=0 y=0 w=1680 h=1050};
[...]
> CopyArea src-drawable=0x02e000ff dst-drawable=0x02e00024 gc=0x02e00056 src-x=0 src-y=0 dst-x=0 dst-y=0 width=1680 height=1050
> FreePixmap drawable=0x02e000ff
We do another round of double-buffered drawing to the fullscreen screensaver window

At this point we must have gone back to the main loop because the next line says ...

> Error 9=Drawable: major=0, minor=53, bad=88080416
Uh oh, X error.  88080416 is 0x5400020 in hex, that's our lock dialog plug
minor=53 is CreatePixmap

> Error 4=Pixmap: major=0, minor=54, bad=48234750
Uh oh, another X error.  48234750 is 0x02e000fe in hex, thats the backing pixmap
for the lock dialog plug we created and free'd immediately afterward without doing anything
to it.

minor=54 is FreePixmap

So the FreePixmap request is failing because the CreatePixmap request failed initially.

Okay, so the problem is gtk is calling CreatePixmap and passing in a foreign drawable that
no longer exists.  Let's look at the code probably at fault:

static void
gdk_window_process_updates_internal (GdkWindow *window)
{
   ...
   end_implicit = gdk_window_begin_implicit_paint (window, &clipbox) {
       ...
       paint->pixmap = gdk_pixmap_new (window, clipbox->width, clipbox->height, -1) {
           ...
           pixmap->xid = XCreatePixmap (display, window, clipbox->width, clipbox->height, -1);
           pixmap->is_foreign = FALSE;
           ...
           return pixmap;
       }
       ...
       return paint;
   }
   ...
   gdk_window_end_implicit_paint (window) {
       ...
       g_object_unref (paint->pixmap) {
           ...
           if (!pixmap->is_foreign) {
              XFreePixmap (display, pixmap->xid);
           }
           ...
       }
   }
   ...
}

So the socket's plug window must be getting added to the list of windows to process by
gdk_window_process_updates_internal.  I don't know if that's right or not.

If it is right, maybe it should have a if (FOREIGN) gdk_error_trap pop / push wrapping the function.

Or maybe this is just something we're supposed to deal with on the screensaver side.  Alex, do you have any insight here?

I found alex, conversation below:

<halfline> alex: basically the screensaver has a lock dialog plug that fits into a socket in the fullscreen screensaver window
<halfline> alex: if the lock dialog process quits, the plug disappears           
<halfline> alex: if that happens under the right circumstances then gtk will generate an X error becuase it's trying to create a backing pixmap using the plug as a reference drawable
<halfline> alex: so i'm wondering 1) should gtk avoid using a foreign window as a reference drawable for the implicit paint pixmap ?
<halfline> 2) if not, should it add its own guards against that foreign window going away
<halfline> or                                                                
<halfline> should gnome-screensaver just deal                                
<alex> If the user specifies exposure events in the foreign window it'll get events and the will trigger the double buffering
<alex> gtk+ should handle this but i don't which of 1) or 2) is the best 
<alex> Technically i guess the child foreign window could have a different visual
<alex> which seems to imply that we want to do 2?
<halfline> sounds reasonable to me, but i'm probably not the best person to ask            
* alex is sort of busy right now so can't look into it in more detail at the moment                       
<halfline> okay, i'll paste this into the bug report
<halfline> what i really want to find out i guess is who is affected
<halfline> i'll dig a bit
<alex> how did it not happen before?
<alex> i guess the double buffering stuff changed
<halfline> everyone who's seen it has been running 2.18 afaict

Created attachment 149335 [details] [review]
Possible gtk fix

I think an easy solution might be to not do implicit painting for foreign windows, as its risky and is not useful.

Looks like a good idea to me.

Shouldn't someone with the appropriate privileges change "Product" to gtk+?

Comment on attachment 149335 [details] [review]
Possible gtk fix

This has been committed a while ago

I dropped the Ubuntu patch for gnome-screensaver some time ago, and we have the GTK version with the above commit in. I don't see this crash any more (and I've not seen anybody report the issue again), so I'm closing this as fixed now. Thanks!

*** Bug 603652 has been marked as a duplicate of this bug. ***

Comment on attachment 146788 [details] [review]
gs_dont_crash_on_invalid_password.patch

FWIW, mccann commited your patch about a week ago:

http://git.gnome.org/browse/gnome-screensaver/commit/?id=ab08cc93f2dc6223c8c00bfa1ca4f2d89069dbe0