indicator-messages crashes and entry call is missed for the user

[Gema Gomez]

Every now and then, under low coverage circumstances, one call doesn't get through to the UI and lets the user know she should be answering.

Preconditions:
- Low cellular coverage
- No connected wifi
- Some missed calls and one sms in the list of the messaging indicator from earlier

STEPS to reproduce:
1. Let the phone sit with black screen on an area with low coverage, with wifi disconnected
2. Make a call to the phone
3. The call seems to go through on the calling phone, but ubuntu won't show any sign of it happening.

See crash file attached from the indicator-messages at the same moment this is happening.

ProblemType: Bug
DistroRelease: Ubuntu 13.10
Package: indicator-messages 13.10.1+13.10.20130930-0ubuntu1
Uname: Linux 3.4.0-3-mako armv7l
ApportVersion: 2.12.5-0ubuntu1
Architecture: armhf
Date: Sun Oct 6 12:09:57 2013
InstallationDate: Installed on 2013-10-03 (3 days ago)
InstallationMedia: Ubuntu Saucy Salamander (development branch) - armhf (20131003)
MarkForUpload: True
ProcEnviron:
 TERM=linux
 PATH=(custom, no user)
SourcePackage: indicator-messages
UpgradeStatus: No upgrade log present (probably fresh install)

[Gema Gomez (gema)]

See crash file attached.

[Charles Kerr (charlesk)]

It looks like indicator-message-service is crashing when it tries to pass an invalid pointer to _int_free(), and that this is happening from somewhere inside GIO, but it's impossible to tell where because the retrace corrupts out at that point.

I see this ticket has been reassigned to me; however, I'm unsure how to proceed on it -- the retrace doesn't contain enough information, and I don't have a phone running Touch to satisfy the preconditions listed in Gema's description.

Gema, is there another way of triggering this on a tablet?

[Gema Gomez (gema)]

@charles, the problem with reproducing on a tablet is that we don't have tablets with sim cards and I have only managed to reproduce this with incoming calls.

I see it every now and then, I may be able to get you more crash logs tomorrow. It normally happens to me when there is stuff in the messaging queue and I have some apps open. I haven't been able to pinpoint the exact conditions. If there is any extra info that you can think of that is useful let me know and I will gather it next time it happens.

[Ted Gould (ted)]

@Gema, when it happens next if you could also include the dbus.log there might be relevant criticals that are being reported in there.

[Sebastien Bacher (seb128)]

backtrace on my tablet

(gdb) bt
#0 __libc_do_syscall ()
    at ../ports/sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:44
#1 0x406b55fe in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#2 0x406b7e1a in __GI_abort () at abort.c:90
#3 0x406db9dc in __libc_message (do_abort=2,
    fmt=0x4075a378 "*** Error in `%s': %s: 0x%s ***\n")
    at ../sysdeps/unix/sysv/linux/libc_fatal.c:199
#4 0x406e273a in malloc_printerr (action=3,
    str=0x4075a594 "invalid fastbin entry (free)", ptr=<optimized out>)
    at malloc.c:4923
#5 0x406e3176 in _int_free (av=<optimized out>, p=0x15ab8c0, have_lock=0)
    at malloc.c:3779
#6 0x40226436 in g_themed_icon_constructed (object=0x1589b18)
    at /build/buildd/glib2.0-2.38.0/./gio/gthemedicon.c:178
#7 0x4030d62a in g_object_new_internal (class=class@entry=0x1595cb0,
    params=params@entry=0xbea42c3c, n_params=n_params@entry=2)
    at /build/buildd/glib2.0-2.38.0/./gobject/gobject.c:1785
#8 0x4030f0d6 in g_object_new_valist (
    object_type=object_type@entry=22633512,
    first_property_name=first_property_name@entry=0x4029add4 "name",
    var_args=..., var_args@entry=...)
    at /build/buildd/glib2.0-2.38.0/./gobject/gobject.c:2002
#9 0x4030f214 in g_object_new (object_type=22633512,
    first_property_name=0x4029add4 "name")
    at /build/buildd/glib2.0-2.38.0/./gobject/gobject.c:1559
