New issue
Advanced search Search tips

Issue 639113 link

Starred by 2 users
Status: Verified
Owner:
achuith@chromium.org
Closed: Oct 2016
Cc:
jdufault@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

CFM enrollment test fails on panther & zako waiting for chrome to restart

Project Member Reported by harpreet@chromium.org, Aug 18 2016 
CrOS: M54 ToT

Some CFM tests randomly fail during enrollment on panther & zako waiting on chrome to restart. We have 5 tests for CFM that run nightly where each tests enrolls the device into remora prior to testing other functionality. This issue does not happen across all tests that are run nightly but happens randomly for some tests on some devices. The following trace is observed on panther & zako:

Traceback (most recent call last):
  File "/usr/local/autotest/client/common_lib/test.py", line 600, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 804, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 461, in execute
    dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 347, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/client/common_lib/test.py", line 376, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/server/site_tests/enterprise_CFM_Perf/enterprise_CFM_Perf.py", line 134, in run_once
    raise error.TestFail(str(e))
TestFail: RPC error: cfm.enroll_device
Traceback (most recent call last):
  File "./multimedia_xmlrpc_server.py", line 70, in _dispatch
    return func(*params)
  File "/usr/local/autotest/cros/multimedia/cfm_facade_native.py", line 41, in enroll_device
    self._PWD)
  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 297, 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 855, in poll_for_condition
    raise TimeoutError(desc)
TimeoutError: Timed out waiting for unnamed condition

Comment 2 by harpreet@chromium.org, Aug 18 2016 

Here are useful snippets of more detailed logs (complete log file attached):

