I've accidentally overwritten logs with a newer test run. I'll share logs if I'll see this issue again.

One set of logs:
http://www.corp.google.com/~nkostylev/no_crawl/cros/20887/

suite_Smoke/security_ProfilePermissions.login      FAIL
--------------------------------------------------------
Total PASS: 18/20 (90%)

========== ERROR FILE /tmp/run_remote_tests.ccmY/suite_Smoke/security_ProfilePermissions.login/debug/security_ProfilePermissions.login.ERROR FOR TEST suite_Smoke/security_ProfilePermissions.login ==============
09/27 02:20:50 ERROR|  warnings:0029| /usr/local/lib/python2.6/site-packages/dbus/connection.py:242: DeprecationWarning: object.__init__() takes no parameters
09/27 02:20:50 ERROR|  warnings:0029|   super(Connection, self).__init__(*args, **kwargs)

=========== END ERROR FILE /tmp/run_remote_tests.ccmY/suite_Smoke/security_ProfilePermissions.login/debug/security_ProfilePermissions.login.ERROR FOR TEST suite_Smoke/security_ProfilePermissions.login ===========

Another case.

4:43:52 INFO | 	START	login_CryptohomeMounted	login_CryptohomeMounted	timestamp=1317120232	localtime=Sep 27 14:43:52	
14:43:52 INFO | Bundling /build/x86-alex/usr/local/autotest/client/site_tests/login_CryptohomeMounted into test-login_CryptohomeMounted.tar.bz2
14:44:54 INFO | 		ERROR	login_CryptohomeMounted	login_CryptohomeMounted	timestamp=1317120294	localtime=Sep 27 14:44:54	Unhandled JSONInterfaceError: Automation call {... 'command': 'Login'} received empty response.  Perhaps the browser crashed.
14:44:54 INFO | 	END ERROR	login_CryptohomeMounted	login_CryptohomeMounted	timestamp=1317120294	localtime=Sep 27 14:44:54

Page is rendered from Google Accounts, says
"The page you requested is invalid".

Logs:
http://www.corp.google.com/~nkostylev/no_crawl/cros/20887/login_CryptohomeMounted/

I'm wondering if this is 20323, and this is the visible symptom of the failure.

Nikita, were you doing this on hardware or on a VM?  I'm trying to figure out the best way to repro, and gather more info.

I was running tests on Alex machine.

Hm.  Nope, looking at the logs, I see Chrome hitting accounts/ServiceLogin on the mock gaia server, and it seems to be responding OK.

I actually see accounts/ServiceLogin getting served twice, once with test_email and test_pwd arguments.  Not sure what those are.

Should not be  issue 20323 . Chrome log shows that automation got all the signals and tried out a login.

http://www.corp.google.com/~nkostylev/no_crawl/cros/20887/login_CryptohomeMounted/sysinfo/var/log/chrome/chrome_20110927-034359

Note "Failed to get the ownership of org.chromium.LibCrosService: " in http://www.corp.google.com/~nkostylev/no_crawl/cros/20887/login_CryptohomeMounted/sysinfo/var/log/chrome/chrome_20110927-034359

Nikita, is there any way to see what URL got the "The page you requested is invalid"?

(No comment was entered for this change.)

Looks like another instance of this:

http://chromeos-botmaster.mtv.corp.google.com:8026/builders/stumpy-binary/builds/832/steps/VMTest/logs/stdio

>> is there any way to see what URL got the "The page you requested is invalid"?

I'm not sure how to do that except that enable verbose logging (--v=1 instead of --log-level=1).

In this set of logs verbose logging wasn't enabled.

Suggestion: should we just enable verbose logging for Chrome in test images?
I believe that might simplify some issues investigations in expense of a larger test-results archives and (unfortunately) noisier logs.

Check out /src/chrome/test/pyautolib/pyauto.py, ExtraChromeFlags. We have some vlog for chromeos test. You can add yours there.

http://codesearch.google.com/codesearch#OAMlx_jo-ck/src/chrome/test/pyautolib/pyauto.py&type=cs&q=pyauto.py&exact_package=chromium&l=244

Also, I have talked with nirnimesh and we are thinking of adding some code to dump out the gaia-frame html when timeout happens during login attemp. So that we could know exactly what is loaded there.

Likely new instance of this problem:
http://chromegw/i/chromiumos/builders/x86%20generic%20PFQ/builds/1056/steps/VMTest/logs/stdio

