New issue
Advanced search Search tips

Issue 798482 link

Starred by 1 user
Status: WontFix
Owner: ----
Closed: Jan 2018
Cc:
pprabhu@chromium.org
ihf@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

autoserv.INFO files contain "tko parser: Unexpected indent: aborting log parse"

Project Member Reported by derat@chromium.org, Jan 2 2018 
While looking at some Chrome PFQ failures, I noticed a bunch of Autotest results file "tko parser: Unexpected indent: aborting log parse" errors. From http://uberchromegw/i/chromeos.chrome/builders/tricky-tot-chrome-pfq-informational/builds/7532:

01/02 07:54:14.229 INFO |        server_job:0218| START	----	----	timestamp=1514908453	localtime=Jan 02 07:54:13	
01/02 07:54:14.306 INFO |        server_job:0218| 	START	security_ProfilePermissions.login	security_ProfilePermissions.login	timestamp=1514908453	localtime=Jan 02 07:54:13	
01/02 07:54:22.895 INFO |        server_job:0218| 		GOOD	security_ProfilePermissions.login	security_ProfilePermissions.login	timestamp=1514908461	localtime=Jan 02 07:54:21	completed successfully
01/02 07:54:22.899 INFO |        server_job:0218| 	END GOOD	security_ProfilePermissions.login	security_ProfilePermissions.login	timestamp=1514908461	localtime=Jan 02 07:54:21	
01/02 07:54:24.714 INFO |        server_job:0218| 	START	security_ProfilePermissions.guest	security_ProfilePermissions.guest	timestamp=1514908463	localtime=Jan 02 07:54:23	
01/02 08:25:46.952 INFO |          autoserv:0685| Results placed in /usr/local/autotest/results/167035351-chromeos-test/chromeos4-row2-rack3-host19
...
01/02 08:25:49.934 ERROR|   logging_manager:0626| tko parser: MACHINE NAME: chromeos4-row2-rack3-host19
01/02 08:25:49.934 ERROR|   logging_manager:0626| tko parser: MACHINE GROUP: tricky
01/02 08:25:49.934 ERROR|   logging_manager:0626| tko parser: parsing partial test ---- SERVER_JOB
01/02 08:25:49.934 ERROR|   logging_manager:0626| tko parser: parsing partial test None CLIENT_JOB.0
01/02 08:25:49.934 ERROR|   logging_manager:0626| tko parser: RUNNING: RUNNING
01/02 08:25:49.934 ERROR|   logging_manager:0626| CLIENT_JOB.0
01/02 08:25:49.935 ERROR|   logging_manager:0626| 
01/02 08:25:49.935 ERROR|   logging_manager:0626| tko parser: parsing partial test security_ProfilePermissions.login security_ProfilePermissions.login
01/02 08:25:49.935 ERROR|   logging_manager:0626| tko parser: RUNNING: RUNNING
01/02 08:25:49.935 ERROR|   logging_manager:0626| Subdir: security_ProfilePermissions.login
01/02 08:25:49.935 ERROR|   logging_manager:0626| Testname: security_ProfilePermissions.login
01/02 08:25:49.935 ERROR|   logging_manager:0626| 
01/02 08:25:49.935 ERROR|   logging_manager:0626| tko parser: update RUNNING reason: completed successfully
01/02 08:25:49.935 ERROR|   logging_manager:0626| tko parser: parsing test security_ProfilePermissions.login security_ProfilePermissions.login
01/02 08:25:49.936 ERROR|   logging_manager:0626| tko parser: ADD: GOOD
01/02 08:25:49.936 ERROR|   logging_manager:0626| Subdir: security_ProfilePermissions.login
01/02 08:25:49.936 ERROR|   logging_manager:0626| Testname: security_ProfilePermissions.login
01/02 08:25:49.936 ERROR|   logging_manager:0626| completed successfully
01/02 08:25:49.936 ERROR|   logging_manager:0626| tko parser: parsing partial test security_ProfilePermissions.guest security_ProfilePermissions.guest
01/02 08:25:49.936 ERROR|   logging_manager:0626| tko parser: RUNNING: RUNNING
01/02 08:25:49.936 ERROR|   logging_manager:0626| Subdir: security_ProfilePermissions.guest
01/02 08:25:49.937 ERROR|   logging_manager:0626| Testname: security_ProfilePermissions.guest
01/02 08:25:49.937 ERROR|   logging_manager:0626| 
01/02 08:25:49.937 ERROR|   logging_manager:0626| tko parser: Unexpected indent: aborting log parse
01/02 08:25:49.937 ERROR|   logging_manager:0626| tko parser: parsing test security_ProfilePermissions.guest security_ProfilePermissions.guest
01/02 08:25:49.937 ERROR|   logging_manager:0626| tko parser: ADD: ABORT
01/02 08:25:49.937 ERROR|   logging_manager:0626| Subdir: security_ProfilePermissions.guest
01/02 08:25:49.937 ERROR|   logging_manager:0626| Testname: security_ProfilePermissions.guest
01/02 08:25:49.937 ERROR|   logging_manager:0626| None
01/02 08:25:49.937 ERROR|   logging_manager:0626| tko parser: Unexpected indent: aborting log parse
01/02 08:25:49.937 ERROR|   logging_manager:0626| tko parser: parsing test security_ProfilePermissions.login CLIENT_JOB.0
01/02 08:25:49.937 ERROR|   logging_manager:0626| tko parser: ADD: ABORT
01/02 08:25:49.938 ERROR|   logging_manager:0626| Subdir: security_ProfilePermissions.login
01/02 08:25:49.938 ERROR|   logging_manager:0626| Testname: CLIENT_JOB.0
01/02 08:25:49.938 ERROR|   logging_manager:0626| None
01/02 08:25:49.938 ERROR|   logging_manager:0626| tko parser: parsing test ---- SERVER_JOB

