1089940 - GeckoFaviconDecoder( 2100): Can't decode null data: URI.

Status: RESOLVED FIXED

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

Description

[Mats Palmgren (inactive)]

Logcat output for debug builds is completely swamped by this warning.
Can we remove it please?


A small sample:
10-27 14:36:36.656 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:36.679 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:36.695 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:36.718 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:36.734 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:36.765 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.039 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.054 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.085 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.093 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.117 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.140 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.492 I/Gecko   ( 2100): ++DOMWINDOW == 42 (0x69f5cf20) [pid = 2100] [serial = 2650] [outer = 0x67b39e20]
10-27 14:36:37.789 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.820 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.828 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.843 D/dalvikvm( 2100): GC_CONCURRENT freed 652K, 9% free 8698K/9543K, paused 2ms+7ms
10-27 14:36:37.867 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:37.890 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:38.023 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:38.078 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:38.132 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:38.156 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.
10-27 14:36:38.179 W/GeckoFaviconDecoder( 2100): Can't decode null data: URI.

Comment 1

[Richard Newman [:rnewman]]

What page are you on when you get this, mats?

The only time this should occur is if a favicon DB load succeeded but returned null, which shouldn't occur.

Comment 2

[Mats Palmgren (inactive)]

It occurs many times per test when running reftests:
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/98524952c1c4bb2d764f3bdbda9c5c2baf0c9f7c8a8b1bfc76cfebbedc7e08c88df8c79b68218ccc5e0bc3e581a60704bb326f4074696665e9d2db1213683ff1

Comment 3

[Mats Palmgren (inactive)]

Heh, now that I think about it it might be caused by my own changes in that Try build.
Let me check some other builds...

Comment 4

[Mats Palmgren (inactive)]

Yeah, I only see the warning once or twice per test in other people's Try pushes and on m-i.
So my patch seem to make the problem much worse for some reason, which was unexpected.
If you know anything about the conditions for this warning I'd be interested to know.

Comment 5

[Mats Palmgren (inactive)]

It's the "logcat.log" file in "Android 4.0 Debug" reftest runs that I'm referring to.

Comment 6

[Richard Newman [:rnewman]]

It'll happen any time the page location changes, in some circumstances. Can you point me to your patch/bug/push?

Comment 7

[Mats Palmgren (inactive)]

Here's my push: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=224a3baf987c
but the problem occurs in all "Android 4.0 Debug" reftest runs that I looked at.

Comment 8

[Mats Palmgren (inactive)]

Here's another one: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=5518af68d629
This one doesn't have the "415491-escape-unsafe-chars" patch, just the "fff" part so it's
that part that seem to trigger it.  It's a style flush related change in Gecko layout:
https://hg.mozilla.org/try/rev/4ce4b02b7c43

Comment 9

[Richard Newman [:rnewman]]

Attachment: Check for null earlier in favicon data: URI handling. v1

mats, see if this works for you.

Comment 10

[Richard Newman [:rnewman]]

Note that that patch will muffle the warning, but if the change you're testing is causing favicon load, it means it's having some kind of weird effect like signaling a page load completion, recording a new history item, or something like that.

Comment 11

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

The reftests use a lot of "data:text/html ..." URLs and if I manually enter one [1] in my own Fennec, I get the same "Can't decode null data: URI" output.

[1] I used data:text/html;charset=UTF-8,%3C%21%2D%2DCLEAR%2D%2D%3E

Comment 12

[Chris Kitching [:ckitching]]

Comment on attachment 8512389 [details] [diff] [review]
Check for null earlier in favicon data: URI handling. v1

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

Doing a null check before calling decodeDataURI is a good idea.