#10 0x402267b6 in g_themed_icon_new_with_default_fallbacks (
    iconname=0x15a9b28 "indicator-messages-offline")
    at /build/buildd/glib2.0-2.38.0/./gio/gthemedicon.c:366

[Ted Gould (ted)]

Valgrind log of call the phone, hang up without answering, call, hangout without answering, and then text.

[Ted Gould (ted)]

Posting a trace stopping at the first critical.

ueabihf/indicator-messages/indicator-messages-service rind /usr/lib/arm-linux-gnu
==3015== Memcheck, a memory error detector
==3015== Copyright (C) 2002-2012, and GNU GPL'd, by Julian Seward et al.
==3015== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info
==3015== Command: /usr/lib/arm-linux-gnueabihf/indicator-messages/indicator-messages-service
==3015==
==3015== Invalid read of size 4
==3015== at 0x493D0A4: g_object_unref (gobject.c:3089)
==3015== by 0x499FA6B: g_source_callback_unref (gmain.c:1549)
==3015== by 0x499FDD3: g_source_destroy_internal (gmain.c:1208)
==3015== by 0x49A1B9B: g_main_context_dispatch (gmain.c:3089)
==3015== by 0x49A1DC9: g_main_context_iterate.isra.22 (gmain.c:3712)
==3015== by 0x49A20E7: g_main_loop_run (gmain.c:3906)
==3015== by 0xC96F: ??? (in /usr/lib/arm-linux-gnueabihf/indicator-messages/indicator-messages-service)
==3015== Address 0x4cdb888 is 0 bytes inside a block of size 52 free'd
==3015== at 0x482E25C: free (vg_replace_malloc.c:446)
==3015== by 0x4951E35: g_type_free_instance (gtype.c:1938)
==3015== by 0x4954ACF: g_value_unset (gvalue.c:274)
==3015== by 0x1275D: ??? (in /usr/lib/arm-linux-gnueabihf/indicator-messages/indicator-messages-service)
==3015==
==3015== Invalid read of size 4
==3015== at 0x49527B4: g_type_check_instance_is_a (gtype.c:3970)
==3015== by 0x493D0B5: g_object_unref (gobject.c:3089)
==3015== by 0x499FA6B: g_source_callback_unref (gmain.c:1549)
==3015== by 0x499FDD3: g_source_destroy_internal (gmain.c:1208)
==3015== by 0x49A1B9B: g_main_context_dispatch (gmain.c:3089)
==3015== by 0x49A1DC9: g_main_context_iterate.isra.22 (gmain.c:3712)
==3015== by 0x49A20E7: g_main_loop_run (gmain.c:3906)
==3015== by 0xC96F: ??? (in /usr/lib/arm-linux-gnueabihf/indicator-messages/indicator-messages-service)
==3015== Address 0x4cdb888 is 0 bytes inside a block of size 52 free'd
==3015== at 0x482E25C: free (vg_replace_malloc.c:446)
==3015== by 0x4951E35: g_type_free_instance (gtype.c:1938)
==3015== by 0x4954ACF: g_value_unset (gvalue.c:274)
==3015== by 0x1275D: ??? (in /usr/lib/arm-linux-gnueabihf/indicator-messages/indicator-messages-service)
==3015==

(process:3015): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
==3015==
==3015== HEAP SUMMARY:
==3015== in use at exit: 154,313 bytes in 3,612 blocks
==3015== total heap usage: 13,095 allocs, 9,483 frees, 450,867 bytes allocated
==3015==
==3015== LEAK SUMMARY:
==3015== definitely lost: 131 bytes in 3 blocks
==3015== indirectly lost: 61 bytes in 1 blocks
==3015== possibly lost: 9,376 bytes in 296 blocks
==3015== still reachable: 135,833 bytes in 3,199 blocks
==3015== suppressed: 0 bytes in 0 blocks
==3015== Rerun with --leak-check=full to see details of leaked memory
==3015==
==3015== For counts of detected and suppressed errors, rerun with: -v
==3015== ERROR SUMMARY: 2 errors from 2 contexts (suppressed: 37 from 7)
Killed
phablet@ubuntu-phablet:~$

[Charles Kerr (charlesk)]

