[TOPBLOCKER] Nearby and News scope do not load on reboot

[Victor Tuson Palau]

reporduce:
1- favourite nearby and/or news
2- reboot the phone
3 - unlock and swipe to nearby/news

result:
Scope is blank, not even departments are loaded in nearby

expected result:
scope load, to see what they look like, search for something and then cancel search. This triggers a refresh and the scopes then load ok.

[Victor Tuson Palau (vtuson)]

I have been able to reproduce on the youtube scope

[Paweł Stołowski (stolowski)]

I'm able to reproduce from time to time with Nearby scope (in 1/5 reboots, approximately) if I quickly go to that scope as soon as my phone boots. I'm not sure yet where the problem lies though, still looking.

[Paweł Stołowski (stolowski)]

I'm not able to reproduce it anymore with image 101. I've rebooted the device multiple times with around 13 favorite scopes (including Nearby, News and Youtube), and it worked every time.

We recently landed some important fixes in scopes api that could explain this issue.

@Victor could tyou please confirm it's no longer an issue in your tests?

[Jean-Baptiste Lallement (jibel)]

I can no longer reproduce with 101 after several reboots and the following scopes enabled: music, photos, videos, nearby, shopping, news, youtube, reddit and store.

[Victor Tuson Palau (vtuson)]

I get now partially loaded scopes see picture of new

[Pete Woods (pete-woods)]

Playing about with this on my krillin with a bunch of favourited scopes (photos, nearby, news, shopping). On almost every reboot at least one of the aggregated scopes is missing from one of the top-level aggregating scopes.

[Pete Woods (pete-woods)]

Rather impressively, we manage to use up 3 log rotations just during startup with this configuration.

[Marcus Tomlinson (marcustomlinson)]

This looks to me to be an issue of buggy scope implementations.

If you search for the phrase "closed unexpectedly" in the log files Pete posted above, you'll see a number of scopes are crashing. Namely: "com.canonical.scopes.fbphotos_fbphotos", "unity-scope-nearby", and "com.canonical.scopes.eljueves_eljueves". That would explain the scopes being empty.

The fact that there are no complains in these logs about scopes not starting properly, means that these scopes are making it through their start() methods just fine. So looks like these crashes are occurring in run().

The log just before these "closed unexpectedly" entries should give an indication of where in the code each of these scopes are when the crash occurs.

E.g. A pretty scary looking one in scope-registry.log.3.gz:

panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xb code=0x1 addr=0x0 pc=0xbdbb8]

goroutine 1 [running]:
runtime.panic(0x20b568, 0x43efe0)
 /usr/lib/go/src/pkg/runtime/panic.c:266 +0x134
launchpad.net/go-unityscopes/v1.(*ScopeBase).ScopeDirectory(0x0, 0x0, 0x0)
 /home/cwayne/go/src/launchpad.net/go-unityscopes/v1/unityscope.go:98 +0x30
main.(*EJScope).SetScopeBase(0x9464d2c0, 0x0)
 /home/cwayne/Projects/scopes/el-jueves/eljueves.go:118 +0x2c
launchpad.net/go-unityscopes/v1.setScopeBase(0xb46286e8, 0x9464d2c0, 0x0)
 /home/cwayne/go/src/launchpad.net/go-unityscopes/v1/unityscope.go:90 +0x4c
launchpad.net/go-unityscopes/v1._Cfunc_run_scope(0x947cb980, 0x94616100, 0x94616110, 0x947cb978, 0x947cb988)
 launchpad.net/go-unityscopes/v1/_obj/_cgo_defun.c:332 +0x34
launchpad.net/go-unityscopes/v1.Run(0xb46286e8, 0x9464d2c0, 0x4523cc, 0xb46286e8)
 /home/cwayne/go/src/launchpad.net/go-unityscopes/v1/unityscope.go:145 +0x318
main.main()
 /home/cwayne/Projects/scopes/el-jueves/eljueves.go:237 +0x1a8

goroutine 4 [syscall]:
runtime.cgocallbackg()
 /usr/lib/go/src/pkg/runtime/cgocall.c:267 +0x68
runtime.cgocallback_gofunc(0x0, 0x0, 0x0)
 /usr/lib/go/src/pkg/runtime/asm_arm.s:495 +0x60
runtime.goexit()
 /usr/lib/go/src/pkg/runtime/proc.c:1394

goroutine 7 [syscall]:
runtime.goexit()
 /usr/lib/go/src/pkg/runtime/proc.c:1394
RegistryObject::ScopeProcess::on_process_death(): Process for scope: "com.canonical.scopes.eljueves_eljueves" exited
RegistryObject::ScopeProcess: Scope: "com.canonical.scopes.eljueves_eljueves" closed unexpectedly. Either the process crashed or was killed forcefully.