.
.
.
08/17 01:04:49.991 DEBUG|inspector_websocke:0097| sent [{
  "id": 37, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "document.getElementById('passwordNext') != null", 
    "returnByValue": true
  }
}]
08/17 01:04:49.993 DEBUG|inspector_websocke:0164| got [{
  "id": 37, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": true
    }
  }
}]
08/17 01:04:49.995 DEBUG|inspector_websocke:0097| sent [{
  "id": 38, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "\n       document.getElementById('password').value='test0000';\n       document.getElementById('passwordNext').click()", 
    "returnByValue": true
  }
}]
08/17 01:04:49.998 DEBUG|inspector_websocke:0164| got [{
  "id": 38, 
  "result": {
    "result": {
      "type": "undefined"
    }
  }
}]
08/17 01:04:50.002 DEBUG|inspector_websocke:0097| sent [{
  "id": 15, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "Oobe.isEnrollmentSuccessfulForTest()", 
    "returnByValue": true
  }
}]
08/17 01:04:50.002 DEBUG|inspector_websocke:0164| got [{
  "method": "Runtime.consoleAPICalled", 
  "params": {
    "args": [
      {
        "type": "string", 
        "value": "Unrecognized message from GAIA: showConfirmCancel"
      }
    ], 
    "executionContextId": 1, 
    "stackTrace": {
      "callFrames": [
        {
          "columnNumber": 14, 
          "functionName": "Authenticator.onMessageFromWebview_", 
          "lineNumber": 2294, 
          "scriptId": "161", 
          "url": "chrome://oobe/gaia_auth_host.js"
        }
      ]
    }, 
    "timestamp": 1471421087658.824, 
    "type": "warning"
  }
}]
08/17 01:04:50.003 DEBUG|inspector_websocke:0164| got [{
  "method": "Runtime.consoleAPICalled", 
  "params": {
    "args": [
      {
        "type": "string", 
        "value": "Unrecognized message from GAIA: clearOldAttempts"
      }
    ], 
    "executionContextId": 1, 
    "stackTrace": {
      "callFrames": [
        {
          "columnNumber": 14, 
          "functionName": "Authenticator.onMessageFromWebview_", 
          "lineNumber": 2294, 
          "scriptId": "161", 
          "url": "chrome://oobe/gaia_auth_host.js"
        }
      ]
    }, 
    "timestamp": 1471421089502.2458, 
    "type": "warning"
  }
}]
08/17 01:04:50.003 DEBUG|inspector_websocke:0164| got [{
  "id": 15, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]
.
.
.
08/17 01:04:50.524 DEBUG|inspector_websocke:0097| sent [{
  "id": 20, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "Oobe.isEnrollmentSuccessfulForTest()", 
    "returnByValue": true
  }
}]
08/17 01:04:50.529 DEBUG|inspector_websocke:0164| got [{
  "method": "Runtime.consoleAPICalled", 
  "params": {
    "args": [
      {
        "type": "string", 
        "value": "Authenticator: No password scraped for SAML."
      }
    ], 
    "executionContextId": 1, 
    "stackTrace": {
      "callFrames": [
        {
          "columnNumber": 14, 
          "functionName": "Authenticator.maybeCompleteAuth_", 
          "lineNumber": 2353, 
          "scriptId": "161", 
          "url": "chrome://oobe/gaia_auth_host.js"
        }, 
        {
          "columnNumber": 11, 
          "functionName": "Authenticator.onLoadCommit_", 
          "lineNumber": 2523, 
          "scriptId": "161", 
          "url": "chrome://oobe/gaia_auth_host.js"
        }, 
        {
          "columnNumber": 22, 
          "functionName": "GuestViewContainer.dispatchEvent", 
          "lineNumber": 176, 
          "scriptId": "42", 
          "url": "extensions::guestViewContainer"
        }, 
        {
          "columnNumber": 12, 
          "functionName": "WebViewEvents.handleLoadCommitEvent", 
          "lineNumber": 253, 
          "scriptId": "44", 
          "url": "extensions::webViewEvents"
        }, 
        {
          "columnNumber": 29, 
          "functionName": "", 
          "lineNumber": 96, 
          "scriptId": "33", 
          "url": "extensions::guestViewEvents"
        }, 
        {
          "columnNumber": 13, 
          "functionName": "target.(anonymous function)", 
          "lineNumber": 18, 
          "scriptId": "28", 
          "url": "extensions::SafeBuiltins"
        }, 
        {
          "columnNumber": 21, 
          "functionName": "", 
          "lineNumber": 168, 
          "scriptId": "33", 
          "url": "extensions::guestViewEvents"
        }, 
        {
          "columnNumber": 13, 
          "functionName": "target.(anonymous function)", 
          "lineNumber": 18, 
          "scriptId": "28", 
          "url": "extensions::SafeBuiltins"
        }, 
        {
          "columnNumber": 21, 
          "functionName": "EventImpl.dispatchToListener", 
          "lineNumber": 387, 
          "scriptId": "34", 
          "url": "extensions::event_bindings"
        }, 
        {
          "columnNumber": 13, 
          "functionName": "target.(anonymous function)", 
          "lineNumber": 18, 
          "scriptId": "28", 
          "url": "extensions::SafeBuiltins"
        }, 
        {
          "columnNumber": 25, 
          "functionName": "publicClassPrototype.(anonymous function)", 
          "lineNumber": 150, 
          "scriptId": "40", 
          "url": "extensions::utils"
        }, 
        {
          "columnNumber": 34, 
          "functionName": "EventImpl.dispatch_", 
          "lineNumber": 371, 
          "scriptId": "34", 
          "url": "extensions::event_bindings"
        }, 
        {
          "columnNumber": 25, 
          "functionName": "dispatchArgs", 
          "lineNumber": 243, 
          "scriptId": "34", 
          "url": "extensions::event_bindings"
        }, 
        {
          "columnNumber": 6, 
          "functionName": "dispatchEvent", 
          "lineNumber": 252, 
          "scriptId": "34", 
          "url": "extensions::event_bindings"
        }
      ]
    }, 
    "timestamp": 1471421090508.595, 
    "type": "warning"
  }
}]
08/17 01:04:50.529 DEBUG|inspector_websocke:0164| got [{
  "id": 20, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]
.
.
.
08/17 01:04:51.042 DEBUG|inspector_websocke:0097| sent [{
  "id": 25, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "Oobe.isEnrollmentSuccessfulForTest()", 
    "returnByValue": true
  }
}]
08/17 01:04:51.042 DEBUG|inspector_websocke:0164| got [{
  "method": "Runtime.consoleAPICalled", 
  "params": {
    "args": [
      {
        "type": "string", 
        "value": "Unrecognized message from GAIA: showConfirmCancel"
      }
    ], 
    "executionContextId": 1, 
    "stackTrace": {
      "callFrames": [
        {
          "columnNumber": 14, 
          "functionName": "Authenticator.onMessageFromWebview_", 
          "lineNumber": 2294, 
          "scriptId": "161", 
          "url": "chrome://oobe/gaia_auth_host.js"
        }
      ]
    }, 
    "timestamp": 1471421090957.6919, 
    "type": "warning"
  }
}]
08/17 01:04:51.044 DEBUG|inspector_websocke:0164| got [{
  "id": 25, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]
.
.
.
08/17 01:05:14.931 DEBUG|inspector_websocke:0164| got [{
  "id": 58, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]
08/17 01:05:17.428 DEBUG|inspector_websocke:0097| sent [{
  "id": 59, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "Oobe.isEnrollmentSuccessfulForTest()", 
    "returnByValue": true
  }
}]
08/17 01:05:17.430 DEBUG|inspector_websocke:0164| got [{
  "id": 59, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]
08/17 01:05:20.178 DEBUG|inspector_websocke:0097| sent [{
  "id": 60, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "Oobe.isEnrollmentSuccessfulForTest()", 
    "returnByValue": true
  }
}]
08/17 01:05:20.179 DEBUG|inspector_websocke:0164| got [{
  "id": 60, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }
  }
}]
08/17 01:05:20.181 DEBUG|inspector_websocke:0097| sent [{
  "id": 61, 
  "method": "Console.enable"
}]
08/17 01:05:20.182 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 9, 
      "level": "log", 
      "line": 1, 
      "source": "console-api", 
      "text": "This file is deprecated. Please use `iron-flex-layout/iron-flex-layout-classes.html`, and one of the specific dom-modules instead", 
      "url": "chrome://resources/polymer/v1_0/iron-flex-layout/classes/iron-shadow-flex-layout-extracted.js"
    }
  }
}]
08/17 01:05:20.183 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 9, 
      "level": "log", 
      "line": 1, 
      "source": "console-api", 
      "text": "This file is deprecated. Please use `iron-flex-layout/iron-flex-layout-classes.html`, and one of the specific dom-modules instead", 
      "url": "chrome://resources/polymer/v1_0/iron-flex-layout/classes/iron-flex-layout-extracted.js"
    }
  }
}]
08/17 01:05:20.184 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 13, 
      "level": "log", 
      "line": 7420, 
      "source": "console-api", 
      "text": "Loading asset bundle oauth-enrollment", 
      "url": "chrome://oobe/oobe.js"
    }
  }
}]
08/17 01:05:20.185 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 13, 
      "level": "log", 
      "line": 7404, 
      "source": "console-api", 
      "text": "Finished loading asset bundle oauth-enrollment", 
      "url": "chrome://oobe/oobe.js"
    }
  }
}]
08/17 01:05:20.186 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 15, 
      "level": "log", 
      "line": 2295, 
      "source": "console-api", 
      "text": "Unrecognized message from GAIA: showConfirmCancel", 
      "url": "chrome://oobe/gaia_auth_host.js"
    }
  }
}]
08/17 01:05:20.187 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 15, 
      "level": "log", 
      "line": 2295, 
      "source": "console-api", 
      "text": "Unrecognized message from GAIA: clearOldAttempts", 
      "url": "chrome://oobe/gaia_auth_host.js"
    }
  }
}]
08/17 01:05:20.187 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 15, 
      "level": "log", 
      "line": 2354, 
      "source": "console-api", 
      "text": "Authenticator: No password scraped for SAML.", 
      "url": "chrome://oobe/gaia_auth_host.js"
    }
  }
}]
08/17 01:05:20.188 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 15, 
      "level": "log", 
      "line": 2295, 
      "source": "console-api", 
      "text": "Unrecognized message from GAIA: showConfirmCancel", 
      "url": "chrome://oobe/gaia_auth_host.js"
    }
  }
}]
08/17 01:05:20.189 DEBUG|inspector_websocke:0164| got [{
  "id": 61, 
  "result": {}
}]
08/17 01:05:30.200 DEBUG|inspector_websocke:0097| sent [{
  "id": 62, 
  "method": "Console.disable"
}]
08/17 01:05:30.201 DEBUG|inspector_websocke:0164| got [{
  "id": 62, 
  "result": {}
}]
08/17 01:05:30.221 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[156 processes]
08/17 01:05:30.342 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[156 processes]
08/17 01:05:30.464 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[156 processes]
08/17 01:05:30.585 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[156 processes]

