Closed Bug 1036514 Opened 5 years ago Closed 5 years ago

Enable stumbler logging in logcat

Categories

(Android Background Services Graveyard :: Geolocation, defect)

Firefox 34
All
Android
defect
Not set

Tracking

(firefox35 fixed, firefox36 fixed, fennec35+)

RESOLVED FIXED
Firefox 36
Tracking Status
firefox35 --- fixed
firefox36 --- fixed
fennec 35+ ---

People

(Reporter: garvan, Assigned: garvan)

References

Details

Attachments

(2 files, 1 obsolete file)

Need a pref to turn on the logging, and to communicate that from Fennec to the stumbler service.
Blocks: 1032506
Component: General → Geolocation
Product: Firefox for Android → Android Background Services
Summary: [geolocation-stumbler] Fennec about:config pref to enable stumbler logging → Fennec about:config pref to enable stumbler logging
Version: Firefox 33 → Firefox 34
Is there a plan to have this fixed? Being able to see some activity in the logs will help testing this feature.
Flags: needinfo?(gkeeley)
There is this bug, and an intention to get to it as soon as possible.
Flags: needinfo?(gkeeley)
Summary: Fennec about:config pref to enable stumbler logging → Enable stumbler logging in logcat
Assignee: nobody → gkeeley
Attached patch stumblerlog_bug1036514.diff (obsolete) — Splinter Review
Setting 

| adb shell setprop log.tag.PassiveStumbler DEBUG |

will turn on additional debug logging for stumbler. The Log.d messages are wrapped in conditionals for the current log level (which is a cached value).

The value is cached in PassiveServiceReceiver. To refresh the cached value, toggle the MLS setting on/off, or stop/start Fennec.
Attachment #8519218 - Flags: review?(nalexander)
Comment on attachment 8519218 [details] [diff] [review]
stumblerlog_bug1036514.diff

Review of attachment 8519218 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/preferences/GeckoPreferences.java
@@ -904,5 @@
>             intent.putExtra("user_agent", GeckoAppShell.getGeckoInterface().getDefaultUAString());
>         }
> -       if (!AppConstants.MOZILLA_OFFICIAL) {
> -           intent.putExtra("is_debug", true);
> -       }

I *was* using this for debug logging, not anymore.

::: mobile/android/stumbler/java/org/mozilla/mozstumbler/service/AppGlobals.java
@@ +62,5 @@
> +        if (name.length() > maxLen) {
> +            name = name.substring(name.length() - maxLen, name.length());
> +        }
> +        return LOG_PREFIX + name;
> +    }

Log tags should be 23 characters or less. Log.<type>() functions don't care, but Log.isLoggable throws IllegalArgumentException if the log tag is longer than this.

All the files were touched as a result of this change (all files have LOG_TAG = makeLogTag(...) in them).

::: mobile/android/stumbler/java/org/mozilla/mozstumbler/service/mainthread/PassiveServiceReceiver.java
@@ +40,5 @@
>          }
>  
> +        if (Log.isLoggable(LOG_TAG, Log.DEBUG)) {
> +            AppGlobals.isDebug = true;
> +        }

Here is where the log level is cached.

