{"action":"created","issue":{"url":"https://api.github.com/repos/ClusterHQ/flocker/issues/2766","repository_url":"https://api.github.com/repos/ClusterHQ/flocker","labels_url":"https://api.github.com/repos/ClusterHQ/flocker/issues/2766/labels{/name}","comments_url":"https://api.github.com/repos/ClusterHQ/flocker/issues/2766/comments","events_url":"https://api.github.com/repos/ClusterHQ/flocker/issues/2766/events","html_url":"https://github.com/ClusterHQ/flocker/issues/2766","id":149040479,"number":2766,"title":"Can't start  flocker-dataset-agent.service or flocker-container-agent.service","user":{"login":"scotty-c","id":8423099,"avatar_url":"https://avatars.githubusercontent.com/u/8423099?v=3","gravatar_id":"","url":"https://api.github.com/users/scotty-c","html_url":"https://github.com/scotty-c","followers_url":"https://api.github.com/users/scotty-c/followers","following_url":"https://api.github.com/users/scotty-c/following{/other_user}","gists_url":"https://api.github.com/users/scotty-c/gists{/gist_id}","starred_url":"https://api.github.com/users/scotty-c/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/scotty-c/subscriptions","organizations_url":"https://api.github.com/users/scotty-c/orgs","repos_url":"https://api.github.com/users/scotty-c/repos","events_url":"https://api.github.com/users/scotty-c/events{/privacy}","received_events_url":"https://api.github.com/users/scotty-c/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/ClusterHQ/flocker/labels/kind:%20using%20flocker","name":"kind: using flocker","color":"e11d21"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":4,"created_at":"2016-04-18T04:38:32Z","updated_at":"2016-04-25T17:24:40Z","closed_at":null,"body":"\r\nGood afternoon,\r\n\r\nI am getting the following error with the flocker-container-agent.service\r\n\r\n````\r\nApr 18 03:53:42 flocker-02 systemd[1]: Started Flocker Dataset Agent.\r\nApr 18 03:53:42 flocker-02 systemd[1]: Starting Flocker Dataset Agent...\r\nApr 18 03:53:43 flocker-02 flocker-dataset-agent[8945]: {\"task_uuid\": \"3a16a839-1b5b-4d50-893a-5884ad7ca507\", \"error\": false, \"timestamp\": 1460951623.950877, \"message\": \"Log opened.\", \"message_type\": \"twisted:log\", \"task_level\": [1]}\r\nApr 18 03:53:43 flocker-02 flocker-dataset-agent[8945]: {\"task_uuid\": \"0f7599cc-6c75-4bd6-967b-2cd3c577ee11\", \"task_level\": [1], \"action_type\": \"flocker:node:script:get_external_ip\", \"timestamp\": 1460951623.95468, \"host\": \"flocker-01.local.test\", \"action_status\": \"started\", \"port\": 4524}\r\nApr 18 03:53:43 flocker-02 flocker-dataset-agent[8945]: {\"task_uuid\": \"0f7599cc-6c75-4bd6-967b-2cd3c577ee11\", \"task_level\": [2], \"action_type\": \"flocker:node:script:get_external_ip\", \"local_ip\": \"172.17.8.102\", \"timestamp\": 1460951623.956358, \"action_status\": \"succeeded\"}\r\nApr 18 03:53:43 flocker-02 flocker-dataset-agent[8945]: {\"task_uuid\": \"dd3e523e-6da8-41d2-a9fb-cb1654f8d33f\", \"error\": true, \"timestamp\": 1460951623.957557, \"message\": \"Unhandled Error\\nTraceback (most recent call last):\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 81, in flocker_dataset_agent_main\\n    options=options,\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 295, in main\\n    self._react(run_and_log, [], _reactor=self._reactor)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/task.py\\\", line 882, in react\\n    finished = main(_reactor, *argv)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 283, in run_and_log\\n    d = maybeDeferred(self.script.main, reactor, options)\\n--- <exception caught here> ---\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/defer.py\\\", line 150, in maybeDeferred\\n    result = f(*args, **kw)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 292, in main\\n    self.service_factory(reactor, options)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 597, in get_service\\n    deployer = agent_service.get_deployer(api)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 553, in get_deployer\\n    node_uuid = self.node_credential.uuid\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/ca/_ca.py\\\", line 533, in uuid\\n    return UUID(hex=common_name[len(self._UUID_PREFIX):])\\n  File \\\"/usr/lib64/python2.7/uuid.py\\\", line 134, in __init__\\n    raise ValueError('badly formed hexadecimal UUID string')\\nexceptions.ValueError: badly formed hexadecimal UUID string\\n\", \"message_type\": \"twisted:log\", \"task_level\": [1]}\r\nApr 18 03:53:43 flocker-02 flocker-dataset-agent[8945]: {\"task_uuid\": \"b548b9be-0cd5-4bab-a43b-4eff7ffb49fc\", \"error\": true, \"timestamp\": 1460951623.957934, \"message\": \"main function encountered error\\nTraceback (most recent call last):\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 81, in flocker_dataset_agent_main\\n    options=options,\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 295, in main\\n    self._react(run_and_log, [], _reactor=self._reactor)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/task.py\\\", line 882, in react\\n    finished = main(_reactor, *argv)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 283, in run_and_log\\n    d = maybeDeferred(self.script.main, reactor, options)\\n--- <exception caught here> ---\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/defer.py\\\", line 150, in maybeDeferred\\n    result = f(*args, **kw)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 292, in main\\n    self.service_factory(reactor, options)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 597, in get_service\\n    deployer = agent_service.get_deployer(api)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 553, in get_deployer\\n    node_uuid = self.node_credential.uuid\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/ca/_ca.py\\\", line 533, in uuid\\n    return UUID(hex=common_name[len(self._UUID_PREFIX):])\\n  File \\\"/usr/lib64/python2.7/uuid.py\\\", line 134, in __init__\\n    raise ValueError('badly formed hexadecimal UUID string')\\nexceptions.ValueError: badly formed hexadecimal UUID string\\n\", \"message_type\": \"twisted:log\", \"task_level\": [1]}\r\nApr 18 03:53:43 flocker-02 flocker-dataset-agent[8945]: {\"task_uuid\": \"185c9c2c-4d44-45b3-8547-54ee01f86641\", \"error\": false, \"timestamp\": 1460951623.958113, \"message\": \"Main loop terminated.\", \"message_type\": \"twisted:log\", \"task_level\": [1]}\r\nApr 18 03:53:44 flocker-02 systemd[1]: flocker-dataset-agent.service: main process exited, code=exited, status=1/FAILURE\r\nApr 18 03:53:44 flocker-02 systemd[1]: Unit flocker-dataset-agent.service entered failed state.\r\nApr 18 03:53:44 flocker-02 systemd[1]: flocker-dataset-agent.service failed.\r\nApr 18 03:53:44 flocker-02 systemd[1]: flocker-dataset-agent.service holdoff time over, scheduling restart.\r\nApr 18 03:53:44 flocker-02 systemd[1]: start request repeated too quickly for flocker-dataset-agent.service\r\nApr 18 03:53:44 flocker-02 systemd[1]: Failed to start Flocker Dataset Agent.\r\nApr 18 03:53:44 flocker-02 systemd[1]: Unit flocker-dataset-agent.service entered failed state.\r\nApr 18 03:53:44 flocker-02 systemd[1]: flocker-dataset-agent.service failed.\r\n\r\n````\r\n\r\nand with the  flocker-dataset-agent.service\r\n````\r\nApr 18 04:00:50 flocker-02 systemd[1]: Started Flocker Container Agent.\r\nApr 18 04:00:50 flocker-02 systemd[1]: Starting Flocker Container Agent...\r\nApr 18 04:00:50 flocker-02 flocker-container-agent[9145]: {\"task_uuid\": \"22d27f0a-74bc-48f5-993a-7d1d71bcb387\", \"error\": false, \"timestamp\": 1460952050.765611, \"message\": \"Log opened.\", \"message_type\": \"twisted:log\", \"task_level\": [1]}\r\nApr 18 04:00:50 flocker-02 flocker-container-agent[9145]: {\"task_uuid\": \"a91bd0a8-6bbf-4d02-a5b2-445cb7074057\", \"task_level\": [1], \"action_type\": \"flocker:node:script:get_external_ip\", \"timestamp\": 1460952050.76827, \"host\": \"flocker-01.local.test\", \"action_status\": \"started\", \"port\": 4524}\r\nApr 18 04:00:50 flocker-02 flocker-container-agent[9145]: {\"task_uuid\": \"a91bd0a8-6bbf-4d02-a5b2-445cb7074057\", \"task_level\": [2], \"action_type\": \"flocker:node:script:get_external_ip\", \"local_ip\": \"172.17.8.102\", \"timestamp\": 1460952050.770161, \"action_status\": \"succeeded\"}\r\nApr 18 04:00:50 flocker-02 flocker-container-agent[9145]: {\"task_uuid\": \"bf95b04f-48df-4a6a-9fae-65ddd008005d\", \"error\": true, \"timestamp\": 1460952050.775076, \"message\": \"Unhandled Error\\nTraceback (most recent call last):\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 106, in flocker_container_agent_main\\n    options=ContainerAgentOptions()\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 295, in main\\n    self._react(run_and_log, [], _reactor=self._reactor)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/task.py\\\", line 882, in react\\n    finished = main(_reactor, *argv)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 283, in run_and_log\\n    d = maybeDeferred(self.script.main, reactor, options)\\n--- <exception caught here> ---\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/defer.py\\\", line 150, in maybeDeferred\\n    result = f(*args, **kw)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 292, in main\\n    self.service_factory(reactor, options)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 343, in get_service\\n    node_uuid=tls_info.node_credential.uuid, hostname=ip,\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/ca/_ca.py\\\", line 533, in uuid\\n    return UUID(hex=common_name[len(self._UUID_PREFIX):])\\n  File \\\"/usr/lib64/python2.7/uuid.py\\\", line 134, in __init__\\n    raise ValueError('badly formed hexadecimal UUID string')\\nexceptions.ValueError: badly formed hexadecimal UUID string\\n\", \"message_type\": \"twisted:log\", \"task_level\": [1]}\r\nApr 18 04:00:50 flocker-02 flocker-container-agent[9145]: {\"task_uuid\": \"ac0947ed-961b-4007-a38d-4d7940788118\", \"error\": true, \"timestamp\": 1460952050.77549, \"message\": \"main function encountered error\\nTraceback (most recent call last):\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 106, in flocker_container_agent_main\\n    options=ContainerAgentOptions()\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 295, in main\\n    self._react(run_and_log, [], _reactor=self._reactor)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/task.py\\\", line 882, in react\\n    finished = main(_reactor, *argv)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 283, in run_and_log\\n    d = maybeDeferred(self.script.main, reactor, options)\\n--- <exception caught here> ---\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/defer.py\\\", line 150, in maybeDeferred\\n    result = f(*args, **kw)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 292, in main\\n    self.service_factory(reactor, options)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 343, in get_service\\n    node_uuid=tls_info.node_credential.uuid, hostname=ip,\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/ca/_ca.py\\\", line 533, in uuid\\n    return UUID(hex=common_name[len(self._UUID_PREFIX):])\\n  File \\\"/usr/lib64/python2.7/uuid.py\\\", line 134, in __init__\\n    raise ValueError('badly formed hexadecimal UUID string')\\nexceptions.ValueError: badly formed hexadecimal UUID string\\n\", \"message_type\": \"twisted:log\", \"task_level\": [1]}\r\nApr 18 04:00:50 flocker-02 flocker-container-agent[9145]: {\"task_uuid\": \"f2ed24b8-daf9-4b36-9e88-7a8f63a44346\", \"error\": false, \"timestamp\": 1460952050.775751, \"message\": \"Main loop terminated.\", \"message_type\": \"twisted:log\", \"task_level\": [1]}\r\nApr 18 04:00:50 flocker-02 systemd[1]: flocker-container-agent.service: main process exited, code=exited, status=1/FAILURE\r\nApr 18 04:00:50 flocker-02 systemd[1]: Unit flocker-container-agent.service entered failed state.\r\nApr 18 04:00:50 flocker-02 systemd[1]: flocker-container-agent.service failed.\r\nApr 18 04:00:51 flocker-02 systemd[1]: flocker-container-agent.service holdoff time over, scheduling restart.\r\nApr 18 04:00:51 flocker-02 systemd[1]: start request repeated too quickly for flocker-container-agent.service\r\nApr 18 04:00:51 flocker-02 systemd[1]: Failed to start Flocker Container Agent.\r\nApr 18 04:00:51 flocker-02 systemd[1]: Unit flocker-container-agent.service entered failed state.\r\nApr 18 04:00:51 flocker-02 systemd[1]: flocker-container-agent.service failed.\r\n````\r\n\r\nI am using Centos 7 with Flocker 1.11.0"},"comment":{"url":"https://api.github.com/repos/ClusterHQ/flocker/issues/comments/214449639","html_url":"https://github.com/ClusterHQ/flocker/issues/2766#issuecomment-214449639","issue_url":"https://api.github.com/repos/ClusterHQ/flocker/issues/2766","id":214449639,"user":{"login":"wallrj","id":978965,"avatar_url":"https://avatars.githubusercontent.com/u/978965?v=3","gravatar_id":"","url":"https://api.github.com/users/wallrj","html_url":"https://github.com/wallrj","followers_url":"https://api.github.com/users/wallrj/followers","following_url":"https://api.github.com/users/wallrj/following{/other_user}","gists_url":"https://api.github.com/users/wallrj/gists{/gist_id}","starred_url":"https://api.github.com/users/wallrj/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wallrj/subscriptions","organizations_url":"https://api.github.com/users/wallrj/orgs","repos_url":"https://api.github.com/users/wallrj/repos","events_url":"https://api.github.com/users/wallrj/events{/privacy}","received_events_url":"https://api.github.com/users/wallrj/received_events","type":"User","site_admin":false},"created_at":"2016-04-25T17:24:40Z","updated_at":"2016-04-25T17:24:40Z","body":"The formatted error looks like\r\n\r\n```\r\nmain function encountered error\r\nTraceback (most recent call last):\r\n  File \"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\", line 81, in flocker_dataset_agent_main\r\n    options=options,\r\n  File \"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\", line 295, in main\r\n    self._react(run_and_log, [], _reactor=self._reactor)\r\n  File \"/opt/flocker/lib/python2.7/site-packages/twisted/internet/task.py\", line 882, in react\r\n    finished = main(_reactor, *argv)\r\n  File \"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\", line 283, in run_and_log\r\n    d = maybeDeferred(self.script.main, reactor, options)\r\n--- <exception caught here> ---\r\n  File \"/opt/flocker/lib/python2.7/site-packages/twisted/internet/defer.py\", line 150, in maybeDeferred\r\n    result = f(*args, **kw)\r\n  File \"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\", line 292, in main\r\n    self.service_factory(reactor, options)\r\n  File \"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\", line 597, in get_service\r\n    deployer = agent_service.get_deployer(api)\r\n  File \"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\", line 553, in get_deployer\r\n    node_uuid = self.node_credential.uuid\r\n  File \"/opt/flocker/lib/python2.7/site-packages/flocker/ca/_ca.py\", line 533, in uuid\r\n    return UUID(hex=common_name[len(self._UUID_PREFIX):])\r\n  File \"/usr/lib64/python2.7/uuid.py\", line 134, in __init__\r\n    raise ValueError('badly formed hexadecimal UUID string')\r\nexceptions.ValueError: badly formed hexadecimal UUID string\r\n\r\n```\r\n\r\n\r\n```\r\n\r\n{\r\n  \"task_uuid\": \"b548b9be-0cd5-4bab-a43b-4eff7ffb49fc\",\r\n  \"error\": true,\r\n  \"timestamp\": 1460951623.957934,\r\n  \"message\": \"main function encountered error\\nTraceback (most recent call last):\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 81, in flocker_dataset_agent_main\\n    options=options,\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 295, in main\\n    self._react(run_and_log, [], _reactor=self._reactor)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/task.py\\\", line 882, in react\\n    finished = main(_reactor, *argv)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/common/script.py\\\", line 283, in run_and_log\\n    d = maybeDeferred(self.script.main, reactor, options)\\n--- <exception caught here> ---\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/twisted/internet/defer.py\\\", line 150, in maybeDeferred\\n    result = f(*args, **kw)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 292, in main\\n    self.service_factory(reactor, options)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 597, in get_service\\n    deployer = agent_service.get_deployer(api)\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/node/script.py\\\", line 553, in get_deployer\\n    node_uuid = self.node_credential.uuid\\n  File \\\"/opt/flocker/lib/python2.7/site-packages/flocker/ca/_ca.py\\\", line 533, in uuid\\n    return UUID(hex=common_name[len(self._UUID_PREFIX):])\\n  File \\\"/usr/lib64/python2.7/uuid.py\\\", line 134, in __init__\\n    raise ValueError('badly formed hexadecimal UUID string')\\nexceptions.ValueError: badly formed hexadecimal UUID string\\n\",\r\n  \"message_type\": \"twisted:log\",\r\n  \"task_level\": [\r\n    1\r\n  ]\r\n}\r\n```\r\n\r\nWhich comes from the following function / property\r\n\r\n```\r\n    @property\r\n    def uuid(self):\r\n        common_name = self.credential.certificate.getSubject().CN\r\n        return UUID(hex=common_name[len(self._UUID_PREFIX):])\r\n\r\n```\r\nSome thoughts:\r\n * I wonder if your certificate is somehow non-standard. \r\n* Did you generate the certificates using `flocker-ca` or using `openssl` ?\r\n* Did you accidentally copy the wrong certificate to the node?\r\n\r\n\r\nA properly constructed node certificate should look something like this:\r\n\r\n```\r\n(master) [/tmp/flocker]$ openssl x509  -text -in 28f2f1cd-02e4-42ec-9d11-c206945098c3.crt\r\nCertificate:\r\n    Data:\r\n        Version: 1 (0x0)\r\n        Serial Number:\r\n            91:f5:60:c3:9a:63:b3:80:1f:1c:22:1f:cf:5c:92:ce\r\n    Signature Algorithm: sha256WithRSAEncryption\r\n        Issuer: OU=25be7b2a-5dee-4055-942a-ac5513c91b29, CN=test-cluster-1\r\n        Validity\r\n            Not Before: Apr 25 17:20:06 2016 GMT\r\n            Not After : Apr 20 17:20:06 2036 GMT\r\n        Subject: OU=25be7b2a-5dee-4055-942a-ac5513c91b29, CN=node-28f2f1cd-02e4-42ec-9d11-c206945098c3\r\n\r\n\r\n```\r\n\r\nNote that the `Subject > CN (Common Name)` of the node certificate should begin with `node-` followed by the node's UUID.\r\n\r\nRun `openssl x509  -text -in /etc/flocker/node.crt` on the faulty node and take a look at the output. Paste it here if you are willing to share.\r\n\r\n\r\n"}}