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

Issue 642052 link

Starred by 1 user

Issue metadata

Status: Verified
Owner:
Closed: Oct 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug

Blocked on:
issue 641865



Sign in to add a comment

CFM enrollment autotest failing on M55 ToT

Project Member Reported by harpreet@chromium.org, Aug 29 2016

Issue description

Starting with R55-8749.0.0 CFM enrollment autotest is failing on all devices.

enterprise_RemoraRequisitionServer: https://wmatrix.googleplex.com/matrix/unfiltered?hide_missing=True&tests=enterprise_RemoraRequisitionServer&days_back=10

All other CFM autotest failing becaues device is not able to enroll: https://wmatrix.googleplex.com/matrix/unfiltered?suites=hotrod&days_back=10&releases=55&hide_missing=True


From the logs it seems that it is not able to find the context with specified id so it keeps waiting on "document.readyState == 'complete' && document.getElementById('Email') != null"

Complete logs can be grabbed from https://wmatrix.googleplex.com/testrun/unfiltered?test_ids=340701178


08/29 00:36:53.277 DEBUG|inspector_websocke:0097| sent [{
  "id": 263, 
  "method": "Runtime.evaluate", 
  "params": {
    "contextId": 2, 
    "expression": "document.readyState == 'complete' && document.getElementById('Email') != null", 
    "returnByValue": true
  }
}]
08/29 00:36:53.278 DEBUG|inspector_websocke:0164| got [{
  "error": {
    "code": -32000, 
    "message": "Cannot find context with specified id"
  }, 
  "id": 263
}]
08/29 00:36:53.279 DEBUG|inspector_websocke:0097| sent [{
  "id": 264, 
  "method": "Runtime.evaluate", 
  "params": {
    "contextId": 3, 
    "expression": "document.readyState == 'complete' && document.getElementById('Email') != null", 
    "returnByValue": true
  }
}]
08/29 00:36:53.280 DEBUG|inspector_websocke:0164| got [{
  "id": 264, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]
 
Here is the exception (it looks similar to  crbug.com/639113  but failure point is different and ALL devices are affected now):

08/29 00:37:53.912 WARNI|              test:0606| Autotest caught exception when running test:
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 600, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/test.py", line 804, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 461, 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 376, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/tests/enterprise_RemoraRequisition/enterprise_RemoraRequisition.py", line 42, in run_once
    enrollment.RemoraEnrollment(cr.browser, user_id, password)
  File "/usr/local/autotest/common_lib/cros/enrollment.py", line 38, in RemoraEnrollment
    lambda: browser.oobe.NavigateGaiaLogin(
  File "/usr/local/autotest/common_lib/cros/chrome.py", line 282, in wait_for_browser_restart
    utils.poll_for_condition(lambda: pid != _cri.GetChromePid(), timeout=60)
  File "/usr/local/autotest/common_lib/site_utils.py", line 940, in poll_for_condition
    raise TimeoutError(desc)
TimeoutError: Timed out waiting for unnamed condition
enterprise_RemoraRequisition.DEBUG.08-29-2016
201 KB Download
Status: Started (was: Untriaged)
Sorry, this is one of my CLs
Blockedon: 641865
Cc: afakhry@chromium.org achuith@chromium.org
Owner: harpreet@chromium.org
Status: Fixed (was: Started)
Harpreet - this should be fixed. You may need to wait for chrome to roll if it didn't last night. Please verify.
Status: Verified (was: Fixed)
Cc: harpreet@chromium.org
Labels: M-55
Owner: achuith@chromium.org
Status: Assigned (was: Verified)
We are seeing this consistently now. Please take a look.

Its failing while waiting on "identifierId":

10/03 02:10:26.268 DEBUG|inspector_websocke:0097| sent [{
  "id": 43, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "document.getElementById('identifierId') != null", 
    "returnByValue": true
  }
}]
10/03 02:10:26.269 DEBUG|inspector_websocke:0164| got [{
  "id": 43, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]

Looks like this is happening because of the new login flow UI. 
Cc: steve...@chromium.org
I just ran the test locally and it times out on the 'network not available' window even though ethernet is available.
With some run's I see the following error.


10/02 02:27:07.054 DEBUG|inspector_websocke:0097| sent [{
  "id": 15, 
  "method": "Runtime.evaluate", 
  "params": {
    "contextId": 5, 
    "expression": "document.readyState == 'complete' && document.getElementById('Email') != null", 
    "returnByValue": true
  }
}]
10/02 02:27:07.071 DEBUG|inspector_websocke:0164| got [{
  "method": "Runtime.consoleAPICalled", 
  "params": {
    "args": [
      {
        "type": "string", 
        "value": "<webview>: The load has aborted with error -100: ERR_CONNECTION_CLOSED."
      }
    ], 
    "executionContextId": 1, 
    "stackTrace": {
      "callFrames": [
        {
          "columnNumber": 19, 
          "functionName": "showWarningMessage", 
          "lineNumber": 236, 
          "scriptId": "43", 
          "url": "extensions::webViewEvents"
        }, 
        {
          "columnNumber": 4, 
          "functionName": "WebViewEvents.handleLoadAbortEvent", 
          "lineNumber": 241, 
          "scriptId": "43", 
          "url": "extensions::webViewEvents"
        }, 
        {
          "columnNumber": 29, 
          "functionName": "", 
          "lineNumber": 96, 
          "scriptId": "32", 
          "url": "extensions::guestViewEvents"
        }, 
        {
          "columnNumber": 13, 
          "functionName": "target.(anonymous function)", 
          "lineNumber": 18, 
          "scriptId": "27", 
          "url": "extensions::SafeBuiltins"
        }, 
        {
          "columnNumber": 21, 
          "functionName": "", 
          "lineNumber": 168, 
          "scriptId": "32", 
          "url": "extensions::guestViewEvents"
        }, 
        {
          "columnNumber": 13, 
          "functionName": "target.(anonymous function)", 
          "lineNumber": 18, 
          "scriptId": "27", 
          "url": "extensions::SafeBuiltins"
        }, 
        {
          "columnNumber": 21, 
          "functionName": "EventImpl.dispatchToListener", 
          "lineNumber": 387, 
          "scriptId": "33", 
          "url": "extensions::event_bindings"
        }, 
        {
          "columnNumber": 13, 
          "functionName": "target.(anonymous function)", 
          "lineNumber": 18, 
          "scriptId": "27", 
          "url": "extensions::SafeBuiltins"
        }, 
        {
          "columnNumber": 25, 
          "functionName": "publicClassPrototype.(anonymous function)", 
          "lineNumber": 150, 
          "scriptId": "39", 
          "url": "extensions::utils"
        }, 
        {
          "columnNumber": 34, 
          "functionName": "EventImpl.dispatch_", 
          "lineNumber": 371, 
          "scriptId": "33", 
          "url": "extensions::event_bindings"
        }, 
        {
          "columnNumber": 25, 
          "functionName": "dispatchArgs", 
          "lineNumber": 243, 
          "scriptId": "33", 
          "url": "extensions::event_bindings"
        }, 
        {
          "columnNumber": 6, 
          "functionName": "dispatchEvent", 
          "lineNumber": 252, 
          "scriptId": "33", 
          "url": "extensions::event_bindings"
        }
      ]
    }, 
    "timestamp": 1475400427069.1782, 
    "type": "warning"
  }
}]
10/02 02:27:07.073 DEBUG|inspector_websocke:0164| got [{
  "id": 15, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]
10/02 02:27:07.175 DEBUG| inspector_backend:0064| InspectorBackend._Connect() to ws://127.0.0.1:60875/devtools/page/5db8df78-3775-4c2d-9378-989e25f4d6f3
Status: Started (was: Assigned)
I know how to fix this, but this needs to land first: https://chromium-review.googlesource.com/#/c/391123/


This should fix this.
https://chromium-review.googlesource.com/#/c/393226/

There seems to be an independent problem where the hotrod app is not being downloaded.
Ok. Let me patch this CL locally and try.
This works for me. It does complain that the app is was not downloaded but relaunching chrome auto launches the hotrod app and the test passes.
That's what I'm seeing too
Yes. I think this has been like this for a long time now but only happens with autotests.

Can you please submit this soon so it gets in before the M55 branch on Thursday. Otherwise the tests will continue to fail on M55 for another 6 weeks unless we merge this back after branch.
Ok, I see you've put it in the CQ. We can chump it in if the CQ fails to land this EOD.
Sure. SG
Status: Fixed (was: Started)
CL has landed. Please verify
Status: Verified (was: Fixed)

Sign in to add a comment