search

ciao-project / ciao

Ciao - Cloud Integrated Advanced Orchestrator
Apache License 2.0
214 stars 51 forks source link

ciao-webui breaks ciao #1007

Closed markdryan closed 7 years ago

markdryan commented 7 years ago

I came across this issue when trying to integrate the webui into ciao-down. I guess the underlying issue must be in ciao (not the webui), but I can't figure out what's going wrong. It's easy to reproduce

git checkout -b markdryan-singlevm-webui master git pull https://github.com/markdryan/ciao.git singlevm-webui

cd $GOPATH/src/github.com/01org/ciao/testutil/ciao-down go build ./ciao-down prepare

wait for 10 minutes

./ciao-down connect

Follow the instructions for running setup.sh

Start a new terminal

Follow the instructions for starting the webui

From a browser on your host, enter https://localhost:3000

log in as csr. The password is hello

Create an instance. The instance will not be created.

Return to the terminal from which you ran setup.sh and run the BAT tests. Many tests will fail.

And here's the weird piece.

Shutdown the single VM (using cleanup.sh) and the web-ui Run setup.sh again Run the BAT tests. They'll pass Run the webui and create an instance. This will work now.

Looking at the logs controller is getting confused and is creating multiple CNCIs. Not sure why.

jorgevgut commented 7 years ago

Hi @markdryan , I was checking out the code for ciao/testutil/identity.go but I'm a little bit confused about how single vm handles scoped projects. webui relies automatically scopes with keystone, this is required in order to start up vms. I noticed on the readme file that scoping is not quite complete on singlevm, perhaps this is a possible cause of the problem.

markdryan commented 7 years ago

I don't really understand why but when you try to create an instance with the webui, two tenants, each with their own CNCI get created.

Then a second attempt is made to launch the CNCI for the first tenant again. This obviously fails and I think this failure is causing the problem. Here are some logs from launcher.

