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

Issue 627336 link

Starred by 2 users
Status: Duplicate
Merged: issue 627832
Owner:
smbar...@chromium.org
Closed: Jul 2016
Cc:
█ dkrahn@chromium.org
█ mlight@chromium.org
█ kkan...@chromium.org
█ dtosic@chromium.org
█ mnilsson@chromium.org
harpreet@chromium.org
jdufault@chromium.org
achuith@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

CFM enrollment broken on M54 tot

Project Member Reported by harpreet@chromium.org, Jul 12 2016 
CrOS: Broken starting with M54-8562.0.0 (works on 8561.0.0 / 54.0.2787.0)
Chrome:	54.0.2790.0
Chrome diff: https://chromium.googlesource.com/chromium/src/+log/54.0.2787.0..54.0.2790.0?pretty=fuller&n=10000


When trying to enroll the device into CFM the following error is shown "Oops! The system failed to establish the device installation-time attributes lock." after entering the username and password and clicking "NEXT".

Broken since Saturday on M54 https://wmatrix.googleplex.com/matrix/unfiltered?hide_missing=True&tests=enterprise_RemoraRequisitionServer&days_back=30

I am able to reproduce this manually. Below is the debug log snippet from the remora requisition test.



07/08 23:09:13.946 DEBUG|inspector_websocke:0097| sent [{
  "id": 59, 
  "method": "Runtime.evaluate", 
  "params": {
    "expression": "Oobe.isEnrollmentSuccessfulForTest()", 
    "returnByValue": true
  }
}]
07/08 23:09:13.948 DEBUG|inspector_websocke:0164| got [{
  "id": 59, 
  "result": {
    "result": {
      "type": "boolean", 
      "value": false
    }, 
    "wasThrown": false
  }
}]
07/08 23:09:13.949 DEBUG|inspector_websocke:0097| sent [{
  "id": 60, 
  "method": "Console.enable"
}]
07/08 23:09:13.952 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 9, 
      "executionContextId": 1, 
      "level": "warning", 
      "line": 1, 
      "parameters": [
        {
          "type": "string", 
          "value": "This file is deprecated. Please use `iron-flex-layout/iron-flex-layout-classes.html`, and one of the specific dom-modules instead"
        }
      ], 
      "source": "console-api", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 9, 
            "functionName": "", 
            "lineNumber": 1, 
            "scriptId": "82", 
            "url": "chrome://resources/polymer/v1_0/iron-flex-layout/classes/iron-shadow-flex-layout-extracted.js"
          }
        ]
      }, 
      "text": "This file is deprecated. Please use `iron-flex-layout/iron-flex-layout-classes.html`, and one of the specific dom-modules instead", 
      "timestamp": 1468044516.11377, 
      "type": "log", 
      "url": "chrome://resources/polymer/v1_0/iron-flex-layout/classes/iron-shadow-flex-layout-extracted.js"
    }
  }
}]
07/08 23:09:13.953 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 9, 
      "executionContextId": 1, 
      "level": "warning", 
      "line": 1, 
      "parameters": [
        {
          "type": "string", 
          "value": "This file is deprecated. Please use `iron-flex-layout/iron-flex-layout-classes.html`, and one of the specific dom-modules instead"
        }
      ], 
      "source": "console-api", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 9, 
            "functionName": "", 
            "lineNumber": 1, 
            "scriptId": "83", 
            "url": "chrome://resources/polymer/v1_0/iron-flex-layout/classes/iron-flex-layout-extracted.js"
          }
        ]
      }, 
      "text": "This file is deprecated. Please use `iron-flex-layout/iron-flex-layout-classes.html`, and one of the specific dom-modules instead", 
      "timestamp": 1468044516.11621, 
      "type": "log", 
      "url": "chrome://resources/polymer/v1_0/iron-flex-layout/classes/iron-flex-layout-extracted.js"
    }
  }
}]
07/08 23:09:13.954 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 9, 
      "level": "warning", 
      "line": 204, 
      "source": "deprecation", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 9, 
            "functionName": "proto.createdCallback", 
            "lineNumber": 204, 
            "scriptId": "43", 
            "url": "extensions::guestViewContainer"
          }
        ]
      }, 
      "text": "/deep/ combinator is deprecated. See https://www.chromestatus.com/features/6750456638341120 for more details.", 
      "timestamp": 1468044516.6464701, 
      "type": "log", 
      "url": "extensions::guestViewContainer"
    }
  }
}]
07/08 23:09:13.956 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 13, 
      "executionContextId": 1, 
      "level": "log", 
      "line": 7380, 
      "parameters": [
        {
          "type": "string", 
          "value": "Loading asset bundle oauth-enrollment"
        }
      ], 
      "source": "console-api", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 13, 
            "functionName": "loadAssets", 
            "lineNumber": 7380, 
            "scriptId": "137", 
            "url": "chrome://oobe/oobe.js"
          }
        ]
      }, 
      "text": "Loading asset bundle oauth-enrollment", 
      "timestamp": 1468044516.7979901, 
      "type": "log", 
      "url": "chrome://oobe/oobe.js"
    }
  }
}]
07/08 23:09:13.957 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 28, 
      "level": "error", 
      "line": 416, 
      "scriptId": "137", 
      "source": "javascript", 
      "text": "Uncaught TypeError: Cannot read property 'showStep' of null", 
      "timestamp": 1468044517.02228, 
      "type": "log", 
      "url": "chrome://oobe/oobe.js"
    }
  }
}]
07/08 23:09:13.957 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 13, 
      "executionContextId": 1, 
      "level": "log", 
      "line": 7364, 
      "parameters": [
        {
          "type": "string", 
          "value": "Finished loading asset bundle oauth-enrollment"
        }
      ], 
      "source": "console-api", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 13, 
            "functionName": "finishedLoading", 
            "lineNumber": 7364, 
            "scriptId": "137", 
            "url": "chrome://oobe/oobe.js"
          }
        ]
      }, 
      "text": "Finished loading asset bundle oauth-enrollment", 
      "timestamp": 1468044517.06078, 
      "type": "log", 
      "url": "chrome://oobe/oobe.js"
    }
  }
}]
07/08 23:09:13.958 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 15, 
      "executionContextId": 1, 
      "level": "warning", 
      "line": 2295, 
      "parameters": [
        {
          "type": "string", 
          "value": "Unrecognized message from GAIA: showConfirmCancel"
        }
      ], 
      "source": "console-api", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 15, 
            "functionName": "Authenticator.onMessageFromWebview_", 
            "lineNumber": 2295, 
            "scriptId": "138", 
            "url": "chrome://oobe/gaia_auth_host.js"
          }
        ]
      }, 
      "text": "Unrecognized message from GAIA: showConfirmCancel", 
      "timestamp": 1468044518.66348, 
      "type": "log", 
      "url": "chrome://oobe/gaia_auth_host.js"
    }
  }
}]
07/08 23:09:13.958 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 15, 
      "executionContextId": 1, 
      "level": "warning", 
      "line": 2295, 
      "parameters": [
        {
          "type": "string", 
          "value": "Unrecognized message from GAIA: clearOldAttempts"
        }
      ], 
      "source": "console-api", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 15, 
            "functionName": "Authenticator.onMessageFromWebview_", 
            "lineNumber": 2295, 
            "scriptId": "138", 
            "url": "chrome://oobe/gaia_auth_host.js"
          }
        ]
      }, 
      "text": "Unrecognized message from GAIA: clearOldAttempts", 
      "timestamp": 1468044520.5334201, 
      "type": "log", 
      "url": "chrome://oobe/gaia_auth_host.js"
    }
  }
}]
07/08 23:09:13.959 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 15, 
      "executionContextId": 1, 
      "level": "warning", 
      "line": 2354, 
      "parameters": [
        {
          "type": "string", 
          "value": "Authenticator: No password scraped for SAML."
        }
      ], 
      "source": "console-api", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 15, 
            "functionName": "Authenticator.maybeCompleteAuth_", 
            "lineNumber": 2354, 
            "scriptId": "138", 
            "url": "chrome://oobe/gaia_auth_host.js"
          }
        ]
      }, 
      "text": "Authenticator: No password scraped for SAML.", 
      "timestamp": 1468044521.33986, 
      "type": "log", 
      "url": "chrome://oobe/gaia_auth_host.js"
    }
  }
}]
07/08 23:09:13.959 DEBUG|inspector_websocke:0164| got [{
  "method": "Console.messageAdded", 
  "params": {
    "message": {
      "column": 15, 
      "executionContextId": 1, 
      "level": "warning", 
      "line": 2295, 
      "parameters": [
        {
          "type": "string", 
          "value": "Unrecognized message from GAIA: showConfirmCancel"
        }
      ], 
      "source": "console-api", 
      "stack": {
        "callFrames": [
          {
            "columnNumber": 15, 
            "functionName": "Authenticator.onMessageFromWebview_", 
            "lineNumber": 2295, 
            "scriptId": "138", 
            "url": "chrome://oobe/gaia_auth_host.js"
          }
        ]
      }, 
      "text": "Unrecognized message from GAIA: showConfirmCancel", 
      "timestamp": 1468044521.86373, 
      "type": "log", 
      "url": "chrome://oobe/gaia_auth_host.js"
    }
  }
}]
07/08 23:09:13.960 DEBUG|inspector_websocke:0164| got [{
  "id": 60, 
  "result": {}
}]
07/08 23:09:23.971 DEBUG|inspector_websocke:0097| sent [{
  "id": 61, 
  "method": "Console.disable"
}]
07/08 23:09:23.972 DEBUG|inspector_websocke:0164| got [{
  "id": 61, 
  "result": {}
}]
07/08 23:09:23.993 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[165 processes]
07/08 23:09:24.107 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[165 processes]
07/08 23:09:24.224 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[165 processes]
07/08 23:09:24.343 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[165 processes]
07/08 23:09:24.458 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[165 processes]
07/08 23:09:24.575 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[165 processes]
.
.
.
07/08 23:10:23.978 ERROR|        site_utils:0876| Timed out waiting for unnamed condition
07/08 23:10:23.993 DEBUG|    cros_interface:0354| ListProcesses(<predicate>)->[165 processes]
07/08 23:10:23.995 INFO |    cros_interface:0525| (Re)starting the ui (logs the user out)
07/08 23:10:24.002 DEBUG|    cros_interface:0422| IsServiceRunning(ui)->True
07/08 23:10:24.002 DEBUG|    cros_interface:0058| sh -c restart ui 
07/08 23:10:24.625 DEBUG|    cros_interface:0067|  > stdout=[ui start/running, process 11613
], stderr=[]
07/08 23:10:24.627 DEBUG|    cros_interface:0058| sh -c cryptohome-path user 'test@test.test' 
07/08 23:10:24.644 DEBUG|    cros_interface:0067|  > stdout=[/home/user/d04b75e599752afbc206b1a832b581b8437dd0d5
], stderr=[]
07/08 23:10:24.644 DEBUG|    cros_interface:0058| sh -c /bin/df /home/user/d04b75e599752afbc206b1a832b581b8437dd0d5 
07/08 23:10:24.650 DEBUG|    cros_interface:0067|  > stdout=[], stderr=[df: '/home/user/d04b75e599752afbc206b1a832b581b8437dd0d5': No such file or directory
]
07/08 23:10:24.651 DEBUG|        base_utils:0185| Running 'mkdir -p /usr/local/autotest/results/default/enterprise_RemoraRequisition/sysinfo/iteration.1/var/spool'
07/08 23:10:24.657 DEBUG|        base_utils:0185| Running 'rsync --no-perms --chmod=ugo+r -a --exclude=autoserv*  /var/spool/crash /usr/local/autotest/results/default/enterprise_RemoraRequisition/sysinfo/iteration.1/var/spool'
07/08 23:10:24.704 DEBUG|        base_utils:0185| Running 'rm -rf /var/spool/crash/*'
07/08 23:10:24.713 DEBUG|        base_utils:0185| Running 'logger "autotest finished iteration /usr/local/autotest/results/default/enterprise_RemoraRequisition/sysinfo/iteration.1"'
07/08 23:10:24.725 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 300, 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 877, in poll_for_condition
    raise TimeoutError(desc)
