CC bartn and anwis as FYI

Diving into the code, it looks like the times we set field trial triggered in session to false are:
- on initialization of BaseSearchProvider (happens at startup / profile open)
- Start()ing a new synchronous autocomplete pass
- SearchProvider::ResetSession()

ResetSession() must be the culprit.  It doesn't clear field trial triggered at the same time.

For this explanation to make sense, it must be possible to select a suggestion without triggering another synchronous autocomplete pass immediately after a ResetSession() call.

I believe this is possible if the user does something like a "paste-and-go" action.  I'll have to check the logs to see if these two unexpected actions are like that.

It's not paste-and-go actions.  Of the ~100 entries with SearchProvider's field_trial_triggered set but field_trial_triggered_in_session not set, none are paste-and-go.

Here's a clue though: about half the actions are when the popup is closed.

After some thought and testing, I found one situation that can cause this:
1. Start typing in the omnibox in one tab.  Leave the temporary text in the box (either what you typed, or arrow down to a suggestion)
2. Switch tabs.
3. Type something else in that other tab that will trigger field_trial_triggered.
4. Switch back to original tab and press enter to accept the temporary text.
This a log entry where
- triggered in session is false (because we just reset the session)
- triggered is true (because on the last synchronous call it was true)
- popup is closed
- selected index is 0

This explained about half the weird situations.  (I checked--all the time the popup is closed, the selected index is 0.)

Now to figure out the other half the cases.  I think it might have to do with ZeroSuggest.

Additional logs analysis shows the other half isn't likely to be related to ZeroSuggest.  Still thinking.

I wonder if this has to do with opening something in a background tab.

I can't check today; I'll need to physically be at my desktop to check.

The opening in the background tab theory did not pan out.

pkasting@: do you know how, though some extremely used UI interface, the user could be in a situation where the ResetSession() is called but the omnibox dropdown is remaining open from earlier input?
i.e.,
OmniboxEditModel::SetInputInProgress() is called in a manner that causes a a ResetSession9) call,
then we have OmniboxEditModel::OpenMatch() called with an index > 0 (the popup is open),
without an calls in between that cause a synchronous autocomplete controller call.

thanks,
mark

We can only call ResetSession() if we're going from input-not-in-progress to input-in-progress.  So the user can't have been typing before and is typing now.  I think that requires autocompletion to have been run.

The only way I can think that the popup would have been open is that ZeroSuggest was running, but I don't think that case is useful to you.  Also you said in comment 4 that wasn't it :)

What if the user previously run autocompletion, switched to a different tab, switched back, focused the omnibox, and hit the down arrow to reopen the popup?  That probably doesn't solve your issue either but that's the only unusual interaction I can think of.

My limited understanding was switching tabs away from an in-progress omnibox edit commits the current text (either what the user typed or the fill into edit of what the user arrowed down to) so that switching away forgets everything else in the dropdown.  i.e., when you switch back and press down, you're restarting autocomplete with the current text in the dropdown.

Can users with some weird windows manager switch away from a window without closing the dropdown?

You can't switch away without closing the dropdown AFAIK.  I think your understanding is correct.  I was sort of racking my brain for any weird situation I could think of.

pkasting:
I found this fragment.

void OmniboxViewViews::UpdatePopup() {
  model()->SetInputInProgress(true);
  if (!model()->has_focus())
    return;
...
}
https://code.google.com/p/chromium/codesearch#chromium/src/chrome/browser/ui/views/omnibox/omnibox_view_views.cc&l=469&rcl=1458127931
Note that the first clauses causes a ResetSession() call if switching the user input was not already in progress.

Can you help me understand what's going on?  Why would we call UpdatePopup when the model does not have focus?  I'd especially like to understand if the popup can be open and the model not have focus.

Here are the two UpdatePopup calls from the edit model:
https://code.google.com/p/chromium/codesearch#chromium/src/components/omnibox/browser/omnibox_edit_model.cc&sq=package:chromium&l=1053&rcl=1458143321
https://code.google.com/p/chromium/codesearch#chromium/src/components/omnibox/browser/omnibox_edit_model.cc&sq=package:chromium&l=1230&rcl=1458143321

There is another within platform-specific UI code.

Here's a comment from the now-deleted Windows-native version of the code:

  if (!model_->has_focus()) {
    // When we're in the midst of losing focus, don't rerun autocomplete.  This
    // can happen when losing focus causes the IME to cancel/finalize a
    // composition.  We still want to note that user input is in progress, we
    // just don't want to do anything else.

The commit comment on this code (which predates the public repository) is:

The Chinese IME actually changes the text in the edit when a composition is
finalized, which led to us erroneously reopening the popup while we were
killing focus.  Change the way we handle this case.

I would be suspicious that we still get the same messages at the same times now that we're not using a Windows native HWND/text control.  So it's not obvious to me that the above scenario can happen anymore.

Thanks for the explanation of the focus issue.  With that in mind, I checked the application_locale of the anomalous omnibox event logs.  It seems the majority (three quarters) are en-US, which leads me to think this isn't the result of an interaction with an IME.

Could there be a similar situation (losing focus and/or popup still open) with accessibility tools?  I'm afraid I don't know much about how accessibility tools work.

I don't either.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/1b55e348738d640be85412d8400e3cb5ef46d52e

commit 1b55e348738d640be85412d8400e3cb5ef46d52e
Author: mpearson <mpearson@chromium.org>
Date: Sat Mar 19 04:36:20 2016

Omnibox Logging - Clear Both Counterfactual Bits on ResetSession() Call

It's weird to have the triggered bit set while the triggered_in_session
bit is not set.  This can happen in weird edge conditions.  For example,
type something in tab A, type something else in tab B where this
something else triggers the field trial, switch back to tab A and
press enter to navigate without typing anything new.  The switching tabs
will cause a ResetSession() call, clearing the triggered_in_session bit.
Yet the triggered bit does not get cleared; it only gets set/reset upon
user typing (i.e., a call to SearchProvider).  Thus, we have this
inconsistency.

Really, conceptually if we send ResetSession() calls at the appropriate
times, it should clear all the bits.

BUG= 593434 

Review URL: https://codereview.chromium.org/1811123003

Cr-Commit-Position: refs/heads/master@{#382181}

[modify] https://crrev.com/1b55e348738d640be85412d8400e3cb5ef46d52e/chrome/browser/autocomplete/search_provider_unittest.cc
[modify] https://crrev.com/1b55e348738d640be85412d8400e3cb5ef46d52e/components/omnibox/browser/search_provider.cc

With the code change in comment #14, the logging anomaly should go away.

I'm disappointed that I managed to only explain about half of the anomalous situations (see comment 3 for the ones I could explain).  The other half--the half in which the popup is still open--I couldn't figure out.  The fact that the popup is still open makes me think that we're calling ResetSession() at some point when we shouldn't, and this means we'll have the triggered bits set incorrectly to false.  However, given the tiny size of this remaining unexplained anomaly (on the order of 0.00001% of omnibox interactions), I don't think it's worth the time to investigate further.  Any experiment we run, even experiments with low triggering rates that need these field-trial-triggered logging bits for analysis, will nonetheless have an effect size that will dwarf that of the incorrectly logged events.

Marking as fixed.

I did my math wrong, forgetting to take into account that the experiment my numbers were derived from was running on only a small fraction of traffic.  Corrected is something more like: the remaining explained component where I think ResetSession is being called when it shouldn't causes 0.05% of the logs to be recorded incorrectly.

Still keeping as fixed; not worth the time to investigate further.