1635622 - can't access property "heuristic", firstResult is undefined

Status: RESOLVED FIXED

(Firefox :: Address Bar, defect, P3)

Description

[kernp25]

Attachment: firefox_QMY37cpMSE.png

I have seen this error in console: can't access property "heuristic", firstResult is undefined

My browser version: 77.0a1 (2020-05-04) (64-Bit)

Comment 1

[kernp25]

Attachment: firefox_leOm2Jf23e.png

Comment 2

[kernp25]

I will try to reproduce the error.

Comment 3

[Drew Willcoxon :adw]

Thanks for flagging me. According to the stack, _chunkTimer has fired after user input, notifying the view of results, but there are no results. That means the providers are really slow, or maybe the query was canceled before any of them returned results. notifyResults should bail if the query is canceled, and somewhere along the way, we should also bail if there are no results. That should probably happen in notifyResults since consumers shouldn't be notified when there are actually no results. In fact that's what one of my patches in bug 1398416 does, so I'll mark it as a dependency and hopefully we can fix this there.

If you do manage to figure out how to reliably reproduce it, I'd be interested.

Comment 4

[kernp25]

This seems to happen at startup (if the browser is loading/busy).

Comment 5

[Drew Willcoxon :adw]

Bug 1398416 ended up not making the change I mentioned in comment 3, so this is likely still a problem. It should be easy enough to fix, but first it would be nice to investigate exactly why this is happening. I still do think it's probably just that the chunk timer fires before results are ready because the results are slow to be fetched. That's consistent with this happening at startup when the browser is busy doing many things.

Comment 6

[kernp25]

Attachment: rHnUeoRvam.mp4

Comment 7

[kernp25]

It seems to happen, if you type "w" at the address bar (maybe "www"?).

Can you look at the video?

Comment 8

[kernp25]

If i type "W" in the address bar, it also makes the error.

Comment 9

[kernp25]

"w" must be the first letter, you type in the address bar.

Comment 10

[Drew Willcoxon :adw]

Thanks for investigating this some more. The stack in your video, like the stack in your screenshot, shows that we're notifying due to the chunk timer timing out. So the chunk timer is timing out before any results have been fetched. All we need to do is bail from _notifyResults if there are no results, or alternatively don't call _notifyResults from the chunk timer callback.

Comment 11

[Drew Willcoxon :adw]

No wait, that doesn't make sense. We only start the chunk timer when a non-heuristic provider adds results. So there should always be at least one result when the chunk timer fires.

So I'll have to think more about why this is happening. It's not a problem with canceling the query since we also cancel the chunk timer.

Comment 12

[Drew Willcoxon :adw]

Could you please enable some logging and post the log here? First, run this in the browser console. It enables a bunch of urlbar logging:

(function() {
let log = Log.repository.getLogger("Urlbar");
log.addAppender(new Log.DumpAppender());
log.addAppender(new Log.ConsoleAppender());
})();

Then please reproduce the error. You should see a lot of "Urlbar" log lines in both the browser console and your Windows terminal/console, if you started Firefox that way. They are the same logs, so you can look at whichever one is easier. Thanks.

Comment 13

[kernp25]