::: mobile/android/stumbler/java/org/mozilla/mozstumbler/service/stumblerthread/StumblerService.java
@@ +143,5 @@
>      @Override
>      public void onDestroy() {
>          super.onDestroy();
>  
> +        UploadAlarmReceiver.cancelAlarm(this, !mScanManager.isPassiveMode());

A likely test approach is to toggle the MLS Setting, this will ensure the alarm gets cancelled.

@@ +203,5 @@
> +        boolean hasFilesWaiting = !DataStorageManager.getInstance().isDirEmpty();
> +        if (AppGlobals.isDebug) {
> +            Log.d(LOG_TAG, "Files waiting:" + hasFilesWaiting);
> +        }
> +        if (hasFilesWaiting) {

Just for additional logging.
Expected output:

D/Stumbler:erviceReceiver(19959): Stumbler: Sending passive start message | isDebug:true
D/Stumbler:ScanManager(19959): Scanning started...
D/Stumbler:GPSScanner(19959): New location: Location[gps 43.660376,-79.438877 acc=23 et=+7d21h46m54s548ms alt=31.0 vel=4.924429 bear=150.3 {Bundle[mParcelledData.dataSize=352]}]
D/Stumbler:ScanManager(19959): New passive location
D/Stumbler:Reporter(19959): Received bundle: {"timestamp":1415378227938,"wifi_count":11,"wifi":[{"signal":-87,"key":"bc1401ec4ba8","frequency":2432},{"signal":-86,"key":"38607774b216","frequency":2462},{"signal":-85,"key":"40f201e54801","frequency":2462},{"signal":-83,"key":"0023f89aebdf","frequency":2437},{"signal":-88,"key":"00236a257b0f","frequency":2462},{"signal":-61,"key":"00236a44b964","frequency":2412},{"signal":-87,"key":"0018f8f3d1c2","frequency":2437}],"lon":-79.438877,"cell_count":3,"altitude":31,"cell":[{"asu":23,"radio":"umts","mnc":720,"psc":376,"cid":1660196,"mcc":302,"lac":60330},{"asu":-66,"radio":"umts","mnc":720,"psc":376,"mcc":302},{"asu":23,"radio":"umts","mnc":720,"psc":376,"cid":1660199,"mcc":302,"lac":60330}],"radio":"gsm","accuracy":23,"lat":43.660376}
D/StumblerFiles(19959): reports-t1415378416936-r1-w11-c3.gz
D/Stumbler_dAlarmReceiver(27477): schedule alarm (ms):2000
D/Stumbler_ScanManager(27477): Scanning started...
D/Stumbler_dAlarmReceiver(27477): Alarm upload(), call AsyncUploader
D/Stumbler_ctCommunicator(27477): Send data: 0.36 kB Session Total:0.36 kB
Comment on attachment 8519218 [details] [diff] [review]
stumblerlog_bug1036514.diff

Review of attachment 8519218 [details] [diff] [review]:
-----------------------------------------------------------------

This looks fine other than the state assignment noted below.

::: mobile/android/stumbler/java/org/mozilla/mozstumbler/service/mainthread/PassiveServiceReceiver.java
@@ +39,5 @@
>              return;
>          }
>  
> +        if (Log.isLoggable(LOG_TAG, Log.DEBUG)) {
> +            AppGlobals.isDebug = true;

Shouldn't this always assign?  So that if you toggle, you set the state.  Right now, you're ORing the state over time.

Also, be clear in AppGlobals that isDebug = false to start.  Right now, it's unset, which is false; but be clear.  And add a comment to isDebug explaining that isDebug can be changed at run time and CANNOT GUARD PII.  In android-sync, we added a special Logger.pii() method so that it was always clear how to really push the log level; and we don't let you turn on pii at run.
Attachment #8519218 - Flags: review?(nalexander) → review+
(In reply to Garvan Keeley [:garvank] from comment #5)
> Expected output:
> 
> D/Stumbler:erviceReceiver(19959): Stumbler: Sending passive start message |
> isDebug:true
> D/Stumbler:ScanManager(19959): Scanning started...
> D/Stumbler:GPSScanner(19959): New location: Location[gps
> 43.660376,-79.438877 acc=23 et=+7d21h46m54s548ms alt=31.0 vel=4.924429
> bear=150.3 {Bundle[mParcelledData.dataSize=352]}]
> D/Stumbler:ScanManager(19959): New passive location
> D/Stumbler:Reporter(19959): Received bundle:
> {"timestamp":1415378227938,"wifi_count":11,"wifi":[{"signal":-87,"key":
> "bc1401ec4ba8","frequency":2432},{"signal":-86,"key":"38607774b216",
> "frequency":2462},{"signal":-85,"key":"40f201e54801","frequency":2462},
> {"signal":-83,"key":"0023f89aebdf","frequency":2437},{"signal":-88,"key":
> "00236a257b0f","frequency":2462},{"signal":-61,"key":"00236a44b964",
> "frequency":2412},{"signal":-87,"key":"0018f8f3d1c2","frequency":2437}],
> "lon":-79.438877,"cell_count":3,"altitude":31,"cell":[{"asu":23,"radio":
> "umts","mnc":720,"psc":376,"cid":1660196,"mcc":302,"lac":60330},{"asu":-66,
> "radio":"umts","mnc":720,"psc":376,"mcc":302},{"asu":23,"radio":"umts","mnc":
> 720,"psc":376,"cid":1660199,"mcc":302,"lac":60330}],"radio":"gsm","accuracy":
> 23,"lat":43.660376}
> D/StumblerFiles(19959): reports-t1415378416936-r1-w11-c3.gz
> D/Stumbler_dAlarmReceiver(27477): schedule alarm (ms):2000
> D/Stumbler_ScanManager(27477): Scanning started...
> D/Stumbler_dAlarmReceiver(27477): Alarm upload(), call AsyncUploader
> D/Stumbler_ctCommunicator(27477): Send data: 0.36 kB Session Total:0.36 kB

I know you want this logging, but this is PII!  You can't leak GPS output to the log!  On Android, it requires a permission, and reading the log requires a different permission; don't allow an escalation attack.
> >  
> > +        if (Log.isLoggable(LOG_TAG, Log.DEBUG)) {
> > +            AppGlobals.isDebug = true;
> 
> Shouldn't this always assign?  So that if you toggle, you set the state. 

It should, I had additional condition I just took out, and didn't correct the assignment.
I suggest you add explicit log{Debug,Pii}, etc methods; make debug runtime configurable, and PII build time configurable.  As it stands, our audit of the original code was not strenuous enough :/

You shouldn't land your (modified) patch yet since it makes this strictly worse: an attacker can now set debug in a circumstance (Fennec!) where they couldn't before, and thereby get the user's GPS location.  But technically your patch is fine; it just needs other work to not do bad things.
> I know you want this logging, but this is PII!  You can't leak GPS output to
> the log!  On Android, it requires a permission, and reading the log requires
> a different permission; don't allow an escalation attack.

Certainly, a persistent history of locations is PII, but showing where the user is *right now*, in an app they have given permission for us to show a location. Moreover, they have explicitly logged this information. This is PII?
I won't try land anything until I the all-clear on what I can log.
(In reply to Garvan Keeley [:garvank] from comment #10)
> > I know you want this logging, but this is PII!  You can't leak GPS output to
> > the log!  On Android, it requires a permission, and reading the log requires
> > a different permission; don't allow an escalation attack.
> 
> Certainly, a persistent history of locations is PII, but showing where the
> user is *right now*, in an app they have given permission for us to show a
> location. Moreover, they have explicitly logged this information. This is
> PII?

Is it Personally Identifying Information?  Can it be used to identify a person?  I certainly interpret PII to say yes.  And the logcat extends backwards in time, so it's not like you only see an instantaneous reading.

In any case, you're enabling another App that has the read logs permission (on older phones, newer devices prevent this entirely) to read GPS locations.  Under no circumstance should you do that.
Best for me to stay clear of any grey areas. The fix for all this is trivial: don't log this info. I'll pull the lat/long, and obfuscate the wifi scans and cell scans, and post the updated log.
Running through some testing with this patch, but here is the log now, free of PII, and still shows what stumbler is doing:

D/PassiveStumbler(29926): Stumbler: Sending passive start message | isDebug:true
D/Stumbler_tumblerService(29926): Files waiting:false
D/Stumbler_ScanManager(29926): Scanning started...
D/Stumbler_ScanManager(29926): New passive location
V/Stumbler_WifiScanner(29926): Activate Periodic Scan
V/Stumbler_WifiScanner(29926): WiFi Scanning Timer fired
V/Stumbler_WifiScanner(29926): WiFi Scanning Timer fired
V/Stumbler_WifiScanner(29926): WiFi Scanning Timer fired
D/Stumbler_Reporter(29926): Received bundle
V/Stumbler_WifiScanner(29926): WiFi Scanning Timer fired
V/Stumbler_WifiScanner(29926): Deactivate periodic scan
D/Stumbler_dAlarmReceiver(29926): cancelAlarm
D/Stumbler_Reporter(29926): shutdown
D/Stumbler_tumblerService(29926): onDestroy
D/Stumbler_Reporter(29926): Received bundle
D/StumblerFiles(29926): reports-t1415401033701-r1-w9-c1.gz
D/Stumbler_ScanManager(29926): Scanning stopped
D/PassiveStumbler(29926): Stumbler: Sending passive start message | isDebug:true
D/Stumbler_tumblerService(29926): Files waiting:true
D/Stumbler_dAlarmReceiver(29926): schedule alarm (ms):2000
D/Stumbler_ScanManager(29926): Scanning started...
D/Stumbler_dAlarmReceiver(29926): Alarm upload(), call AsyncUploader
D/Stumbler_ctCommunicator(29926): Send data: 0.28 kB Session Total:0.28 kB
D/Stumbler_ctCommunicator(29926): Send data: 0.32 kB Session Total:0.61 kB
* Removed any logging of PII: location, wifi, and cell info.
* AppGlobals.isDebug _was_ being used in stumbler for development-level debugging. Now it is used for logging of user-level messages. I will need to port this change back to the MozStumbler github: https://github.com/mozilla/MozStumbler/issues/1227 
* AppGlobals.isDebug also changed the storage location to a public location, but this is now for user-level non-PII debugging, thus this code was removed.
Attachment #8519218 - Attachment is obsolete: true
Attachment #8519263 - Flags: review?(nalexander)
Attached file All uses of Log
Adding the full list of the use of Log in stumbler.
Comment on attachment 8519272 [details]
All uses of Log

Victor you want to double-check the things we are logging?
Attachment #8519272 - Flags: feedback?(vng)
Victor, comment 17 and the attachment of the Logs, isn't for detailed review without line context, and I don't see any particular problem. It illustrates how little logging of variables there is (most logs are string constants that just describe state). 
In the few places where the code logs variables, I think the code is ok (no  PII), maybe it could be a bit clearer for grep'ing the code periodically to check the logging, something we can cleanup in Github for future.
Comment on attachment 8519263 [details] [diff] [review]
stumblerlog_bug1036514.diff

Review of attachment 8519263 [details] [diff] [review]:
-----------------------------------------------------------------

I'm fine with this if you are, but in future, please separate mechanical changes (LOGTAG mangling) from substantive changes (how the AppConstants.isDebug gets set).
Attachment #8519263 - Flags: review?(nalexander) → review+
Thanks for there review, yeah I could have separated those items better.

Victor, we should consider Nick's point about logging on pre-4.2 being insecure, and do a log review on the stand-alone stumbler.

I'll update the bug in stumbler github, but I need 3 logging states (the first 2 we have), 
1) quiet state, 
2) |adb shell setprop log.tag.PassiveStumbler DEBUG| turns on some noisy PII-safe debugging for QA, 
3) _The missing log level_: if built in debug, log detailed scanning info; developing without this level of verbosity is hard
Attachment #8519272 - Flags: feedback?(vng)
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/20c8a5244227
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Whiteboard: [fixed-in-fx-team]
Target Milestone: --- → Firefox 36
Comment on attachment 8519263 [details] [diff] [review]
stumblerlog_bug1036514.diff

Approval Request Comment
[Feature/regressing bug #]: Stumbler in Fennec
[User impact if declined]: None. This adds logging for QA, without it, they can't verify the feature is working as expected.
[Describe test coverage new/current, TBPL]: None
[Risks and why]: Zero risk, this code adds a debug logging mode. The logging is very generic, no PII.
[String/UUID change made/needed]: None.
Attachment #8519263 - Flags: approval-mozilla-aurora?
Attachment #8519263 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
tracking-fennec: --- → ?
tracking-fennec: ? → 35+
You need to log in before you can comment on or make changes to this bug.