various apps abort on assertion - g_file_monitor_source_handle_event: code should not be reached

[Glebushka]

I was opening "War Thunder"- Steam game and when I changed settings in game and it restarted I saw also in desktop error-message. I do not remember did I have anything from "nautilus" open.

ProblemType: Crash
DistroRelease: Ubuntu 15.10
Package: nautilus 1:3.14.2-0ubuntu10
ProcVersionSignature: Ubuntu 4.2.0-7.7-generic 4.2.0
Uname: Linux 4.2.0-7-generic x86_64
NonfreeKernelModules: nvidia
ApportVersion: 2.18.1-0ubuntu1
Architecture: amd64
CurrentDesktop: Unity
Date: Fri Sep 11 22:00:01 2015
ExecutablePath: /usr/bin/nautilus
GsettingsChanges:

InstallationDate: Installed on 2015-09-11 (0 days ago)
InstallationMedia: Ubuntu 15.10 "Wily Werewolf" - Alpha amd64 (20150910)
ProcCmdline: nautilus -n
Signal: 6
SourcePackage: nautilus
StacktraceTop:
 g_assertion_message () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
 g_assertion_message_expr () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
 g_file_monitor_source_handle_event () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
 ?? () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
 ?? () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
Title: nautilus crashed with SIGABRT in g_assertion_message()
UpgradeStatus: No upgrade log present (probably fresh install)
UserGroups: adm cdrom dip lpadmin plugdev sambashare saned scanner sudo

[aaronfranke (arnfranke)]

Line 430 of gio/glocalfilemonitor.c doesn't handle case G_FILE_MONITOR_EVENT_MOVED, crashing many programs.

The list of programs affected includes but is not limited to:

xfdesktop https://bugs.launchpad.net/ubuntu/+source/xfdesktop4/+bug/1598360

pcmanfm https://bugs.launchpad.net/ubuntu/+source/pcmanfm/+bug/1598488

and caja https://bugs.launchpad.net/ubuntu/+source/caja/+bug/1598359

The affected code can be found at https://github.com/GNOME/glib/blob/master/gio/glocalfilemonitor.c and looks like this:

  switch (event_type)
    {

    (other conditions are located here)

    case G_FILE_MONITOR_EVENT_MOVED:
      /* was never available in this API */
    default:
      g_assert_not_reached ();
    }

This matches with the g_assertion_message() crash that these programs are experiencing. So, I think we've found the culprit, and the solution would be to do something to handle case G_FILE_MONITOR_EVENT_MOVED so that these programs do not crash. Alternatively, if this API function should never be used, then the maintainers of these programs should be notified of this easily reproducible bug and be shown how to fix it. Right now, many packages that come default on major distros such as Ubuntu flavors are completely broken.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[aaronfranke (arnfranke)]

Upstream bug: https://bugzilla.gnome.org/show_bug.cgi?id=776147

[Bugzilla-tecnocode (bugzilla-tecnocode)]

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

[Robert Ayrapetyan (robert-ayrapetyan)]

Why not to move:
case G_FILE_MONITOR_EVENT_MOVED:

under:
case G_FILE_MONITOR_EVENT_RENAMED:

so they will handle same way (because they are *almost* same right?). G_FILE_MONITOR_EVENT_RENAMED branch even operates with names like "G_FILE_MONITOR_WATCH_MOVES" and "G_FILE_MONITOR_SEND_MOVED" internally.

Apparently "was never available in this API" is not true because of the list of affected apps.

[Bugzilla-tecnocode (bugzilla-tecnocode)]

Created attachment 363349
kqueue: Fix invalid emission of G_FILE_MONITOR_EVENT_MOVED event

That event is deprecated, and the kqueue backend can’t provide enough
information to go alongside the event (i.e. the name of the new file).
Use G_FILE_MONITOR_EVENT_DELETED instead.

Quite disappointed in the kqueue documentation for this: I cannot find a
single piece of documentation or example about how NOTE_RENAME is
supposed to communicate the new name of the file.

If it turns out that this is possible, the code can be amended again in
future. At least now it doesn’t abort.

Signed-off-by: Philip Withnall <email address hidden>

[Bugzilla-tecnocode (bugzilla-tecnocode)]