1590570334343 Urlbar.ProvidersManager INFO Query start w
1590570334343 Urlbar.ProvidersManager INFO Using muxer UnifiedComplete
1590570334343 Urlbar.Tokenizer INFO Tokenizing: {"allowAutofill":true,"isPrivate":false,"maxResults":10,"searchString":"w","allowSearchSuggestions":true,"currentPage":"about:home","formHistoryName":"searchbar-history","lastResultCount":0,"userContextId":0}
1590570334344 Urlbar.Tokenizer DEBUG Restriction chars: ^+%?#$
1590570334344 Urlbar.Tokenizer INFO Found tokens: ["w"]
1590570334344 Urlbar.Tokenizer DEBUG userinfo:
1590570334345 Urlbar.Tokenizer DEBUG hostPort: w
1590570334345 Urlbar.Tokenizer INFO Filtered Tokens: ["w"]
1590570334345 Urlbar.ProvidersManager DEBUG Context sources 1,2,3,4,5,6
1590570334347 Urlbar.Provider.UnifiedComplete INFO Starting query for w
1590570334347 Urlbar.Tokenizer INFO Tokenizing: {"searchString":"w"}
1590570334348 Urlbar.Tokenizer DEBUG Restriction chars: ^+%?#$
1590570334348 Urlbar.Tokenizer INFO Found tokens: ["w"]
1590570334348 Urlbar.Tokenizer DEBUG userinfo:
1590570334348 Urlbar.Tokenizer DEBUG hostPort: w
1590570334349 Urlbar.Tokenizer INFO Filtered Tokens: ["w"]
1590570334350 Urlbar.ProvidersManager DEBUG SkippableTimer :: Query provider timer :: Started
1590570334350 Urlbar.ProvidersManager INFO Queried 3 providers
1590570334352 Urlbar.Tokenizer DEBUG userinfo:
1590570334352 Urlbar.Tokenizer DEBUG hostPort: w
1590570334401 Urlbar.ProvidersManager DEBUG SkippableTimer :: Query provider timer :: Timed out!
1590570334401 Urlbar.Provider.PrivateSearch INFO Starting query for w
1590570334401 Urlbar.Provider.SearchSuggestions INFO Starting query for w
1590570334401 Urlbar.Provider.PrivateSearch INFO isPrivateEngine: false
1590570334401 Urlbar.Provider.PrivateSearch DEBUG SkippableTimer :: ProviderPrivateSearch :: Started
1590570334405 Urlbar.Provider.SearchSuggestions DEBUG SkippableTimer :: ProviderSearchSuggestions :: Started
1590570334502 Urlbar.Provider.PrivateSearch DEBUG SkippableTimer :: ProviderPrivateSearch :: Timed out!
1590570334503 Urlbar.ProvidersManager DEBUG SkippableTimer :: Query chunk timer :: Started
1590570334506 Urlbar.Provider.SearchSuggestions DEBUG SkippableTimer :: ProviderSearchSuggestions :: Timed out!
1590570334520 Urlbar.ProvidersManager DEBUG SkippableTimer :: Query chunk timer :: Timed out!
1590570334520 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334520 Urlbar.ProvidersManager DEBUG SkippableTimer :: Query chunk timer :: Canceling
1590570334520 Urlbar.ProvidersManager DEBUG SkippableTimer :: Query chunk timer :: Skipped
1590570334520 Urlbar.ProvidersManager DEBUG Cropping 0 results to 10
1590570334660 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334660 Urlbar.ProvidersManager DEBUG Cropping 1 results to 10
1590570334719 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334719 Urlbar.ProvidersManager DEBUG Cropping 2 results to 10
1590570334720 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334720 Urlbar.ProvidersManager DEBUG Cropping 3 results to 10
1590570334721 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334721 Urlbar.ProvidersManager DEBUG Cropping 4 results to 10
1590570334723 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334723 Urlbar.ProvidersManager DEBUG Cropping 5 results to 10
1590570334724 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334724 Urlbar.ProvidersManager DEBUG Cropping 6 results to 10
1590570334731 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334731 Urlbar.ProvidersManager DEBUG Cropping 7 results to 10
1590570334733 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334733 Urlbar.ProvidersManager DEBUG Cropping 8 results to 10
1590570334734 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334734 Urlbar.ProvidersManager DEBUG Cropping 9 results to 10
1590570334735 Urlbar.Muxer.UnifiedComplete DEBUG Buckets: heuristic,1,extension,5,suggestion,4,general,Infinity,suggestion,Infinity,general,Infinity
1590570334736 Urlbar.ProvidersManager DEBUG Cropping 10 results to 10
1590570334737 Urlbar.ProvidersManager INFO Query cancel w
1590570334737 Urlbar.Provider.UnifiedComplete INFO Canceling query for w
1590570334737 Urlbar.Provider.Interventions INFO Canceling query for w
1590570334737 Urlbar.Provider.PrivateSearch INFO Canceling query for w
1590570334737 Urlbar.Provider.SearchTips INFO Canceling query for w
1590570334737 Urlbar.Provider.SearchSuggestions INFO Canceling query for w
1590570334737 Urlbar.Provider.TokenAliasEngines INFO Canceling query for w
1590570334737 Urlbar.Provider.TopSites INFO Canceling query for w
1590570334737 Urlbar.ProvidersManager DEBUG SkippableTimer :: Query provider timer :: Skipped
1590570336422 Urlbar.EventBufferer DEBUG Clearing queue on blur

Comment 14

[Drew Willcoxon :adw]

Thank you. We can see that the chunk timer is starting and timing out. We can also see that the muxer is called for each of the 10 results being added. And right around where the chunk timer starts and times out, we have logs from the private search provider. It looks like the private search provider is the first provider to add results: its internal timer times out and the next line logged is "Query chunk timer :: Started", i.e., the chunk timer is started (due to adding results).

That's helpful. It makes me remember that the muxer doesn't always include each result in the final list of results -- of course. It can exclude results. So I think I was basically right. What's likely happening is that the private search provider adds the private search result (and I see you're on Nightly, which is required for it) but the muxer excludes it (because the search also returns history for example), so the final context.results on return from the first call to the muxer is empty.

The right fix is bailing when context.results is empty after all.

Comment 15

[Drew Willcoxon :adw]

Actually in this case the condition that causes the muxer to exclude the private search result is probably context.results.length > 1, not the presence of history. The private search provider is the first provider to add results, and it only adds the one.

Comment 16

[Drew Willcoxon :adw]

Attachment: Bug 1635622 - Don't notify urlbar consumers when there aren't any results in a search.

See https://bugzilla.mozilla.org/show_bug.cgi?id=1635622#c14

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d7d503d53382
Don't notify urlbar consumers when there aren't any results in a search. r=mak

Comment 18

[Razvan Maries]

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