Additional logging for LoginPromptBrowserTest.IncorrectConfirmation

Additional logging for LoginPromptBrowserTest.IncorrectConfirmation

This test runs into intermittent timeouts. Logging is being added to help track
down causes.

BUG=69266
TEST=none

Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=71439

[asanka, 2011-01-11 19:17:39]

Added logging and made one minor change to the test to make sure we are seeing
the correct number of notifications.

[cbentzel, 2011-01-11 19:40:34]

Do LOG(INFO)'s show up on trybot runs? 

I'm going to look at other tests to see if logging-to-track-races-in-tests is OK
or verboten. There's a bit of a cultural bias against logging.

http://codereview.chromium.org/6156008/diff/1/chrome/browser/ui/login/login_p...
File chrome/browser/ui/login/login_prompt_browsertest.cc (right):

http://codereview.chromium.org/6156008/diff/1/chrome/browser/ui/login/login_p...
chrome/browser/ui/login/login_prompt_browsertest.cc:353:
EXPECT_EQ(observer.auth_needed_count_, observer.auth_supplied_count_);
Was this added for a stronger test?

[asanka, 2011-01-11 19:50:14]

On 2011/01/11 19:40:34, cbentzel wrote:
> Do LOG(INFO)'s show up on trybot runs?

They do.

> I'm going to look at other tests to see if logging-to-track-races-in-tests is
OK
> or verboten. There's a bit of a cultural bias against logging.

Ok. "git grep LOG\(INFO\) -- \*test.cc" seems to indicate a few instances of
logging during tests, but not many.

[cbentzel, 2011-01-11 19:53:59]

+brettw

Brett, what are your feelings towards adding LOG(INFO) to test code?
Asanka's trying to track down a race condition as described in
http://code.google.com/p/chromium/issues/detail?id=69266 and
http://code.google.com/p/chromium/issues/detail?id=68860

On Tue, Jan 11, 2011 at 2:50 PM, <asanka@chromium.org> wrote:

> On 2011/01/11 19:40:34, cbentzel wrote:
>
>> Do LOG(INFO)'s show up on trybot runs?
>>
>
> They do.
>
>
>  I'm going to look at other tests to see if logging-to-track-races-in-tests
>> is
>>
> OK
>
>> or verboten. There's a bit of a cultural bias against logging.
>>
>
> Ok. "git grep LOG\(INFO\) -- \*test.cc" seems to indicate a few instances
> of
> logging during tests, but not many.
>
>
>
> http://codereview.chromium.org/6156008/
>

[brettw, 2011-01-11 20:52:36]

Logging like this is discouraged but in some cases like yours is probably the
best approach, as long as you're actively researching the bug.

The problem is when people get distracted and then the logging statements end up
there forever, which is annoying for everybody.

I might make the "Begin" and "Done" statements more specific to say what's
beginning & finishing, which will give more context for somebody looking at the
output. You might even add something in "Begin" about what all this extra
logging is for.

[cbentzel, 2011-01-11 21:35:34]

LGTM

Please consider adding extra context to the "Begin" and "Done" log statements,
as Brett suggested.

[asanka, 2011-01-11 21:58:05]

Added context to log entries and moved the final load_stop_waiter.Wait() call
below the post condition checks.  The post conditions should still hold before
we receive the LOAD_STOP, and the previous try-bot run indicated that we might
not be receiving the LOAD_STOP message.

http://codereview.chromium.org/6156008/diff/1/chrome/browser/ui/login/login_p...
File chrome/browser/ui/login/login_prompt_browsertest.cc (right):

http://codereview.chromium.org/6156008/diff/1/chrome/browser/ui/login/login_p...
chrome/browser/ui/login/login_prompt_browsertest.cc:353:
EXPECT_EQ(observer.auth_needed_count_, observer.auth_supplied_count_);
On 2011/01/11 19:40:34, cbentzel wrote:
> Was this added for a stronger test?

Yeah.  With the current state of the code, we should see an equal number of
AUTH_NEEDED and AUTH_SUPPLIED notifications for this test.  The exact number may
change based on how many concurrent requests are issued for the same target, but
the two counts should be the same.

[brettw, 2011-01-11 23:10:58]

BTW if you give up on this bug for a while, please remove the logging statements
to avoid long-term log bloat.

[cbentzel, 2011-01-12 15:04:25]

Still LGTM

http://codereview.chromium.org/6156008/diff/1/chrome/browser/ui/login/login_p...
File chrome/browser/ui/login/login_prompt_browsertest.cc (right):

http://codereview.chromium.org/6156008/diff/1/chrome/browser/ui/login/login_p...
chrome/browser/ui/login/login_prompt_browsertest.cc:279: // Marked as flaky. 
See crbug.com/69266 and http://crbug.com/68860
Nit: use full URL for 69266.