806394 - updater should log more things

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[[e-mail] (:bhearsum)]

On desktop we can set app.update.log = True to get more detailed information from the updater. Eg:
app.update.lastUpdateTime.background-update-timer 1350570593

Partial listing of messages:
AUS:SVC Checker:checkForUpdates - sending request to: https://aus3.mozilla.org/update/3/Firefox/15.0.1/20120905151427/WINNT_x86-msvc/en-US/release/Windows_NT%205.1.3.0%20(x86)/default/default/update.xml

AUS:SVC Checker:onProgress - 42/42

AUS:SVC Checker:onLoad - request completed downloading document

AUS:SVC Checker:onLoad - number of updates available: 0


The "sending request to" and "number of updates available" are particularly important. Also the details of an update when it is available.

Comment 1

[[e-mail] (:bhearsum)]

I just want to make sure you're aware that it can be nearly impossible to debug certain types of update problems without this information.

Comment 2

[Mark Capella [:capella]]

Attachment: Patch (v1)

As discussed briefly in #build ... we can add more information to logcat from the android UpdateService ... see attached for an initial pass ... this may be more than you need (?)

How to capture downloading an update using my nightly build is the next trick ... maybe we can hardcode something for testing?

Comment 3

[Mark Capella [:capella]]

Attachment: Sample logcat

Comment 4

[Kevin Brosnan [Ex-Mozilla]]

Should this logging be behind a pref? There was a lot of work to cleanup the logcat spew. In release and Beta builds that we put in the Play Store this is just noise.

Comment 5

[Mark Capella [:capella]]

I had tried to tie it to a preference like |app.update.log| from comment #0 that the user could switch in the pref.js file but was unable to read / write values there from the PrefsHelper routine. Since UpdateService isn't part of package org.mozilla.gecko I wound up having to import org.mozilla.gecko.PrefsHelper to build it successfully.

But then, "Preferences:Get" messages sent from PrefsHelper.java to Gecko weren't making it to the BrowserApp observer in Browser.js like I expected them to... I was wondering if this is due to UpdateService being in a different build package (org.mozilla.gecko.updater vs. org.mozilla.gecko) ... 

As an alternative I was thinking we could extend the current approach in the routine and tie it to a Java SharedPrefs entry in user_preferences.

Comment 6

[Mark Finkle (:mfinkle) (use needinfo?)]

Two things:

#1:
Don't use Gecko prefs. Let's use the Log.isLoggable(...) approach. See this code for a simple example:
http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/db/LocalBrowserDB.java#41

Now we have a debug(...) method that will only output if the log level is enabled. Enabling is done via adb:

adb shell setprop log.tag.<YOUR_LOG_TAG> <LEVEL>

YOUR_LOG_TAG = UpdateService
LEVEL = DEBUG

#2:

I don't know that we need log calls on each function entry. Seems overkill. Although it's not a perfect match in functionality, looking in this for for LOG(...) calls might show us what types of data we should log:
http://mxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/nsUpdateService.js

Comment 7

[Mark Capella [:capella]]

Nice ! :D

Comment 8

[[e-mail] (:bhearsum)]

(In reply to Kevin Brosnan [:kbrosnan] from comment #4)
> Should this logging be behind a pref? There was a lot of work to cleanup the
> logcat spew. In release and Beta builds that we put in the Play Store this
> is just noise.

I would strongly discourage putting things like logging the update URL and short "failed for reason X" behind a pref for builds that update through us. Oftentimes update problems are very difficult to reproduce, and having information like this always available sometimes makes it possible to debug issue that we otherwise wouldn't be able to.

I don't see any reason to it enabled for Beta or Release though.

Comment 9

[[e-mail] (:bhearsum)]

Comment on attachment 707469 [details]
Sample logcat

I don't really feel qualified to comment on the patch directly, I have a things about this output though:

>mozilla@ubuntu:~/mozilla-central$ adb logcat -c;adb logcat | grep UpdateService
>D/UpdateService(26455): onStartCommand()
>D/UpdateService(26455): setAutoDownloadPolicy()
>D/UpdateService(26455): registerForUpdates()
>D/UpdateService(26455): getLastAttemptDate()
>D/UpdateService(26455): onHandleIntent()

If these methods always return the same thing, I'm not sure it matters to have them in the log.

>D/UpdateService(26455): openConnectionWithProxy() url:   https://aus2.mozilla.org/update/4/Fennec/21.0a1/20130127143652/Android_arm-eabi-gcc3/en-US/default/4.1.1/default/default/21.0a1/update.xml

This is the big thing I want, thumbs up!

>D/UpdateService(26455): openConnectionWithProxy() proxy: DIRECT@
>D/UpdateService(26455): found: org.apache.harmony.xml.dom.DocumentImpl@41d14dc8
>D/UpdateService(26455): found no 'update' node
>D/UpdateService(26455): onHandleIntent()
>I/UpdateService(26455): no update available

"no update available" is definitely useful.

I'd be curious to see output from a request that finds an update too. If there's any way to override the channel I could set-up a fake update on the server to help test.

Comment 10

[Mark Capella [:capella]]

Attachment: Patch (v2)

Comment 11

[Mark Capella [:capella]]

After testing with bhearsum and reviewing existing messages specifically in failure conditions, it seems if we add this one extra info message we should satisfy the requirements. 

(They don't want it behind a pref so I've avoided the extra code)

Comment 12

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 708160 [details] [diff] [review]
Patch (v2)

I'll allow it, but we have been cracking down on logging URLs for privacy issues.

Also note: Using the isLoggable() approach is not the same as "behind a pref" since the user can turn on the logging from ADB and not need to start Firefox and use about:config and then restart.

If we add any other logging in this file, I'll suggest using isLoggable.

Comment 13

[Mark Capella [:capella]]

Noted and thanks. I meant to convey that they wanted to always log that message, without previously having to set a flag, being concerned that certain failures are difficult to reproduce.

Comment 14

[Mark Capella [:capella]]

trying: https://tbpl.mozilla.org/?tree=Try&rev=dee8f5b6d688

Comment 15

[Mark Capella [:capella]]

and on to inbound
https://hg.mozilla.org/integration/mozilla-inbound/rev/b93addbe127d

Comment 16

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b93addbe127d