Today Scope

arale ota6 reports of only date and weather showing

Bug #1489478 reported by Kyle Nitzsche
16
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Canonical System Image
Fix Released
High
John McAleely
Canonical System Image ww40-2015 "ota7"
Today Scope
Fix Released
Critical
Kyle Nitzsche

Bug Description

Two users reports that on MX4 (arale) with OTA6 installed only Date and Weather display. (not all user experience this.)

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

Perhaps this is relevant. I found a smart scope server error in scope-registry.log relating to weather scope:
I noticed this in the scope-registry.log:
36802 : unity::ResourceException: HTTP request failed with: bad_gateway(502)
 36803 <!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">
 36804 <html><head>
 36805 <title>502 Proxy Error</title>
 36806 </head><body>
 36807 <h1>Proxy Error</h1>
 36808 <p>The proxy server received an invalid^M
 36809 response from an upstream server.<br />^M
 36810 The proxy server could not handle the request <em><a href="/smartscopes/v2/weatherchannel/search">GET&nbsp;/smartscopes/v2/weatherchannel/search</a></em>.<p>
 36811 Reason: <strong>Error reading from remote server</strong></p></p>
 36812 <p>Additionally, a 403 Forbidden
 36813 error was encountered while trying to use an ErrorDocument to handle the request.</p>
 36814 <hr>
 36815 <address>Apache/2.2.22 (Ubuntu) Server at dash.ubuntu.com Port 443</address>
 36816 </body></html>

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

Please attach /home/phablet/.cache/upstart/scope-registry.log from a time the issue occurred if possible.

Also, please also attach the output of this command on the device: click list > clicks

Many thanks

Kyle Nitzsche (knitzsche)
summary: - arale ota6 user reports only data and weather showing
+ arale ota6 reports of only data and weather showing
Revision history for this message
John McAleely (john.mcaleely) wrote : Re: arale ota6 reports of only data and weather showing

Is this likely to be a problem with the upgrade process? is it the bug we found the last OTA when the user installed scope trumped the one in the image?

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

I just found a case on refresh where Today scope OTA6 krillin [1] displayed nothing after Today's News.

The latest scope-registry.log shows this:

Image not found, adding default:
"file:///custom/click/com.canonical.elpais/0.8.5/ELPAIS/images/default.png"
new item found
video found "http://ep00.epimg.net/elpais/videos/2015/08/26/videos/1440609981_013872_1440609998.mp4"
Type content:encoded not found in item
new item found
parsing ended
query complete, status: error

It looks like 1) Today scope needs to be made more resilient to child scopes returning errors on query completion and 2) elpais child scope is behaving badly.

[1] phablet@ubuntu-phablet:~$ system-image-cli -i
current build number: 110
device name: krillin
channel: ubuntu-touch/rc-proposed/bq-aquaris.en
last update: 2015-08-27 14:48:32
version version: 110
version ubuntu: 20150827
version device: 20150821-736d127
version custom: 20150821-887-33-32-vivid

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :
Download full text (4.8 KiB)

I also found that occasionally on OTA6 krillin the Weather channel scope does NOT display:

(it happened to me on the 10th refresh on brand new image and then did not happen in 50 refreshes after that).

When Weather does not display, the following exists in scope-registry.log, indicating Today scope thinks on this run weather scope is NOT currently registered:

"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.day_day, local_id: day_localId"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.weatherchannel, local_id: weather_channel_localId"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.holidays_holidays, local_id: holidays_localID"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.events_events, local_id: events_localID"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.tasks_sctasks, local_id: tasks_localID"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.contacts_contacts, local_id: contacts"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.fitbit_fitbit, local_id: fitbit_localId"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.twittertrending_twittertrending, local_id: twitter"
"com.canonical.scopes.dashboard_dashboard: ADDING CATEGORY KEYWORD child scope: com.canonical.scopes.calls_calls, by keyword recent, to department: "
"com.canonical.scopes.dashboard_dashboard: ADDING CATEGORY KEYWORD child scope: com.canonical.scopes.texts_texts, by keyword recent, to department: "
"com.canonical.scopes.dashboard_dashboard: ADDING CATEGORY KEYWORD child scope: com.ubuntu.telegram_sctelegram, by keyword recent, to department: "
"com.canonical.scopes.dashboard_dashboard: ADDING CATEGORY KEYWORD child scope: com.canonical.elpais_ELPAIS, by keyword news.headlines, to department: "
"com.canonical.scopes.dashboard_dashboard: ADDING CATEGORY KEYWORD child scope: com.canonical.scopes.bbc_bbc, by keyword news.headlines, to department: "
"com.canonical.scopes.dashboard_dashboard: ADDING CATEGORY KEYWORD child scope: com.canonical.scopes.euronews_euronews, by keyword news.headlines, to department: "
"com.canonical.scopes.dashboard_dashboard: scope is NOT REGISTERED, skipping: com.canonical.scopes.weatherchannel"
"com.canonical.scopes.aggregator_aggregator: NOT using departments"
"com.canonical.scopes.aggregator_aggregator: scope is NOT REGISTERED, skipping: com.canonical.scopes.weatherchannel"

Here is an example of how it looks on refresh with Weather scope available:
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.day_day, local_id: day_localId"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.weatherchannel, local_id: weather_channel_localId"
"com.canonical.scopes.dashboard_dashboard: ADDING DECLARED child scope: com.canonical.scopes.holidays_holidays, local_id: holidays_localID"
"com.canonical.scopes.dashboard_dashboard: ...

Read more...

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

I just found a case on refresh where Today scope displayed nothing after Today's News.

The latest scope-registry.log shows this:

Image not found, adding default:
"file:///custom/click/com.canonical.elpais/0.8.5/ELPAIS/images/default.png"
new item found
video found "http://ep00.epimg.net/elpais/videos/2015/08/26/videos/1440609981_013872_1440609998.mp4"
Type content:encoded not found in item
new item found
parsing ended
query complete, status: error

It looks like:
1) Today scope (really-scope-aggregator) needs to be made more resiliant to child scopes returning errors on query completion.
2) elpais may be erroring on a query

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

SSRegistry log [1] reports an exception (json error) with weather scope:

[2015-08-27 15:02:07.923155] INFO: SSRegistry: SmartScopesClient.search(): GET https://dash.ubun
tu.com/smartscopes/v2/weatherchannel/search?q=&session_id=a421b14f-6212-4129-959e-97130c6609ec&q
uery_id=0&platform=phone&settings=%7B%22internal.location%22%3Atrue%7D&locale=en_US&country=US&l
atitude=42.52440&longitude=-71.76570&limit=3
[2015-08-27 15:02:07.923212] INFO: SSRegistry: User agent: scopes-api=0.6.19+15.04.20150724.3-0ubuntu1&plugin=0.5.5+15.04.20150810.1-0ubuntu1&unity8=8.11+15.04.20150821-0ubuntu1&release=15.04&build=110&partner=bq
[2015-08-27 15:02:08.441339] ERROR: SSRegistry: SmartScopesClient.handle_chunk(): Failed to parse line: unity::ResourceException: Failed to parse json string: * Line 1, Column 1
  Syntax error: value, object or array expected.

[1] /home/phablet/.local/share/unity-scopes/unconfined/SSRegistry/logs/SSRegistry-0.log

Kyle Nitzsche (knitzsche)
summary: - arale ota6 reports of only data and weather showing
+ arale ota6 reports of only date and weather showing
Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

SSRegistry log shows many "couldn't resolve host" errors:

[2015-08-27 14:49:02.996770] ERROR: SSRegistry: SmartScopesClient.get_remote_scopes(): Failed to retrieve remote scopes from uri: https://dash.ubuntu.com/smartscopes/v2/remote-scopes: unity::ResourceException: /build/buildd/net-cpp-1.2.0+15.04.20150415.2/src/core/net/http/impl/curl/request.h@220 - operator(): Couldn't resolve host name
[2015-08-27 14:49:02.996890] ERROR: SSRegistry: SmartScopesClient.get_remote_scopes(): Using remote scopes from cache
[2015-08-27 14:49:02.997196] ERROR: SSRegistry: SSRegistryObject: get_remote_scopes() failed: unity::ResourceException: SmartScopesClient.get_remote_scopes(): Remote scopes cache is empty:
    unity::ResourceException: /build/buildd/net-cpp-1.2.0+15.04.20150415.2/src/core/net/http/impl/curl/request.h@220 - operator(): Couldn't resolve host name
[2015-08-27 14:49:13.000189] INFO: SSRegistry: SmartScopesClient.get_remote_scopes(): GET https://dash.ubuntu.com/smartscopes/v2/remote-scopes?locale=en_US
[2015-08-27 14:49:13.000673] INFO: SSRegistry: User agent: partner=bq%0A

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

attaching SSRegistry-0.log

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

A couple users report disabling calls scope fixes the issue for them.

I asked them in phone-list thread to 1) confirm this is reliable connected and 2) what their calls click version is

arale ota6 custom tarball contains calls scopes version 1.3.1

For me, krillin ota6 (proposed): I do not have an issue. I have calls 1.31. HOWEVER: my calls db (history-service db) is artificially created (I don't have a sim for the krillin).

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

main reporter says enabling/disabling calls scope makes no difference.

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

Note: I see occasionally no Twitter Trending results in Today. And I see these in scope-registry.log:

"
query complete, status: error

: json: cannot unmarshal object into Go value of type []main.TrendList

"

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

And every single query that returns an error in my log is followed on the next line with a go error, probably from the twitter scope (written in go), although sometimes the reported object is different like so:

query complete, status: error

: json: cannot unmarshal object into Go value of type []main.Loc

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

So far I have been unable to reproduce the main reported issues of this bug: only Day and Weather scopes showing.

As mentioned I am running the rc-proposed OTA6 for krillin plus I updated Today scope from store to 1.9.1.

We need to be sure anyone who has this bug:
1) confirms the Today scope settings are sane (child scopes are enabled)
2) they have the expected click packages installed (I attach here my click packages for reference)

If possible we need their:
* /home/phablet/.cache/upstart/scope-registry.log
* adb shell click list > clicks
* output of device system-image-cli -i

Revision history for this message
JkB (joergberroth) wrote :

For me on rc-proposed on krillin everything works on todays scope but the last calls!
If I enable them this section won't show up.
If disabled it works.

Hope that helps

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

Hi Joerg (Sorry if I have your name wrong):

Can you please help me understand?

Note: the "Recent" category in the Today scope now shows:
* the most recent call if a call was received today (It does not show calls received yesterday or before, or calls you made ever)
* the most recent message if a message was received today (it does not show messages received yesterday or before or messages you made)
* the most recent telegram (or if you have not used telegram a message saying it could not retrieve your telegram data)

Examples:
If you disable Calls in Today scope and enabled Messages and Telegram: you should still see a message (if you received one today) and then a telegram item
If you disable Calls, Messages and Telegram, you will not see the "Recent" section at all.

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

I dropped a word. If you have Telegram enabled you will see the most recent RECEIVED telegram (unless it is quite old).

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

The bug reporter on email provided his clicks list and scope-registry.log (via email in phone-list) and I attach them here.

Click list looked OK to me.

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

reporter's click list

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

reporter's scope-registry.log

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

Based on the scope-registry.log, I wonder whether the network is actually on and working. I also wonder whether location is disabled in Today scope settings. (I've asked in phone-list to check this.)

This is based on the following, which happens every time the reporter refreshed the Today scope:
"
Location object not found: "unity::scopes::NotFoundException: SearchMetadata::location() (name = location)"
===== The JSON file missing!
"
These are from the new Day scope lunar phase caching. Line one indicates location is not known, but the exception is handled, and line two indicates there is no lunar phase cache file, which indicates the used has *never* successfully connected the Day scope with the web api.)