As a side issue, it looks like we're leaking the icon_name that im_application_list_update_draws_attention() builds for passing to g_themed_icon_new_with_default_fallbacks().

[Ted Gould (ted)]

phablet@ubuntu-phablet:~$ G_DEBUG=fatal_criticals valgrind /usr/lib/arm-linux-gnueabihf/indicator-messages/indicator-messages-service
==3132== Memcheck, a memory error detector
==3132== Copyright (C) 2002-2012, and GNU GPL'd, by Julian Seward et al.
==3132== Using Valgrind-3.8.1 and LibVEX; rerun with -h for copyright info
==3132== Command: /usr/lib/arm-linux-gnueabihf/indicator-messages/indicator-messages-service
==3132==
==3132== Invalid read of size 4
==3132== at 0x493D0A4: g_object_unref (gobject.c:3089)
==3132== by 0x499FA6B: g_source_callback_unref (gmain.c:1549)
==3132== by 0x499FDD3: g_source_destroy_internal (gmain.c:1208)
==3132== by 0x49A1B9B: g_main_context_dispatch (gmain.c:3089)
==3132== by 0x49A1DC9: g_main_context_iterate.isra.22 (gmain.c:3712)
==3132== by 0x49A20E7: g_main_loop_run (gmain.c:3906)
==3132== by 0xC96F: main (messages-service.c:252)
==3132== Address 0x4cd9e20 is 0 bytes inside a block of size 52 free'd
==3132== at 0x482E25C: free (vg_replace_malloc.c:446)
==3132== by 0x4951E35: g_type_free_instance (gtype.c:1938)
==3132== by 0x4954ACF: g_value_unset (gvalue.c:274)
==3132== by 0x1275D: _indicator_messages_service_skeleton_handle_method_call (indicator-messages-service.c:1443)
==3132== by 0x48E59B7: skeleton_intercept_handle_method_call (gdbusinterfaceskeleton.c:609)
==3132== by 0x48D4CBB: call_in_idle_cb (gdbusconnection.c:4868)
==3132== by 0x49A1B69: g_main_context_dispatch (gmain.c:3065)
==3132== by 0x49A1DC9: g_main_context_iterate.isra.22 (gmain.c:3712)
==3132== by 0x49A20E7: g_main_loop_run (gmain.c:3906)
==3132== by 0xC96F: main (messages-service.c:252)
==3132==
==3132== Invalid read of size 4
==3132== at 0x49527B4: g_type_check_instance_is_a (gtype.c:3970)
==3132== by 0x493D0B5: g_object_unref (gobject.c:3089)
==3132== by 0x499FA6B: g_source_callback_unref (gmain.c:1549)
==3132== by 0x499FDD3: g_source_destroy_internal (gmain.c:1208)
==3132== by 0x49A1B9B: g_main_context_dispatch (gmain.c:3089)
==3132== by 0x49A1DC9: g_main_context_iterate.isra.22 (gmain.c:3712)
==3132== by 0x49A20E7: g_main_loop_run (gmain.c:3906)
==3132== by 0xC96F: main (messages-service.c:252)
==3132== Address 0x4cd9e20 is 0 bytes inside a block of size 52 free'd
==3132== at 0x482E25C: free (vg_replace_malloc.c:446)
==3132== by 0x4951E35: g_type_free_instance (gtype.c:1938)
==3132== by 0x4954ACF: g_value_unset (gvalue.c:274)
==3132== by 0x1275D: _indicator_messages_service_skeleton_handle_method_call (indicator-messages-service.c:1443)
==3132== by 0x48E59B7: skeleton_intercept_handle_method_call (gdbusinterfaceskeleton.c:609)
==3132== by 0x48D4CBB: call_in_idle_cb (gdbusconnection.c:4868)
==3132== by 0x49A1B69: g_main_context_dispatch (gmain.c:3065)
==3132== by 0x49A1DC9: g_main_context_iterate.isra.22 (gmain.c:3712)
==3132== by 0x49A20E7: g_main_loop_run (gmain.c:3906)
==3132== by 0xC96F: main (messages-service.c:252)
==3132==