.
.
.
08/17 01:06:30.093 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[156 processes]
08/17 01:06:30.214 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[156 processes]
08/17 01:06:30.215 ERROR|        site_utils:0854| Timed out waiting for unnamed condition
08/17 01:06:30.235 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[156 processes]
08/17 01:06:30.237 INFO |    cros_interface:0525| (Re)starting the ui (logs the user out)
08/17 01:06:30.248 DEBUG|    cros_interface:0422| IsServiceRunning(ui)->True
08/17 01:06:30.248 DEBUG|    cros_interface:0058| sh -c restart ui 
08/17 01:06:30.878 DEBUG|    cros_interface:0067|  > stdout=[ui start/running, process 17840
], stderr=[]
08/17 01:06:30.879 DEBUG|    cros_interface:0058| sh -c cryptohome-path user 'test@test.test' 
08/17 01:06:30.895 DEBUG|    cros_interface:0067|  > stdout=[/home/user/498417657fe56e8fe599c8115d4bbccea10cff44
], stderr=[]
08/17 01:06:30.896 DEBUG|    cros_interface:0058| sh -c /bin/df /home/user/498417657fe56e8fe599c8115d4bbccea10cff44 
08/17 01:06:30.911 DEBUG|    cros_interface:0067|  > stdout=[], stderr=[df: '/home/user/498417657fe56e8fe599c8115d4bbccea10cff44': No such file or directory
]
08/17 01:06:30.913 DEBUG|        base_utils:0185| Running 'logger "autotest finished iteration /usr/local/autotest/results/default/enterprise_RemoraRequisition/sysinfo/iteration.1"'
08/17 01:06:30.930 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 297, 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 855, in poll_for_condition
    raise TimeoutError(desc)
TimeoutError: Timed out waiting for unnamed condition
enterprise_RemoraRequisition.DEBUG
216 KB Download

Comment 3 by harpreet@chromium.org, Aug 18 2016 

So looks like it is able to enter the password but then keeps waiting on Oobe.isEnrollmentSuccessfulForTest()

Comment 4 by harpreet@chromium.org, Aug 23 2016

Status: Unconfirmed (was: Untriaged)

Comment 5 by abodenha@chromium.org, Aug 25 2016

Status: Assigned (was: Unconfirmed)

Comment 6 by achuith@chromium.org, Oct 5 2016

Status: Fixed (was: Assigned)
This should be fixed.

Comment 7 by harpreet@chromium.org, Oct 5 2016

Status: Verified (was: Fixed)
Yes. Have not seen the test fail for the reason listed here recently.
►

Sign in to add a comment