804457 - Reduce log chattiness

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Comment 1

[Richard Newman [:rnewman]]

Attachment: Part 1: spelling, grammar, punctuation, and log levels in GeckoApp.java. v1

Comment 2

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

Comment on attachment 674111 [details] [diff] [review]
Part 1: spelling, grammar, punctuation, and log levels in GeckoApp.java. v1

>diff --git a/mobile/android/base/GeckoApp.java b/mobile/android/base/GeckoApp.java

In general, I would skip the pure comment changes, just to minimimze bitrot to other devs. My requests to remove might be a bit aggressive, but I am considering just how useful this output is to external users. Internal devs can just add their own logs as needed... and then remove them. The "zerdatime" stuff is not helpful anymore.

>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - start of getPluginDirectories");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - start of getPluginDirectories");

I'd be happier to see these "zerdatime" logs go away. We are using telemetry to gather timing

>-                Log.w(LOGTAG, "Loading plugin: " + serviceInfo.packageName);
>-
>-
>-                // retrieve information from the plugin's manifest
>+                Log.d(LOGTAG, "Loading plugin: " + serviceInfo.packageName);


Let's remove these "You are here" logs

>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - end of getPluginDirectories");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - end of getPluginDirectories");

Remove

>     protected void onSaveInstanceState(Bundle outState) {

>-        Log.i(LOGTAG, "onSaveInstanceState");
>+        Log.d(LOGTAG, "Entered onSaveInstanceState.");

More "You are here". Remove.

>+    /**
>+     * This function might perform synchronous IO. Don't call it
>+     * from the main thread.
>+     */
>     public StartupMode getStartupMode() {
>-        // This function might touch the disk and should not
>-        // be called from UI's main thread.

Good comment change

>     public void handleMessage(String event, JSONObject message) {
>-        Log.i(LOGTAG, "Got message: " + event);
>+        Log.d(LOGTAG, "Got message: " + event);

I have not seen any value in this log. I vote to remove it.

>             for (int i = 0; i < aPermissions.length(); i++) {
>                 try {
>-                    items[i] = aPermissions.getJSONObject(i).
>-                               getString("setting");
>-                    // Make all the items checked by default
>+                    items[i] = aPermissions.getJSONObject(i).getString("setting");
>+                    // Make all the items checked by default.

Yeah. I like this too.

>         mMainHandler = new Handler();
>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onCreate");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onCreate");

Burn it.

>         if (savedInstanceState != null) {
>-            Log.i(LOGTAG, "Restoring from OOM");
>+            Log.i(LOGTAG, "Restoring from OOM.");

Burn it.

>             boolean wasInBackground =
>                 savedInstanceState.getBoolean(SAVED_STATE_IN_BACKGROUND, false);
>-            Log.i(LOGTAG, "Was in background: " + wasInBackground);
>+            Log.d(LOGTAG, "Was in background: " + wasInBackground);

Burn it.

>                 boolean wasOOM = prefs.getBoolean(PREFS_OOM_EXCEPTION, false);
>                 boolean wasStopped = prefs.getBoolean(PREFS_WAS_STOPPED, true);
>                 if (wasOOM || !wasStopped) {
>-                    Log.i(LOGTAG, "Crashed due to OOM last run");
>+                    Log.i(LOGTAG, "Crashed due to OOM on last run.");

Burn it.

>         if (mRestoreMode == GeckoAppShell.RESTORE_NONE && getProfile().shouldRestoreSession()) {
>-            Log.i(LOGTAG, "Restoring crash");
>+            Log.d(LOGTAG, "Restoring crash.");

Burn it.

>         } else if (ACTION_DEBUG.equals(action) &&
>             checkAndSetLaunchState(LaunchState.Launching, LaunchState.WaitForDebugger)) {
>             mMainHandler.postDelayed(new Runnable() {
>                 public void run() {
>-                    Log.i(LOGTAG, "Launching from debug intent after 5s wait");
>+                    Log.d(LOGTAG, "Launching from debug intent after 5s wait");
>                     setLaunchState(LaunchState.Launching);
>                     sGeckoThread.start();
>                 }
>             }, 1000 * 5 /* 5 seconds */);
>-            Log.i(LOGTAG, "Intent : ACTION_DEBUG - waiting 5s before launching");
>+            Log.d(LOGTAG, "Intent : ACTION_DEBUG - waiting 5s before launching");

These seem useless too, but we probably never see them anyway.

>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - UI almost up");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - UI almost up");

Remove

>         GeckoAppShell.getHandler().postDelayed(new Runnable() {
>             public void run() {
>-                Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - pre checkLaunchState");
>+                Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - pre checkLaunchState");

Remove

>                 // Kick off our background service to fetch product announcements.
>                 // We do this by invoking the broadcast receiver, which uses the
>                 // system alarm infrastructure to perform tasks at intervals.
>                 Log.d(LOGTAG, "Broadcasting announcements pref.");

This seems like a "You are here" debugging output.

>     protected void onNewIntent(Intent intent) {
>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onNewIntent");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onNewIntent");

Remove

>         if (Intent.ACTION_MAIN.equals(action)) {
>-            Log.i(LOGTAG, "Intent : ACTION_MAIN");
>+            Log.d(LOGTAG, "Intent: ACTION_MAIN");

Remove

>     public void onResume()
>     {
>-        Log.i(LOGTAG, "resume");
>+        Log.d(LOGTAG, "Entering onResume.");

Remove

>     public void onStop()
>     {
>-        Log.i(LOGTAG, "stop");
>+        Log.d(LOGTAG, "Entering onStop.");

Remove

>     public void onPause()
>     {
>-        Log.i(LOGTAG, "pause");
>+        Log.d(LOGTAG, "Entering onPause.");

Remove

>     public void onRestart()
>     {
>-        Log.i(LOGTAG, "restart");
>+        Log.d(LOGTAG, "Entering onRestart.");

Remove

>     public void onStart()
>     {
>-        Log.w(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onStart");
>-
>-        Log.i(LOGTAG, "start");
>+        Log.d(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - onStart");

Remove

>     public void onDestroy()
>     {
>-        Log.i(LOGTAG, "destroy");
>+        Log.d(LOGTAG, "Entering onDestroy.");

Remove

>     public void onConfigurationChanged(Configuration newConfig)
>     {
>-        Log.i(LOGTAG, "configuration changed");
>+        Log.d(LOGTAG, "Configuration changed.");

Remove

>     public void doRestart(String action) {
>-        Log.i(LOGTAG, "doRestart(\"" + action + "\")");
>+        Log.d(LOGTAG, "doRestart(\"" + action + "\")");

Remove

>-            Log.i(LOGTAG, intent.toString());
>+            Log.d(LOGTAG, "Restart intent: " + intent.toString());

Remove

>-                    Log.i(LOGTAG, "Checking profile migration in: " + profileDir.getAbsolutePath());
>+                    Log.d(LOGTAG, "Checking profile migration in: " + profileDir.getAbsolutePath());

Remove

>                         long timeDiff = SystemClock.uptimeMillis() - currentTime;
>-                        Log.i(LOGTAG, "Profile migration took " + timeDiff + " ms");
>+                        Log.v(LOGTAG, "Profile migration took " + timeDiff + " ms");

Is this useful anymore? I don't think it is. Remove the log and timing code.

>             if (!profileMigrator.hasSyncMigrated()) {
>-                Log.i(LOGTAG, "Checking Sync settings in: " + profileDir.getAbsolutePath());
>+                Log.d(LOGTAG, "Checking Sync settings in: " + profileDir.getAbsolutePath());

Remove

Thoughts?

Comment 3

[Richard Newman [:rnewman]]

Attachment: Part 1: spelling, grammar, punctuation, and log levels in GeckoApp.java. v2

Now with 300% fewer nitpicky comment changes, and ∞ less zerdatime.

Comment 4

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

Comment on attachment 674123 [details] [diff] [review]
Part 1: spelling, grammar, punctuation, and log levels in GeckoApp.java. v2

Worth it

Comment 5

[Mozilla RelEng Bot]

Try run for b41d581399f0 is complete.
Detailed breakdown of the results available here:
    https://tbpl.mozilla.org/?tree=Try&rev=b41d581399f0
Results (out of 48 total builds):
    success: 40
    warnings: 5
    failure: 3
Builds (or logs if builds failed) available at:
http://ftp.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-b41d581399f0

Comment 6

[Richard Newman [:rnewman]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/7b01f6cf02b4

Parts 2+ are open to community participation, unless I get to them tonight :D

Comment 7

[Richard Newman [:rnewman]]

Attachment: Part 2: hit other classes. v1

(Still building; I'll wait for that before I land, assuming r+!)

Touched most of the other noisy classes, taking the same approach.

In a couple of spots where I broke a lot of blame/patch application, I took the opportunity to improve the code; you'll see the places. Happy to rip those out if you don't want to take them.

Comment 8

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/7b01f6cf02b4

Comment 9

[Richard Newman [:rnewman]]

Attachment: Part 2: hit other classes. v2

How 'bout I use correct Java syntax?

Comment 10

[Geoff Brown [:gbrown]]

Comment on attachment 674529 [details] [diff] [review]
Part 2: hit other classes. v2

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

::: mobile/android/base/BrowserToolbar.java
@@ -556,5 @@
>          if (visible) {
>              mFavicon.setImageDrawable(mProgressSpinner);
>              mProgressSpinner.start();
>              setPageActionVisibility(true);
> -            Log.i(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - Throbber start");

I think the "Throbber start" and "Throbber stop" messages are used by S1/S2 tests (http://mrcote.info/phonedash/#) - we probably need to leave them in.

Comment 11

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

(In reply to Geoff Brown [:gbrown] from comment #10)
> Comment on attachment 674529 [details] [diff] [review]
> Part 2: hit other classes. v2
> 
> Review of attachment 674529 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: mobile/android/base/BrowserToolbar.java
> @@ -556,5 @@
> >          if (visible) {
> >              mFavicon.setImageDrawable(mProgressSpinner);
> >              mProgressSpinner.start();
> >              setPageActionVisibility(true);
> > -            Log.i(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - Throbber start");
> 
> I think the "Throbber start" and "Throbber stop" messages are used by S1/S2
> tests (http://mrcote.info/phonedash/#) - we probably need to leave them in.

Indeed, but I was wondering if we could remove the "zerdatime" and millisec parts. Does phonedash use the times too, or just the "Throbber Start/Stop" text?

Comment 12

[Richard Newman [:rnewman]]

> > I think the "Throbber start" and "Throbber stop" messages are used by S1/S2
> > tests (http://mrcote.info/phonedash/#) - we probably need to leave them in.

Good to know, thanks Geoff.

> Indeed, but I was wondering if we could remove the "zerdatime" and millisec
> parts. Does phonedash use the times too, or just the "Throbber Start/Stop"
> text?

And also: does this have to log at INFO? And if it really is used by a test somewhere, I'll add a comment to that effect.

Is there a doc somewhere for what that test needs?

Comment 13

[Geoff Brown [:gbrown]]

(In reply to Mark Finkle (:mfinkle) from comment #11)
> (In reply to Geoff Brown [:gbrown] from comment #10)
> Indeed, but I was wondering if we could remove the "zerdatime" and millisec
> parts. Does phonedash use the times too, or just the "Throbber Start/Stop"
> text?

It uses the times too. 

It does not look for "zerdatime" specifically, but it extracts the millisec times from the nth space-delimited word -- so "zerdatime" can be changed to something else, but it you remove it entirely, the tests will break.

Code is here: https://github.com/mozilla/autophone/blob/master/tests/s1s2test.py#L142

I don't think INFO is necessary. I don't know of any doc.

Comment 14

[Richard Newman [:rnewman]]

(In reply to Geoff Brown [:gbrown] from comment #13)

> It uses the times too. 

I'm going to strip that change out of this patch, add a comment about it being necessary for that test, and file a follow-up bug to do this in a less janky way.

Comment 15

[Richard Newman [:rnewman]]

Attachment: Part 2: hit other classes. v3

Comment 16

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

Comment on attachment 674771 [details] [diff] [review]
Part 2: hit other classes. v3


>-        Log.i(LOGTAG, "post native init");
>+        Log.v(LOGTAG, "Native init spawned.");

Remove

>-        Log.i(LOGTAG, "Location provider - high accuracy: " + enable);
>+        Log.v(LOGTAG, "Location provider - high accuracy: " + enable);

>-            Log.i(LOGTAG, "Enabling SENSOR_ORIENTATION");
>+            Log.v(LOGTAG, "Enabling SENSOR_ORIENTATION");

>-            Log.i(LOGTAG, "Enabling SENSOR_ACCELERATION");
>+            Log.v(LOGTAG, "Enabling SENSOR_ACCELERATION");

>-            Log.i(LOGTAG, "Enabling SENSOR_PROXIMITY");
>+            Log.v(LOGTAG, "Enabling SENSOR_PROXIMITY");

>-            Log.i(LOGTAG, "Enabling SENSOR_LIGHT");
>+            Log.v(LOGTAG, "Enabling SENSOR_LIGHT");

>-            Log.i(LOGTAG, "Enabling SENSOR_LINEAR_ACCELERATION");
>+            Log.v(LOGTAG, "Enabling SENSOR_LINEAR_ACCELERATION");

>-            Log.i(LOGTAG, "Enabling SENSOR_GYROSCOPE");
>+            Log.v(LOGTAG, "Enabling SENSOR_GYROSCOPE");

Remove

>-            Log.i(LOGTAG, "Disabling SENSOR_ORIENTATION");
>+            Log.v(LOGTAG, "Disabling SENSOR_ORIENTATION");

>-            Log.i(LOGTAG, "Disabling SENSOR_ACCELERATION");
>+            Log.v(LOGTAG, "Disabling SENSOR_ACCELERATION");

>-            Log.i(LOGTAG, "Disabling SENSOR_PROXIMITY");
>+            Log.v(LOGTAG, "Disabling SENSOR_PROXIMITY");

>-            Log.i(LOGTAG, "Disabling SENSOR_LIGHT");
>+            Log.v(LOGTAG, "Disabling SENSOR_LIGHT");

>-            Log.i(LOGTAG, "Disabling SENSOR_LINEAR_ACCELERATION");
>+            Log.v(LOGTAG, "Disabling SENSOR_LINEAR_ACCELERATION");

>-            Log.i(LOGTAG, "Disabling SENSOR_GYROSCOPE");
>+            Log.v(LOGTAG, "Disabling SENSOR_GYROSCOPE");

Let's remove these too

>     static void scheduleRestart() {
>-        Log.i(LOGTAG, "scheduling restart");
>+        Log.v(LOGTAG, "Scheduling restart.");

Remove

>     public static void addPluginView(View view,

>-        Log.i(LOGTAG, "addPluginView:" + view + " @ x:" + x + " y:" + y + " w:" + w + " h:" + h + " fullscreen: " + isFullScreen);
>+        Log.d(LOGTAG, "addPluginView:" + view + " @ x:" + x + " y:" + y + " w:" + w + " h:" + h + " fullscreen: " + isFullScreen);

>     public static void removePluginView(View view, boolean isFullScreen) {
>-        Log.i(LOGTAG, "removePluginView:" + view + " fullscreen: " + isFullScreen);
>+        Log.d(LOGTAG, "removePluginView:" + view + " fullscreen: " + isFullScreen);
>         GeckoApp.mAppContext.removePluginView(view, isFullScreen);
>     }
> 
>     public static Class<?> loadPluginClass(String className, String libName) {
>-        Log.i(LOGTAG, "in loadPluginClass... attempting to access className, then libName.....");
>-        Log.i(LOGTAG, "className: " + className);
>-        Log.i(LOGTAG, "libName: " + libName);
>-
>+        Log.d(LOGTAG, "loadPluginClass(" + className + ", " + libName + ")");

Tempted to remove these. Seem like something we only want while debugging the app locally.
[Update: after reviewing the patch, let's remove these too]

>     static int[] initCamera(String aContentType, int aCamera, int aWidth, int aHeight) {
>-        Log.i(LOGTAG, "initCamera(" + aContentType + ", " + aWidth + "x" + aHeight + ") on thread " + Thread.currentThread().getId());
>+        Log.d(LOGTAG, "initCamera(" + aContentType + ", " + aWidth + "x" + aHeight + ") on thread " + Thread.currentThread().getId());

Same temptation. [Update: Remove]

>-            Log.i(LOGTAG, "Camera: " + params.getPreviewSize().width + "x" + params.getPreviewSize().height +
>+            Log.v(LOGTAG, "Camera: " + params.getPreviewSize().width + "x" + params.getPreviewSize().height +

More of the same.  [Update: Remove]

>     static synchronized void closeCamera() {
>-        Log.i(LOGTAG, "closeCamera() on thread " + Thread.currentThread().getId());
>+        Log.d(LOGTAG, "closeCamera() on thread " + Thread.currentThread().getId());

More (why do we do this kind of output?).  [Update: Remove]

>diff --git a/mobile/android/base/Tabs.java b/mobile/android/base/Tabs.java

>-        Log.i(LOGTAG, "Added a tab with id: " + id);
>+        Log.d(LOGTAG, "Added a tab with id: " + id);

Remove

>-            Log.i(LOGTAG, "Removed a tab with id: " + id);
>+            Log.d(LOGTAG, "Removed a tab with id: " + id);

Remove

>     public void handleMessage(String event, JSONObject message) {
>-        Log.i(LOGTAG, "Got message: " + event);
>+        Log.d(LOGTAG, "Got message: " + event);

Remove

>diff --git a/mobile/android/base/gfx/LayerView.java b/mobile/android/base/gfx/LayerView.java

>     public void setPaintState(int paintState) {
>-        Log.d(LOGTAG, "LayerView paint state set to " + paintState);
>+        Log.v(LOGTAG, "LayerView paint state set to " + paintState);

Remove

Comment 17

[Richard Newman [:rnewman]]

Part 2:

https://hg.mozilla.org/integration/mozilla-inbound/rev/4b8cc8b4db5e

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/4b8cc8b4db5e