(process:3132): GLib-GObject-CRITICAL **: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
==3132==
==3132== HEAP SUMMARY:
==3132== in use at exit: 154,313 bytes in 3,612 blocks
==3132== t...

[Ted Gould (ted)]

(gdb) bt full
#0 __libc_do_syscall ()
    at ../ports/sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:44
No locals.
#1 0x402132de in raise (sig=sig@entry=5)
    at ../nptl/sysdeps/unix/sysv/linux/pt-raise.c:38
        _a1 = <optimized out>
        _a3tmp = 5
        _a1tmp = 0
        _a3 = <optimized out>
        _a2tmp = 3143
        _a2 = <optimized out>
        _name = <optimized out>
        _sys_result = <optimized out>
        pid = 0
#2 0x401889ba in g_logv (log_domain=0x4013a250 "GLib-GObject",
    log_level=log_level@entry=G_LOG_LEVEL_CRITICAL,
    format=format@entry=0x401bc99c "%s: assertion '%s' failed", args=...,
    args@entry=...) at /build/buildd/glib2.0-2.38.0/./glib/gmessages.c:989
        domain = 0x0
        data = <optimized out>
        depth = 1
        log_func = <optimized out>
        domain_fatal_mask = <optimized out>
        masquerade_fatal = <optimized out>
        test_level = 10
        was_fatal = 0
        was_recursion = 0
        msg = 0x46ac8 "g_object_unref: assertion 'G_IS_OBJECT (object)' failed"
        msg_alloc = 0x46ac8 "g_object_unref: assertion 'G_IS_OBJECT (object)' failed"
        i = 3
#3 0x40188a74 in g_log (log_domain=<optimized out>,
    log_level=log_level@entry=G_LOG_LEVEL_CRITICAL,
    format=0x401bc99c "%s: assertion '%s' failed")
    at /build/buildd/glib2.0-2.38.0/./glib/gmessages.c:1025
        args = {__ap = 0xbefff28c}
#4 0x40188a92 in g_return_if_fail_warning (log_domain=<optimized out>,
    pretty_function=<optimized out>, expression=<optimized out>)
    at /build/buildd/glib2.0-2.38.0/./glib/gmessages.c:1034
No locals.
#5 0x40181a6c in g_source_callback_unref (cb_data=0x417043d0)
    at /build/buildd/glib2.0-2.38.0/./glib/gmain.c:1549
        cb_data = 0x417043d0
        callback = 0x417043d0
#6 0x40181dd4 in g_source_destroy_internal (source=source@entry=0x41704248,
    context=context@entry=0x26568, have_lock=have_lock@entry=1)
    at /build/buildd/glib2.0-2.38.0/./glib/gmain.c:1208
        tmp_list = <optimized out>
        old_cb_data = 0x417043d0
        old_cb_funcs = 0x402065b8 <g_source_callback_funcs>
#7 0x40183b9c in g_main_dispatch (context=0x26568)
    at /build/buildd/glib2.0-2.38.0/./glib/gmain.c:3089
        dispatch = <optimized out>
        was_in_call = 0
        user_data = 0x41702400
        callback = 0x400b6c21 <call_in_idle_cb>
        cb_funcs = 0x402065b8 <g_source_callback_funcs>
        cb_data = 0x417043d0
        need_destroy = 1
        current_source_link = {data = 0x41704248, next = 0x0}
        source = 0x41704248
        current = 0x25910
        i = 0
#8 g_main_context_dispatch (context=context@entry=0x26568)
    at /build/buildd/glib2.0-2.38.0/./glib/gmain.c:3641
No locals.
#9 0x40183dca in g_main_context_iterate (context=0x26568,
    block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at /build/buildd/glib2.0-2.38.0/./glib/gmain.c:3712
        max_priority = 0
        timeout = 0
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = <optimized out>
        fds = 0x3cc08
#10 0x401840e8 in g_main_loop_run (loop=0x26660)
    at /build/buildd/glib2.0-2.38.0/./glib/gmain.c:3906
      ...

[Ted Gould (ted)]

This bug was fixed on 9/30 in r383. http://bazaar.launchpad.net/~indicator-applet-developers/indicator-messages/trunk.13.10/revision/383