indicator-datetime-service panel clock freezes

[Kees Bos]

The clock in the panel freezes after running for (at least sometimes) a few seconds.

ProblemType: Bug
DistroRelease: Ubuntu 14.04
Package: indicator-datetime 13.10.0+14.04.20140314.1-0ubuntu1
ProcVersionSignature: Ubuntu 3.13.0-17.37-generic 3.13.6
Uname: Linux 3.13.0-17-generic i686
ApportVersion: 2.13.3-0ubuntu1
Architecture: i386
CurrentDesktop: Unity
Date: Wed Mar 19 11:08:59 2014
ExecutablePath: /usr/lib/i386-linux-gnu/indicator-datetime/indicator-datetime-service
InstallationDate: Installed on 2013-12-24 (84 days ago)
InstallationMedia: Ubuntu 14.04 LTS "Trusty Tahr" - Alpha i386 (20131224)
SourcePackage: indicator-datetime
UpgradeStatus: No upgrade log present (probably fresh install)
upstart.indicator-datetime.log: (process:6082): Indicator-Datetime-WARNING **: AddressStart() failed: GDBus.Error:org.freedesktop.Geoclue.Error.notAvailable: Geoclue master client has no usable Address providers

[Kees Bos (k-bos)]

Added strace of same process after a while (still no updates of time in panel, i.e. still freezed)

[Kees Bos (k-bos)]

I added this to my crontab:

# m h dom mon dow command
* * * * * killall indicator-datetime-service

Now it seems consistable freezing within 3 or 4 seconds (I have seconds displayed also and it stops at hh:mm:03 or hh:mm:04)

[Sebastien Bacher (seb128)]

The report has that warning

" Indicator-Datetime-WARNING **: AddressStart() failed: GDBus.Error:org.freedesktop.Geoclue.Error.notAvailable: Geoclue master client has no usable Address providers"

Does it work better if you install geoclue-ubuntu-geoip?

[Kees Bos (k-bos)]

Nope. Is already installed and newest version. This error doesn't occur on every restart of indicator-datetime-service (from the cron).

[Sebastien Bacher (seb128)]

