Intermittent TestCreateTenant failure

[markdryan]

This following failure was noticed on semaphore.

tenant_bat   TestCreateTenant                  300.01s    FAIL    
tenant_bat   TestGetTenantConfig               N/A        NOT RUN 
tenant_bat   TestUpdateTenantConfig            N/A        NOT RUN 
workload_bat TestCreateTenantWorkload          300.00s    FAIL    
workload_bat TestCreatePublicWorkload          N/A        NOT RUN 
workload_bat TestCreateWorkloadWithSizedVolume N/A        NOT RUN 


Logs for failed tests
---------------------
Logs for tenant_bat.TestCreateTenant
	tenant_bat_test.go:78: Failed to retrieve tenant list : failed to launch ciao-cli [tenant list -all -f {{tojson .}}] : signal: killed
	tenant_bat_test.go:68: Failed to delete tenant: failed to launch ciao-cli [tenant delete -tenant 75030c75-8002-41f5-9ae4-8c8b1cd52b6a] : context deadline exceeded

Logs for workload_bat.TestCreateTenantWorkload
	workload_bat_test.go:53: failed to launch ciao-cli [image list -f 
		{
		{{- range $i, $val := .}}
		  {{- if $i }},{{end}}
		  "{{$val.ID | js }}" : {{tojson $val}}
		{{- end }}
		}
		] : signal: killed
		
Output from stderr
------------------
SIGQUIT: quit
PC=0x468f38 m=0 sigcode=0

The test passed when re-run

The semaphore build is

https://semaphoreci.com/kaccardi/ciao/branches/pull-request-1566/builds/3

Interesting logs are

launcher

I1108 10:57:14.078426   25085 overseer.go:408] Overseer: looking for instance f2e0af2b-5d65-41b3-95a6-953f4bdaf06b
I1108 10:57:14.078434   25085 overseer.go:466] Overseer: removing f2e0af2b-5d65-41b3-95a6-953f4bdaf06b
I1108 10:57:14.078440   25085 instance.go:209] Powerdown f2e0af2b-5d65-41b3-95a6-953f4bdaf06b before deleting
I1108 10:57:14.078467   25085 qmp.go:282] {"execute":"system_powerdown"}
I1108 10:57:14.078684   25085 qmp.go:147] {"return": {}}
I1108 10:57:14.078693   25085 qmp.go:147] {"timestamp": {"seconds": 1510138634, "microseconds": 78627}, "event": "POWERDOWN"}
I1108 10:57:17.044322   25085 qmp.go:147] {"timestamp": {"seconds": 1510138637, "microseconds": 44188}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/peripheral-anon/device[0]/virtio-backend"}}
I1108 10:57:18.687971   25085 overseer.go:240] Memory Available: 4860 Disk space Available 55386
I1108 10:57:18.688582   25085 overseer.go:630] Consumed: Disk 0 Mem 2048 CPUs 4
W1108 10:57:24.078607   25085 qemu.go:500] Failed to power down cleanly: context deadline exceeded
I1108 10:57:24.078643   25085 qmp.go:282] {"execute":"quit"}
I1108 10:57:24.078792   25085 qmp.go:147] {"return": {}}
I1108 10:57:24.078884   25085 qmp.go:147] {"timestamp": {"seconds": 1510138644, "microseconds": 78846}, "event": "SHUTDOWN"}
I1108 10:57:24.107693   25085 qemu.go:419] Releasing VC Port 6704
I1108 10:57:24.107702   25085 port_grabber.go:78] Releasing port: 6704
I1108 10:57:24.107705   25085 port_grabber.go:87] Ports available 998
I1108 10:57:24.107709   25085 delete_instance.go:54] Deleting Vnic
I1108 10:57:24.107835   25085 network.go:197] Creating CN Vnic CFG
I1108 10:57:24.203533   25085 network.go:347] CN VNIC Destroyed = 172.16.0.2 &{4 198.51.100.66 198.51.100.1 172.16.0.0/24 55b214b6-dcc2-4bf4-8204-3e9b0929cc06 172.16.0.0/24 f8a2ea84-8111-425e-911e-285ab68550e2  4268 }
I1108 10:57:24.203726   25085 instance.go:307] Unmapping volumes for f2e0af2b-5d65-41b3-95a6-953f4bdaf06b
I1108 10:57:24.252242   25085 instance.go:316] Unmapping volume ae0fbb11-b25f-4379-9c98-008e6e328bc5
I1108 10:57:24.252365   25085 instance.go:372] Instance goroutine f2e0af2b-5d65-41b3-95a6-953f4bdaf06b waiting for monitor to exit
I1108 10:57:24.252383   25085 overseer.go:493] Overseer: Received Status Command
I1108 10:57:24.252374   25085 qemu.go:464] Monitor function for f2e0af2b-5d65-41b3-95a6-953f4bdaf06b exitting

controller

I1108 10:57:24.252521   23756 client.go:116] SSNTP Info: Waiting for next frame
I1108 10:57:24.252548   23756 client.go:327] EVENT Instance Deleted for ciao Controller
I1108 10:57:24.252554   23756 client.go:329] instance_deleted:
  instance_uuid: f2e0af2b-5d65-41b3-95a6-953f4bdaf06b
I1108 10:57:24.321684   23756 instance.go:193] Instance f2e0af2b-5d65-41b3-95a6-953f4bdaf06b: active -> deleted
I1108 10:57:24.689725   23756 client.go:116] SSNTP Info: Waiting for next frame
I1108 10:57:24.689742   23756 client.go:72] COMMAND STATISTICS for ciao Controller
I1108 10:57:24.691201   23756 client.go:86] node_uuid: 9ea74a7c-e0ad-4008-88bc-f8ff245b3a2e
status: READY
mem_total_mb: 7983
mem_available_mb: 6990
disk_total_mb: 60921
disk_available_mb: 55411
load: 1
cpus_online: 4
hostname: singlevm
networks:
- ip: 198.51.100.1
  mac: 16:2a:1c:f3:58:c5
instances:
- instance_uuid: f8a2ea84-8111-425e-911e-285ab68550e2
  state: active
  ssh_ip: ""
  ssh_port: 0
  memory_usage_mb: 264
  disk_usage_mb: 0
  cpu_usage: 0
  volumes:
  - b4584e1d-8a66-4ac8-b204-2486c4239757
W1108 10:57:24.945203   23756 api.go:281] Returning error response to request: /55b214b6-dcc2-4bf4-8204-3e9b0929cc06/instances/f2e0af2b-5d65-41b3-95a6-953f4bdaf06b: Instance not found
I1108 10:57:25.579299   23756 sqlite3db.go:434] exec: INSERT into tenants VALUES ('75030c75-8002-41f5-9ae4-8c8b1cd52b6a','CreateTenantTest',20);
I1108 11:02:24.320939   23756 cnci.go:267] RemoveSubnet 172.16.0.0/24
I1108 11:02:24.321357   23756 instance.go:193] Instance f8a2ea84-8111-425e-911e-285ab68550e2: active -> stopping
I1108 11:02:24.322504   23756 client.go:544] DELETE instance_id: f8a2ea84-8111-425e-911e-285ab68550e2node_id 9ea74a7c-e0ad-4008-88bc-f8ff245b3a2e
I1108 11:02:24.322513   23756 client.go:545] delete:
  instance_uuid: f8a2ea84-8111-425e-911e-285ab68550e2
  workload_agent_uuid: 9ea74a7c-e0ad-4008-88bc-f8ff245b3a2e
  stop: false
W1108 11:04:27.093545   23756 cnci.go:255] Unable to remove subnet: (timeout waiting for event concentrator removed)