I0111 15:17:16.717932    7955 client.go:116] SSNTP Info: Waiting for next frame
I0111 15:17:16.718627    7955 payload.go:56] cloud-init file content
I0111 15:17:16.718631    7955 payload.go:57] -----------------------
I0111 15:17:16.718633    7955 payload.go:58] Instance UUID:        57efb1bc-ccaa-476d-9b18-92e5edc12912
I0111 15:17:16.718635    7955 payload.go:59] Disk image UUID:      
I0111 15:17:16.718637    7955 payload.go:60] FW Type:              efi
I0111 15:17:16.718650    7955 payload.go:61] VM Type:              qemu
I0111 15:17:16.718652    7955 payload.go:62] TenantUUID:          97c1f5f2eb374d999e702704d1975c8e
I0111 15:17:16.718653    7955 payload.go:64] VnicMAC:              02:dd:22:e2:52:fe
I0111 15:17:16.718655    7955 payload.go:65] VnicIP:               
I0111 15:17:16.718656    7955 payload.go:66] ConcIP:               
I0111 15:17:16.718658    7955 payload.go:67] SubnetIP:             
I0111 15:17:16.718660    7955 payload.go:68] ConcUUID:             
I0111 15:17:16.718661    7955 payload.go:69] VnicUUID:             8c8a6361-1d3d-4260-865b-2d2b137fe4d3
I0111 15:17:16.718663    7955 payload.go:71] Requested resources:
I0111 15:17:16.718665    7955 payload.go:74]    vcpus:     4
I0111 15:17:16.718670    7955 payload.go:74]   mem_mb:     128
I0111 15:17:16.718673    7955 payload.go:74]  disk_mb:     128
I0111 15:17:16.718675    7955 payload.go:74] network_node:     1
I0111 15:17:16.718677    7955 payload.go:79] Volumes:
I0111 15:17:16.718680    7955 payload.go:80]   4003aa91-0628-451b-8419-077f55d15906 Bootable=true
I0111 15:17:16.718774    7955 overseer.go:508] Overseer: adding 57efb1bc-ccaa-476d-9b18-92e5edc12912
I0111 15:17:16.718777    7955 overseer.go:297] disk Avail 54155 MemAvail 5823
I0111 15:17:16.719008    7955 overseer.go:600] STATS Update for 57efb1bc-ccaa-476d-9b18-92e5edc12912: Mem -1 Disk 0 Cpu -1
I0111 15:17:16.719053    7955 instance.go:110] Found start command
I0111 15:17:16.719161    7955 network.go:213] Creating CNCI Vnic CFG
I0111 15:17:16.722503    7955 network.go:290] CNCI VNIC created = svc_1aa5396a
I0111 15:17:16.834547    7955 qemu.go:203] ISO image /var/lib/ciao/instances/57efb1bc-ccaa-476d-9b18-92e5edc12912/seed.iso created
I0111 15:17:16.835095    7955 qemu.go:508] Launching qemu
I0111 15:17:16.835654    7955 port_grabber.go:62] Ports available 1000
I0111 15:17:16.835658    7955 port_grabber.go:70] Grabbing port: 6755
I0111 15:17:16.835988    7955 qemu.go:994] Adding extra file [0xc42018a300 0xc42018a308 0xc42018a310 0xc42018a318]
I0111 15:17:16.836010    7955 qemu.go:1000] launching qemu with: [-drive file=rbd:rbd/4003aa91-0628-451b-8419-077f55d15906:id=ciao,if=none,id=drive_4003aa91-0628-451b-8419-077f55d15906,format=raw -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x3,id=device_4003aa91-0628-451b-8419-077f55d15906,drive=drive_4003aa91-0628-451b-8419-077f55d15906 -drive file=/var/lib/ciao/instances/57efb1bc-ccaa-476d-9b18-92e5edc12912/seed.iso,if=virtio,media=cdrom -netdev type=tap,fds=3:4:5:6,id=svc_1aa5396a,vhost=on -device virtio-net-pci,netdev=svc_1aa5396a,mq=on,vectors=32,mac=02:dd:22:e2:52:fe -enable-kvm -cpu host -daemonize -qmp unix:/var/lib/ciao/instances/57efb1bc-ccaa-476d-9b18-92e5edc12912/socket,server,nowait -m 128 -smp cpus=4 -bios /usr/share/qemu/OVMF.fd -display none -vga none -device isa-serial,chardev=gnc0 -chardev socket,port=6755,host=198.51.100.1,server,id=gnc0,server,nowait]
I0111 15:17:17.004895    7955 qemu.go:367] ============================================
I0111 15:17:17.004918    7955 qemu.go:368] Connect to vm with netcat 198.51.100.1 6755
I0111 15:17:17.004923    7955 qemu.go:369] ============================================
I0111 15:17:17.004928    7955 qemu.go:561] Launched VM
I0111 15:17:17.005096    7955 overseer.go:567] Overseer: Received Status Command
I0111 15:17:17.005208    7955 overseer.go:339] Memory Available: 5784 Disk space Available 54154
I0111 15:17:17.005707    7955 qmp.go:147] {"QMP": {"version": {"qemu": {"micro": 0, "minor": 5, "major": 2}, "package": " (Debian 1:2.5+dfsg-5ubuntu10.6)"}, "capabilities": []}}
I0111 15:17:17.006255    7955 qemu.go:629] Connected to 57efb1bc-ccaa-476d-9b18-92e5edc12912.
I0111 15:17:17.006259    7955 qemu.go:630] QMP version 2.5.0
I0111 15:17:17.006262    7955 qemu.go:631] QMP capabilities []
I0111 15:17:17.006368    7955 qmp.go:273] {"execute":"qmp_capabilities"}
I0111 15:17:17.006553    7955 qmp.go:147] {"return": {}}
I0111 15:17:17.006581    7955 instance.go:286] ================ START TRACE ============
I0111 15:17:17.006584    7955 instance.go:287] Total time to start instance: 287 ms
I0111 15:17:17.006587    7955 instance.go:288] Launcher routing time: 0 ms
I0111 15:17:17.006589    7955 instance.go:289] Creating time: 285 ms
I0111 15:17:17.006591    7955 instance.go:290] Time to running: 287 ms
I0111 15:17:17.006592    7955 instance.go:291] Running detection time: 1 ms
I0111 15:17:17.006594    7955 instance.go:292] 
I0111 15:17:17.006596    7955 instance.go:293] Detailed creation times
I0111 15:17:17.006597    7955 instance.go:294] -----------------------
I0111 15:17:17.006599    7955 instance.go:295] Backing Image Check: 0
I0111 15:17:17.006601    7955 instance.go:296] Network creation: 3
I0111 15:17:17.006603    7955 instance.go:297] VM/Container creation: 112
I0111 15:17:17.006605    7955 instance.go:298] Time to start: 170
I0111 15:17:17.006607    7955 instance.go:299] =========================================
I0111 15:17:17.025761    7955 qemu.go:741] PID of qemu for instance /var/lib/ciao/instances/57efb1bc-ccaa-476d-9b18-92e5edc12912 is 9629
I0111 15:17:17.025808    7955 overseer.go:589] Overseer: Received State Change {57efb1bc-ccaa-476d-9b18-92e5edc12912 1}
I0111 15:17:17.029883    7955 overseer.go:600] STATS Update for 57efb1bc-ccaa-476d-9b18-92e5edc12912: Mem 49 Disk 0 Cpu -1
I0111 15:17:17.278953    7955 qmp.go:147] {"timestamp": {"seconds": 1484147837, "microseconds": 278842}, "event": "RTC_CHANGE", "data": {"offset": -1}}
I0111 15:17:18.703172    7955 client.go:116] SSNTP Info: Waiting for next frame
I0111 15:17:18.703377    7955 payload.go:56] cloud-init file content
I0111 15:17:18.703380    7955 payload.go:57] -----------------------
I0111 15:17:18.703382    7955 payload.go:58] Instance UUID:        38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b
I0111 15:17:18.703385    7955 payload.go:59] Disk image UUID:      
I0111 15:17:18.703386    7955 payload.go:60] FW Type:              efi
I0111 15:17:18.703389    7955 payload.go:61] VM Type:              qemu
I0111 15:17:18.703391    7955 payload.go:62] TenantUUID:          fc86b4d8cb8b4193b610dd05c8ad8eb1
I0111 15:17:18.703392    7955 payload.go:64] VnicMAC:              02:6e:6d:49:cd:60
I0111 15:17:18.703394    7955 payload.go:65] VnicIP:               
I0111 15:17:18.703396    7955 payload.go:66] ConcIP:               
I0111 15:17:18.703397    7955 payload.go:67] SubnetIP:             
I0111 15:17:18.703399    7955 payload.go:68] ConcUUID:             
I0111 15:17:18.703401    7955 payload.go:69] VnicUUID:             dac8ad91-024a-4e45-b5f5-d67dae982cf4
I0111 15:17:18.703403    7955 payload.go:71] Requested resources:
I0111 15:17:18.703405    7955 payload.go:74]    vcpus:     4
I0111 15:17:18.703409    7955 payload.go:74]   mem_mb:     128
I0111 15:17:18.703411    7955 payload.go:74]  disk_mb:     128
I0111 15:17:18.703413    7955 payload.go:74] network_node:     1
I0111 15:17:18.703415    7955 payload.go:79] Volumes:
I0111 15:17:18.703418    7955 payload.go:80]   5f3c6940-6834-47e8-882b-93fdc47b0e13 Bootable=true
I0111 15:17:18.703442    7955 overseer.go:508] Overseer: adding 38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b
I0111 15:17:18.703446    7955 overseer.go:297] disk Avail 54026 MemAvail 5656
I0111 15:17:18.703470    7955 instance.go:110] Found start command
I0111 15:17:18.703484    7955 network.go:213] Creating CNCI Vnic CFG
I0111 15:17:18.703529    7955 overseer.go:600] STATS Update for 38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b: Mem -1 Disk 0 Cpu -1
I0111 15:17:18.706601    7955 network.go:290] CNCI VNIC created = svc_5b1b6c46
I0111 15:17:18.810256    7955 qemu.go:203] ISO image /var/lib/ciao/instances/38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b/seed.iso created
I0111 15:17:18.810490    7955 qemu.go:508] Launching qemu
I0111 15:17:18.810539    7955 port_grabber.go:62] Ports available 999
I0111 15:17:18.810543    7955 port_grabber.go:70] Grabbing port: 6012
I0111 15:17:18.810565    7955 qemu.go:994] Adding extra file [0xc42018a470 0xc42018a478 0xc42018a480 0xc42018a488]
I0111 15:17:18.810574    7955 qemu.go:1000] launching qemu with: [-drive file=rbd:rbd/5f3c6940-6834-47e8-882b-93fdc47b0e13:id=ciao,if=none,id=drive_5f3c6940-6834-47e8-882b-93fdc47b0e13,format=raw -device virtio-blk-pci,scsi=off,bus=pci.0,addr=0x3,id=device_5f3c6940-6834-47e8-882b-93fdc47b0e13,drive=drive_5f3c6940-6834-47e8-882b-93fdc47b0e13 -drive file=/var/lib/ciao/instances/38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b/seed.iso,if=virtio,media=cdrom -netdev type=tap,fds=3:4:5:6,id=svc_5b1b6c46,vhost=on -device virtio-net-pci,netdev=svc_5b1b6c46,mq=on,vectors=32,mac=02:6e:6d:49:cd:60 -enable-kvm -cpu host -daemonize -qmp unix:/var/lib/ciao/instances/38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b/socket,server,nowait -m 128 -smp cpus=4 -bios /usr/share/qemu/OVMF.fd -display none -vga none -device isa-serial,chardev=gnc0 -chardev socket,port=6012,host=198.51.100.1,server,id=gnc0,server,nowait]
I0111 15:17:18.924646    7955 qemu.go:367] ============================================
I0111 15:17:18.924661    7955 qemu.go:368] Connect to vm with netcat 198.51.100.1 6012
I0111 15:17:18.924665    7955 qemu.go:369] ============================================
I0111 15:17:18.924668    7955 qemu.go:561] Launched VM
I0111 15:17:18.924699    7955 overseer.go:567] Overseer: Received Status Command
I0111 15:17:18.924800    7955 overseer.go:339] Memory Available: 5631 Disk space Available 54026
I0111 15:17:18.925089    7955 qmp.go:147] {"QMP": {"version": {"qemu": {"micro": 0, "minor": 5, "major": 2}, "package": " (Debian 1:2.5+dfsg-5ubuntu10.6)"}, "capabilities": []}}
I0111 15:17:18.925155    7955 qemu.go:629] Connected to 38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b.
I0111 15:17:18.925158    7955 qemu.go:630] QMP version 2.5.0
I0111 15:17:18.925160    7955 qemu.go:631] QMP capabilities []
I0111 15:17:18.925172    7955 qmp.go:273] {"execute":"qmp_capabilities"}
I0111 15:17:18.934840    7955 qmp.go:147] {"return": {}}
I0111 15:17:18.934876    7955 instance.go:286] ================ START TRACE ============
I0111 15:17:18.934878    7955 instance.go:287] Total time to start instance: 231 ms
I0111 15:17:18.934882    7955 instance.go:288] Launcher routing time: 0 ms
I0111 15:17:18.934883    7955 instance.go:289] Creating time: 221 ms
I0111 15:17:18.934885    7955 instance.go:290] Time to running: 231 ms
I0111 15:17:18.934886    7955 instance.go:291] Running detection time: 10 ms
I0111 15:17:18.934888    7955 instance.go:292] 
I0111 15:17:18.934890    7955 instance.go:293] Detailed creation times
I0111 15:17:18.934892    7955 instance.go:294] -----------------------
I0111 15:17:18.934894    7955 instance.go:295] Backing Image Check: 0
I0111 15:17:18.934896    7955 instance.go:296] Network creation: 3
I0111 15:17:18.934898    7955 instance.go:297] VM/Container creation: 103
I0111 15:17:18.934900    7955 instance.go:298] Time to start: 114
I0111 15:17:18.934902    7955 instance.go:299] =========================================
I0111 15:17:18.991288    7955 qemu.go:741] PID of qemu for instance /var/lib/ciao/instances/38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b is 9750
I0111 15:17:18.991398    7955 overseer.go:589] Overseer: Received State Change {38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b 1}
I0111 15:17:18.995560    7955 overseer.go:600] STATS Update for 38fb4527-b3b0-42e0-9e4c-bd1dcbd1e16b: Mem 43 Disk 0 Cpu -1
I0111 15:17:19.238824    7955 qmp.go:147] {"timestamp": {"seconds": 1484147839, "microseconds": 238724}, "event": "RTC_CHANGE", "data": {"offset": -1}}
I0111 15:17:20.538321    7955 overseer.go:339] Memory Available: 5632 Disk space Available 54026
I0111 15:17:20.538737    7955 overseer.go:667] Consumed: Disk 256 Mem 256 CPUs 8
I0111 15:17:20.855445    7955 client.go:116] SSNTP Info: Waiting for next frame
I0111 15:17:20.855674    7955 payload.go:56] cloud-init file content
I0111 15:17:20.855678    7955 payload.go:57] -----------------------
I0111 15:17:20.855680    7955 payload.go:58] Instance UUID:        0a293ace-7703-4081-afb2-9859f28954ae
I0111 15:17:20.855682    7955 payload.go:59] Disk image UUID:      
I0111 15:17:20.855683    7955 payload.go:60] FW Type:              efi
I0111 15:17:20.855686    7955 payload.go:61] VM Type:              qemu
I0111 15:17:20.855688    7955 payload.go:62] TenantUUID:          97c1f5f2eb374d999e702704d1975c8e
I0111 15:17:20.855689    7955 payload.go:64] VnicMAC:              02:dd:22:e2:52:fe
I0111 15:17:20.855691    7955 payload.go:65] VnicIP:               
I0111 15:17:20.855692    7955 payload.go:66] ConcIP:               
I0111 15:17:20.855694    7955 payload.go:67] SubnetIP:             
I0111 15:17:20.855696    7955 payload.go:68] ConcUUID:             
I0111 15:17:20.855698    7955 payload.go:69] VnicUUID:             9909250f-b03a-4877-b705-54cfbef9b546
I0111 15:17:20.855699    7955 payload.go:71] Requested resources:
I0111 15:17:20.855701    7955 payload.go:74]    vcpus:     4
I0111 15:17:20.855705    7955 payload.go:74]   mem_mb:     128
I0111 15:17:20.855708    7955 payload.go:74]  disk_mb:     128
I0111 15:17:20.855710    7955 payload.go:74] network_node:     1
I0111 15:17:20.855712    7955 payload.go:79] Volumes:
I0111 15:17:20.855715    7955 payload.go:80]   10888114-f2e2-4213-aeca-21c7038a27ea Bootable=true
I0111 15:17:20.855737    7955 overseer.go:508] Overseer: adding 0a293ace-7703-4081-afb2-9859f28954ae
I0111 15:17:20.855741    7955 overseer.go:297] disk Avail 53898 MemAvail 5504
I0111 15:17:20.855785    7955 instance.go:110] Found start command
I0111 15:17:20.855811    7955 overseer.go:600] STATS Update for 0a293ace-7703-4081-afb2-9859f28954ae: Mem -1 Disk 0 Cpu -1
I0111 15:17:20.855813    7955 network.go:213] Creating CNCI Vnic CFG
E0111 15:17:20.856164    7955 network.go:286] cn.CreateCnciVnic failed cncivnic error: enable link up device or resource busy
markdryan commented 7 years ago

