controller test hang

controller test hang

18:52:21.437 START: controller_test.go:43: S.SetUpSuite
18:52:21.942 START: controller_test.go:306: S.TestAppList
18:52:21.942 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=04a0d1c6-e471-4b7f-9629-939227f4d725 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=04a0d1c6-e471-4b7f-9629-939227f4d725 status=200 duration=2.159147ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=90ee70d8-dc5c-4697-a2fb-63eb7956fe96 method=GET path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=90ee70d8-dc5c-4697-a2fb-63eb7956fe96 status=200 duration=321.65µs
18:52:21.946 START: controller_test.go:326: S.TestAppReleaseList
18:52:21.946 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" req_id=966923df-7cc2-4e35-874c-0f8fc1bdecd9 component=controller method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" req_id=966923df-7cc2-4e35-874c-0f8fc1bdecd9 component=controller status=200 duration=1.451511ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=93743dff-d395-4b0a-b534-8b617fd97e1d method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=93743dff-d395-4b0a-b534-8b617fd97e1d status=200 duration=1.229093ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=8520bade-8946-4df7-bf5c-860e02316f96 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=8520bade-8946-4df7-bf5c-860e02316f96 status=200 duration=1.03217ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=187684a0-5a96-48c5-866a-906bb6ed01eb method=PUT path=/apps/62395243-c968-47f5-9379-26d713fc9f1b/formations/296803a4-a120-45d3-8cd1-c51c7ae49ede client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=187684a0-5a96-48c5-866a-906bb6ed01eb status=200 duration=2.17544ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=a88a1304-13ba-45ab-9c58-7e7634e6a697 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=a88a1304-13ba-45ab-9c58-7e7634e6a697 status=200 duration=735.188µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=2436945d-411f-4f9e-a767-06b19bda23cc method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=2436945d-411f-4f9e-a767-06b19bda23cc status=200 duration=900.295µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=08a2c9a2-c4c2-4604-87d8-6f5f3bafd49a method=PUT path=/apps/62395243-c968-47f5-9379-26d713fc9f1b/formations/2b1e8cf6-736f-43c7-a2e0-a40899df412f client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=08a2c9a2-c4c2-4604-87d8-6f5f3bafd49a status=200 duration=1.200922ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=d38062f2-3d79-4c04-a614-8620c311be33 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=d38062f2-3d79-4c04-a614-8620c311be33 status=200 duration=1.0052ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=5d9fa579-76b7-4063-9247-5d0208de4eda method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=5d9fa579-76b7-4063-9247-5d0208de4eda status=200 duration=736.322µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=dd045e44-cb03-4668-b178-446eed035157 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=dd045e44-cb03-4668-b178-446eed035157 status=200 duration=884.82µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=b5065fc6-c921-4c85-8466-557d31502d4c method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=b5065fc6-c921-4c85-8466-557d31502d4c status=200 duration=695.126µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=f38dfbe1-61fe-4cad-b5d4-78aaae58371c method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=f38dfbe1-61fe-4cad-b5d4-78aaae58371c status=200 duration=825.89µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=85f862e0-e7c7-4e61-b040-91e866d2ec08 method=PUT path=/apps/4834b5a7-989f-4e5e-9fb1-34393d98a583/formations/09fdeac0-dccf-44b3-9997-91c27885c77a client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=85f862e0-e7c7-4e61-b040-91e866d2ec08 status=200 duration=1.265942ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=e6913840-5bcb-46de-8790-a4449e91b671 method=GET path=/apps/62395243-c968-47f5-9379-26d713fc9f1b/releases client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=e6913840-5bcb-46de-8790-a4449e91b671 status=200 duration=515.244µs
18:52:21.964 START: controller_test.go:353: S.TestArtifactList
18:52:21.964 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=2eb8ce19-deca-4609-b2c8-4e7e7c05340b method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=2eb8ce19-deca-4609-b2c8-4e7e7c05340b status=200 duration=765.955µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=cb3108cf-2ab7-4a3e-80ea-04cc42b1924d method=GET path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=cb3108cf-2ab7-4a3e-80ea-04cc42b1924d status=200 duration=240.472µs
18:52:21.965 START: controller_test.go:91: S.TestBadAuth
18:52:21.966 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=95ab7019-b1e9-4dcd-96a4-c6004e6c5bc5 method=GET path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=95ab7019-b1e9-4dcd-96a4-c6004e6c5bc5 status=401 duration=46.476µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=c8435a0a-71d5-4a83-b9d0-6f2477386b45 method=GET path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=c8435a0a-71d5-4a83-b9d0-6f2477386b45 status=401 duration=29.633µs
18:52:21.968 START: controller_test.go:111: S.TestCreateApp
18:52:21.968 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=4f9e3106-e0a0-4f06-8bbc-356de3b9cf75 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=4f9e3106-e0a0-4f06-8bbc-356de3b9cf75 status=200 duration=2.482191ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=8f87852d-1349-4f8f-84ae-d8ce5375cffa method=GET path=/apps/482fcd72-7336-42d0-b1cc-5b0d7703e819 client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=8f87852d-1349-4f8f-84ae-d8ce5375cffa status=200 duration=310.944µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=138c0cd4-8848-40a5-9886-78aa6f8ed1e2 method=GET path=/apps/parrots-scare-newbury client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=138c0cd4-8848-40a5-9886-78aa6f8ed1e2 status=200 duration=510.548µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=73e52990-4b35-48ab-b52f-27d56379ee77 method=GET path=/apps/fail482fcd72-7336-42d0-b1cc-5b0d7703e819 client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=73e52990-4b35-48ab-b52f-27d56379ee77 status=400 duration=286.05µs

----------------------------------------------------------------------
18:52:21.975 FAIL: controller_test.go:111: S.TestCreateApp

controller_test.go:130:
    c.Assert(err, Equals, controller.ErrNotFound)
... obtained httphelper.JSONError = httphelper.JSONError{Code:"syntax_error", Message:"The provided JSON input is invalid", Detail:json.RawMessage(nil), Retry:false} ("syntax_error: The provided JSON input is invalid")
... expected *errors.errorString = &errors.errorString{s:"controller: resource not found"} ("controller: resource not found")