TimeoutError: Timed out waiting for unnamed condition
IMG_20160711_185553.jpg
3.1 MB View Download

Comment 1 by achuith@chromium.org, Jul 12 2016 

And enterprise enrollment works ok?

Can you post the chrome log as well?

Someone needs to do a bisect. I'm still remote this week so I can't look at this.

Comment 2 by dchan@google.com, Jul 12 2016

Cc: harpreet@chromium.org mlight@chromium.org
Status: Assigned (was: Untriaged)

Comment 3 by harpreet@chromium.org, Jul 12 2016

Components: Enterprise
Status: Untriaged (was: Assigned)
Yes enterprise enrollment is broken as well. Will post the chrome logs soon.

Comment 4 by harpreet@chromium.org, Jul 12 2016

Status: Assigned (was: Untriaged)

Comment 6 by abodenha@chromium.org, Jul 12 2016

Owner: achuith@chromium.org
achuith@ can you dig deeper on this one?

Comment 7 by mnissler@chromium.org, Jul 12 2016

Cc: dkrahn@chromium.org
From the logs:

[629:629:0712/104419:ERROR:enterprise_install_attributes.cc(256)] Install attributes invalid.
[629:629:0712/104419:WARNING:enrollment_handler_chromeos.cc(489)] Enrollment failed: 9, client: 0, validation: 0, store: 0, lock: 3

So it looks like a problem on the cryptohome side. Indeed, syslog has these:

2016-07-12T10:44:15.741531-07:00 INFO kernel: [   35.112132] tpm_tis tpm_tis: command 0xcc (size 146) returned code 0x2
2016-07-12T10:44:15.782881-07:00 ERR cryptohomed[640]: TPM error 0x2 (Bad memory index): Could not define NVRAM space: 0
2016-07-12T10:44:15.783281-07:00 ERR cryptohomed[640]: Create() failed to defined NVRAM space.

dkrahn@ might know?

Comment 8 by dkrahn@chromium.org, Jul 13 2016

Owner: smbar...@chromium.org
That doesn't look right, I don't think the index should be 0.

Comment 9 by achuith@chromium.org, Jul 13 2016 

harpreet@: Could you try enrollment on another device with TOT please?

Comment 10 by harpreet@chromium.org, Jul 13 2016 

achuith@ we have tried on few different devices on TOT and get the same error.

Comment 11 by smbar...@chromium.org, Jul 13 2016

Mergedinto: 627832
Status: Duplicate (was: Assigned)
►

Sign in to add a comment