Closed Bug 1021395 Opened 6 years ago Closed 4 years ago

Web app machinery dumps lots of semi-sensitive data to logcat

Categories

(Firefox for Android :: Web Apps (PWAs), defect, P1, major)

All
Android
defect

Tracking

()

RESOLVED WONTFIX

People

(Reporter: rnewman, Assigned: myk)

References

(Depends on 1 open bug)

Details

(Whiteboard: [WebRuntime])

Attachments

(1 file, 5 obsolete files)

Find and install an app.

E/GeckoConsole(25145): [nav] Received navigate event: /app/8tracks?src=featured
...
E/GeckoConsole(25145): [req] GETing https://marketplace.firefox.com/api/v1/fireplace/app/8tracks/?cache=1&dev=android&device=tablet&lang=en-US&limit=25&region=us&vary=0
...
D/GeckoWebappManager(25145): _downloadApk for http://8tracks.com/mobile/manifest.webapp
D/GeckoWebappManager(25145): downloading APK from https://controller.apk.firefox.com/application.apk?manifestUrl=http%3A%2F%2F8tracks.com%2Fmobile%2Fmanifest.webapp
D/GeckoWebappManager(25145): downloading APK to /storage/emulated/0/Download/http8trackscommobilemanifestwebapp.apk
...


We try not to log this kind of thing at a default-on log level, because other apps on Android can read it.
Severity: normal → major
Priority: -- → P1
Whiteboard: [WebRuntime]
Assignee: nobody → mhaigh
Step one is to implement a way for developers to print out debug statements which are only printed to the Android log when Fennec is in debuggable mode.

I'm unsure if this is the best approach as I don't like having to force a getIsDebuggable call at the end of GeckoApp onCreate, but as I couldn't make getIsDebuggable static this was the next best way of making that value available to JNI.  I'm most concerned around whether this is going to increase startup time.
Attachment #8447506 - Flags: feedback?(wjohnston)
Attachment #8447506 - Flags: feedback?(myk)
Attachment #8447506 - Flags: feedback?(mark.finkle)
Comment on attachment 8447506 [details] [diff] [review]
Implement Android Log debug method which only prints out when Fennec is debuggable

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

We already have DEBUG_BUILD in AppConstants.java.in, which is computed at build time.

I'm sure there's an equivalent in Gecko, but it would seem that the whole PackageManager shenanigans is unnecessary.
Comment on attachment 8447506 [details] [diff] [review]
Implement Android Log debug method which only prints out when Fennec is debuggable

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

