Sometimes alarms trigger at xx seconds past their time and dismiss on snap doesn't stop the ringing

[Dave Morley]

Steps to debug:
adb shell
sudo -u phablet -i
stop indicator-datetime
G_MESSAGES_DEBUG=all /usr/lib/arm-linux-gnueabihf/indicator-datetime/indicator-datetime-service

In a separate terminal run:
adb shell
powerd-cli active

Steps to reproduce:
Set an alarm for 3 minutes time
Hit the power button
Repeat until the issue triggers.

At some point the alarm will sound you hit dismiss in the snap decision and the alarm doesn't stop ringing.

ProblemType: Bug
DistroRelease: Ubuntu 14.04
Package: indicator-datetime 13.10.0+14.04.20140314.1-0ubuntu1
Uname: Linux 3.4.0-5-mako armv7l
ApportVersion: 2.13.3-0ubuntu1
Architecture: armhf
Date: Thu Mar 20 16:51:23 2014
InstallationDate: Installed on 2014-03-20 (0 days ago)
InstallationMedia: Ubuntu Trusty Tahr (development branch) - armhf (20140320)
ProcEnviron:
 TERM=linux
 PATH=(custom, no user)
SourcePackage: indicator-datetime
UpgradeStatus: No upgrade log present (probably fresh install)

[Didier Roche-Tolomelli (didrocks)]

confirming, seems a promotion blocker as well

[Dave Morley (davmor2)]

This is an example of a failed alarm:
(process:6560): Indicator-Datetime-DEBUG: adding appointment 'Alarm' ''
(process:6560): Indicator-Datetime-DEBUG: RangePlanner 0x1a08228 got 1 appointments
(process:6560): Indicator-Datetime-DEBUG: time to delete task 0x1ad72a0
(process:6560): Indicator-Datetime-DEBUG: adding appointment 'Alarm' ''
(process:6560): Indicator-Datetime-DEBUG: RangePlanner 0x1a09500 got 1 appointments
(process:6560): Indicator-Datetime-DEBUG: time to delete task 0x1aa0c30
(process:6560): Indicator-Datetime-DEBUG: adding appointment 'Alarm' ''
(process:6560): Indicator-Datetime-DEBUG: RangePlanner 0x1a0e398 got 1 appointments
(process:6560): Indicator-Datetime-DEBUG: ClockWatcher 0xbe92d450 calling pulse() due to appointments changed
(process:6560): Indicator-Datetime-DEBUG: time to delete task 0x1acd3d8
(process:6560): Indicator-Datetime-DEBUG: ClockWatcher 0xbe92d450 calling pulse() due to clock minute_changed

(process:6560): libnotify-WARNING **: Failed to connect to proxy
(process:6560): Indicator-Datetime-WARNING **: Unable to show snap decision for 'Alarm': Timeout was reached

[Charles Kerr (charlesk)]

Looks like what's happening here is indicator-datetime is blocking for 25 seconds inside of libnotify's notify_notification_show() call, waiting for unity-notifications to respond.

> (process:6560): Indicator-Datetime-DEBUG: ClockWatcher 0xbe92d450 calling pulse() due to clock minute_changed
> (process:6560): libnotify-WARNING **: Failed to connect to proxy
> (process:6560): Indicator-Datetime-WARNING **: Unable to show snap decision for 'Alarm': Timeout was reached

Those last three lines of that log are the interesting part. The code being triggered is this:

====

    auto nn = notify_notification_new(title, body.c_str(), icon_name);
    if (mode == NOTIFY_MODE_SNAP)
    {
        notify_notification_set_hint_string(nn, "x-canonical-snap-decisions", "true");
        notify_notification_set_hint_string(nn, "x-canonical-private-button-tint", "true");
        notify_notification_add_action(nn, "show", _("Show"), on_snap_show, data, nullptr);
        notify_notification_add_action(nn, "dismiss", _("Dismiss"), on_snap_dismiss, data, nullptr);
        g_signal_connect(G_OBJECT(nn), "closed", G_CALLBACK(on_snap_closed), data);
    }
    g_object_set_data_full(G_OBJECT(nn), "snap-data", data, snap_data_destroy_notify);

    GError * error = nullptr;
    notify_notification_show(nn, &error);
    if (error != NULL)
    {
        g_warning("Unable to show snap decision for '%s': %s", body.c_str(), error->message);
        g_error_free(error);
        data->show(data->appointment);
    }

In libnotify, notify_notification_show() calls its helper function _notify_get_proxy(), which calls g_dbus_proxy_new_for_bus_sync(). g_dbus_connection_send_message_with_reply_unlocked() uses a default timeout of 25 seconds, which is consistent with what davmor2's seeing:

[11:38:20] <davmor2> charles: it went off at 16:35:26 rather than 16:35:00

Another indication that this is where the 25 seconds went is the error message returned by gio, which matches the one in the log. send_message_with_reply_timeout_cb()'s message is "Timeout was reached"

[Ted Gould (ted)]

I'm unable to connect to org.freedesktop.Notifications using gdbus command line utility or with d-feet either. Marking the datetime item invalid.

[Dave Morley (davmor2)]