@jorgevgut Single VM uses keystone now. The webui works for me with single VM as long as I create an instance from the command line first. I think this must be an issue with ciao and not the ciao-webui. It shouldn't be possible to get ciao into a state where it fails, although perhaps the BAT tests are just failing as there are multiple tenants.

markdryan commented 7 years ago

I double-checked this just now. I confirm that if I create an instance via the web-ui (which fails) before creating an instance from the command line the Single VM cluster breaks. Running the BAT tests gives me.

Package     Test Case                        Time Taken Result 
base_bat    TestGetTenants                   0.33s      PASS   
base_bat    TestGetClusterStatus             0.22s      PASS   
base_bat    TestGetWorkloads                 0.21s      PASS   
base_bat    TestGetInstance                  0.86s      FAIL   
base_bat    TestStartAllWorkloads            1.98s      FAIL   
base_bat    TestGetCNCIs                     0.86s      FAIL   
base_bat    TestGetAllInstances              0.61s      FAIL   
base_bat    TestDeleteAllInstances           1.08s      FAIL   
image_bat   TestAddShowDelete                1.81s      PASS   
image_bat   TestDeleteNonExisting            0.26s      PASS   
image_bat   TestImageList                    2.53s      PASS   
storage_bat TestCreateBlockDevice            0.24s      PASS   
storage_bat TestCreateSizedBlockDevice       0.07s      PASS   
storage_bat TestCopyBlockDevice              0.61s      PASS   
storage_bat TestBootFromVolume               0.88s      FAIL   
storage_bat TestStoppedInstance              0.90s      FAIL   
storage_bat TestDeleteInUse                  0.91s      FAIL   
storage_bat TestDetachRootFS                 0.88s      FAIL   
storage_bat TestAddListDelete                5.76s      PASS   
storage_bat TestDeleteInstanceWhileAttaching 0.92s      FAIL   
storage_bat TestDeleteBeforeDetached         0.87s      FAIL   
storage_bat TestAttachDetach                 0.89s      FAIL   
storage_bat TestAttachToRunningContainer     0.83s      FAIL   
storage_bat TestDoubleAttach                 0.93s      FAIL   
storage_bat TestAttachToStoppedInstance      0.86s      FAIL   
storage_bat TestCreateVolumeFromImage        2.62s      PASS   
storage_bat TestCreateVolumeFromVolume       1.80s      PASS   