18:52:21.975 START: controller_test.go:196: S.TestCreateArtifact
18:52:21.975 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=032eb83f-366a-4e73-bf3d-0d29613e4a9d method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=032eb83f-366a-4e73-bf3d-0d29613e4a9d status=200 duration=1.633244ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=c0c9da86-5e9a-4e51-b460-1cc7d3501259 method=GET path=/artifacts/b5c57a20-e325-4b28-add7-dfc634f5a322 client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=c0c9da86-5e9a-4e51-b460-1cc7d3501259 status=200 duration=298.809µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=ef3ce949-14ae-4128-a7d9-f5bb80cc65ed method=GET path=/artifacts/failb5c57a20-e325-4b28-add7-dfc634f5a322 client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=ef3ce949-14ae-4128-a7d9-f5bb80cc65ed status=404 duration=117.936µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=c602a7a9-3f37-4690-b5c6-95c7deae0e26 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=c602a7a9-3f37-4690-b5c6-95c7deae0e26 status=200 duration=2.153156ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" req_id=3a4e6466-f20d-479d-a020-f28adf0e9ffb component=controller method=GET path=/artifacts/91a41730-229a-4731-bcdc-f37aa75aef93 client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" req_id=3a4e6466-f20d-479d-a020-f28adf0e9ffb component=controller status=200 duration=266.857µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=ef6325a8-b186-4e9a-b09b-99dd48e6782f method=GET path=/artifacts/fail91a41730-229a-4731-bcdc-f37aa75aef93 client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=ef6325a8-b186-4e9a-b09b-99dd48e6782f status=404 duration=310.14µs
18:52:21.981 START: deployment_test.go:13: S.TestCreateDeployment
18:52:21.981 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=a27b01fd-db5e-479d-ae6a-35356b09a289 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=a27b01fd-db5e-479d-ae6a-35356b09a289 status=200 duration=1.190111ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=716e9f3f-d0a0-4055-ba15-669fda80a9ea method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=716e9f3f-d0a0-4055-ba15-669fda80a9ea status=200 duration=1.208271ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=7c79bf12-53d1-4210-a21e-5a5d7a460462 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=7c79bf12-53d1-4210-a21e-5a5d7a460462 status=200 duration=1.720482ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=9a152a86-0bf0-420e-a0f6-59932787fd2d method=PUT path=/apps/ed0ca453-f21e-406a-9391-d3f721c73c18/formations/afa3e88b-6af1-4115-b59c-c33392745c5b client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=9a152a86-0bf0-420e-a0f6-59932787fd2d status=200 duration=1.558043ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=bb5c3e6e-c02e-4fae-ae2c-332db336294c method=POST path=/apps/ed0ca453-f21e-406a-9391-d3f721c73c18/deploy client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=bb5c3e6e-c02e-4fae-ae2c-332db336294c status=200 duration=4.211979ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=0b3fd6f6-156f-4f80-b958-cebe645bcd29 method=GET path=/apps/ed0ca453-f21e-406a-9391-d3f721c73c18/release client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=0b3fd6f6-156f-4f80-b958-cebe645bcd29 status=200 duration=569.617µs
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=5fbc525c-6ea2-4fc2-88e6-ef2892735a8b method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=5fbc525c-6ea2-4fc2-88e6-ef2892735a8b status=200 duration=1.073426ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=f6a28322-170a-4250-b920-8aa73b380ccd method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=f6a28322-170a-4250-b920-8aa73b380ccd status=200 duration=1.16342ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=ecd36836-6450-4a9a-8f41-e01f46f17f7e method=POST path=/apps/ed0ca453-f21e-406a-9391-d3f721c73c18/deploy client_ip=127.0.0.1
t=2015-09-05T18:52:21+0000 lvl=info msg="request completed" component=controller req_id=ecd36836-6450-4a9a-8f41-e01f46f17f7e status=200 duration=3.072321ms
t=2015-09-05T18:52:21+0000 lvl=info msg="request started" component=controller req_id=ae6749ac-1761-4d6e-9dec-1faa767b73de method=POST path=/apps/ed0ca453-f21e-406a-9391-d3f721c73c18/deploy client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=ae6749ac-1761-4d6e-9dec-1faa767b73de status=400 duration=1.209086ms
18:52:22.002 START: controller_test.go:245: S.TestCreateFormation
18:52:22.002 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=78b2649c-160a-4ffb-ad89-988e91ad9fa0 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=78b2649c-160a-4ffb-ad89-988e91ad9fa0 status=200 duration=859.743µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=1293adc7-f9be-4e9b-a887-e8ad76f5c014 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=1293adc7-f9be-4e9b-a887-e8ad76f5c014 status=200 duration=1.054868ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=174e0cd9-041b-4566-9d56-8e44a4ad18bc method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=174e0cd9-041b-4566-9d56-8e44a4ad18bc status=200 duration=1.081345ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" req_id=58e63912-64f2-4f15-8f2e-e2e0cbf2fd9a component=controller method=PUT path=/apps/85dd4aae-394b-49db-9c2c-73c2fe3f0c0b/formations/c12d3331-5747-42dc-b712-b349e2e6633a client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" req_id=58e63912-64f2-4f15-8f2e-e2e0cbf2fd9a component=controller status=400 duration=518.86µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=4a9898f8-1374-4a8a-a220-0b3efdf0fa51 method=PUT path=/apps/85dd4aae-394b-49db-9c2c-73c2fe3f0c0b/formations/c12d3331-5747-42dc-b712-b349e2e6633a client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=4a9898f8-1374-4a8a-a220-0b3efdf0fa51 status=200 duration=2.43705ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=7d701a1e-42e2-4075-9948-7121009c0abe method=GET path=/apps/85dd4aae-394b-49db-9c2c-73c2fe3f0c0b/formations/c12d3331-5747-42dc-b712-b349e2e6633a client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=7d701a1e-42e2-4075-9948-7121009c0abe status=200 duration=422.532µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=93a4059d-ee2b-4345-abfa-3a3516e855ac method=GET path=/apps/85dd4aae-394b-49db-9c2c-73c2fe3f0c0b/formations/c12d3331-5747-42dc-b712-b349e2e6633afail client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=93a4059d-ee2b-4345-abfa-3a3516e855ac status=404 duration=328.766µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=f0e078e7-d84c-4d6e-b32f-2c029e30cf6a method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=f0e078e7-d84c-4d6e-b32f-2c029e30cf6a status=200 duration=971.178µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=b6f2bef3-52bb-4b66-892f-c3b5b148ace1 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=b6f2bef3-52bb-4b66-892f-c3b5b148ace1 status=200 duration=1.060568ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=480881fe-4f74-4ce0-89ef-f481c4094759 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=480881fe-4f74-4ce0-89ef-f481c4094759 status=200 duration=1.086966ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=4bea4b26-2e36-45ca-8d2d-7069769a6fde method=PUT path=/apps/create-formation-1/formations/26a394b2-710a-4055-ae1e-12e9109fce73 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=4bea4b26-2e36-45ca-8d2d-7069769a6fde status=400 duration=644.16µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=8159ed84-fa02-44fb-a075-61d186322905 method=PUT path=/apps/create-formation-1/formations/26a394b2-710a-4055-ae1e-12e9109fce73 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=8159ed84-fa02-44fb-a075-61d186322905 status=200 duration=1.370045ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=3d46e806-d0bc-4468-844b-1c15c3838257 method=GET path=/apps/create-formation-1/formations/26a394b2-710a-4055-ae1e-12e9109fce73 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=3d46e806-d0bc-4468-844b-1c15c3838257 status=200 duration=456.832µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=6724dedf-6093-4418-b79e-f04276dc3560 method=GET path=/apps/create-formation-1/formations/26a394b2-710a-4055-ae1e-12e9109fce73fail client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=6724dedf-6093-4418-b79e-f04276dc3560 status=404 duration=349.981µs
18:52:22.017 START: controller_test.go:411: S.TestCreateProvider
18:52:22.017 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=57c957b0-1aad-41c3-a7f2-84f86a3a8e33 method=POST path=/providers client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=57c957b0-1aad-41c3-a7f2-84f86a3a8e33 status=200 duration=1.310671ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" req_id=07621864-aba5-48dd-9639-9819af08fb27 component=controller method=GET path=/providers/3c154042-e57c-4233-9453-a22b259b5f86 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" req_id=07621864-aba5-48dd-9639-9819af08fb27 component=controller status=200 duration=479.394µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=ca6af941-327f-4fda-a5c1-73d5710669f0 method=GET path=/providers/foo client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=ca6af941-327f-4fda-a5c1-73d5710669f0 status=200 duration=346.39µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=aded4c26-4f64-448e-a882-4e3e68cf9af6 method=GET path=/providers/fail3c154042-e57c-4233-9453-a22b259b5f86 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=aded4c26-4f64-448e-a882-4e3e68cf9af6 status=404 duration=200.844µs
18:52:22.020 START: controller_test.go:229: S.TestCreateRelease
18:52:22.020 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=992efae3-8efa-41bd-830f-d6ffd7bd453e method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=992efae3-8efa-41bd-830f-d6ffd7bd453e status=200 duration=1.06777ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=79f7ea19-bd1f-415a-aefe-5d353fbae044 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=79f7ea19-bd1f-415a-aefe-5d353fbae044 status=200 duration=871.858µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=667576b9-b5bb-4f00-b6b3-744a79958848 method=GET path=/releases/e05243a4-1aa3-4a7e-8c4b-be5640606253 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=667576b9-b5bb-4f00-b6b3-744a79958848 status=200 duration=208.929µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=a5656a46-6110-466a-9a78-eb97dcdf4e46 method=GET path=/releases/faile05243a4-1aa3-4a7e-8c4b-be5640606253 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=a5656a46-6110-466a-9a78-eb97dcdf4e46 status=404 duration=196.79µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" req_id=a8dcab51-6a7e-4b21-b872-acd24ccc1824 component=controller method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" req_id=a8dcab51-6a7e-4b21-b872-acd24ccc1824 component=controller status=200 duration=1.009868ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=71b88461-9ca0-472a-9c90-d353dcc71ff6 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=71b88461-9ca0-472a-9c90-d353dcc71ff6 status=200 duration=1.060194ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" req_id=a3b5fb2e-064a-484d-9007-477ada98964c component=controller method=GET path=/releases/ecdc62cc-cb98-49a8-84a6-88a6c9c3c986 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" req_id=a3b5fb2e-064a-484d-9007-477ada98964c component=controller status=200 duration=211.968µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=23471b36-e5a3-4f9a-9082-1924290c040f method=GET path=/releases/failecdc62cc-cb98-49a8-84a6-88a6c9c3c986 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=23471b36-e5a3-4f9a-9082-1924290c040f status=404 duration=163.43µs
18:52:22.026 START: routes_test.go:97: S.TestCreateRoute
18:52:22.026 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=4df78a55-2eee-447b-9630-992a26dd0aac method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=4df78a55-2eee-447b-9630-992a26dd0aac status=200 duration=1.04184ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=6eefb780-ae4c-4e2a-9cf0-53685d3d0802 method=POST path=/apps/030f81ee-7fdf-46b7-bd0f-cb25388ac731/routes client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=6eefb780-ae4c-4e2a-9cf0-53685d3d0802 status=200 duration=344.374µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=dca39299-3714-41d4-a3ce-0f48e95389fa method=GET path=/apps/030f81ee-7fdf-46b7-bd0f-cb25388ac731/routes/tcp/1fb5b5d9-5ed8-4718-9b97-f65cc0b87de6 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=dca39299-3714-41d4-a3ce-0f48e95389fa status=200 duration=390.411µs
18:52:22.029 START: controller_test.go:287: S.TestDeleteFormation
18:52:22.029 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=3b5e1694-1dc1-4623-ae5d-05bebefcb222 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=3b5e1694-1dc1-4623-ae5d-05bebefcb222 status=200 duration=929.066µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=382c6157-5cf1-480e-b271-6a86cb6047b6 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=382c6157-5cf1-480e-b271-6a86cb6047b6 status=200 duration=917.944µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=c5762338-864b-4e3b-a3cb-e3a87ca91e98 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=c5762338-864b-4e3b-a3cb-e3a87ca91e98 status=200 duration=1.049288ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=b8237b42-4c4f-47e0-9e01-1699fc8a080b method=PUT path=/apps/7bd03c18-8d77-4c5a-b278-8a45e8ed463e/formations/7b0c8641-ff88-4269-a32e-949486bb409d client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=b8237b42-4c4f-47e0-9e01-1699fc8a080b status=200 duration=1.646332ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" req_id=adbe9f64-ad92-4206-8b52-33dab647ddd0 component=controller method=DELETE path=/apps/7bd03c18-8d77-4c5a-b278-8a45e8ed463e/formations/7b0c8641-ff88-4269-a32e-949486bb409d client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" req_id=adbe9f64-ad92-4206-8b52-33dab647ddd0 component=controller status=200 duration=1.909414ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=d29a4633-b3ca-422c-9424-a77a64e98868 method=GET path=/apps/7bd03c18-8d77-4c5a-b278-8a45e8ed463e/formations/7b0c8641-ff88-4269-a32e-949486bb409d client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=d29a4633-b3ca-422c-9424-a77a64e98868 status=404 duration=380.08µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=0ade5ad8-7173-467c-90a1-d225cb0971e9 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=0ade5ad8-7173-467c-90a1-d225cb0971e9 status=200 duration=956.147µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=4ea2749e-f863-4878-82a2-0ecd188ec7ea method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=4ea2749e-f863-4878-82a2-0ecd188ec7ea status=200 duration=1.025192ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=49ebf0f5-5d59-495d-936d-817d5b9730d5 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=49ebf0f5-5d59-495d-936d-817d5b9730d5 status=200 duration=1.074658ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=e7555e76-6332-4d7e-96e6-71d11782fb81 method=PUT path=/apps/a22fdd77-9866-466b-bc37-74b017664940/formations/3ac59979-364f-433c-b063-bfb963350530 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=e7555e76-6332-4d7e-96e6-71d11782fb81 status=200 duration=1.427313ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" req_id=a00f4b9d-c5d1-4379-8c20-09405b1cf87b component=controller method=DELETE path=/apps/delete-formation-1/formations/3ac59979-364f-433c-b063-bfb963350530 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" req_id=a00f4b9d-c5d1-4379-8c20-09405b1cf87b component=controller status=200 duration=1.493753ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=1cab0f6e-2ff1-455e-86b2-1ad49804ffeb method=GET path=/apps/delete-formation-1/formations/3ac59979-364f-433c-b063-bfb963350530 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=1cab0f6e-2ff1-455e-86b2-1ad49804ffeb status=404 duration=271.301µs
18:52:22.045 START: routes_test.go:107: S.TestDeleteRoute
18:52:22.045 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=8aee8005-e6c5-4375-801a-f5d3ca3bc643 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=8aee8005-e6c5-4375-801a-f5d3ca3bc643 status=200 duration=807.508µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=cec4bb46-f50c-42ae-b6cb-c2515d627385 method=POST path=/apps/fd550641-fd0f-4ba9-86ac-d4f4acf255b9/routes client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=cec4bb46-f50c-42ae-b6cb-c2515d627385 status=200 duration=438.152µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=2d59dcec-a767-4cfa-bd8b-2d2746633e8d method=DELETE path=/apps/fd550641-fd0f-4ba9-86ac-d4f4acf255b9/routes/tcp/41796e6c-83e7-40be-a18e-b8fc516b8809 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=2d59dcec-a767-4cfa-bd8b-2d2746633e8d status=200 duration=197.559µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=dd81135c-f440-4bf7-9e56-6ec1102393b2 method=GET path=/apps/fd550641-fd0f-4ba9-86ac-d4f4acf255b9/routes/tcp/41796e6c-83e7-40be-a18e-b8fc516b8809 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=dd81135c-f440-4bf7-9e56-6ec1102393b2 status=404 duration=205.628µs
18:52:22.048 START: deployment_test.go:126: S.TestDeploymentList
18:52:22.048 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=d92fb45e-c398-4b07-80e2-934ede870766 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=d92fb45e-c398-4b07-80e2-934ede870766 status=200 duration=1.403787ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=233f6a42-7d9f-4e1e-bc2a-531937c220c7 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=233f6a42-7d9f-4e1e-bc2a-531937c220c7 status=200 duration=1.08716ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=e24e3e1c-d0e2-43ec-a7ba-01fa1cd2b43a method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=e24e3e1c-d0e2-43ec-a7ba-01fa1cd2b43a status=200 duration=1.00506ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=dfdea84b-57db-4a75-a820-79d37d69f281 method=PUT path=/apps/809e9856-ee07-44de-a76a-de031fd340bf/formations/e13e843d-536e-46fc-b0b5-3dbb068f415f client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=dfdea84b-57db-4a75-a820-79d37d69f281 status=200 duration=1.689396ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=bc0083d7-85ce-4cf0-9da5-51e2d6652e83 method=POST path=/apps/809e9856-ee07-44de-a76a-de031fd340bf/deploy client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=bc0083d7-85ce-4cf0-9da5-51e2d6652e83 status=200 duration=3.09916ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=72179560-cbc7-4762-9f05-b909018cef74 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=72179560-cbc7-4762-9f05-b909018cef74 status=200 duration=1.01972ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=a6397149-a8c5-4626-8bfc-5f39c1ef6371 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=a6397149-a8c5-4626-8bfc-5f39c1ef6371 status=200 duration=1.80387ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=f9c3583b-8ce1-45da-9453-7513d5375a18 method=POST path=/apps/809e9856-ee07-44de-a76a-de031fd340bf/deploy client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=f9c3583b-8ce1-45da-9453-7513d5375a18 status=200 duration=2.600634ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=80ddeb22-bbc2-407c-a40d-8ada19d0a575 method=GET path=/apps/809e9856-ee07-44de-a76a-de031fd340bf/deployments client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=80ddeb22-bbc2-407c-a40d-8ada19d0a575 status=200 duration=1.023244ms
18:52:22.064 START: events_test.go:13: S.TestEvents
18:52:22.064 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=01d515fe-9256-46bf-b911-02a959673c99 method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=01d515fe-9256-46bf-b911-02a959673c99 status=200 duration=1.141157ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=df1ba3c0-84ea-4783-bb4d-6581c454ac1b method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=df1ba3c0-84ea-4783-bb4d-6581c454ac1b status=200 duration=918.348µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=7dad7971-3c24-41b5-bda4-ea64c1c1c793 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=7dad7971-3c24-41b5-bda4-ea64c1c1c793 status=200 duration=998.421µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=fad4b936-d7cf-4878-ab8a-c8e7e43a9465 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=fad4b936-d7cf-4878-ab8a-c8e7e43a9465 status=200 duration=1.121724ms
t=2015-09-05T18:52:22+0000 lvl=info msg="pq listener connected" component=controller fn=EventListener.Listen
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=cab24123-d8ad-4124-92dd-793b1fa0bcbd method=PUT path=/apps/b9886539-6841-4e03-81c4-05a783b5ad88/jobs/host-job1 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=cab24123-d8ad-4124-92dd-793b1fa0bcbd status=200 duration=2.076033ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=c790ca91-90e5-4e76-b170-2c7c48bfebaf method=PUT path=/apps/b9886539-6841-4e03-81c4-05a783b5ad88/jobs/host-job1 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=c790ca91-90e5-4e76-b170-2c7c48bfebaf status=200 duration=2.623919ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=3e733b50-a1b1-4c77-84f0-9f495e76a45f method=PUT path=/apps/b9886539-6841-4e03-81c4-05a783b5ad88/jobs/host-job2 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=3e733b50-a1b1-4c77-84f0-9f495e76a45f status=200 duration=2.092045ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=64752830-f1ff-40eb-8378-60c9abbf21b2 method=PUT path=/apps/b9886539-6841-4e03-81c4-05a783b5ad88/jobs/host-job2 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=64752830-f1ff-40eb-8378-60c9abbf21b2 status=200 duration=1.826155ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=bfebd21f-82f4-4c36-987f-2977f2f4278a method=PUT path=/apps/01854caa-8bb1-4eae-b94d-24e228ce11e0/jobs/host-job3 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=bfebd21f-82f4-4c36-987f-2977f2f4278a status=200 duration=1.09217ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=3e39a466-3877-4096-9be2-a5e2b1d9a268 method=PUT path=/apps/01854caa-8bb1-4eae-b94d-24e228ce11e0/jobs/host-job3 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=3e39a466-3877-4096-9be2-a5e2b1d9a268 status=200 duration=1.401083ms
18:52:22.085 START: controller_test.go:363: S.TestFormationList
18:52:22.085 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=d90d792b-6bf5-4355-911d-06bfe965e131 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=d90d792b-6bf5-4355-911d-06bfe965e131 status=200 duration=1.218713ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=af3c52ad-f8b9-4ef6-9813-95946c0ad7ea method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=af3c52ad-f8b9-4ef6-9813-95946c0ad7ea status=200 duration=1.337678ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" req_id=73e4b11d-2917-4ce4-a720-0a5c704c02a0 component=controller method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" req_id=73e4b11d-2917-4ce4-a720-0a5c704c02a0 component=controller status=200 duration=1.528516ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=78ed72e9-ee68-48b6-9fb0-5440eed62633 method=PUT path=/apps/66ac40f5-4078-4b08-83a4-6089ba7c418b/formations/77a8d606-f74c-416f-91f8-8e7811b0cf45 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=78ed72e9-ee68-48b6-9fb0-5440eed62633 status=200 duration=3.533532ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=c5992251-2223-414a-a289-2e7028f3c529 method=GET path=/apps/66ac40f5-4078-4b08-83a4-6089ba7c418b/formations client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=c5992251-2223-414a-a289-2e7028f3c529 status=200 duration=957.026µs
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=1d3a5a87-d902-40f8-a12b-e74c3356ab28 method=DELETE path=/apps/66ac40f5-4078-4b08-83a4-6089ba7c418b/formations/77a8d606-f74c-416f-91f8-8e7811b0cf45 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=1d3a5a87-d902-40f8-a12b-e74c3356ab28 status=200 duration=1.4688ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=0b74848e-6b32-4473-b648-05590b0a3db6 method=GET path=/apps/66ac40f5-4078-4b08-83a4-6089ba7c418b/formations client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=0b74848e-6b32-4473-b648-05590b0a3db6 status=200 duration=703.706µs
18:52:22.098 START: formation_test.go:10: S.TestFormationStreaming
18:52:22.098 START: controller_test.go:87: S.SetUpTest
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=73d5b47e-2eba-4ce2-ac77-7e59b5a4edc7 method=POST path=/artifacts client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=73d5b47e-2eba-4ce2-ac77-7e59b5a4edc7 status=200 duration=1.231476ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=ad838d5d-cbae-443f-9856-4eba3a7685f1 method=POST path=/releases client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=ad838d5d-cbae-443f-9856-4eba3a7685f1 status=200 duration=1.358428ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=7e095116-dc43-4599-ae9d-4bdf1e6b921a method=POST path=/apps client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=7e095116-dc43-4599-ae9d-4bdf1e6b921a status=200 duration=1.277105ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=857271f1-bdc9-45e8-a720-42d42e7e0e8e method=PUT path=/apps/055b095d-5fba-4c55-901d-38b717585aa0/formations/ce5ed5d0-3d01-4351-9d79-3c4f88523580 client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="request completed" component=controller req_id=857271f1-bdc9-45e8-a720-42d42e7e0e8e status=200 duration=1.692645ms
t=2015-09-05T18:52:22+0000 lvl=info msg="request started" component=controller req_id=da4c25d1-0aa0-4692-ba70-78e62c30e083 method=GET path=/formations client_ip=127.0.0.1
t=2015-09-05T18:52:22+0000 lvl=info msg="pq listener connected" component=controller fn=FormationRepo.startListener
SIGQUIT: quit
PC=0x43f483