Here are some more from the same run:

01/02 08:20:50.411 ERROR|   logging_manager:0626| tko parser: MACHINE NAME: chromeos4-row2-rack3-host12
01/02 08:20:50.412 ERROR|   logging_manager:0626| tko parser: MACHINE GROUP: tricky
01/02 08:20:50.412 ERROR|   logging_manager:0626| tko parser: parsing partial test ---- SERVER_JOB
01/02 08:20:50.412 ERROR|   logging_manager:0626| tko parser: parsing partial test None CLIENT_JOB.0
01/02 08:20:50.412 ERROR|   logging_manager:0626| tko parser: RUNNING: RUNNING
01/02 08:20:50.413 ERROR|   logging_manager:0626| CLIENT_JOB.0
01/02 08:20:50.413 ERROR|   logging_manager:0626| 
01/02 08:20:50.413 ERROR|   logging_manager:0626| tko parser: parsing partial test graphics_Idle graphics_Idle
01/02 08:20:50.413 ERROR|   logging_manager:0626| tko parser: RUNNING: RUNNING
01/02 08:20:50.413 ERROR|   logging_manager:0626| Subdir: graphics_Idle
01/02 08:20:50.413 ERROR|   logging_manager:0626| Testname: graphics_Idle
01/02 08:20:50.413 ERROR|   logging_manager:0626| 
01/02 08:20:50.413 ERROR|   logging_manager:0626| tko parser: Unexpected indent: aborting log parse
01/02 08:20:50.413 ERROR|   logging_manager:0626| tko parser: parsing test graphics_Idle graphics_Idle
01/02 08:20:50.414 ERROR|   logging_manager:0626| tko parser: ADD: ABORT
01/02 08:20:50.414 ERROR|   logging_manager:0626| Subdir: graphics_Idle
01/02 08:20:50.414 ERROR|   logging_manager:0626| Testname: graphics_Idle
01/02 08:20:50.414 ERROR|   logging_manager:0626| None
01/02 08:20:50.414 ERROR|   logging_manager:0626| tko parser: Unexpected indent: aborting log parse
01/02 08:20:50.414 ERROR|   logging_manager:0626| tko parser: parsing test graphics_Idle CLIENT_JOB.0
01/02 08:20:50.414 ERROR|   logging_manager:0626| tko parser: ADD: ABORT

---