suite_Smoke/security_ProfilePermissions.login      FAIL

========== ERROR FILE /tmp/cbuildbotfh9i7g/test_harness/SimpleTestUpdateAndVerify/2_verify/suite_Smoke/security_ProfilePermissions.login/debug/security_ProfilePermissions.login.ERROR FOR TEST suite_Smoke/security_ProfilePermissions.login ==============
09/28 10:03:22 ERROR|  warnings:0029| /usr/local/lib/python2.6/site-packages/dbus/connection.py:242: DeprecationWarning: object.__init__() takes no parameters
09/28 10:03:22 ERROR|  warnings:0029|   super(Connection, self).__init__(*args, **kwargs)

@16 happened again. Chrome is with the logs I added yesterday but I don't see offline/portal message showing and no frame error in chrome log at all. Form is submitted but auth server does not get the POST. :(

Nirnimesh, it seems we have to dump out the gaia frame to find out what's wrong here.

Tree closer with similar symptoms to this issue or 20323

http://build.chromium.org/p/chromiumos/builders/x86%20generic%20PFQ/builds/1065/steps/cbuildbot/logs/stdio

(No comment was entered for this change.)

@18 is  issue 20323  and see my comments @60. Seems like Chrome tightened ssl check and refuses to talk to our auth server.

Again today, suite_Smoke/desktopui_ScreenLocker in:

http://chromeos-botmaster.mtv.corp.google.com:8026/builders/x86-mario%20canary/builds/1092

/var/log/chrome logs in build artifacts show:


[3559:3559:77837950:VERBOSE2:automation_provider.cc(229)] OnLoginWebuiReady
[3559:3582:77839041:ERROR:base_paths_linux.cc(112)] Couldn't find your source root.  Try running from your chromium/src directory.
[3559:3582:77843463:ERROR:plugin_data_remover.cc(146)] ClearSiteData returned error
[3559:3559:77927642:INFO:CONSOLE(3004)] "Opening extension: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/main.html, opt_email=", source: chrome://oobe/login (3004)
[3559:3559:77986474:INFO:CONSOLE(158)] "#### main.html start", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/main.html?gaiaOrigin=https%3A%2F%2Fwww.google.com&hl=en-US&test_email=performancetestaccount%40gmail.com&test_password=perfsmurf (158)
[3559:3559:77986898:INFO:CONSOLE(48)] "### Authenticator.initialize", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/main.html?gaiaOrigin=https%3A%2F%2Fwww.google.com&hl=en-US&test_email=performancetestaccount%40gmail.com&test_password=perfsmurf (48)
[3559:3559:78017247:INFO:CONSOLE(100)] "#### Authenticator.onPageLoad: navigator.onLine = true", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/main.html?gaiaOrigin=https%3A%2F%2Fwww.google.com&hl=en-US&test_email=performancetestaccount%40gmail.com&test_password=perfsmurf (100)
[3559:3559:78018031:INFO:CONSOLE(102)] "#### Authenticator.onPageLoad: loading frame...", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/main.html?gaiaOrigin=https%3A%2F%2Fwww.google.com&hl=en-US&test_email=performancetestaccount%40gmail.com&test_password=perfsmurf (102)
[3559:3559:78018287:INFO:CONSOLE(85)] "Loading GAIA frame", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/main.html?gaiaOrigin=https%3A%2F%2Fwww.google.com&hl=en-US&test_email=performancetestaccount%40gmail.com&test_password=perfsmurf (85)
[3559:3559:78085737:INFO:CONSOLE(90)] "### Authenticator.loadFrame_: Frame loaded.", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/main.html?gaiaOrigin=https%3A%2F%2Fwww.google.com&hl=en-US&test_email=performancetestaccount%40gmail.com&test_password=perfsmurf (90)
[3559:3559:78108065:INFO:CONSOLE(5)] "Test script injected!", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/test/content.js (5)
[3559:3559:78113615:INFO:CONSOLE(23)] "Got test account info: performancetestaccount@gmail.com/perfsmurf", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/test/content.js (23)
[3559:3559:78116558:INFO:CONSOLE(26)] "Form field changed!", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/test/content.js (26)
[3559:3559:78124921:INFO:CONSOLE(29)] "Form submitted!", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/test/content.js (29)
[3559:3559:78448713:INFO:CONSOLE(90)] "### Authenticator.loadFrame_: Frame loaded.", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/main.html?gaiaOrigin=https%3A%2F%2Fwww.google.com&hl=en-US&test_email=performancetestaccount%40gmail.com&test_password=perfsmurf (90)
[3559:3559:78457819:INFO:CONSOLE(5)] "Test script injected!", source: chrome-extension://mfffpogegjflfpflabcdkioaeobkgjik/test/content.js (5)
[3559:3604:85665978:WARNING:audio_mixer_alsa.cc(207)] Attach to card default failed: No such file or directory
<<<<< note 30+ second gap here >>>>>
[3559:3559:122866599:VERBOSE1:automation_provider.cc(452)] AutomationProxy disconnected, resetting AutomationProvider.

 Issue 21289  has been merged into this issue.

