Dash restarts when refreshing News scope (VerticalJournal)

some logs

[2016-07-07 09:51:20.596] ERROR: com.canonical.scopes.dashboard_dashboard: ReplyObject::push(): ReplyObject::push(VariantMap): unity::LogicException: Variant does not contain a string value:
boost::bad_get: failed value get using boost::get
query complete, status: error
ReplyObject::push(VariantMap): unity::LogicException: Variant does not contain a string value:
boost::bad_get: failed value get using boost::get

When it dies, it gets OOM-killed:

Jul 7 10:59:15 ubuntu-phablet kernel: [ 556.220003] (3)[3262:unity8-dash]lowmemorykiller: Killing 'unity8-dash' (3262), adj 0, score_adj 50,
Jul 7 10:59:15 ubuntu-phablet kernel: [ 556.220003] to free 1535216kB on behalf of 'unity8-dash' (3262) because
Jul 7 10:59:15 ubuntu-phablet kernel: [ 556.220003] cache 65380kB is below limit 65536kB for oom_score_adj 12
Jul 7 10:59:15 ubuntu-phablet kernel: [ 556.220003] Free memory is 0kB above reserved

That suggests it's leaking crazy when it gets stuck.

When it was stuck, I got this out from gdb info threads:

Program received signal SIGINT, Interrupt.
0xf67466ba in ?? () from /lib/arm-linux-gnueabihf/libc.so.6
(gdb) info threads
  Id Target Id Frame
  44 Thread 0xda61b410 (LWP 4885) "unity8-dash" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  43 Thread 0xd3eff410 (LWP 4992) "unity8-dash" 0xf6788132 in epoll_wait () from /lib/arm-linux-gnueabihf/libc.so.6
  42 Thread 0xd36ff410 (LWP 5042) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  41 Thread 0xf332a410 (LWP 3287) "RPC Thread" 0xf67814e0 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
  40 Thread 0xf16c7410 (LWP 3628) "mali-mem-purge" 0xf4947c64 in ?? ()
  39 Thread 0xf0ec7410 (LWP 3629) "mali-event-hnd" 0xf4947b1c in ?? ()
  38 Thread 0xf06c7410 (LWP 3630) "mali-utility-wo" 0xf4920484 in ?? ()
  37 Thread 0xefec7410 (LWP 3631) "mali-utility-wo" 0xf4920484 in ?? ()
  36 Thread 0xef6c7410 (LWP 3632) "mali-utility-wo" 0xf4920484 in ?? ()
  35 Thread 0xeeec7410 (LWP 3633) "mali-utility-wo" 0xf4920484 in ?? ()
  34 Thread 0xee6c7410 (LWP 3634) "mali-renderer" 0xf4920484 in ?? ()
  33 Thread 0xed4ff410 (LWP 3636) "ged-swd" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  32 Thread 0xecaba410 (LWP 3637) "QQmlThread" 0xf67814e0 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
  31 Thread 0xea5ff410 (LWP 3648) "Qt bearer threa" 0xf67814e0 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
  30 Thread 0xe9cff410 (LWP 3649) "QProcessManager" 0xf67833e2 in select () from /lib/arm-linux-gnueabihf/libc.so.6
  29 Thread 0xe8761410 (LWP 3651) "QQuickPixmapRea" 0xf67814e0 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
  28 Thread 0xe7596410 (LWP 3657) "Input dispatch" 0xf67814e0 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
  27 Thread 0xe6d96410 (LWP 3668) "QSGRenderThread" 0xf1b074f0 in ?? ()
  26 Thread 0xe4d2e410 (LWP 3673) "Qt HTTP thread" 0xf67814e0 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
  24 Thread 0xe352e410 (LWP 3676) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  23 Thread 0xe2d2e410 (LWP 3677) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  22 Thread 0xe252e410 (LWP 3678) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  21 Thread 0xe1d2e410 (LWP 3679) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  20 Thread 0xe152e410 (LWP 3680) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  19 Thread 0xe0d2e410 (LWP 3681) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  18 Thread 0xe052e410 (LWP 3682) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  17 Thread 0xdfd2e410 (LWP 3683) "scopes_ng::Scop" 0xf66edd44 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
  16 ...