(In reply to Robert from comment #2)
> Why not to move:
> case G_FILE_MONITOR_EVENT_MOVED:
>
> under:
> case G_FILE_MONITOR_EVENT_RENAMED:
>
> so they will handle same way (because they are *almost* same right?).
> G_FILE_MONITOR_EVENT_RENAMED branch even operates with names like
> "G_FILE_MONITOR_WATCH_MOVES" and "G_FILE_MONITOR_SEND_MOVED" internally.

Because that would be fixing the symptom of the problem, rather than the underlying cause. This problem hasn’t been fixed already because nobody’s found time to investigate it yet.

> Apparently "was never available in this API" is not true because of the list
> of affected apps.

I just spent a bit of time looking into it, and it seems this is caused by the kqueue backend sending through an invalid event. I’ve attached a patch for that.

If you weren’t using FreeBSD (or another system which uses kqueue, like OS X), please let me know. There’s a potential bug in the inotify backend where a -1 return value from ih_mask_to_EventFlags() can be passed through to g_file_monitor_source_handle_event(), but I’m not 100% sure that’s possible due to other checks beforehand.

[Robert Ayrapetyan (robert-ayrapetyan)]

Hm, I though this ticket was initially regarding Linux distros (there was an Ubuntu mentioned in the initial description), I doubt it was an Ubuntu based on BSD kernel, it's very rare...
Thanks for the fix!

[aaronfranke (arnfranke)]

The bugs occur for me on Xubuntu 16.04 LTS, which is Linux. If this patch is only for BSD and OSX then it won't solve the problem on Linux.

I do think it's strange that programs would use it if it was never available.

[Robert Ayrapetyan (robert-ayrapetyan)]

With all that said, I would revert subject back to what it was (unrelated to kqueue), and extend affected OSes list.

[Bugzilla-tecnocode (bugzilla-tecnocode)]

Right.

Here’s an actual backtrace from a Linux system, retrieved from Launchpad: https://launchpadlibrarian.net/217269912/Stacktrace.txt. I’ll try and find time to take a look at this next week, but given that the inotify event details are not in the backtrace, any fix I come up with is going to be an educated guess.

#0 0x00007fd1bf60b267 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:55
        resultvar = 0
        pid = 1816
        selftid = 1863
#1 0x00007fd1bf60ceca in __GI_abort () at abort.c:89
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x7fd1ac001610, sa_sigaction = 0x7fd1ac001610}, sa_mask = {__val = {145, 140538850251488, 140538910469920, 140538650802016, 140538510579216, 145, 140538850251488, 140538650802144, 140538853953248, 0, 140538836002972, 0, 131072, 0, 0, 140538510573568}}, sa_flags = 1184, sa_restorer = 0x1}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2 0x00007fd1c0152ed5 in g_assertion_message (domain=domain@entry=0x7fd1c0749738 "GLib-GIO", file=file@entry=0x7fd1c0778cb0 "/build/glib2.0-hcw3A1/glib2.0-2.45.7/./gio/glocalfilemonitor.c", line=line@entry=433, func=func@entry=0x7fd1c0778ee0 <__func__.24251> "g_file_monitor_source_handle_event", message=message@entry=0x7fd1ac0015b0 "code should not be reached") at /build/glib2.0-hcw3A1/glib2.0-2.45.7/./glib/gtestutils.c:2429
        lstr = "433\000\000\000\000\000\016\245e\277\321\177\000\000 \034\327\000\000\000\000\000\033\000\000\000\000\000\000"
        s = 0x7fd1ac001610 "GLib-GIO:ERROR:/build/glib2.0-hcw3A1/glib2.0-2.45.7/./gio/glocalfilemonitor.c:433:g_file_monitor_source_handle_event: code should not be reached"
#3 0x00007fd1c0152f6a in g_assertion_message_expr (domain=domain@entry=0x7fd1c0749738 "GLib-GIO", file=file@entry=0x7fd1c0778cb0 "/build/glib2.0-hcw3A1/glib2.0-2.45.7/./gio/glocalfilemonitor.c", line=line@entry=433, func=func@entry=0x7fd1c0778ee0 <__func__.24251> "g_file_monitor_source_handle_event", expr=expr@entry=0x0) at /build/glib2.0-hcw3A1/glib2.0-2.45.7/./glib/gtestutils.c:2444
        s = 0x7fd1ac0015b0 "code should not be reached"
#4 0x00007fd1c073ed82 in g_file_monitor_source_handle_event (fms=0xd71c20, event_type=4294967295, child=0x7fd1ac001250 ".warThunderProps.eblk", rename_to=rename_to@entry=0x0, other=other@entry=0x0, event_time=15808271055) at /build/glib2.0-hcw3A1/glib2.0-2.45.7/./gio/glocalfilemonitor.c:433
        interesting = 1
        __func__ = "g_file_monitor_source_handle_event"
#5 0x00007fd1c0744b7d in ih_event_callback (event=0x7fd1ac001460, sub=0xd7a800, file_event=<optimized out>) at /build/glib2.0-hcw3A1/glib2.0-2.45.7/./gio/inotify/inotify-helper.c:201
        interesting = <optimized out>
        __func__ = "ih_event_callback"