I believe that this just happened at http://build.chromium.org/p/chromiumos/builders/x86%20generic%20PFQ/builds/1136 as well.

From the above build:

10/05 15:51:27 INFO |logging_ma:0560| chrome/test/pyautolib/pyautolib.cc:338: Failure
10/05 15:51:27 INFO |logging_ma:0560| Value of: automation()->SendJSONRequest(request, timeout, &response)
10/05 15:51:27 INFO |logging_ma:0560|   Actual: false
10/05 15:51:27 INFO |logging_ma:0560| Expected: true
10/05 15:51:27 DEBUG|base_utils:0081| Running 'logger "cros/login.py: Attempting StopSession..."'
10/05 15:51:27 DEBUG|base_utils:0081| Running 'ls -tr1 /var/log/messages.*'
10/05 15:51:28 DEBUG|base_utils:0081| Running 'logger "cros/login.py: StopSession complete."'

And from Chrome logs:
[1005/155042:INFO:upstart_signal_emitter.cc(21)] Emitting login-prompt-visible Upstart signal
[10580:10602:144489061:ERROR:base_paths_linux.cc(112)] Couldn't find your source root.  Try running from your chromium/src directory.
[1005/155127:INFO:session_manager_service.cc(642)] SessionManagerService StopSession
[1005/155127:INFO:policy_service.cc(203)] Persisted policy to disk.
[1005/155127:INFO:session_manager_service.cc(411)] SessionManagerService quitting run loop
[1005/155127:INFO:session_manager_service.cc(897)] SessionManagerService exiting
[1005/155127:INFO:system_utils.cc(50)] Sending 15 to 10580 as 1000
[1005/155127:INFO:chromeos_login.cc(181)] Filter:: PropertyChangeComplete signal received
Entity: line 8: parser error : Extra content at the end of the document
argetidhash="/fbuZKBYiFWSClUUveb7AQ==" window="0" session="0" time="1317855071"/
                                                                               ^
error : xmlTextWriterWriteDocCallback : XML error 5 !
[1005/155127:INFO:chromeos_login.cc(227)] Disconnected from session manager
[1005/155127:INFO:session_manager_service.cc(384)] emitting D-Bus signal SessionStateChanged:stopped
[1005/155127:189885133:ERROR:main.cc(80)] Got X I/O error (probably lost connection to server); exiting

Happened again: http://build.chromium.org/p/chromiumos/builders/x86%20generic%20PFQ/builds/1149

Seen on http://chromeos-botmaster.mtv.corp.google.com:8026/builders/x86-zgb-binary/builds/1458/steps/VMTest/logs/stdio. P1->P0.

Commit: 2f932d2893a3b8eef1d35818a33cbdc737255f8d
 Email: cmasone@chromium.org

[autotest] Switch to resolv.conf munging in lieu of iptables-fu

IPTables is letting us down.  Every now and again, a DNS resolution request
gets through, leading to a botched webui login flow, leading to test failure.

Punt on iptables and move to directly munging /var/run/flimflam/resolv.conf
(which we find by following the symlink at /etc/resolv.conf)

BUG=chromium-os:20323, chromium-os:20887
TEST=suite_Smoke, CryptohomeMounted x 50 on hardware and VM

Change-Id: Ibd0725fc2176dc7cedc46994f8299b0b1b33536e
Reviewed-on: http://gerrit.chromium.org/gerrit/9813
Commit-Ready: Chris Masone <cmasone@chromium.org>
Reviewed-by: Chris Masone <cmasone@chromium.org>
Tested-by: Chris Masone <cmasone@chromium.org>

M	client/cros/cros_ui_test.py

Hoping that last CL worked :-)

Declaring victory after several days of no repro!

(No comment was entered for this change.)

(No comment was entered for this change.)

(No comment was entered for this change.)

(No comment was entered for this change.)