The cause of failure for PaygenTestDev in this build:
https://uberchromegw.corp.google.com/i/chromeos/builders/wizpig-release/builds/1056
is hard to determine. The stdio reports a test failure:
https://uberchromegw.corp.google.com/i/chromeos/builders/wizpig-release/builds/1056/steps/PaygenTestDev/logs/stdio
04-20-2017 [11:01:27] Suite job is finished.
04-20-2017 [11:01:27] Start collectint test results and dump them to json.
Suite job [ PASSED ]
autoupdate_EndToEndTest.paygen_au_dev_delta [ PASSED ]
autoupdate_EndToEndTest.paygen_au_dev_full [ PASSED ]
autoupdate_EndToEndTest.paygen_au_dev_delta [ PASSED ]
autoupdate_EndToEndTest.paygen_au_dev_full [ PASSED ]
autoupdate_EndToEndTest.paygen_au_dev_full [ FAILED ]
autoupdate_EndToEndTest.paygen_au_dev_full ABORT: None
autoupdate_EndToEndTest.paygen_au_dev_full retry_count: 1
so first of all, the "None" above is suspicious. The bucket is
https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/113507434-chromeos-test/chromeos6-row2-rack20-host1/debug/
and autoserv.DEBUG is confusing. First there is this:
04/20 09:44:44.719 INFO | autoupdater:0302| Updating image via: /usr/bin/update_engine_client --update --omaha_url=http://100.115.185.227:33117/update
04/20 09:44:44.719 DEBUG| ssh_host:0284| Running (ssh) '/usr/bin/update_engine_client --update --omaha_url=http://100.115.185.227:33117/update'
04/20 09:44:44.900 ERROR| base_utils:0280| [stderr] [0420/094444:INFO:update_engine_client.cc(471)] Forcing an update by setting app_version to ForcedUpdate.
04/20 09:44:44.901 ERROR| base_utils:0280| [stderr] [0420/094444:INFO:update_engine_client.cc(473)] Initiating update check and install.
04/20 09:44:44.978 ERROR| base_utils:0280| [stderr] [0420/094444:INFO:update_engine_client.cc(502)] Waiting for update to complete.
04/20 09:50:43.773 ERROR| base_utils:0280| [stderr] [0420/095043:INFO:update_engine_client.cc(224)] Update succeeded -- reboot needed.
04/20 09:50:43.857 WARNI| autoupdater:0315| Unable to parse build name /update for metrics. Continuing anyway.
04/20 09:50:43.857 DEBUG| ssh_host:0284| Running (ssh) '/usr/bin/update_engine_client -status | grep CURRENT_OP'
04/20 09:50:44.178 ERROR| base_utils:0280| [stderr] [0420/095043:INFO:update_engine_client.cc(493)] Querying Update Engine status...
04/20 09:50:44.255 DEBUG| base_utils:0280| [stdout] CURRENT_OP=UPDATE_STATUS_UPDATED_NEED_REBOOT
04/20 09:50:44.258 INFO | autoupdater:0521| Updating stateful partition...
04/20 09:50:44.258 DEBUG| abstract_ssh:0448| send_file. source: /usr/local/google/chromeos/src/platform/dev/stateful_update, dest: /tmp/stateful_update, delete_dest: True,preserve_symlinks:False
04/20 09:50:44.258 DEBUG| ssh_host:0284| Running (ssh) 'rsync --version'
Those lines marked with ERROR, are they errors or not? The messages don't look like errors.
There are a few more. (Why would "Querying Update Engine status" be logged as an error?)
04/20 09:54:02.990 DEBUG| base_utils:0280| [stdout] CURRENT_OP=UPDATE_STATUS_IDLE
04/20 09:54:02.991 ERROR| base_utils:0280| [stderr] [0420/095402:INFO:update_engine_client.cc(493)] Querying Update Engine status...
04/20 09:54:02.992 INFO | autoupdater:0253| Triggering update via: /usr/bin/update_engine_client --check_for_update --omaha_url=http://100.115.185.227:46439/update
04/20 09:54:02.992 DEBUG| ssh_host:0284| Running (ssh) '/usr/bin/update_engine_client --check_for_update --omaha_url=http://100.115.185.227:46439/update'
04/20 09:54:03.190 ERROR| base_utils:0280| [stderr] [0420/095402:INFO:update_engine_client.cc(473)] Initiating update check and install.
04/20 09:54:03.191 WARNI| autoupdater:0266| Unable to parse build name /update for metrics. Continuing anyway.
then there are the errors from the TKO parser:
04/20 10:47:51.299 INFO | get_network_stats:0048| get_network_stats: at-start RXbytes 15583273 TXbytes 933352
04/20 10:47:51.301 ERROR| logging_manager:0626| tko parser: {'aborted_by': 'autotest_system', 'job_started': 1492706563, 'parent_job_id': 113497744, 'user': 'chromeos-test', 'aborted_on': 1492710462, 'builds': "{'cros-version': 'wizpig-release/R60-9479.0.0'}", 'job_finished': 1492710462, 'hostname': 'chromeos6-row2-rack20-host1', 'status_version': 1, 'label': 'wizpig-release/R60-9479.0.0/paygen_au_dev/autoupdate_EndToEndTest_paygen_au_dev_full_9449.0.0', 'drone': 'chromeos-server82.cbf.corp.google.com', 'build': 'wizpig-release/R60-9479.0.0', 'suite': 'paygen_au_dev', 'retry_original_job_id': 113497829, 'experimental': 'False', 'job_queued': 1492706327}
04/20 10:47:51.302 ERROR| logging_manager:0626| tko parser: MACHINE NAME: chromeos6-row2-rack20-host1
04/20 10:47:51.302 ERROR| logging_manager:0626| tko parser: MACHINE GROUP: wizpig
04/20 10:47:51.302 ERROR| logging_manager:0626| tko parser: parsing partial test ---- SERVER_JOB
04/20 10:47:51.302 ERROR| logging_manager:0626| tko parser: parsing partial test autoupdate_EndToEndTest.paygen_au_dev_full autoupdate_EndToEndTest.paygen_au_dev_full
04/20 10:47:51.302 ERROR| logging_manager:0626| tko parser: RUNNING: RUNNING
04/20 10:47:51.302 ERROR| logging_manager:0626| Subdir: autoupdate_EndToEndTest.paygen_au_dev_full
04/20 10:47:51.303 ERROR| logging_manager:0626| Testname: autoupdate_EndToEndTest.paygen_au_dev_full
04/20 10:47:51.303 ERROR| logging_manager:0626|
04/20 10:47:51.303 ERROR| logging_manager:0626| tko parser: Unexpected indent: aborting log parse
04/20 10:47:51.303 ERROR| logging_manager:0626| tko parser: parsing test autoupdate_EndToEndTest.paygen_au_dev_full autoupdate_EndToEndTest.paygen_au_dev_full
04/20 10:47:51.303 ERROR| logging_manager:0626| tko parser: ADD: ABORT
04/20 10:47:51.304 ERROR| logging_manager:0626| Subdir: autoupdate_EndToEndTest.paygen_au_dev_full
04/20 10:47:51.304 ERROR| logging_manager:0626| Testname: autoupdate_EndToEndTest.paygen_au_dev_full
04/20 10:47:51.304 ERROR| logging_manager:0626| None
04/20 10:47:51.304 DEBUG| ssh_host:0284| Running (ssh) 'grep -q CHROMEOS /etc/lsb-release && ! test -f /mnt/stateful_partition/.android_tester && ! grep -q moblab /etc/lsb-release'
04/20 10:47:51.304 ERROR| logging_manager:0626| tko parser: parsing test ---- SERVER_JOB
04/20 10:47:51.311 INFO | abstract_ssh:0809| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_rjzxFissh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/tmp/tmps1x9Af -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=300 -l root -p 22 chromeos6-row2-rack20-host1'
and finally these:
04/20 10:47:54.209 INFO | site_crashcollect:0111| Generating stack trace using devserver for /usr/local/autotest/results/113507434-chromeos-test/chromeos6-row2-rack20-host1/sysinfo/var/spool/crash/chrome.20170420.094209.14714.dmp
04/20 10:47:56.573 DEBUG| dev_server:0294| RPC call get_load has timed out on devserver 172.25.61.81.
04/20 10:47:56.574 ERROR| dev_server:0428| Devserver call failed: "http://172.25.61.81:8082/check_health?", timeout: 2.0 seconds, Error: retry exception (label="get_load"), timeout = 2s
04/20 10:47:56.599 DEBUG| dev_server:0294| RPC call get_load has timed out on devserver 172.25.66.216.
04/20 10:47:56.600 ERROR| dev_server:0428| Devserver call failed: "http://172.25.66.216:8082/check_health?", timeout: 2.0 seconds, Error: retry exception (label="get_load"), timeout = 2s
04/20 10:47:56.617 DEBUG| retry:0155| Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0)
04/20 10:47:56.617 INFO | connectionpool:0188| Starting new HTTP connection (1): 100.108.1.59
04/20 10:48:38.422 DEBUG| connectionpool:0362| "POST /symbolicate_dump?archive_url=gs://chromeos-image-archive/wizpig-release/R60-9479.0.0 HTTP/1.1" 500 1643
04/20 10:48:38.425 INFO | site_crashcollect:0128| Failed to generate stack trace on devserver for dump /usr/local/autotest/results/113507434-chromeos-test/chromeos6-row2-rack20-host1/sysinfo/var/spool/crash/chrome.20170420.094209.14714.dmp:
DevServerException('\n\n\n \n 500 Internal Server Error\n \n #powered_by {\n margin-top: 20px;\n border-top: 2px solid black;\n font-style: italic;\n }\n\n #traceback {\n color: red;\n }\n \n\n \n 500 Internal Server Error\n The server encountered an unexpected condition which prevented it from fulfilling the request.\n Traceback (most recent call last):\n File "/usr/lib/python2.7/dist-packages/cherrypy/_cprequest.py", line 656, in respond\n response.body = self.handler()\n File "/usr/lib/python2.7/dist-packages/cherrypy/lib/encoding.py", line 188, in __call__\n self.body = self.oldhandler(*args, **kwargs)\n File "/usr/lib/python2.7/dist-packages/cherrypy/_cpdispatch.py", line 34, in __call__\n return self.callable(*self.args, **self.kwargs)\n File "/usr/local/google/home/chromeos-test/chromiumos/src/platform/dev/devserver.py", line 1112, in symbolicate_dump\n stdout=subprocess.PIPE, stderr=subprocess.PIPE)\n File "/usr/lib/python2.7/subprocess.py", line 710, in __init__\n errread, errwrite)\n File "/usr/lib/python2.7/subprocess.py", line 1327, in _execute_child\n raise child_exception\nOSError: [Errno 2] No such file or directory\n\n \n Powered by CherryPy 3.2.2\n \n \n\n',)
04/20 10:48:38.425 WARNI| site_crashcollect:0132| Failed to generate stack trace for /usr/local/autotest/results/113507434-chromeos-test/chromeos6-row2-rack20-host1/sysinfo/var/spool/crash/chrome.20170420.094209.14714.dmp (see info logs)
So where's the error??????????????
Comment 1 by semenzato@chromium.org
, Apr 20 2017