::: mobile/android/modules/AndroidLog.jsm
@@ +69,5 @@
>    w: (tag, msg) => __android_log_write(ANDROID_LOG_WARN, "Gecko" + tag.substring(0, MAX_TAG_LENGTH), msg),
>    e: (tag, msg) => __android_log_write(ANDROID_LOG_ERROR, "Gecko" + tag.substring(0, MAX_TAG_LENGTH), msg),
> +  dd: (tag, msg) => {
> +    let jni = new JNI();
> +    let cls = jni.findClass("org/mozilla/gecko/GeckoApp");

We shouldn't be doing JNI work on every debug call. This isn't a value that's going to change over time.

I'd be inclined to simply preprocess this file rather than go grubbing around through JNI, but if JNI is the best option, let's compute this once.
Depends on: 1032936
Comment on attachment 8447506 [details] [diff] [review]
Implement Android Log debug method which only prints out when Fennec is debuggable

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

(In reply to Richard Newman [:rnewman] from comment #3)

> We shouldn't be doing JNI work on every debug call. This isn't a value
> that's going to change over time.

Agreed!  We should only use JNI once.


> I'd be inclined to simply preprocess this file rather than go grubbing
> around through JNI, but if JNI is the best option, let's compute this once.

I get the sense Fennec hackers want to minimize the number of files we preprocess.


Overall, this seems like a reasonable approach.  We'll want it to work in a chrome worker too, although we might consider stubbing out the method there if blocker crasher bug 1032936 proves difficult to fix.
Attachment #8447506 - Flags: feedback?(myk) → feedback+
(In reply to Myk Melez [:myk] [@mykmelez] from comment #4)

> Overall, this seems like a reasonable approach.  We'll want it to work in a
> chrome worker too, although we might consider stubbing out the method there
> if blocker crasher bug 1032936 proves difficult to fix.

I'm a bit worried about perf, however, so it'd be useful to know how much time it takes to import JNI.jsm and use it to get this value, and how early in the startup process the first call to AndroidLog.dd would be.  (Also useful to know is how soon JNI.jsm gets loaded anyway; perhaps it's loaded early in startup by browser.js, so it doesn't particularly matter if AndroidLog.jsm also loads it.)
As discussed importing JNI.jsm shouldn't take any time as it's already imported by other scripts and further imports reference the same code.  

When trying to log time for the first AndroidLog.dd call I'm getting a time of 3 and importing JNI in AndroidLog is showing a time of either 0 or 1 using the following call:

    let then = Date.now();
    // thing to measure
    dump("time taken: " + (Date.now() - then));

I'm unsure if this falls in to an acceptable range.
Flags: needinfo?(wjohnston)
Flags: needinfo?(myk)
(In reply to Martyn Haigh (:mhaigh) from comment #6)
> When trying to log time for the first AndroidLog.dd call I'm getting a time
> of 3 and importing JNI in AndroidLog is showing a time of either 0 or 1
> using the following call:
> 
>     let then = Date.now();
>     // thing to measure
>     dump("time taken: " + (Date.now() - then));
> 
> I'm unsure if this falls in to an acceptable range.

That seems quite reasonable!
Flags: needinfo?(myk)
Comment on attachment 8447506 [details] [diff] [review]
Implement Android Log debug method which only prints out when Fennec is debuggable

>diff --git a/mobile/android/modules/AndroidLog.jsm b/mobile/android/modules/AndroidLog.jsm

>+  dd: (tag, msg) => {

>+    if(val) {

add a space after the "if" -> if (
Attachment #8447506 - Flags: feedback?(mark.finkle) → feedback+
Optimised codepath to only use JNI once via the use of a memoizing unary getter, without the need for preprocessing, and cleaned up a bit.
Attachment #8447506 - Attachment is obsolete: true
Attachment #8447506 - Flags: feedback?(wjohnston)
Attachment #8455300 - Flags: review?(myk)
Comment on attachment 8455300 [details] [diff] [review]
Implement Android Log debug method which only prints out when Fennec is debuggable

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

Looks good, but there are a few things to button up.

Also, I would be curious to know if the behavior described in this StackOverflow comment will cause mIsDebuggable to get reset sometimes:

http://stackoverflow.com/questions/6589797/how-to-get-package-name-from-anywhere#comment15247626_6589829

::: mobile/android/base/GeckoApp.java
@@ +220,4 @@
>      private static final String RESTARTER_ACTION = "org.mozilla.gecko.restart";
>      private static final String RESTARTER_CLASS = "org.mozilla.gecko.Restarter";
>  
> +    public static boolean mIsDebuggable;

Since isDebuggable is available, shouldn't mIsDebuggable be *private*?  Otherwise, we're providing two different ways to get the value, which creates unnecessary complexity and uncertainty.

@@ +1327,5 @@
>          GeckoAppShell.setNotificationClient(makeNotificationClient());
>          NotificationHelper.init(getApplicationContext());
>          IntentHelper.init(this);
> +
> +        getIsDebuggable();

Nit: I would add a comment here explaining why we're calling this method and then throwing away its return value.

But since mIsDebuggable should only ever be calculated once, upon instantiation, even better would be to get rid of getIsDebuggable and inline the code to calculate mIsDebuggable here.  WebappImpl would then do the same for its instance of mIsDebuggable, and you would just need to also update the NativeApp:IsDebuggable event handler to call isDebuggable instead of getIsDebuggable.

@@ +2747,1 @@
>          // If we ever want to expose this for Fennec, here's how we would do it:

Nit: this comment doesn't make sense now that the code in question has been uncommented.

::: mobile/android/modules/JNI.jsm
@@ +16,5 @@
>  
> +if (typeof Components != "undefined") {
> +  // Specify exported symbols for JSM module loader.
> +  this.EXPORTED_SYMBOLS = ["JNI"];
> +  Components.utils.import("resource://gre/modules/ctypes.jsm")

Nit: append semicolon.

::: mobile/android/modules/WebappManager.jsm
@@ +55,4 @@
>  }
>  
>  let Log = Cu.import("resource://gre/modules/AndroidLog.jsm", {}).AndroidLog;
> +let debug = Log.dd.bind(null, "WebappManager");

Hmm, shouldn't we differentiate between privacy-sensitive and regular debug messages?  This essentially restricts all debug logging to certain builds, whereas a bunch of our debug messages are not privacy-sensitive.

I'd rather we audit the debug calls in WebappManager.jsm/WebappManagerWorker.js and only restrict the privacy-sensitive ones.
Attachment #8455300 - Flags: review?(myk) → review-
I've removed the WebappWorker code as it was causing a silent crash.  Have also audited the WebAppManager code to only remove sensitive logs
Attachment #8455300 - Attachment is obsolete: true
Attachment #8461454 - Flags: review?(myk)
Comment on attachment 8461454 [details] [diff] [review]
Implement Android Log debug method which only prints out when Fennec is debuggable

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

(In reply to Martyn Haigh (:mhaigh) from comment #11)
> I've removed the WebappWorker code as it was causing a silent crash.

But WebappManagerWorker still logs semi-sensitive data (the path to the APK file), so at the very least we should remove that statement (or modify it so it doesn't mention the name of the file being removed).

Also, AndroidLog.dd will still crash if another worker tries to call it, and we should protect against that by returning early after logging a warning like this:

  Ignoring AndroidLog.dd call, as it crashes when called from a worker due to bug 1032936.


> Have also audited the WebAppManager code to only remove sensitive logs

Woot!

::: mobile/android/chrome/content/browser.js
@@ +187,4 @@
>  // the "debug" priority and a log tag.
>  let dump = Log.d.bind(null, "Browser");
>  
> +

Nit: remove this whitespace-only change.

::: mobile/android/modules/WebappManager.jsm
@@ +115,4 @@
>    }).bind(this)); },
>  
>    _downloadApk: function(aManifestUrl) {
> +    dev_debug("_downloadApk for " + aManifestUrl);

Hmm, when introducing AndroidLog, I kept the debug function for backward compatibility, but I would actually prefer we call AndroidLog directly for this and future logging statements:

  const LOGTAG = "WebappManager"; (at the top of the script)
  …
  this.WebappManager = {
    …
    _downloadApk: function(aManifestUrl) {
      Log.dd(LOGTAG, "_downloadApk for " + aManifestUrl);

Then future calls can use AndroidLog's functionality to specify a severity, so they don't all fall into the "debug" or "developer debug" buckets.

If we want to avoid having to pass a LOGTAG each time, then we could bind AndroidLog functions:

  const LOGTAG = "WebappManager";
  let AndroidLog = Cu.import("resource://gre/modules/AndroidLog.jsm", {}).AndroidLog;
  let Log = {
    v: AndroidLog.v.bind(null, LOGTAG),
    d: AndroidLog.d.bind(null, LOGTAG),
    dd: AndroidLog.dd.bind(null, LOGTAG),
    i: AndroidLog.i.bind(null, LOGTAG),
    w: AndroidLog.w.bind(null, LOGTAG),
    e: AndroidLog.e.bind(null, LOGTAG),
  };
  …
  this.WebappManager = {
    …
    _downloadApk: function(aManifestUrl) {
      Log.dd("_downloadApk for " + aManifestUrl);

Or even build this functionality into AndroidLog itself, such that one can obtain a Log object that is bound to a log tag:

  let Log = Cu.import("resource://gre/modules/AndroidLog.jsm", {}).AndroidLog.bind("WebappManager");

But at the very least, when changing these debug calls, we should change them to Log.dd calls rather than adding another logging wrapper function.
Attachment #8461454 - Flags: review?(myk) → review-
Feedback addressed apart from the last point (reducing the need to pass the LOGTAG param) which feels like an optimisation at the moment and not essential to the success of this bug.  Also I couldn't do it in a way that I was happy about, I didn't fancy mapping each function as in the first example and I couldn't get the second example to work.  Perhaps it's worth adding this as a separate bug to address later?
Attachment #8461454 - Attachment is obsolete: true
Attachment #8462665 - Flags: review?(myk)
Comment on attachment 8462665 [details] [diff] [review]
Implement Android Log debug method which only prints out when Fennec is debuggable

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

::: mobile/android/base/GeckoApp.java
@@ +2523,1 @@
>      protected boolean getIsDebuggable() {

Nit: We don't need both of these methods (isDebuggable and getIsDebuggable).  We should remove one.

::: mobile/android/modules/AndroidLog.jsm
@@ +73,5 @@
>    i: (tag, msg) => __android_log_write(ANDROID_LOG_INFO, "Gecko" + tag.substring(0, MAX_TAG_LENGTH), msg),
>    w: (tag, msg) => __android_log_write(ANDROID_LOG_WARN, "Gecko" + tag.substring(0, MAX_TAG_LENGTH), msg),
>    e: (tag, msg) => __android_log_write(ANDROID_LOG_ERROR, "Gecko" + tag.substring(0, MAX_TAG_LENGTH), msg),
> +  dd: (tag, msg) => {
> +    if(typeof Components == "undefined") {

Nit: add a space between "if" and the opening parenthesis.

@@ +74,5 @@
>    w: (tag, msg) => __android_log_write(ANDROID_LOG_WARN, "Gecko" + tag.substring(0, MAX_TAG_LENGTH), msg),
>    e: (tag, msg) => __android_log_write(ANDROID_LOG_ERROR, "Gecko" + tag.substring(0, MAX_TAG_LENGTH), msg),
> +  dd: (tag, msg) => {
> +    if(typeof Components == "undefined") {
> +      dump ("Ignoring AndroidLog.dd call, as it crashes when called from a worker due to bug 1032936");

Nit: remove the space between "dump" and the opening parenthesis.

Also, make this a call to AndroidLog.warn(), as this should be a warning.

::: mobile/android/modules/WebappManager.jsm
@@ +590,4 @@
>          try {
>            yield OS.file.remove(apk.filePath);
>          } catch(ex) {
> +          Log.d(LOGTAG, "error removing " + apk.filePath + " for cancelled update: " + ex);

This should be a Log.dd call, since it reveals the file path (and thus the APK name/URL).

@@ +644,3 @@
>              },
>              function(error) {
> +              Log.d(LOGTAG, "error uninstalling " + app.name + ": " + error);

If the other Log.* calls above are Log.dd, then this too should be a Log.dd, since they all reveal the same sensitive information (app.name).

@@ +672,4 @@
>      if (aPrefs.length > 0) {
>        let array = new TextEncoder().encode(JSON.stringify(aPrefs));
>        OS.File.writeAtomic(aFile.path, array, { tmpPath: aFile.path + ".tmp" }).then(null, function onError(reason) {
> +        Log.d(LOGTAG, "Error writing default prefs: " + reason);

We don't control the value of "reason", so I'd make this a Log.dd too.

::: mobile/android/modules/WebappManagerWorker.js
@@ +24,4 @@
>    };
>  
>    request.onreadystatechange = function(event) {
> +    Log.dd(LOGTAG, "onreadystatechange: " + request.readyState);

The three statements here and above don't need to be Log.dd, as they don't reveal personal information.

@@ +38,4 @@
>        try {
>          OS.File.remove(path);
>        } catch(ex) {
> +        Log.dd(LOGTAG, "error removing " + path + ": " + ex);

Nit: rather than triggering the warning, change this to remove the sensitive information, or just remove the log statement entirely.
Attachment #8462665 - Flags: review?(myk) → review-
(In reply to Martyn Haigh (:mhaigh) from comment #13)
> Feedback addressed apart from the last point (reducing the need to pass the
> LOGTAG param) which feels like an optimisation at the moment and not
> essential to the success of this bug.

Indeed!

> Also I couldn't do it in a way that I
> was happy about, I didn't fancy mapping each function as in the first
> example and I couldn't get the second example to work.  Perhaps it's worth
> adding this as a separate bug to address later?

Good idea!  Filed as bug 1046156.
All points address with the exception of needing both the isDebuggable and the getIsDebuggable methods in BrowserApp.java - this is because we can't access static fields via JNI.jsm, only methods, and changing the existing isDebuggable method to static creates a load of headaches when trying to change the implementation in WebAppImpl.java.
Attachment #8462665 - Attachment is obsolete: true
Attachment #8464731 - Flags: feedback?(myk)
Comment on attachment 8464731 [details] [diff] [review]
Implement Android Log debug method which only prints out when Fennec is debuggable

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

(In reply to Martyn Haigh (:mhaigh) from comment #16)
> All points address with the exception of needing both the isDebuggable and
> the getIsDebuggable methods in BrowserApp.java - this is because we can't
> access static fields via JNI.jsm, only methods, and changing the existing
> isDebuggable method to static creates a load of headaches when trying to
> change the implementation in WebAppImpl.java.

Hmm, it should be possible to do something like this:

  diff --git a/mobile/android/base/GeckoApp.java b/mobile/android/base/GeckoApp.java
  index df2395f..e36bc05 100644
  --- a/mobile/android/base/GeckoApp.java
  +++ b/mobile/android/base/GeckoApp.java
  @@ -204,7 +204,7 @@ public abstract class GeckoApp
       private static final String RESTARTER_ACTION = "org.mozilla.gecko.restart";
       private static final String RESTARTER_CLASS = "org.mozilla.gecko.Restarter";
   
  -    private static boolean mIsDebuggable;
  +    protected static boolean mIsDebuggable;
   
       @SuppressWarnings("serial")
       class SessionRestoreException extends Exception {
  @@ -661,7 +661,7 @@ public abstract class GeckoApp
                   }
               } else if ("NativeApp:IsDebuggable".equals(event)) {
                   JSONObject ret = new JSONObject();
  -                ret.put("isDebuggable", getIsDebuggable());
  +                ret.put("isDebuggable", mIsDebuggable);
                   EventDispatcher.sendResponse(message, ret);
               } else if (event.equals("Accessibility:Event")) {
                   GeckoAccessibility.sendAccessibilityEvent(message);
  @@ -1301,6 +1301,10 @@ public abstract class GeckoApp
           GeckoAppShell.setNotificationClient(makeNotificationClient());
           IntentHelper.init(this);
   
  +        setIsDebuggable();
  +    }
  +
  +    protected void setIsDebuggable() {
           int flags = 0;
           try {
               flags = getPackageManager().getPackageInfo(getPackageName(), 0).applicationInfo.flags;
  @@ -2521,10 +2525,6 @@ public abstract class GeckoApp
           return mIsDebuggable;
       }
   
  -    protected boolean getIsDebuggable() {
  -        return mIsDebuggable;
  -    }
  -
       // FHR reason code for a session end prior to a restart for a
       // locale change.
       private static final String SESSION_END_LOCALE_CHANGED = "L";
  diff --git a/mobile/android/base/webapp/WebappImpl.java b/mobile/android/base/webapp/WebappImpl.java
  index 999de41..860553e 100644
  --- a/mobile/android/base/webapp/WebappImpl.java
  +++ b/mobile/android/base/webapp/WebappImpl.java
  @@ -381,13 +381,7 @@ public class WebappImpl extends GeckoApp implements InstallCallback {
       }
   
       @Override
  -    protected boolean getIsDebuggable() {
  -        if (mIsApk) {
  -            return mApkResources.isDebuggable();
  -        }
  -
  -        // This is a legacy shortcut, which didn't provide a way to determine
  -        // that the app is debuggable, so we say the app is not debuggable.
  -        return false;
  +    protected void setIsDebuggable() {
  +        mIsDebuggable = mIsApk ? mApkResources.isDebuggable() : false;
       }
   }


We should also update NativeApp:IsDebuggable event dispatchers to call GeckoApp.isDebuggable instead, but we can do that in a separate bug.

::: mobile/android/modules/AndroidLog.jsm
@@ +84,5 @@
> +    let isDebuggable = !!jni.callStaticIntMethod(cls, method);
> +    jni.close();
> +    AndroidLog.dd = isDebuggable ? AndroidLog.d : (tag, msg) => {};
> +    AndroidLog.dd(tag, msg);
> +  },

Now that bug 1046156 has landed, update AndroidLog's new "bind" function to bind "dd" as well.

(Optionally, also update WebappManager to bind the Log object to the "WebappManager" tag; but this can happen in a separate bug.)

::: mobile/android/modules/WebappManagerWorker.js
@@ +38,4 @@
>        try {
>          OS.File.remove(path);
>        } catch(ex) {
> +        Log.d(LOGTAG, "error removing: " + ex);

Nit: this sentence fragment is a bit vague without an object; I would make it:

  Log.d(LOGTAG, "error removing APK: " + ex);
Attachment #8464731 - Flags: feedback?(myk) → feedback+
Assignee: mhaigh → nobody
As Martyn is off working on another project now, I'll take over finishing up and landing this patch.
Assignee: nobody → myk
Status: NEW → ASSIGNED
Flags: needinfo?(wjohnston)
Here's a version of the last patch that has been rebased onto master.
Attachment #8464731 - Attachment is obsolete: true
Per bug 1235869, we're going to disable the Android web runtime, so we won't fix this bug in it.

(This is part of a bulk resolution of bugs in the Firefox for Android::Web Apps component, from which I attempted to exclude bugs that are not specific to the runtime, but it's possible that I included one accidentally.  If so, I'm sorry, and please reopen the bug!)
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.