01/02 08:35:53.350 ERROR|   logging_manager:0626| tko parser: MACHINE NAME: chromeos4-row2-rack3-host13
01/02 08:35:53.350 ERROR|   logging_manager:0626| tko parser: MACHINE GROUP: tricky
01/02 08:35:53.351 ERROR|   logging_manager:0626| tko parser: parsing partial test ---- SERVER_JOB
01/02 08:35:53.351 ERROR|   logging_manager:0626| tko parser: parsing partial test None CLIENT_JOB.0
01/02 08:35:53.351 ERROR|   logging_manager:0626| tko parser: RUNNING: RUNNING
01/02 08:35:53.351 ERROR|   logging_manager:0626| CLIENT_JOB.0
01/02 08:35:53.351 ERROR|   logging_manager:0626| 
01/02 08:35:53.352 ERROR|   logging_manager:0626| tko parser: parsing partial test login_CryptohomeIncognito login_CryptohomeIncognito
01/02 08:35:53.352 ERROR|   logging_manager:0626| tko parser: RUNNING: RUNNING
01/02 08:35:53.352 ERROR|   logging_manager:0626| Subdir: login_CryptohomeIncognito
01/02 08:35:53.352 ERROR|   logging_manager:0626| Testname: login_CryptohomeIncognito
01/02 08:35:53.353 ERROR|   logging_manager:0626| 
01/02 08:35:53.353 ERROR|   logging_manager:0626| tko parser: Unexpected indent: aborting log parse
01/02 08:35:53.353 ERROR|   logging_manager:0626| tko parser: parsing test login_CryptohomeIncognito login_CryptohomeIncognito
01/02 08:35:53.353 ERROR|   logging_manager:0626| tko parser: ADD: ABORT
01/02 08:35:53.353 ERROR|   logging_manager:0626| Subdir: login_CryptohomeIncognito
01/02 08:35:53.354 ERROR|   logging_manager:0626| Testname: login_CryptohomeIncognito
01/02 08:35:53.354 ERROR|   logging_manager:0626| None
01/02 08:35:53.354 ERROR|   logging_manager:0626| tko parser: Unexpected indent: aborting log parse
01/02 08:35:53.354 ERROR|   logging_manager:0626| tko parser: parsing test login_CryptohomeIncognito CLIENT_JOB.0
01/02 08:35:53.354 ERROR|   logging_manager:0626| tko parser: ADD: ABORT
01/02 08:35:53.354 ERROR|   logging_manager:0626| Subdir: login_CryptohomeIncognito
01/02 08:35:53.355 ERROR|   logging_manager:0626| Testname: CLIENT_JOB.0
01/02 08:35:53.355 ERROR|   logging_manager:0626| None

---

Are these "expected" errors? The show up in autoserv.INFO logs and make it harder to see what the actual problem is.

Comment 1 by jrbarnette@chromium.org, Jan 4 2018

Owner: derat@chromium.org
Status: Assigned (was: Untriaged)
The symptom seems to be specific to this failure.  Basically, the
tests wrote "status" files that look like this:

START	----	----	timestamp=1514907967	localtime=Jan 02 07:46:07	
	START	graphics_Idle	graphics_Idle	timestamp=1514907967	localtime=Jan 02 07:46:07	

That content is incomplete:  It means the test started execution, but
never finished.  The tko parser messages are just its way of saying
"the status file input is incomplete".

As for _why_ the test never finished writing the status file:  I
haven't the foggiest.  It could be something came through and terminated
the tests early, or it could be that the tests hung...  The various
"client.INFO" or "client.DEBUG" log files should offer better insights.

Passing back to derat@ to answer a triage question: "Is there a different
bug for the original failures?"  If yes, then I think we can close this
as WAI.  If there's no separate bug, we can use this to debug (or not)
why the tests actually failed.

Comment 2 by ihf@chromium.org, Jan 4 2018 

According to issue 798876 incognito login was broken for a while affecting graphics_Idle. I have not looked into the details, but a failure to login could lead to timeouts and such messages.

Comment 3 by derat@chromium.org, Jan 4 2018

Owner: ----
Status: WontFix (was: Assigned)
I wasn't gardener at the time, but yes, I think that there were (harder-to-find) test failures when this happened.
►

Sign in to add a comment