Logs for failed tests
---------------------
Logs for base_bat.TestGetInstance
    base_bat_test.go:103: Failed to retrieve instance status: failed to launch ciao-cli [instance show -instance 45b44359-7036-4b45-98c6-58aa6bb5bbb2 -f {{.Status}}] : exit status 255
        F0112 15:55:17.146280   23254 instance.go:884] ciao-cli FATAL: HTTP Error [500] for [GET https://singlevm:8774/v2.1/e76180b8cd304feaa439c369eb530ba1/servers/45b44359-7036-4b45-98c6-58aa6bb5bbb2]: {"error":{"code":500,"name":"Internal Server Error","message":"Instance not found"}}
        null
        goroutine 1 [running]:
        github.com/01org/ciao/vendor/github.com/golang/glog.stacks(0x983400, 0xc400000000, 0x11e, 0x29a)
            /home/markus/go-fork/src/github.com/01org/ciao/vendor/github.com/golang/glog/glog.go:769 +0xa5
        github.com/01org/ciao/vendor/github.com/golang/glog.(*loggingT).output(0x967080, 0xc400000003, 0xc420199980, 0x941280, 0xb, 0x374, 0x0)
            /home/markus/go-fork/src/github.com/01org/ciao/vendor/github.com/golang/glog/glog.go:720 +0x357
        github.com/01org/ciao/vendor/github.com/golang/glog.(*loggingT).printDepth(0x967080, 0xc400000003, 0x1, 0xc420143d70, 0x1, 0x1)
            /home/markus/go-fork/src/github.com/01org/ciao/vendor/github.com/golang/glog/glog.go:646 +0x126
        github.com/01org/ciao/vendor/github.com/golang/glog.FatalDepth(0x1, 0xc420143d70, 0x1, 0x1)
            /home/markus/go-fork/src/github.com/01org/ciao/vendor/github.com/golang/glog/glog.go:1134 +0x5d
        main.fatalf(0xc4202547e0, 0xde, 0x0, 0x0, 0x0)
            /home/markus/go-fork/src/github.com/01org/ciao/ciao-cli/main.go:132 +0x126
        main.(*instanceShowCommand).run(0xc420072680, 0xc42000c140, 0x0, 0x0, 0xc42000c140, 0x0)
            /home/markus/go-fork/src/github.com/01org/ciao/ciao-cli/instance.go:884 +0x33b
        main.(*command).run(0x9654e8, 0xc42000c140, 0x0, 0x0, 0xc42009ccd8, 0x0)
            /home/markus/go-fork/src/github.com/01org/ciao/ciao-cli/main.go:58 +0x15b
        main.main()
            /home/markus/go-fork/src/github.com/01org/ciao/ciao-cli/main.go:466 +0xf7
    base_bat_test.go:108: Instance 45b44359-7036-4b45-98c6-58aa6bb5bbb2 did not launch: Instance 45b44359-7036-4b45-98c6-58aa6bb5bbb2 does not exist
Logs for base_bat.TestStartAllWorkloads
    base_bat_test.go:144: Instance 1ef75d66-7c43-487d-b89c-eb2751aa8176 did not launch correctly : Instance 1ef75d66-7c43-487d-b89c-eb2751aa8176 does not exist
    base_bat_test.go:144: Instance 0f89adcd-ec9f-4eb7-b749-eba5e9250505 did not launch correctly : Instance 0f89adcd-ec9f-4eb7-b749-eba5e9250505 does not exist
    base_bat_test.go:144: Instance d56f85ae-f819-4f3f-bc03-2a94998313d7 did not launch correctly : Instance d56f85ae-f819-4f3f-bc03-2a94998313d7 does not exist
    base_bat_test.go:144: Instance 9eb56f7e-76f9-476c-9d93-873b44c607fd did not launch correctly : Instance 9eb56f7e-76f9-476c-9d93-873b44c607fd does not exist
Logs for base_bat.TestGetCNCIs
    base_bat_test.go:189: No CNCIs found
    base_bat_test.go:174: Instance ef5c49da-5b38-4e5f-aa7f-59afcd3ddbe4 did not launch: Instance ef5c49da-5b38-4e5f-aa7f-59afcd3ddbe4 does not exist
Logs for base_bat.TestGetAllInstances
    base_bat_test.go:237: Instance c44c466a-8b4d-41c1-a2ff-edcbceabda99 did not launch: Instance c44c466a-8b4d-41c1-a2ff-edcbceabda99 does not exist
Logs for base_bat.TestDeleteAllInstances
    base_bat_test.go:281: Instance a40bec00-849c-426c-8a3f-b3c71cf16482 did not launch: Instance a40bec00-849c-426c-8a3f-b3c71cf16482 does not exist
Logs for storage_bat.TestBootFromVolume
    storage_bat_test.go:59: Instance a45bf822-5030-4075-ab5e-4fbf47106f3a did not start correctly : Instance a45bf822-5030-4075-ab5e-4fbf47106f3a does not exist
Logs for storage_bat.TestStoppedInstance
    storage_bat_test.go:59: Instance 627ef9f9-24a7-4e4a-821f-9be8c3447daf did not start correctly : Instance 627ef9f9-24a7-4e4a-821f-9be8c3447daf does not exist
Logs for storage_bat.TestDeleteInUse
    storage_bat_test.go:59: Instance a1fc0569-ad74-406c-807a-0a02de529335 did not start correctly : Instance a1fc0569-ad74-406c-807a-0a02de529335 does not exist
Logs for storage_bat.TestDetachRootFS
    storage_bat_test.go:59: Instance 12f39e58-2448-4e49-bf48-60481d160220 did not start correctly : Instance 12f39e58-2448-4e49-bf48-60481d160220 does not exist
Logs for storage_bat.TestDeleteInstanceWhileAttaching
    storage_bat_test.go:59: Instance 3fa2cdfc-470b-4813-8e25-cc99ee3cdece did not start correctly : Instance 3fa2cdfc-470b-4813-8e25-cc99ee3cdece does not exist
Logs for storage_bat.TestDeleteBeforeDetached
    storage_bat_test.go:59: Instance 0a58340d-f38f-4419-b5c2-99a91941de49 did not start correctly : Instance 0a58340d-f38f-4419-b5c2-99a91941de49 does not exist
Logs for storage_bat.TestAttachDetach
    storage_bat_test.go:59: Instance 4176dc9b-f7a2-49d4-be16-9348d606d267 did not start correctly : Instance 4176dc9b-f7a2-49d4-be16-9348d606d267 does not exist
Logs for storage_bat.TestAttachToRunningContainer
    storage_bat_test.go:59: Instance 0be7e1d7-56ed-499b-9c1c-642dbdf69860 did not start correctly : Instance 0be7e1d7-56ed-499b-9c1c-642dbdf69860 does not exist
Logs for storage_bat.TestDoubleAttach
    storage_bat_test.go:59: Instance b8bbcfa5-afae-4b61-a3f2-e0a3cabf5c5a did not start correctly : Instance b8bbcfa5-afae-4b61-a3f2-e0a3cabf5c5a does not exist
Logs for storage_bat.TestAttachToStoppedInstance
    storage_bat_test.go:59: Instance a71c61c0-ba69-4a90-abe8-45bfb4c6f42b did not start correctly : Instance a71c61c0-ba69-4a90-abe8-45bfb4c6f42b does not exist

There must be some issue with ciao here.

markdryan commented 7 years ago

I've been able to reproduce this by just using ciao-cli. I started a new SingleVM cluster using ./setup.sh and then executed the following commands.

$ ciao-cli instance add --workload=ab68111c-03a6-11e6-87de-001320fb6e31 --instances=1 &
[1] 12469
$ ciao-cli volume list
F0123 12:06:57.592963   12608 main.go:468] ciao-cli FATAL: Expected HTTP response code [200 204] when accessing [GET https://singlevm:8776/v2/46c68e3e2674486aa4f9145b5eec3f03/volumes/detail], but got 500 instead
Internal Server Error
null

$ ciao-cli instance list
$ ciao-cli instance add --workload=ab68111c-03a6-11e6-87de-001320fb6e31 --instances=1
Created new (pending) instance: b928dfb8-833c-4db9-a485-63ca145207ac
$ ciao-cli instance list

Note that the first attempt to create an instance is run in parallel with the command to list volumes. It seems that if these two operations happen in parallel before a CNCI is created things go wrong. This simulates what happens when you log into the web-ui. It will send concurrent requests for instances and volumes, which I guess is causing the problems.

markdryan commented 7 years ago

And the problem seems to be that controller.confirmTenant is racy. If I shove a mutex in that function everything works. This is a little inelegant though as it introduces a synchronisation point and bottleneck for all requests. I'll see if I can figure out a more elegant solution.