Provisioning job's tasks' results:
[root@headnode (nightly-1) ~]# sdc-workflow /jobs/9a2caf14-958f-4218-bc55-207511997ccd | json -H chain_results
[
{
"result": "All parameters OK!",
"error": "",
"name": "common.validate_params",
"started_at": "2017-09-25T09:29:02.763Z",
"finished_at": "2017-09-25T09:29:02.779Z"
},
{
"result": "Action set",
"error": "",
"name": "workflow.set_job_action",
"started_at": "2017-09-25T09:29:02.943Z",
"finished_at": "2017-09-25T09:29:02.958Z"
},
{
"result": "Image has generate_passwords=true but no users found",
"error": "",
"name": "imgapi.generate_passwords",
"started_at": "2017-09-25T09:29:03.123Z",
"finished_at": "2017-09-25T09:29:03.145Z"
},
{
"result": "Networks are valid",
"error": "",
"name": "napi.validate_networks",
"started_at": "2017-09-25T09:29:03.313Z",
"finished_at": "2017-09-25T09:29:03.345Z"
},
{
"result": "OK",
"error": "",
"name": "dapi.get_allocation_ticket",
"started_at": "2017-09-25T09:29:03.473Z",
"finished_at": "2017-09-25T09:29:03.559Z"
},
{
"result": "OK",
"error": "",
"name": "dapi.wait_allocation_ticket",
"started_at": "2017-09-25T09:29:03.623Z",
"finished_at": "2017-09-25T09:29:03.640Z"
},
{
"result": "Server UUID present, no need to get allocation from DAPI",
"error": "",
"name": "dapi.get_allocation",
"started_at": "2017-09-25T09:29:03.773Z",
"finished_at": "2017-09-25T09:29:03.788Z"
},
{
"result": "OK",
"error": "",
"name": "cnapi.acquire_vm_ticket",
"started_at": "2017-09-25T09:29:03.853Z",
"finished_at": "2017-09-25T09:29:03.928Z"
},
{
"result": "OK",
"error": "",
"name": "dapi.release_allocation_ticket",
"started_at": "2017-09-25T09:29:04.053Z",
"finished_at": "2017-09-25T09:29:04.121Z"
},
{
"result": "OK",
"error": "",
"name": "cnapi.wait_on_vm_ticket",
"started_at": "2017-09-25T09:29:04.273Z",
"finished_at": "2017-09-25T09:29:04.295Z"
},
{
"result": "OK",
"error": "",
"name": "cnapi.get_server_nic_tags",
"started_at": "2017-09-25T09:29:04.413Z",
"finished_at": "2017-09-25T09:29:04.536Z"
},
{
"result": "Server has all the required NIC tags",
"error": "",
"name": "cnapi.check_manual_server_nics",
"started_at": "2017-09-25T09:29:04.753Z",
"finished_at": "2017-09-25T09:29:04.776Z"
},
{
"result": "NICs allocated",
"error": "",
"name": "napi.provision_nics",
"started_at": "2017-09-25T09:29:05.003Z",
"finished_at": "2017-09-25T09:29:05.107Z"
},
{
"result": "No fabric NATs to provision",
"error": "",
"name": "cnapi.acquire_fabric_nat_tickets",
"started_at": "2017-09-25T09:29:05.283Z",
"finished_at": "2017-09-25T09:29:05.305Z"
},
{
"result": "No fabric NATs to provision",
"error": "",
"name": "napi.provision_fabric_nats",
"started_at": "2017-09-25T09:29:05.482Z",
"finished_at": "2017-09-25T09:29:05.499Z"
},
{
"result": "Payload prepared successfully",
"error": "",
"name": "prepare_payload",
"started_at": "2017-09-25T09:29:05.673Z",
"finished_at": "2017-09-25T09:29:05.699Z"
},
{
"result": "Ensure image task queued!",
"error": "",
"name": "cnapi.ensure_image",
"started_at": "2017-09-25T09:29:05.864Z",
"finished_at": "2017-09-25T09:29:06.003Z"
},
{
"result": "",
"error": {
"name": "Error",
"message": "socket hang up"
},
"name": "cnapi.wait_task_ensure_image",
"started_at": "2017-09-25T09:29:06.503Z",
"finished_at": "2017-09-25T10:29:06.428Z"
}
]
Image and server UUID:
[root@headnode (nightly-1) ~]# sdc-workflow /jobs/9a2caf14-958f-4218-bc55-207511997ccd | json -H params.image_uuid
fd2cc906-8938-11e3-beab-4359c665ac99
[root@headnode (nightly-1) ~]# sdc-workflow /jobs/9a2caf14-958f-4218-bc55-207511997ccd | json -H params.server_uuid
00000000-0000-0000-0000-002590918ccc
[root@headnode (nightly-1) ~]# sdc-server list | grep 00000000-0000-0000-0000-002590918ccc
headnode 00000000-0000-0000-0000-002590918ccc 7.0 true running 131039 172.25.1.4
[root@headnode (nightly-1) ~]#
From cn-agent logs:
[2017-09-25T09:29:06.336Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
evt: {
"ph": "b",
"name": "image_ensure_present"
}
[2017-09-25T09:29:06.340Z] DEBUG: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: Child ready to start, sending ready event to parent (req_id=792a2041-2c20-
ea19-fe85-809efd4b6095)
[2017-09-25T09:29:06.343Z] DEBUG: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: Child received hydracp message from parent: (req_id=792a2041-2c20-ea19-fe8
5-809efd4b6095)
[2017-09-25T09:29:06.344Z] DEBUG: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: (req_id=792a2041-2c20-ea19-fe85-809efd4b6095, action=start, req.req_id=79
2a2041-2c20-ea19-fe85-809efd4b6095, req.req_host=172.25.1.4:5309, req.task=image_ensure_present)
undefined undefined HTTP/1.1
--
taskspath: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks
--
req.params: {
"server_uuid": "00000000-0000-0000-0000-002590918ccc",
"image_uuid": "fd2cc906-8938-11e3-beab-4359c665ac99"
}
[2017-09-25T09:29:06.344Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: Instantiating /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
[2017-09-25T09:29:06.404Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: Received event (progress) from task instance (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
event: {
"value": 0
}
[2017-09-25T09:29:06.404Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: Received event (start) from task instance (req_id=792a2041-2c20-ea19-fe85-809efd4b6095, event={})
[2017-09-25T09:29:06.406Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: Checking whether zone template dataset zones/fd2cc906-8938-11e3-beab-4359c665ac99 exists on the system. (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
[2017-09-25T09:29:06.449Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: image already installed (zones/fd2cc906-8938-11e3-beab-4359c665ac99) (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
[2017-09-25T09:29:06.450Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: Received event (progress) from task instance (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
event: {
"value": 100
}
[2017-09-25T09:29:06.450Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: Received event (finish) from task instance (req_id=792a2041-2c20-ea19-fe85-809efd4b6095, event={})
[2017-09-25T09:29:06.456Z] INFO: /opt/smartdc/agents/lib/node_modules/cn-agent/lib/tasks/image_ensure_present/15678 on headnode: (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
evt: {
"ph": "e",
"name": "image_ensure_present"
}
From CNAPI logs:
Starting the ensure_image task:
[2017-09-25T09:29:05.905Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: sending task to 00000000-0000-0000-0000-002590918ccc
[2017-09-25T09:29:05.905Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: task params
params: {
"server_uuid": "00000000-0000-0000-0000-002590918ccc",
"image_uuid": "fd2cc906-8938-11e3-beab-4359c665ac99"
}
[2017-09-25T09:29:05.905Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: Task id = 8b1d7864-920a-e6cf-b7ae-ecdd2a380232 (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
[2017-09-25T09:29:05.906Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: sysinfo for 00000000-0000-0000-0000-002590918ccc before task image_ensure_present (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
[2017-09-25T09:29:05.999Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: posting task to http://172.25.1.4:5309/tasks (req_id=792a2041-2c20-ea19-fe85-809efd4b6095) (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
[2017-09-25T09:29:06.002Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: done posting task to client (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
[2017-09-25T09:29:06.003Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
evt: {
"ph": "e",
"name": "serverensureimage",
"req_seq": 1506331745891800
}
[2017-09-25T09:29:06.004Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: handled: 200 (req_id=792a2041-2c20-ea19-fe85-809efd4b6095, route=serverensureimage, audit=true, remoteAddress=::ffff:172.25.1.19, remotePort=58937, latency=112, _audit=true, req.query={}, req.version=*)
POST /servers/00000000-0000-0000-0000-002590918ccc/ensure-image HTTP/1.1
x-request-id: 792a2041-2c20-ea19-fe85-809efd4b6095
accept: application/json
content-type: application/json
user-agent: restify/1.5.0 (ia32-sunos; v8/3.14.5.9; OpenSSL/1.0.1e) node/0.10.26
date: Mon, 25 Sep 2017 09:29:05 GMT
content-length: 53
content-md5: LghbK5Yb7aIwE3f3F3W9XA==
host: cnapi.nightly-1.joyent.us
connection: keep-alive
--
HTTP/1.1 200 OK
content-type: application/json
content-length: 45
date: Mon, 25 Sep 2017 09:29:06 GMT
server: Compute Node API
x-request-id: 792a2041-2c20-ea19-fe85-809efd4b6095
x-response-time: 111
x-server-name: 1816d397-468a-47c9-b59b-52352e3269f5
--
req.timers: {
"bunyan": 112,
"setTracing": 503,
"parseAccept": 137,
"parseAuthorization": 29,
"parseQueryString": 63,
"readBody": 341,
"parseBody": 85,
"handler-0": 67,
"setDefaultTimeouts": 34,
"setHeaders": 46,
"handlerEnsureStash": 31,
"handlerEnsureConnectionTimeout": 24,
"handlerEnsureConnectionMoray": 38,
"handlerEnsureServerPrepopulated": 10651,
"handlerEnsureServerRunning": 511,
"handlerServerEnsureImage": 98208
}
[2017-09-25T09:29:06.456Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: post came back with (req_id=792a2041-2c20-ea19-fe85-809efd4b6095, obj={})
Starting to wait on this task:
[2017-09-25T09:29:06.528Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
evt: {
"ph": "b",
"name": "taskwait",
"req_seq": 1506331746527801
}
After ~1 hour, end wait:
[2017-09-25T10:29:06.553Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: (req_id=792a2041-2c20-ea19-fe85-809efd4b6095)
evt: {
"ph": "e",
"name": "taskwait",
"req_seq": 1506331746527801
}
[2017-09-25T10:29:06.553Z] INFO: cnapi/16576 on 1816d397-468a-47c9-b59b-52352e3269f5: handled: 200 (req_id=792a2041-2c20-ea19-fe85-809efd4b6095, route=taskwait, audit=true, latency=3600026, _audit=true,
req.query={}, req.version=*)
GET /tasks/8b1d7864-920a-e6cf-b7ae-ecdd2a380232/wait HTTP/1.1
x-request-id: 792a2041-2c20-ea19-fe85-809efd4b6095
accept: application/json
user-agent: restify/1.5.0 (ia32-sunos; v8/3.14.5.9; OpenSSL/1.0.1e) node/0.10.26
date: Mon, 25 Sep 2017 09:29:06 GMT
host: cnapi.nightly-1.joyent.us
connection: keep-alive
--
HTTP/1.1 200 OK
content-type: application/json
content-length: 315
date: Mon, 25 Sep 2017 10:29:06 GMT
server: Compute Node API
x-request-id: 792a2041-2c20-ea19-fe85-809efd4b6095
x-response-time: 3600025
x-server-name: 1816d397-468a-47c9-b59b-52352e3269f5
--
req.timers: {
"bunyan": 138,
"setTracing": 412,
"parseAccept": 186,
"parseAuthorization": 54,
"parseQueryString": 28,
"readBody": 52,
"parseBody": 19,
"handler-0": 64,
"setDefaultTimeouts": 41,
"setHeaders": 23,
"bound handlerTaskWait": 3600129299
}