New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 753070 link

Starred by 1 user

Issue metadata

Status: Duplicate
Merged: issue 753116
Owner:
Closed: Aug 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug
M62



Sign in to add a comment

CFM Enrollment Autotest failing on latest M62 since Saturday

Project Member Reported by harpreet@chromium.org, Aug 7 2017

Issue description

Issue started with latest M62 ChromeOS / Chrome : 9807.0.0 / 62.0.3176.0

Test goes through all the enrollment steps successfully but times out on utils.poll_for_condition(lambda: pid != _cri.GetChromePid(), timeout=60)

Trace from test log (complete logs attached):


08/05 01:25:35.925 ERROR|             utils:2757| Timed out waiting for unnamed condition
08/05 01:25:35.935 DEBUG|    cros_interface:0363| ListProcesses(<predicate>)->[177 processes]
08/05 01:25:35.944 DEBUG|    cros_interface:0363| ListProcesses(<predicate>)->[177 processes]
08/05 01:25:35.944 INFO |           browser:0268| Closing browser (pid=3066) ...
08/05 01:25:35.945 INFO |    cros_interface:0546| (Re)starting the ui (logs the user out)
08/05 01:25:35.954 DEBUG|    cros_interface:0439| IsServiceRunning(ui)->True
08/05 01:25:35.954 DEBUG|    cros_interface:0058| sh -c restart ui 
08/05 01:25:36.435 DEBUG|    cros_interface:0067|  > stdout=[ui start/running, process 5700
], stderr=[]
08/05 01:25:36.436 DEBUG|    cros_interface:0058| sh -c cryptohome-path user 'test@test.test' 
08/05 01:25:36.449 DEBUG|    cros_interface:0067|  > stdout=[/home/user/04b21cd820066cb3b69dc32741f5091b2b772b42
], stderr=[]
08/05 01:25:36.450 DEBUG|    cros_interface:0058| sh -c /bin/df --output=source,target /home/user/04b21cd820066cb3b69dc32741f5091b2b772b42 
08/05 01:25:36.456 DEBUG|    cros_interface:0067|  > stdout=[], stderr=[df: /home/user/04b21cd820066cb3b69dc32741f5091b2b772b42: No such file or directory
]
08/05 01:25:36.456 INFO |           browser:0283| Browser is closed.
08/05 01:25:36.456 DEBUG|              test:0389| Test failed due to Timed out waiting for unnamed condition. Exception log follows the after_iteration_hooks.
08/05 01:25:36.456 DEBUG|              test:0392| starting after_iteration_hooks
08/05 01:25:36.457 DEBUG|             utils:0212| Running 'mkdir -p /usr/local/autotest/results/default/enterprise_RemoraRequisition/sysinfo/iteration.1/var/spool'
08/05 01:25:36.462 DEBUG|             utils:0212| Running 'rsync --no-perms --chmod=ugo+r -a --safe-links --exclude=/crash/**autoserv* --exclude=/crash/*.core /var/spool/crash /usr/local/autotest/results/default/enterprise_RemoraRequisition/sysinfo/iteration.1/var/spool'
08/05 01:25:36.471 DEBUG|             utils:0212| Running 'rm -rf /var/spool/crash/*'
08/05 01:25:36.476 DEBUG|             utils:0212| Running 'logger "autotest finished iteration /usr/local/autotest/results/default/enterprise_RemoraRequisition/sysinfo/iteration.1"'
08/05 01:25:36.482 DEBUG|              test:0395| after_iteration_hooks completed
08/05 01:25:36.483 WARNI|              test:0612| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 606, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/test.py", line 806, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 470, in execute
    dargs)
  File "/usr/local/autotest/common_lib/test.py", line 347, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/common_lib/test.py", line 380, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/tests/enterprise_RemoraRequisition/enterprise_RemoraRequisition.py", line 43, in run_once
    enrollment.RemoraEnrollment(cr.browser, user_id, password)
  File "/usr/local/autotest/common_lib/cros/enrollment.py", line 39, in RemoraEnrollment
    lambda: browser.oobe.NavigateGaiaLogin(
  File "/usr/local/autotest/common_lib/cros/chrome.py", line 276, in wait_for_browser_restart
    utils.poll_for_condition(lambda: pid != _cri.GetChromePid(), timeout=60)
  File "/usr/local/autotest/common_lib/utils.py", line 2758, in poll_for_condition
    raise TimeoutError(desc)
TimeoutError: Timed out waiting for unnamed condition
08/05 01:25:36.487 DEBUG|              test:0617| Running cleanup for test.
 
And some tests are failing because of chrome://oobe/oobe.js:8581: TypeError: Cannot read property 'apply' of undefined


08/07 01:00:41.007 DEBUG|              test:0389| Test failed due to RPC error: cfm.enroll_device
Traceback (most recent call last):
  File "./multimedia_xmlrpc_server.py", line 89, in _dispatch
    return func(*params)
  File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 46, in enroll_device
    self._PWD)
  File "/usr/local/autotest/common_lib/cros/enrollment.py", line 39, in RemoraEnrollment
    lambda: browser.oobe.NavigateGaiaLogin(
  File "/usr/local/autotest/common_lib/cros/chrome.py", line 275, in wait_for_browser_restart
    Chrome.did_browser_crash(func)
  File "/usr/local/autotest/common_lib/cros/chrome.py", line 260, in did_browser_crash
    func()
  File "/usr/local/autotest/common_lib/cros/enrollment.py", line 41, in <lambda>
    for_user_triggered_enrollment=False))
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/oobe.py", line 77, in NavigateGaiaLogin
    'Oobe.isEnrollmentSuccessfulForTest()', timeout=30)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 192, in WaitForJavaScriptCondition
    return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 287, in WaitForJavaScriptCondition
    e.message + '\n' + debug_message)
TimeoutException: Timed out while waiting 30s for IsJavaScriptExpressionTrue.
Console output:
(log) chrome://oobe/oobe.js:8064: Loading asset bundle oauth-enrollment
(log) chrome://oobe/oobe.js:8048: Finished loading asset bundle oauth-enrollment
(error) chrome://oobe/oobe.js:8581: TypeError: Cannot read property 'apply' of undefined
    at Object.api.(anonymous function) [as showStep] (chrome://oobe/oobe.js:416:43)
    at <anonymous>:1:29
(warning) chrome://oobe/oobe.js:16533: Unrecognized message from GAIA: showConfirmCancel
(warning) chrome://oobe/oobe.js:16533: Unrecognized message from GAIA: clearOldAttempts
(warning) chrome://oobe/oobe.js:16533: Unrecognized message from GAIA: showConfirmCancel

. Exception log follows the after_iteration_hooks.
Cc: jdufault@chromium.org
Not sure if this is due to recent changes to oobe?
Cc: mzhuo@chromium.org dtosic@chromium.org
There's a strong possibility it's this issue since the timing matches up:
https://bugs.chromium.org/p/chromium/issues/detail?id=753116

Harpreet, are you able to bisect to this CL? If not, I can try.

Comment 6 Deleted

Mergedinto: 753116
Status: Duplicate (was: Untriaged)
Tests have cycled green.

Sign in to add a comment