goroutine 16 [syscall]:
runtime.notetsleepg(0xc00f98, 0x6fc238d3a, 0x16)
	/usr/local/go/src/runtime/lock_futex.go:201 +0x52 fp=0xc208016768 sp=0xc208016740
runtime.timerproc()
	/usr/local/go/src/runtime/time.go:207 +0xfa fp=0xc2080167e0 sp=0xc208016768
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:2232 +0x1 fp=0xc2080167e8 sp=0xc2080167e0
created by runtime.addtimerLocked
	/usr/local/go/src/runtime/time.go:113 +0x1ba

goroutine 1 [chan receive]:
testing.RunTests(0xa6a5e8, 0xbf4780, 0x1, 0x1, 0x1)
	/usr/local/go/src/testing/testing.go:556 +0xad6
testing.(*M).Run(0xc20802e640, 0xc08fe0)
	/usr/local/go/src/testing/testing.go:485 +0x6c
main.main()
	github.com/flynn/flynn/controller/_test/_testmain.go:52 +0x1d5

goroutine 5 [syscall]:
os/signal.loop()
	/usr/local/go/src/os/signal/signal_unix.go:21 +0x1f
created by os/signal.init·1
	/usr/local/go/src/os/signal/signal_unix.go:27 +0x35

goroutine 6 [chan receive]:
github.com/flynn/flynn/pkg/shutdown.(*handler).wait(0xc20803b350)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/shutdown/handler.go:58 +0x158
created by github.com/flynn/flynn/pkg/shutdown.newHandler
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/shutdown/handler.go:25 +0xa8