Again No alarm sounder this time though at 11 seconds past 17:38 I hit the power button and saw http://popey.com/~alan/phablet/device-2014-03-20-123802.png this shows no buttons to dimiss the alarm.

Log in terminal:
phablet@ubuntu-phablet:~$ G_MESSAGES_DEBUG=all /usr/lib/arm-linux-gnueabihf/indicator-datetime/indicator-datetime-service
(process:8617): Indicator-Datetime-DEBUG: /build/buildd/indicator-datetime-13.10.0+14.04.20140314.1/src/timezone-file.cpp:83 Monitoring timezone file '/etc/writable/timezone'
(process:8617): Indicator-Datetime-DEBUG: /build/buildd/indicator-datetime-13.10.0+14.04.20140314.1/src/timezone-file.cpp:83 Monitoring timezone file '/etc/writable/timezone'
(process:8617): Indicator-Datetime-DEBUG: PlannerMonth 0xc89828 setting calendar month range: [2014-03-01 00:00:00..2014-03-31 23:59:59]
(process:8617): Indicator-Datetime-DEBUG: rebuilding because the date range changed
(process:8617): Indicator-Datetime-DEBUG: 0xc888b8 setting date range to [2014-03-19 17:34:39..2014-04-20 17:34:39]
(process:8617): Indicator-Datetime-DEBUG: rebuilding because the date range changed
(process:8617): Indicator-Datetime-DEBUG: 0xc94130 setting date range to [2014-03-19 17:34:39..2014-04-20 17:34:39]
(process:8617): Indicator-Datetime-DEBUG: rebuilding because the date range changed
(process:8617): Indicator-Datetime-DEBUG: /build/buildd/indicator-datetime-13.10.0+14.04.20140314.1/src/formatter.cpp:104 guint unity::indicator::datetime::{anonymous}::calculate_seconds_until_next_fifteen_minutes(GDateTime*) the next timestamp rebuild will be at 2014-03-20 17:45:00
(process:8617): Indicator-Datetime-DEBUG: /build/buildd/indicator-datetime-13.10.0+14.04.20140314.1/src/formatter.cpp:104 guint unity::indicator::datetime::{anonymous}::calculate_seconds_until_next_fifteen_minutes(GDateTime*) the next timestamp rebuild will be at 2014-03-20 17:45:00
(process:8617): Indicator-Datetime-DEBUG: /build/buildd/indicator-datetime-13.10.0+14.04.20140314.1/src/formatter.cpp:104 guint unity::indicator::datetime::{anonymous}::calculate_seconds_until_next_fifteen_minutes(GDateTime*) the next timestamp rebuild will be at 2014-03-20 17:45:00
(process:8617): Indicator-Datetime-DEBUG: /build/buildd/indicator-datetime-13.10.0+14.04.20140314.1/src/formatter.cpp:104 guint unity::indicator::datetime::{anonymous}::calculate_seconds_until_next_fifteen_minutes(GDateTime*) the next timestamp rebuild will be at 2014-03-20 17:45:00
(process:8617): Indicator-Datetime-DEBUG: bus acquired: com.canonical.indicator.datetime
(process:8617): Indicator-Datetime-DEBUG: static void unity::indicator::datetime::EdsEngine::Impl::on_source_enabled(ESourceRegistry*, ESource*, gpointer) connecting a client to source birthdays
(process:8617): Indicator-Datetime-DEBUG: static void unity::indicator::datetime::EdsEngine::Impl::on_source_enabled(ESourceRegistry*, ESource*, gpointer) connecting a client to source system-calendar
(process:8617): Indicator-Datetime-DEBUG: static void unity::indicator::datetime::EdsEngine::Impl::on_source_enabled(ESourceRegistry*, ESource*, gpointer) connecting a client to source 1395316840.26311.0@ubuntu-phablet
(process:8617): Indicator-Datetime-DEBUG: static ...

[Charles Kerr (charlesk)]

I agree with Ted that it sounds like the real issue is outside of the indicator code, but it still has some rough edges that need to be smoothed out here: it should =not= loop the alarm sound forever when unity-notifications stops responding. :-)

[Ted Gould (ted)]

Using the mir binaries on bug 1292306 the notifications daemon responds properly and things work. Removing the bug task for notifications as it seems to be a Qt 5.2 issue.

[taiebot65 (dedreuil)]

I am seeing this on 237 never had a working alarm apart from my 1st test

[Launchpad Janitor (janitor)]

This bug was fixed in the package indicator-datetime - 13.10.0+14.04.20140321-0ubuntu1

---------------
indicator-datetime (13.10.0+14.04.20140321-0ubuntu1) trusty; urgency=low

  [ Charles Kerr ]
  * If we notify_notification_show() fails, we shouldn't play the alarm
    sound. The alarm sound loops until the user dismisses it, which will
    never happen if we can't talk to unity-notiifications. So the
    outcome in this error case is that the alarm plays forever and can't
    be dismissed by the user. (LP: #1295237)
  * Add debug logging of what capabilities the notification server said
    it supports. (LP: #1295271)
 -- Ubuntu daily release <email address hidden> Fri, 21 Mar 2014 05:23:04 +0000