[Marcus Tomlinson (marcustomlinson)]

that said ^, I've just done a few reboots with nearby and news favourited (installed from latest lp:~hanloon-team/hanloon/clicks). When I reboot, the news scope works just fine every time. The strange one is the nearby scope. When the nearby scope finishes surfacing, all child scopes show up but, other than weather, they all show "No Location found" (which is weird because the weather results are location specific and correct). Then when I trigger another surfacing (add and remove a character in the search), the nearby scope then only shows me results from weather and nearby wikipedia articles, and this time the wikipedia results are location specific and correct. Every surfacing from then on do the same.

I assume that since this bug was reported we've been through a number of updates and hence shifted from issue to issue.

(I'm testing on RTM #88 btw)

[Marcus Tomlinson (marcustomlinson)]

Ok, a further discovery. If I don't have the nearby scope favourited then reboot. Opening the nearby scope from the Dash Manager works perfectly. If I tap back then open it again though, I get only the weather and wiki articles again.

So looks like one issue uncovered is that location data is not available when this scope starts up on boot. Race between location data becoming available and the scope requesting it perhaps?

[Marcus Tomlinson (marcustomlinson)]

Ok so Pete made a mistake when posting the scope-registry log. We don't actually rotate the log multiple times during boot up.

Here is the registry log during a boot on my mako RTM #88, with news, nearby, photos, shopping, and dashboard favorited:

(so again, imo, this issue seems to be a combination of the delayed availability of location data on start up, and a bit of buggy scope implementation causing crashes)

[Rick Spencer (rick-rickspencer3)]

I just reproduced this on My Photos scope. Starting and not completing a search caused it to start loading.

[Paweł Stołowski (stolowski)]

The branch lp:~stolowski/unity-scopes-shell/fix-1374481 linked with this bug reduces the risk of network congestion issues caused by too many concurrent scope queries on startup (which would then cause time-out for some of them, resulting in empty pages). It does't however completly fix the issue, which is caused by a few different problems as explained by Marcus in comment #17.

[Launchpad Janitor (janitor)]

This bug was fixed in the package unity-scopes-shell - 0.5.4+14.10.20141015-0ubuntu1

---------------
unity-scopes-shell (0.5.4+14.10.20141015-0ubuntu1) utopic; urgency=low

  [ Pawel Stolowski ]
  * Don't query all favorite scopes on startup - query only next two
    scopes following current active. (LP: #1374481)
 -- Ubuntu daily release <email address hidden> Wed, 15 Oct 2014 15:39:34 +0000

[Michi Henning (michihenning)]

Not a bug in unity-scopes-api, removing it from affected projects.

[Chris Wayne (cwayne)]

As for comment 14, the el jueves scope has been fixed (and also removed from the image) so that's not affecting anything (also was never part of Nearby, so would only ever affect News) FWIW is was crashing on closing down, so it launched and got the content fine, the issue was that go scopes call SetScopeBase with nil on shutdown, which it wasn't handling properly

[Timo Jyrinki (timo-jyrinki)]

This is ready and QA sign-off:d in a silo, but this bug has not been marked as "topblocker" nor is it in the additional bug wishlist.

[Launchpad Janitor (janitor)]

This bug was fixed in the package unity-scopes-shell - 0.5.4+14.10.20141029.1~rtm-0ubuntu1

---------------
unity-scopes-shell (0.5.4+14.10.20141029.1~rtm-0ubuntu1) 14.09; urgency=low

  [ Pete Woods ]
  * Wait for location data at startup (with 1 second timeout) (LP:
    #1374481)
 -- Ubuntu daily release <email address hidden> Wed, 29 Oct 2014 13:16:23 +0000

[Launchpad Janitor (janitor)]

This bug was fixed in the package unity-scopes-shell - 0.5.4+15.04.20141119-0ubuntu1

---------------
unity-scopes-shell (0.5.4+15.04.20141119-0ubuntu1) vivid; urgency=low

  [ Marcus Tomlinson ]
  * Listen to list update pub/sub mechanism to invalidate smart scopes
    (LP: #1361221)

unity-scopes-shell (0.5.4+14.10.20141029.1~rtm-0ubuntu1) 14.09; urgency=low

  [ Pete Woods ]
  * Wait for location data at startup (with 1 second timeout) (LP:
    #1374481)
 -- Ubuntu daily release <email address hidden> Wed, 19 Nov 2014 08:20:34 +0000

[Omer Akram (om26er)]

I don't think this bug is really fixed. Today and NearyBy area always empty for me on reboot.

[XiaoGuo, Liu (liu-xiao-guo)]

Could this bug be fixed for utopic as well? On Utopic desktop, I cannot get the location information, while it is true for the vivid. Thanks!