#6 0x00007fd1c0743fd8 in ip_event_dispatch (dir_list=dir_list@entry=0x7fd1a80092a0, file_list=0x0, event=event@entry=0x7fd1ac001460) at /build/glib2.0-hcw3A1/glib2.0-2.45.7/./gio/inotify/inotify-path.c:493
        sub = 0xd7a800
        subl = 0x7fd1a80092e0
        dir = 0xd31d50
        interesting = 0
        l = 0x7fd1a80092a0
#7 0x00007fd1c07441a6 in ip_event_callback (event=event@entry=0x7fd1ac001460) at /build/glib2.0-hcw3A1/gl...

[Bugzilla-tecnocode (bugzilla-tecnocode)]

From that backtrace:

#4 0x00007fd1c073ed82 in g_file_monitor_source_handle_event (fms=0xd71c20, event_type=4294967295, …

So event_type is being set to -1, which definitely makes it look like the bug I was thinking about in ih_mask_to_EventFlags(). Assuming the kernel isn’t giving us a mask with multiple bits set, or any flags we didn’t ask for (IN_OPEN, IN_CLOSE_NOWRITE, IN_ACCESS), it’s either an IN_Q_OVERFLOW event or an IN_IGNORED event. It can’t be IN_IGNORED since that’s handled at the top of ip_event_dispatch(), so it has to be IN_Q_OVERFLOW.

I don’t think there’s much we can do to recover from events being dropped as a result of queue overflow. But we can at least not assert in that case.

Patches coming shortly. I can’t think of a decent way of producing a reliable unit test for this, although I would really like to. inotify events are pulled off the inotify FD in a GLib worker thread, and we have no control over that worker thread — I can’t think of a way to suspend it, cancel and restart it, or otherwise cause it to not read the FD for long enough for a load of events to queue up. This is probably only replicable using a highly contested main context with a lot of inotify watches and events; and that can’t reliably be turned into a test. :-(

[Bugzilla-tecnocode (bugzilla-tecnocode)]

Created attachment 364356
kqueue: Fix invalid emission of G_FILE_MONITOR_EVENT_MOVED event

That event is deprecated, and the kqueue backend can’t provide enough
information to go alongside the event (i.e. the name of the new file).
Use G_FILE_MONITOR_EVENT_DELETED instead.

Quite disappointed in the kqueue documentation for this: I cannot find a
single piece of documentation or example about how NOTE_RENAME is
supposed to communicate the new name of the file.

If it turns out that this is possible, the code can be amended again in
future. At least now it doesn’t abort.

Signed-off-by: Philip Withnall <email address hidden>

[Bugzilla-tecnocode (bugzilla-tecnocode)]

Created attachment 364357
inotify: Ignore IN_Q_OVERFLOW events

There’s not much we can do about them, and if they go unhandled, they
can propagate through to g_file_monitor_source_handle_event() and cause
assertion failures due to not mapping to a GFileMonitorEvent.

Signed-off-by: Philip Withnall <email address hidden>

[Bugzilla-tecnocode (bugzilla-tecnocode)]

Created attachment 364358
inotify: Don’t propagate unrecognised events to GLocalFileMonitor

If we can’t convert the inotify event mask into a GFileMonitorEvent enum
value, don’t propagate it to GLocalFileMonitor, since it hits an
assertion failure in that case.

This should no longer be possible since the previous commit to ignore
IN_Q_OVERFLOW events, but we might as well change this just in case
other bugs crop up in event mask handling.

Signed-off-by: Philip Withnall <email address hidden>

[Emmanuele Bassi (ebassi)]

Review of attachment 364356:

Looks reasonable.

[Emmanuele Bassi (ebassi)]

Review of attachment 364357:

Okay

[Emmanuele Bassi (ebassi)]

Review of attachment 364358:

Okay

[Bugzilla-tecnocode (bugzilla-tecnocode)]

Great, thanks for the reviews.

Attachment 364356 pushed as 76072a2 - kqueue: Fix invalid emission of G_FILE_MONITOR_EVENT_MOVED event
Attachment 364357 pushed as 9853842 - inotify: Ignore IN_Q_OVERFLOW events
Attachment 364358 pushed as 748bb24 - inotify: Don’t propagate unrecognised events to GLocalFileMonitor

[Bugzilla-tecnocode (bugzilla-tecnocode)]

Also backported to glib-2-54:

3246f1df9 inotify: Don’t propagate unrecognised events to GLocalFileMonitor
d97e07709 inotify: Ignore IN_Q_OVERFLOW events
38ec9c6da kqueue: Fix invalid emission of G_FILE_MONITOR_EVENT_MOVED event

[aaronfranke (arnfranke)]

Downstream bug: https://bugzilla.xfce.org/show_bug.cgi?id=12556

[Vlad Orlov (monsta)]

Fixed in 2.56

[aaronfranke (arnfranke)]

Non-backported fix is available in glib version 2.56.