$ smemstat -p `pidof unity8-dash` 5 1000
Change in memory (average per second):
  PID Swap USS PSS RSS User Command
  2695 0.0 B 30.9 M 30.9 M 30.9 M phablet unity8-dash

So it allocates as much as 30MB a second...

Starting to suspect this is not a regression, have downgraded down to 101 for frieza rc-proposed and can reproduce the issue there.

I confirm that it is reproducible on OTA11.

I find that the el pais scope reliably causes the log error in comment #1 in both news scope and in today scope (dashboard).

Disabling el pais in both fixes it (no more exceptions).

Seems the el pais related exception is not required for the core symptom. I just simply rebooted and refreshed the news scope twice (with el pais disabled in news). I saw no exceptions in the scope-registry.log, but the hang on a long refresh followed by dash restart did occur.

filed bug 1599948 for the el pais related exception.

The log exceptions are due to handling cases where the incoming result lacks art in the expected result attribute and we attempt to check other result attributes to find it. This code was trying to access a result attribute that did not exist in some cases and threw and execption.

Attaching stacktrace of all threads with debug symbols for unity-scopes-api, unity-scopes-shell and unity8-private.

I can easily reproduce the problem on frieza with News scope, by just pulling to refresh a couple of times. I wasn't able to reproduce it with Nearby scope.

I've attached with gdb to the running dash and my attention was drawn by VerticalJournal::addItemToView; a breakpoint + a simple gdb script to count all calls when this problem is reproduced reveals that it's being called repeatedly in a loop - I've counted 23000+ hits and it's growing (with this bp and gdb overhead the dash runs much slower and I bet it will take a while before it gets killed).

This is the backtrace when addItemToView breakpoint gets hit:

Breakpoint 2, VerticalJournal::addItemToView (this=0x105a898, modelIndex=0, item=0x1810ef0) at /build/unity8-PQzVl4/unity8-8.12+15.04.20160707/plugins/Dash/verticaljournal.cpp:129
129 in /build/unity8-PQzVl4/unity8-8.12+15.04.20160707/plugins/Dash/verticaljournal.cpp
$22149 = 22149
#0 VerticalJournal::addItemToView (this=0x105a898, modelIndex=0, item=0x1810ef0) at /build/unity8-PQzVl4/unity8-8.12+15.04.20160707/plugins/Dash/verticaljournal.cpp:129
#1 0xeac150d2 in AbstractDashView::createItem (this=this@entry=0x105a898, modelIndex=0, asynchronous=asynchronous@entry=false) at /build/unity8-PQzVl4/unity8-8.12+15.04.20160707/plugins/Dash/abstractdashview.cpp:252
#2 0xeac152c0 in AbstractDashView::addVisibleItems (this=0x105a898, fillFromY=0, fillToY=389, asynchronous=<optimized out>) at /build/unity8-PQzVl4/unity8-8.12+15.04.20160707/plugins/Dash/abstractdashview.cpp:221
#3 0xeac15332 in AbstractDashView::refill (this=0x105a898) at /build/unity8-PQzVl4/unity8-8.12+15.04.20160707/plugins/Dash/abstractdashview.cpp:186
#4 0xeac15392 in AbstractDashView::updatePolish (this=0x105a898) at /build/unity8-PQzVl4/unity8-8.12+15.04.20160707/plugins/Dash/abstractdashview.cpp:324
#5 0xec8c6ee0 in QQuickWindowPrivate::polishItems() () from /usr/lib/arm-linux-gnueabihf/libQt5Quick.so.5
#6 0xec8a8da2 in ?? () from /usr/lib/arm-linux-gnueabihf/libQt5Quick.so.5

So, is this perhaps related to the Vertical Journal?

Thanks Paweł, seems like the News scope is the only one using the journal layout, and frieza is the only device where there's three columns, so that might explain why it only happens there.