1036514 - Enable stumbler logging in logcat

Status: RESOLVED FIXED

(Android Background Services Graveyard :: Geolocation, defect)

Description

[:garvan]

Need a pref to turn on the logging, and to communicate that from Fennec to the stumbler service.

Comment 1

[Catalin Suciu [:csuciu]]

Is there a plan to have this fixed? Being able to see some activity in the logs will help testing this feature.

Comment 2

[:garvan]

There is this bug, and an intention to get to it as soon as possible.

Comment 3

[:garvan]

Attachment: stumblerlog_bug1036514.diff

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.

Comment 4

[:garvan]

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.

Comment 5

[:garvan]

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 6

[Nick Alexander :nalexander [he/him]]

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.

Comment 7

[Nick Alexander :nalexander [he/him]]

(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.

Comment 8

[:garvan]

> >  
> > +        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.

Comment 9

[Nick Alexander :nalexander [he/him]]

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.

Comment 10

[:garvan]

> 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?

Comment 11

[:garvan]

I won't try land anything until I the all-clear on what I can log.

Comment 12

[Nick Alexander :nalexander [he/him]]

(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.

Comment 13

[:garvan]

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.

Comment 14

[:garvan]

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

Comment 15

[:garvan]

Attachment: stumblerlog_bug1036514.diff

* 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.

Comment 16

[:garvan]

Attachment: All uses of Log

Adding the full list of the use of Log in stumbler.

Comment 17

[:garvan]

Comment on attachment 8519272 [details]
All uses of Log

Victor you want to double-check the things we are logging?

Comment 18

[:garvan]

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 19

[Nick Alexander :nalexander [he/him]]

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).

Comment 20

[:garvan]

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

Comment 21

[:garvan]

Try green:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=43775feb5ec4

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/20c8a5244227

Comment 23

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/20c8a5244227

Comment 24

[:garvan]

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.

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/70837f682156