997478 - Lots of "GeckoFavicons: Cancelling favicon load (NN)" spew in logcat

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Favicon Handling, defect)

Description

[Ed Morley [:emorley]]

Bug 699786 added:
https://hg.mozilla.org/mozilla-central/file/b735e618c2a8/mobile/android/base/favicons/Favicons.java#l334
>   334             Log.d(LOGTAG, "Cancelling favicon load (" + taskId + ")");

This causes quite a lot of noise in the logcats during automation test runs, eg look in:
https://tbpl.mozilla.org/php/getParsedLog.php?id=37956010&tree=Mozilla-Inbound
14:59:29     INFO -  --------- beginning of /dev/log/main
14:59:29     INFO -  04-16 14:57:14.492 E/GeckoConsole( 2119): [JavaScript Warning: "An unbalanced tree was written using document.write() causing data from the network to be reparsed. For more information https://developer.mozilla.org/en/Optimizing_Your_Pages_for_Speculative_Parsing" {file: "http://10.12.129.21:30222/jsreftest/tests/jsreftest.html?test=test262/ch13/13.0/S13_A6_T1.js" line: 15}]
14:59:29     INFO -  04-16 14:57:15.093 I/GeckoDump( 2119):  PASSED!
14:59:29     INFO -  04-16 14:57:15.109 E/GeckoConsole( 2119): [JavaScript Warning: "An unbalanced tree was written using document.write() causing data from the network to be reparsed. For more information https://developer.mozilla.org/en/Optimizing_Your_Pages_for_Speculative_Parsing" {file: "http://10.12.129.21:30222/jsreftest/tests/jsreftest.html?test=test262/ch13/13.0/S13_A6_T2.js" line: 15}]
14:59:29     INFO -  04-16 14:57:15.687 I/GeckoDump( 2119):  PASSED!
14:59:29     INFO -  04-16 14:57:15.695 D/GeckoFavicons( 2119): Cancelling favicon load (15638)
14:59:29     INFO -  04-16 14:57:15.695 D/GeckoFavicons( 2119): Cancelling favicon load (15639)
14:59:29     INFO -  04-16 14:57:15.695 D/GeckoFavicons( 2119): Cancelling favicon load (15640)
14:59:29     INFO -  04-16 14:57:15.695 D/GeckoFavicons( 2119): Cancelling favicon load (15641)
14:59:29     INFO -  04-16 14:57:15.695 D/GeckoFavicons( 2119): Cancelling favicon load (15642)
14:59:29     INFO -  04-16 14:57:15.695 D/GeckoFavicons( 2119): Cancelling favicon load (15643)
14:59:29     INFO -  04-16 14:57:15.695 E/GeckoConsole( 2119): [JavaScript Warning: "An unbalanced tree was written using document.write() causing data from the network to be reparsed. For more information https://developer.mozilla.org/en/Optimizing_Your_Pages_for_Speculative_Parsing" {file: "http://10.12.129.21:30222/jsreftest/tests/jsreftest.html?test=test262/ch13/13.0/S13_A7_T1.js" line: 15}]
14:59:29     INFO -  04-16 14:57:16.101 I/GeckoDump( 2119):  PASSED!
14:59:29     INFO -  04-16 14:57:16.109 E/GeckoConsole( 2119): [JavaScript Warning: "An unbalanced tree was written using document.write() causing data from the network to be reparsed. For more information https://developer.mozilla.org/en/Optimizing_Your_Pages_for_Speculative_Parsing" {file: "http://10.12.129.21:30222/jsreftest/tests/jsreftest.html?test=test262/ch13/13.0/S13_A7_T2.js" line: 15}]
14:59:29     INFO -  04-16 14:57:16.390 D/GeckoFavicons( 2119): Cancelling favicon load (15646)
14:59:29     INFO -  04-16 14:57:16.390 D/GeckoFavicons( 2119): Cancelling favicon load (15647)
14:59:29     INFO -  04-16 14:57:16.390 D/GeckoFavicons( 2119): Cancelling favicon load (15648)
14:59:29     INFO -  04-16 14:57:16.390 D/GeckoFavicons( 2119): Cancelling favicon load (15649)
14:59:29     INFO -  04-16 14:57:16.390 D/GeckoFavicons( 2119): Cancelling favicon load (15650)
14:59:29     INFO -  04-16 14:57:16.390 D/GeckoFavicons( 2119): Cancelling favicon load (15651)
14:59:29     INFO -  04-16 14:57:16.851 D/GeckoFavicons( 2119): Cancelling favicon load (15654)
14:59:29     INFO -  04-16 14:57:16.851 D/GeckoFavicons( 2119): Cancelling favicon load (15655)
14:59:29     INFO -  04-16 14:57:16.851 D/GeckoFavicons( 2119): Cancelling favicon load (15656)
14:59:29     INFO -  04-16 14:57:16.851 D/GeckoFavicons( 2119): Cancelling favicon load (15657)
14:59:29     INFO -  04-16 14:57:16.851 D/GeckoFavicons( 2119): Cancelling favicon load (15658)
14:59:29     INFO -  04-16 14:57:16.851 D/GeckoFavicons( 2119): Cancelling favicon load (15659)
14:59:29     INFO -  04-16 14:57:17.375 D/GeckoFavicons( 2119): Cancelling favicon load (15662)
14:59:29     INFO -  04-16 14:57:17.382 D/GeckoFavicons( 2119): Cancelling favicon load (15663)
14:59:29     INFO -  04-16 14:57:17.382 D/GeckoFavicons( 2119): Cancelling favicon load (15664)
14:59:29     INFO -  04-16 14:57:17.382 D/GeckoFavicons( 2119): Cancelling favicon load (15665)
14:59:29     INFO -  04-16 14:57:17.382 D/GeckoFavicons( 2119): Cancelling favicon load (15666)
14:59:29     INFO -  04-16 14:57:17.382 D/GeckoFavicons( 2119): Cancelling favicon load (15667)
14:59:29     INFO -  04-16 14:57:17.578 I/GeckoDump( 2119):  PASSED!
(...)

The log only saves the last N lines of the logcat (failing that we have to resort to the blobuploader, but this is active on the pandas only), so logcat spam can push the important lines out.

Do we need these log dumps still? Also, is it expected to have so many favicon load cancellations?

Comment 1

[Richard Newman [:rnewman]]

It's not a bad thing -- it implies that we're opening and closing 15,000 pages faster than we can load the favicons -- but those should be verbose-level, not debug.

Comment 2

[Ed Morley [:emorley]]

Thank you :-)

Comment 3

[Richard Newman [:rnewman]]

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

Ed, is this something you want to uplift for sanity's sake?

Comment 4

[Ed Morley [:emorley]]

(In reply to Richard Newman [:rnewman] from comment #3)
> Ed, is this something you want to uplift for sanity's sake?

I think we'll be fine - thank you for landing that :-)

Comment 5

[Ryan VanderMeulen [:RyanVM]]

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