A lot of normal content would not display under the following circumstances:
* reporter has My Activity (FitBit) disabled [1]
* reporter has twitter-trending disabled [1]
* reporter may not have synced Google contacts, in which case that would not show
* with no network, news would not show
* if no calls received or texts received today, Recent would only have a single results from Telegram, and if user has not authenticated from the TG app, this would be a single text line that is easy to miss

I would expect to see Events though.

[1] from reporter scope-registery.log
"com.canonical.scopes.aggregator_aggregator: scope is NOT ENABLED, skipping: com.canonical.scopes.fitbit_fitbit"
"com.canonical.scopes.aggregator_aggregator: scope is NOT ENABLED, skipping: com.canonical.scopes.twittertrending_twittertrending"

Revision history for this message
Michi Henning (michihenning) wrote :

It looks like the implementation of the result forwarder in the aggregator scope isn't thread-safe. I suspect that this can lead to a race where the observers are never notified, meaning that, beyond a certain point, nothing will be displayed.

Even if this doesn't fix this issue, the result forwarder still needs to be made thread-safe regardless. For an example thread-safe implementation, you can check BufferedResultForwarder.cpp and BufferedSearchReplyImpl.cpp in src/scopes/utility/internal in the unity-scopes-api tree.

Yuan-Chen Cheng (ycheng-twn)
Changed in today-scope:
importance: Undecided → Critical
Revision history for this message
Paweł Stołowski (stolowski) wrote :

Michi is right about the thread safety problem in the forwarder code. The original old buffered result forwarder (in mediascanner scope) had this issue and afair since we didn't have that code in the scopes library at that time, it was copied to some other aggregator scopes (namely Today scope). We now have BufferedResultForwarder in scopes API, but it uses somewhat different semantics than the original implementation. For a quickfix I think all you need to do is make sure that access to 'ready' state flag is synchronized.

Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

Regarding the thread non-safety issue. I just discussed this with Pawel.
1) This issue has been present in all of our aggregator scopes from the very beginning (before scope-aggregator was used).
2) It might occasionally create an issue for an agg scope, but on refresh it is highly unlikely to occur again immediately, therefore this cannot explain a report such as this, where the user seems to say he only sees Day and Weather scopes persistently through multiple refreshes. Therefore I do not think this is actually a CRITICAL bug. (In general our agg scopes are quite reliable.)
3) This seems like an easy to fix. I will do it in scope-aggregator. All agg scopes will need to rebase on the new scope-aggregator when it is ready.

Revision history for this message
Facundo Batista (facundo) wrote :

The error detail indicates that the Dash Server's search received an error from the The Weather Channel backend.

This happens once in a while, but it's not frequent at all. It should be handled gracefully client side.

Thanks,

Revision history for this message
John McAleely (john.mcaleely) wrote :

I agree this is not yet proven to be critical - I think it would have to be widely reproduced to be handled as a critical fix for ota-6. At the moment this is a candidate for any hotfix release we sweep issues found with ota-6 into.

Changed in canonical-devices-system-image:
importance: Undecided → High
Revision history for this message
Kyle Nitzsche (knitzsche) wrote :

Making the buffering code of scope-aggregator (upstream to today) thread safe is tracked in bug 1489906.

Pat McGowan (pat-mcgowan)
Changed in canonical-devices-system-image:
assignee: nobody → John McAleely (john.mcaleely)
milestone: none → ww40-2015
status: New → Confirmed
Yuan-Chen Cheng (ycheng-twn)
Changed in today-scope:
status: New → Fix Released
status: Fix Released → Fix Committed
assignee: nobody → Kyle Nitzsche (knitzsche)
Pat McGowan (pat-mcgowan)
Changed in canonical-devices-system-image:
status: Confirmed → Fix Committed
Pat McGowan (pat-mcgowan)
Changed in canonical-devices-system-image:
status: Fix Committed → Fix Released
Yuan-Chen Cheng (ycheng-twn)
Changed in today-scope:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.