goroutine 7 [chan receive]:
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.(*suiteRunner).runTest(0xc20807e480, 0xc208077420, 0xc208174b40)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/check.go:847 +0x5e
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.(*suiteRunner).run(0xc20807e480, 0xc208088580)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/check.go:651 +0x4a0
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.Run(0x94bbc0, 0xc208088580, 0xc20802e6e0, 0xc20807c2a0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/run.go:131 +0x58
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.RunAll(0xc20802e6e0, 0x0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/run.go:123 +0x5fe
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.TestingT(0xc20807e360)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/run.go:85 +0x20c
github.com/flynn/flynn/controller.Test(0xc20807e360)
	/home/vagrant/go/src/github.com/flynn/flynn/controller/controller_test.go:29 +0x28
testing.tRunner(0xc20807e360, 0xbf4780)
	/usr/local/go/src/testing/testing.go:447 +0xbf
created by testing.RunTests
	/usr/local/go/src/testing/testing.go:555 +0xa8b

goroutine 8 [select]:
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.(*resultTracker)._loopRoutine(0xc20807e3f0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/check.go:452 +0x395
created by github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.(*resultTracker).start
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/check.go:432 +0x32

goroutine 68 [chan receive]:
github.com/flynn/flynn/pkg/postgres.(*Listener).listen(0xc2082a7560)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/postgres/listener.go:73 +0x5c
created by github.com/flynn/flynn/pkg/postgres.(*DB).Listen
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/postgres/listener.go:23 +0x292

goroutine 12 [IO wait]:
net.(*pollDesc).Wait(0xc2081c6450, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2081c6450, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).accept(0xc2081c63f0, 0x0, 0x7fbd4047ee08, 0xc2081327d0)
	/usr/local/go/src/net/fd_unix.go:419 +0x40b
net.(*TCPListener).AcceptTCP(0xc208135688, 0x7fbd40488230, 0x0, 0x0)
	/usr/local/go/src/net/tcpsock_posix.go:234 +0x4e
net.(*TCPListener).Accept(0xc208135688, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/tcpsock_posix.go:244 +0x4c
net/http/httptest.(*historyListener).Accept(0xc2081140c0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/httptest/server.go:48 +0x7a
net/http.(*Server).Serve(0xc208053260, 0x7fbd40487fe0, 0xc2081140c0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:1728 +0x92
created by net/http/httptest.(*Server).Start
	/usr/local/go/src/net/http/httptest/server.go:109 +0x35e

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:2232 +0x1

goroutine 11 [chan receive]:
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-sql.(*DB).connectionOpener(0xc208040c80)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-sql/sql.go:613 +0x4c
created by github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-sql.Open
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-sql/sql.go:454 +0x31c

goroutine 20 [chan receive]:
github.com/flynn/flynn/pkg/sse.ServeStream(0x7fbd404884b8, 0xc2081c3bc0, 0x7da520, 0xc2082a73e0, 0x7fbd4047f6c8, 0xc208255c60)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/sse/stream.go:46 +0x94
github.com/flynn/flynn/controller.(*controllerAPI).GetFormations(0xc208242000, 0x7fbd40488478, 0xc2081c3d10, 0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0)
	/home/vagrant/go/src/github.com/flynn/flynn/controller/formation.go:396 +0x2a0
github.com/flynn/flynn/controller.*controllerAPI.GetFormations·fm(0x7fbd40488478, 0xc2081c3d10, 0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0)
	/home/vagrant/go/src/github.com/flynn/flynn/controller/controller.go:268 +0x59
github.com/flynn/flynn/pkg/httphelper.HandlerFunc.ServeHTTP(0xc2081fd8a0, 0x7fbd40488478, 0xc2081c3d10, 0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/httphelper/httphelper.go:103 +0x55
github.com/flynn/flynn/pkg/httphelper.func·002(0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0, 0x0, 0x0, 0x0)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/httphelper/httphelper.go:110 +0xcb
github.com/flynn/flynn/Godeps/_workspace/src/github.com/julienschmidt/httprouter.(*Router).ServeHTTP(0xc2081b3f60, 0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/julienschmidt/httprouter/router.go:276 +0x188
github.com/flynn/flynn/controller.func·009(0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0)
	/home/vagrant/go/src/github.com/flynn/flynn/controller/controller.go:326 +0x44b
net/http.HandlerFunc.ServeHTTP(0xc2080d4740, 0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0)
	/usr/local/go/src/net/http/server.go:1265 +0x41
github.com/flynn/flynn/pkg/httphelper.func·004(0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/httphelper/request_logger.go:34 +0x8a0
net/http.HandlerFunc.ServeHTTP(0xc2081fdcd0, 0x7fbd404884b8, 0xc2081c3bc0, 0xc2081ba1a0)
	/usr/local/go/src/net/http/server.go:1265 +0x41
github.com/flynn/flynn/pkg/httphelper.func·003(0x7fbd40488400, 0xc2082a8a00, 0xc2081ba1a0)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/httphelper/httphelper.go:123 +0x25c
net/http.HandlerFunc.ServeHTTP(0xc2080d4760, 0x7fbd40488400, 0xc2082a8a00, 0xc2081ba1a0)
	/usr/local/go/src/net/http/server.go:1265 +0x41
net/http/httptest.(*waitGroupHandler).ServeHTTP(0xc2080d47e0, 0x7fbd40488400, 0xc2082a8a00, 0xc2081ba1a0)
	/usr/local/go/src/net/http/httptest/server.go:200 +0xb7
net/http.serverHandler.ServeHTTP(0xc208053260, 0x7fbd40488400, 0xc2082a8a00, 0xc2081ba1a0)
	/usr/local/go/src/net/http/server.go:1703 +0x19a
net/http.(*conn).serve(0xc208168be0)
	/usr/local/go/src/net/http/server.go:1204 +0xb57
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:1751 +0x35e

goroutine 18 [select]:
net/http.(*persistConn).readLoop(0xc208242210)
	/usr/local/go/src/net/http/transport.go:928 +0x9ce
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:660 +0xc9f

goroutine 19 [select]:
net/http.(*persistConn).writeLoop(0xc208242210)
	/usr/local/go/src/net/http/transport.go:945 +0x41d
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:661 +0xcbc

goroutine 30 [IO wait]:
net.(*pollDesc).Wait(0xc2081d1e20, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2081d1e20, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).Read(0xc2081d1dc0, 0xc208184000, 0x1000, 0x1000, 0x0, 0x7fbd4047ee08, 0xc2081333c0)
	/usr/local/go/src/net/fd_unix.go:242 +0x40f
net.(*conn).Read(0xc2081358a8, 0xc208184000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:121 +0xdc
net/http.(*liveSwitchReader).Read(0xc2081e0368, 0xc208184000, 0x1000, 0x1000, 0x2, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:214 +0xab
io.(*LimitedReader).Read(0xc20812b1a0, 0xc208184000, 0x1000, 0x1000, 0x2, 0x0, 0x0)
	/usr/local/go/src/io/io.go:408 +0xce
bufio.(*Reader).fill(0xc208138780)
	/usr/local/go/src/bufio/bufio.go:97 +0x1ce
bufio.(*Reader).ReadSlice(0xc208138780, 0xc2082bbb0a, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/bufio/bufio.go:295 +0x257
bufio.(*Reader).ReadLine(0xc208138780, 0x0, 0x0, 0x0, 0xc208245300, 0x0, 0x0)
	/usr/local/go/src/bufio/bufio.go:324 +0x62
net/textproto.(*Reader).readLineSlice(0xc208244d50, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/textproto/reader.go:55 +0x9e
net/textproto.(*Reader).ReadLine(0xc208244d50, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/textproto/reader.go:36 +0x4f
net/http.ReadRequest(0xc208138780, 0xc2081655f0, 0x0, 0x0)
	/usr/local/go/src/net/http/request.go:598 +0xcb
net/http.(*conn).readRequest(0xc2081e0320, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/server.go:586 +0x26f
net/http.(*conn).serve(0xc2081e0320)
	/usr/local/go/src/net/http/server.go:1162 +0x69e
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:1751 +0x35e

goroutine 28 [IO wait]:
net.(*pollDesc).Wait(0xc2081d1d40, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2081d1d40, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).Read(0xc2081d1ce0, 0xc20808e000, 0x1000, 0x1000, 0x0, 0x7fbd4047ee08, 0xc2081333e8)
	/usr/local/go/src/net/fd_unix.go:242 +0x40f
net.(*conn).Read(0xc208135898, 0xc20808e000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:121 +0xdc
net/http.noteEOFReader.Read(0x7fbd40488190, 0xc208135898, 0xc2081b4738, 0xc20808e000, 0x1000, 0x1000, 0xc20810bbc0, 0x0, 0x0)
	/usr/local/go/src/net/http/transport.go:1270 +0x6e
net/http.(*noteEOFReader).Read(0xc20812b0c0, 0xc20808e000, 0x1000, 0x1000, 0xc208012000, 0x0, 0x0)
	<autogenerated>:125 +0xd4
bufio.(*Reader).fill(0xc208138660)
	/usr/local/go/src/bufio/bufio.go:97 +0x1ce
bufio.(*Reader).Peek(0xc208138660, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/bufio/bufio.go:132 +0xf0
net/http.(*persistConn).readLoop(0xc2081b46e0)
	/usr/local/go/src/net/http/transport.go:842 +0xa4
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:660 +0xc9f

goroutine 29 [select]:
net/http.(*persistConn).writeLoop(0xc2081b46e0)
	/usr/local/go/src/net/http/transport.go:945 +0x41d
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:661 +0xcbc

goroutine 53 [chan receive]:
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*Listener).listenerConnLoop(0xc208096600)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:733 +0x1a1
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*Listener).listenerMain(0xc208096600)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:754 +0x28
created by github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.NewListener
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:422 +0x21d

goroutine 54 [IO wait]:
net.(*pollDesc).Wait(0xc20809cae0, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc20809cae0, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).Read(0xc20809ca80, 0xc208236000, 0x1000, 0x1000, 0x0, 0x7fbd4047ee08, 0xc208252ed0)
	/usr/local/go/src/net/fd_unix.go:242 +0x40f
net.(*conn).Read(0xc208134c20, 0xc208236000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:121 +0xdc
bufio.(*Reader).fill(0xc208096a80)
	/usr/local/go/src/bufio/bufio.go:97 +0x1ce
bufio.(*Reader).Read(0xc208096a80, 0xc20803dba0, 0x5, 0x200, 0xc2081c3500, 0x0, 0x0)
	/usr/local/go/src/bufio/bufio.go:174 +0x26c
io.ReadAtLeast(0x7fbd40480970, 0xc208096a80, 0xc20803dba0, 0x5, 0x200, 0x5, 0x0, 0x0, 0x0)
	/usr/local/go/src/io/io.go:298 +0xf1
io.ReadFull(0x7fbd40480970, 0xc208096a80, 0xc20803dba0, 0x5, 0x200, 0x1f5, 0x0, 0x0)
	/usr/local/go/src/io/io.go:316 +0x6d
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*conn).recvMessage(0xc20803db80, 0xc2081b2120, 0xc20824df10, 0x0, 0x0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/conn.go:727 +0x17a
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*ListenerConn).listenerConnLoop(0xc2082963c0, 0x0, 0x0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:132 +0x12f
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*ListenerConn).listenerConnMain(0xc2082963c0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:178 +0x28
created by github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.NewListenerConn
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:78 +0x1a6

goroutine 56 [chan receive]:
github.com/flynn/flynn/pkg/postgres.(*Listener).listen(0xc2080963c0)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/postgres/listener.go:73 +0x5c
created by github.com/flynn/flynn/pkg/postgres.(*DB).Listen
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/postgres/listener.go:23 +0x292

goroutine 57 [chan receive]:
github.com/flynn/flynn/controller.func·019()
	/home/vagrant/go/src/github.com/flynn/flynn/controller/events.go:347 +0x70
created by github.com/flynn/flynn/controller.(*EventListener).Listen
	/home/vagrant/go/src/github.com/flynn/flynn/controller/events.go:369 +0x35c

goroutine 63 [chan receive]:
github.com/flynn/flynn/controller.(*S).TestFormationStreaming(0xc208088580, 0xc2081754a0)
	/home/vagrant/go/src/github.com/flynn/flynn/controller/formation_test.go:21 +0x319
reflect.Value.call(0x94bbc0, 0xc208088580, 0x2513, 0x9563b0, 0x4, 0xc2082b9f78, 0x1, 0x1, 0x0, 0x0, ...)
	/usr/local/go/src/reflect/value.go:419 +0x10e5
reflect.Value.Call(0x94bbc0, 0xc208088580, 0x2513, 0xc2082b9f78, 0x1, 0x1, 0x0, 0x0, 0x0)
	/usr/local/go/src/reflect/value.go:296 +0xbc
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.func·004(0xc2081754a0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/check.go:809 +0x401
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.func·002()
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/check.go:703 +0x92
created by github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check.(*suiteRunner).forkCall
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/go-check/check.go:704 +0x3fd

goroutine 65 [chan receive]:
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*Listener).listenerConnLoop(0xc2082a7620)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:733 +0x1a1
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*Listener).listenerMain(0xc2082a7620)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:754 +0x28
created by github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.NewListener
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:422 +0x21d

goroutine 66 [IO wait]:
net.(*pollDesc).Wait(0xc2082fa220, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2082fa220, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).Read(0xc2082fa1c0, 0xc2082fe000, 0x1000, 0x1000, 0x0, 0x7fbd4047ee08, 0xc2082538c0)
	/usr/local/go/src/net/fd_unix.go:242 +0x40f
net.(*conn).Read(0xc208135ba0, 0xc2082fe000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:121 +0xdc
bufio.(*Reader).fill(0xc2082a77a0)
	/usr/local/go/src/bufio/bufio.go:97 +0x1ce
bufio.(*Reader).Read(0xc2082a77a0, 0xc20821c520, 0x5, 0x200, 0x1, 0x0, 0x0)
	/usr/local/go/src/bufio/bufio.go:174 +0x26c
io.ReadAtLeast(0x7fbd40480970, 0xc2082a77a0, 0xc20821c520, 0x5, 0x200, 0x5, 0x0, 0x0, 0x0)
	/usr/local/go/src/io/io.go:298 +0xf1
io.ReadFull(0x7fbd40480970, 0xc2082a77a0, 0xc20821c520, 0x5, 0x200, 0x1, 0x0, 0x0)
	/usr/local/go/src/io/io.go:316 +0x6d
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*conn).recvMessage(0xc20821c500, 0xc2082fc400, 0xc20824bf88, 0x0, 0x0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/conn.go:727 +0x17a
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*ListenerConn).listenerConnLoop(0xc208272e00, 0x0, 0x0)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:132 +0x12f
github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.(*ListenerConn).listenerConnMain(0xc208272e00)
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:178 +0x28
created by github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq.NewListenerConn
	/home/vagrant/go/src/github.com/flynn/flynn/Godeps/_workspace/src/github.com/flynn/pq/notify.go:78 +0x1a6

goroutine 69 [select]:
github.com/flynn/flynn/controller.func·020()
	/home/vagrant/go/src/github.com/flynn/flynn/controller/formation.go:217 +0x218
created by github.com/flynn/flynn/controller.(*FormationRepo).startListener
	/home/vagrant/go/src/github.com/flynn/flynn/controller/formation.go:230 +0x2ef

goroutine 71 [chan receive]:
github.com/flynn/flynn/pkg/sse.func·001()
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/sse/stream.go:58 +0x65
created by github.com/flynn/flynn/pkg/sse.(*Stream).Serve
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/sse/stream.go:60 +0x34c

goroutine 72 [select]:
reflect.Select(0xc2082f3f30, 0x3, 0x3, 0xc2082a73e0, 0x0, 0x0, 0x0, 0x1)
	/usr/local/go/src/reflect/value.go:1965 +0x218
github.com/flynn/flynn/pkg/sse.func·002()
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/sse/stream.go:81 +0x1e8
created by github.com/flynn/flynn/pkg/sse.(*Stream).Serve
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/sse/stream.go:97 +0x509

goroutine 73 [IO wait]:
net.(*pollDesc).Wait(0xc2081c6840, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2081c6840, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).Read(0xc2081c67e0, 0xc208300000, 0x8000, 0x8000, 0x0, 0x7fbd4047ee08, 0xc208253a68)
	/usr/local/go/src/net/fd_unix.go:242 +0x40f
net.(*conn).Read(0xc208134998, 0xc208300000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:121 +0xdc
io.Copy(0x7fbd4048f5c0, 0xc208135bf0, 0x7fbd40488190, 0xc208134998, 0x0, 0x0, 0x0)
	/usr/local/go/src/io/io.go:362 +0x1f6
net/http.func·008()
	/usr/local/go/src/net/http/server.go:171 +0x7d
created by net/http.(*conn).closeNotify
	/usr/local/go/src/net/http/server.go:177 +0x2e2

goroutine 74 [IO wait]:
net.(*pollDesc).Wait(0xc2081c67d0, 0x72, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc2081c67d0, 0x0, 0x0)
	/usr/local/go/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).Read(0xc2081c6770, 0xc208120000, 0x1000, 0x1000, 0x0, 0x7fbd4047ee08, 0xc208253ea8)
	/usr/local/go/src/net/fd_unix.go:242 +0x40f
net.(*conn).Read(0xc208134988, 0xc208120000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:121 +0xdc
net/http.noteEOFReader.Read(0x7fbd40488190, 0xc208134988, 0xc208242268, 0xc208120000, 0x1000, 0x1000, 0x7, 0x0, 0x0)
	/usr/local/go/src/net/http/transport.go:1270 +0x6e
net/http.(*noteEOFReader).Read(0xc2080d4dc0, 0xc208120000, 0x1000, 0x1000, 0x7, 0x0, 0x0)
	<autogenerated>:125 +0xd4
bufio.(*Reader).fill(0xc2080539e0)
	/usr/local/go/src/bufio/bufio.go:97 +0x1ce
bufio.(*Reader).ReadSlice(0xc2080539e0, 0xa, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/bufio/bufio.go:295 +0x257
net/http/internal.readLine(0xc2080539e0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/internal/chunked.go:110 +0x5a
net/http/internal.(*chunkedReader).beginChunk(0xc2081c4960)
	/usr/local/go/src/net/http/internal/chunked.go:47 +0x46
net/http/internal.(*chunkedReader).Read(0xc2081c4960, 0xc2082ff000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/internal/chunked.go:77 +0xbb
net/http.(*body).readLocked(0xc208272f40, 0xc2082ff000, 0x1000, 0x1000, 0xffffffff, 0x0, 0x0)
	/usr/local/go/src/net/http/transfer.go:584 +0x7a
net/http.(*body).Read(0xc208272f40, 0xc2082ff000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/transfer.go:579 +0x115
net/http.(*bodyEOFSignal).Read(0xc208272f80, 0xc2082ff000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/transport.go:1193 +0x285
bufio.(*Reader).fill(0xc2082a7b60)
	/usr/local/go/src/bufio/bufio.go:97 +0x1ce
bufio.(*Reader).Peek(0xc2082a7b60, 0x1, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/go/src/bufio/bufio.go:132 +0xf0
github.com/flynn/flynn/pkg/sse.(*Reader).Read(0xc208135c28, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/sse/sse.go:84 +0x470
github.com/flynn/flynn/pkg/sse.(*Decoder).Decode(0xc208135c20, 0x7c6240, 0xc208273400, 0x0, 0x0)
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/sse/sse.go:104 +0x43
github.com/flynn/flynn/pkg/httpclient.func·004()
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/httpclient/stream.go:56 +0x353
created by github.com/flynn/flynn/pkg/httpclient.Stream
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/httpclient/stream.go:79 +0x3d5

goroutine 75 [select]:
github.com/flynn/flynn/pkg/httpclient.func·003()
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/httpclient/stream.go:45 +0x10d
created by github.com/flynn/flynn/pkg/httpclient.func·004
	/home/vagrant/go/src/github.com/flynn/flynn/pkg/httpclient/stream.go:50 +0x1fa

rax     0xfffffffffffffffc
rbx     0x3b9aab3a
rcx     0xffffffffffffffff
rdx     0x0
rdi     0xc00f98
rsi     0x0
rbp     0xc208016700
rsp     0xc2080166c0
r8      0x0
r9      0x0
r10     0xc2080166f8
r11     0x216
r12     0x0
r13     0x0
r14     0x2
r15     0x10
rip     0x43f483
rflags  0x216
cs      0x33
fs      0x0
gs      0x0
FAIL	github.com/flynn/flynn/controller	54.189s