::: mobile/android/base/favicons/LoadFaviconTask.java
@@ -365,5 @@
>              if (storedFaviconUrl != null) {
>                  faviconURL = storedFaviconUrl;
>              } else {
>                  // If we don't have a stored one, fall back to the default.
>                  faviconURL = Favicons.guessDefaultFaviconURL(pageUrl);

This is a write to faviconURL...

@@ +370,5 @@
>              } else {
>                  // If we don't have a stored one, fall back to the default.
>                  faviconURL = Favicons.guessDefaultFaviconURL(pageUrl);
>  
> +                if (isEmpty) {

... Which means you probably don't want to do this!

Comment 13

[Richard Newman [:rnewman]]

Over-zealous code extraction thar…

Comment 14

[Richard Newman [:rnewman]]

Attachment: Check for null earlier in favicon data: URI handling. v2

With less zeal, now.

Chris, do you think there's a better fix we can apply at a higher level to avoid doing this work?

Comment 15

[Chris Kitching [:ckitching]]

(In reply to Richard Newman [:rnewman] from comment #14)
> Created attachment 8512397 [details] [diff] [review]
> Check for null earlier in favicon data: URI handling. v2
> 
> With less zeal, now.
> 
> Chris, do you think there's a better fix we can apply at a higher level to
> avoid doing this work?

Well, one obvious way to avoid this check is to null check in decodeDataURI (I thought we did that already? My phone dislikes mxr too much to check :P )

As for the big picture, this logic is here for mostly historical reasons...

Null favicons are a saddeningly-common thing. This is largely a leftover from the earlier favicon caching implementation that keyed by page URL: that led to most of the clients of the favicon system being designed to request a favicon in terms of only a page URL. 
When I switched things over so the favicon system internally understands favicons in terms of their favicon url (which makes sense, for hopefully-obvious reasons - we stop duplicating identical favicons, for one thing) this created a bit of a problem. The workaround was to add methods to Favicons that allows for requests that omit a favicon URL and then have this logic you're poking to try and figure out what the client really meant.

The "best" solution (in terms of simplifying the favicon loading, anyway) would be to refactor many (or all) callers of the favicon system to do so with favicon URLs. That way, we can safely start assuming that null favicons won't happen and lose a lot of annoying checks.

It might not be worth the trouble. It might not be sanely possible to do (we might just end up doing a background task to load the favicon URL from the database before calling into favicon-land, which seems strictly more stupid than what we currently do).

*shrug*

Comment 16

[Chris Kitching [:ckitching]]

Comment on attachment 8512397 [details] [diff] [review]
Check for null earlier in favicon data: URI handling. v2

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

Now with more sanity :D.

Before doing this, decide if you really want to do this, or if you'd rather add (or change) a null check in decodeDataURI. It seems likely that there may be consumers of decodeDataURI who aren't LoadFaviconTask (I have a feeling I've seen one somewhere. Why hasn't someone ported IDEA to Android yet?) who would benefit from this problem being solved there.
(in which case, presumably, the "fix" reduces to deleting the overzealous logging line).

Or, maybe the real thing to do is eliminate the null check from decodeDataURI entirely (if there is one) and to stop being so sloppy about nulls (in which case we'd need to have the check here in LoadFaviconTask, where we *do* expect nulls for reasons mentioned earlier).

Comment 17

[Richard Newman [:rnewman]]

Here's my take.

To show favicons for the web, we'll always need some kind of guessing. Lots of pages are:

  /index.html
  /favicon.ico

and we ought to handle that. We could move this logic out of the favicon code itself, but it'd just move into GeckoApp (where it came from).


I think in this case, though, we can do better: we're loading from a data: URI, so we know in advance that we'll never guess a favicon. Furthermore, it doesn't make sense to have a stored favicon for those pages: it's a page without a real URL, and if a given data: URI encodes a page with a favicon, it will always continue to do so.

In short: if we don't get favicon events from inside the encoded page, we'll never have a favicon.

That implies to me that there's a spot higher up, where we instantiate the LoadFaviconTask, where we should decide: is this the kind of page that will always send us a message with its favicon, or should I load it with the usual path?

Comment 18

[Richard Newman [:rnewman]]

(In reply to Chris Kitching [:ckitching] from comment #16)

> Before doing this, decide if you really want to do this, or if you'd rather
> add (or change) a null check in decodeDataURI. 

decodeDataURI has input checking, but it warns.

> It seems likely that there
> may be consumers of decodeDataURI who aren't LoadFaviconTask

There's only one other: getMostSuitableBitmapFromDataURI (for createShortcut and setSearchEngineFromJSON). These are expected to always pass in valid URIs, and if they don't I think it's acceptable to log a warning.

Comment 19

[Chris Kitching [:ckitching]]

(In reply to Richard Newman [:rnewman] from comment #17)
> Here's my take.
> 
> To show favicons for the web, we'll always need some kind of guessing. Lots
> of pages are:
> 
>   /index.html
>   /favicon.ico
> 
> and we ought to handle that. We could move this logic out of the favicon
> code itself, but it'd just move into GeckoApp (where it came from).
> 
> 
> I think in this case, though, we can do better: we're loading from a data:
> URI, so we know in advance that we'll never guess a favicon. Furthermore, it
> doesn't make sense to have a stored favicon for those pages: it's a page
> without a real URL, and if a given data: URI encodes a page with a favicon,
> it will always continue to do so.
> 
> In short: if we don't get favicon events from inside the encoded page, we'll
> never have a favicon.

That makes sense. Such pages ought to have their favicon bitmap put in the memory cache (so we save the need to decode it all the time), but there's no point putting them in the database.

> That implies to me that there's a spot higher up, where we instantiate the
> LoadFaviconTask, where we should decide: is this the kind of page that will
> always send us a message with its favicon, or should I load it with the
> usual path?

This is a good idea. That'll be in Favicons.java. Would you like me to find time to poke this at some point?

And, yes, you're right, LoadFaviconTask will always need to handle nulls and do the guessing stuff, so prettymuch all of Comment 15 is complete crap.

... We're on fire tonight.

Comment 20

[Mats Palmgren (inactive)]

The patch seems to work, there are no "Can't decode null data: URI" warnings at all:
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/9d0d15562053a183ed23bfa322f29d0db70d8a4306b30e9cdc56cab5a5ed7e588224824a3462918076709b016e9c5bd38b078e8300fd03a107a042124d3f6701

I'd still like to understand how my patch affected the loading of favicons.
What is the event/signal/condition you're waiting for that triggers the action
leading to the warning?

Comment 21

[Mats Palmgren (inactive)]

Perhaps unrelated, but I wonder if these warnings are related to favicon loads (occurs for each test in the link above):
10-28 07:51:00.671 W/GeckoNetworkManager( 2103): Already stopped!
10-28 07:51:00.687 I/Gecko   ( 2103): AndroidBridge::GetCurrentNetworkInformation
10-28 07:51:00.687 E/GeckoNetworkManager( 2103): Registering receiver failed

I see those on m-i also, so at least it's not related to my patch.

Comment 22

[Richard Newman [:rnewman]]

It'll be called:

* Every time we get a PAGE_SHOW event.
* Every time we get a LINK_FAVICON event.
* Whenever the data layer changes for a page that's shown in one of Fennec's homepages (e.g., a history row).
* When certain context menu events occur.

My guess is that you're somehow triggering a PAGE_SHOW.

Comment 23

[Richard Newman [:rnewman]]

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

Comment 24

[Richard Newman [:rnewman]]

(In reply to Chris Kitching [:ckitching] from comment #19)

> This is a good idea. That'll be in Favicons.java. Would you like me to find
> time to poke this at some point?

I filed Bug 1090549. And yes, poke at it at some point, but take a look at your outstanding assigned bugs first :)

Comment 25

[Mats Palmgren (inactive)]

(In reply to Richard Newman [:rnewman] from comment #22)
Thanks for the info.  I don't think my patch can affect any of those.
So to get to the bottom of this I pushed a debug printf when PageLoad occurs:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/a604c2b4c1c504f3083194778b37f1a7402ecf7de1e0b7da2d6fd77776114aa46b0c8404b2c7f6d16a7a747f5dafbc1708c224e31612d89faf9a7ed07dfb2388

To my surprise the GeckoFaviconDecoder warnings are gone!
So I went back used the same base revision as when I reported this bug:

http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/18791ceb99cdb7779fdaf0e2c4d01f247d93dc99f7504a98ef1ffc82de1f8bd736e910b0c137ad58edc0e441e5846b803d27dae13a67b1be36f81bc5ebb03ec8

And the warnings are back (and you can also see from my debug printf
that there is only one PageLoad event per test).

So what happened?
Well, I updated my m-i tree in between and picked up this backout:
http://hg.mozilla.org/mozilla-central/rev/6f053fd0e8b8
So I'm confident that my patch had nothing to do with these warnings at all.
I was just unlucky and picked up a buggy m-i rev in my first Try push.

I strongly suspect that bug 1088669 is (was) the root cause of these warnings.

Comment 26

[Mats Palmgren (inactive)]

Sorry, I meant PaheShow above (not PageLoad).

Comment 27

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

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