can you get a gdb backtrace (https://wiki.ubuntu.com/Backtrace)?

[Kees Bos (k-bos)]

I did as described at https://wiki.ubuntu.com/Backtrace#Already_running_programs

One differenc: Hitting ^C didn't work, so I've used 'kill -SIGINT <PID ofindicator-datetime-service >' to get back to the gdb prompt.

[Sebastien Bacher (seb128)]

thanks, backtrace seems to indicator the process is running normally and not blocked in some codepath though :/

[Kees Bos (k-bos)]

Yeah, that's what I see in the strace log.

I think that the problem/symptom is that the poll just times out and doesn't get data on the event-fd.

tail of indicator-datetime-service.strace.log:
11:00:28 eventfd2(0, O_NONBLOCK|O_CLOEXEC) = 22
11:00:28 write(22, "\1\0\0\0\0\0\0\0", 8) = 8
11:00:28 write(6, "\1\0\0\0\0\0\0\0", 8) = 8
11:00:28 futex(0xb580af10, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:28 futex(0xb580ab08, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:28 clock_gettime(CLOCK_MONOTONIC, {2931, 622027924}) = 0
11:00:28 futex(0xb5802f80, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:28 clock_gettime(CLOCK_MONOTONIC, {2931, 622178855}) = 0
11:00:28 poll([{fd=22, events=POLLIN}], 1, 180000) = 1 ([{fd=22, revents=POLLIN}])
11:00:28 clock_gettime(CLOCK_MONOTONIC, {2931, 622230836}) = 0
11:00:28 clock_gettime(CLOCK_MONOTONIC, {2931, 622254879}) = 0
11:00:28 poll([{fd=22, events=POLLIN}], 1, 180000) = 1 ([{fd=22, revents=POLLIN}])
11:00:28 read(22, "\1\0\0\0\0\0\0\0", 16) = 8
11:00:28 clock_gettime(CLOCK_MONOTONIC, {2931, 622328380}) = 0
11:00:28 clock_gettime(CLOCK_MONOTONIC, {2931, 622352161}) = 0
11:00:28 poll([{fd=22, events=POLLIN}], 1, 180000 <detached ...>

and here just happens nothing, except a timeout after 180000 miliseconds (3 minutes). My guess is that there should have been a return with read action on fd=22. Similar as earlier:

11:00:25 eventfd2(0, O_NONBLOCK|O_CLOEXEC) = 8
11:00:25 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
11:00:25 write(6, "\1\0\0\0\0\0\0\0", 8) = 8
11:00:25 futex(0xb580af10, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 futex(0xb580ab08, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 clock_gettime(CLOCK_MONOTONIC, {2928, 426833813}) = 0
11:00:25 futex(0xb5802f80, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 poll([{fd=8, events=POLLIN}], 1, 0) = 1 ([{fd=8, revents=POLLIN}])
11:00:25 write(6, "\1\0\0\0\0\0\0\0", 8) = 8
11:00:25 futex(0xb580af10, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 futex(0xb580ab08, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 clock_gettime(CLOCK_MONOTONIC, {2928, 427817851}) = 0
11:00:25 futex(0xb5802f80, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 poll([{fd=8, events=POLLIN}], 1, 0) = 1 ([{fd=8, revents=POLLIN}])
11:00:25 read(8, "\3\0\0\0\0\0\0\0", 16) = 8
11:00:25 poll([{fd=8, events=POLLIN}], 1, 0) = 0 (Timeout)
11:00:25 read(8, 0xbfa5694c, 16) = -1 EAGAIN (Resource temporarily unavailable)
11:00:25 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
11:00:25 close(8) = 0
11:00:25 eventfd2(0, O_NONBLOCK|O_CLOEXEC) = 8
11:00:25 write(8, "\1\0\0\0\0\0\0\0", 8) = 8
11:00:25 write(6, "\1\0\0\0\0\0\0\0", 8) = 8
11:00:25 futex(0xb580af10, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 futex(0xb580ab08, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 clock_gettime(CLOCK_MONOTONIC, {2928, 429068530}) = 0
11:00:25 futex(0xb5802f80, FUTEX_WAKE_PRIVATE, 1) = 1
11:00:25 clock_gettime(CLOCK_MONOTONIC, {2928, 429726382}) = 0
11:00:25 poll([{fd=8, events=POLLIN}], 1, 25000) = 1 ([{fd=8, revents=POLLIN}])
11:00:25 clock_gettime(CLOCK_MONOTONIC, {2928, 429874461}) = 0
11:00:25 clock_gettime(CLOCK_MONOTONIC, {2928, 429945589}) = 0
11:00:25 poll([{fd=8, events=POLLIN}], 1, 25000) = 1 ([{fd=8, revents=POLLIN}])
11:00:25 read(8, "\1\0\0\0\0\0\0\0", 16) = 8
11:00:25 clock_gettime(CLOCK_MONOTONIC, {2928...

[Charles Kerr (charlesk)]

Judging from that backtrace it's blocking in e_dbus_calendar_call_get_timezone_sync(), which is being called from e_cal_client_get_timezone_sync(), which in turn is being called from generate_instances() after being called asynchronously from indicator-datetime via a call to e_cal_client_generate_instances().

indicator-datetime is already invoking this as an asynchronous function, so you could argue that this is a lesser bug in EDS -- it shouldn't block. Even then, though, I don't understand why its call of e_cal_client_get_timezone_sync() would take a couple of *seconds*.

Kees, do you have any interesting configuration settings in Evolution / EDS that might account for such a lag? Do you have a lot of calendar sources, remotely-connected/mounted sources, an unusual number of appointments, etc etc?

[Kees Bos (k-bos)]

It appears to be related to my EWS account in evolution. When I remove that, all works fine. When I added that account again (all default settings, except for checking mail every 10 minutes in stead of 60 and disabeling the 'apply filters'), the clock stopped after a short while (but several seconds later than previously). At that time I saw that /usr/lib/evolution/evolution-calendar-factory was consuming quite some cpu power.

When I remove the account again and kill the remaining /usr/lib/evolution/evolution-* processes, the clock starts ticking again (after waiting some time).

I've configured the ews account again. Now it seems that the clock stops ticking when the cpu usdage of evolution-calendar-factory dropped.

Looks like that there's somthing wrong in evolution-calendar-factory that causes the clock to stop. Killing just evolution-calendar-factory gets the clock running again. I don't think I've an abnormal number of appointments in my calander.

BWT. I'd rather see the clock going on when errors occur...

[Kees Bos (k-bos)]

BTW. I noticed yesterday that the calendar items of the EWS account are not displayed in the evolution calendar interface and that the calendar interface/evolution seems to hang.

[Kees Bos (k-bos)]

Well, the items apear, but only after about 15 minutes (while evolution is unresponsive).

[Kees Bos (k-bos)]

In outlook, I've archived all events before this year (that didn't help) and then removed about 30 yearly events. The latter made evolution responsive again.

I guess we can change this bug to a feture request: Make clock going on when timeouts/errors occur in calendar.

[Ulrich Neu (ulrich-neu)]

Same for me...
Also affects x64...