scheduler.log

t=2016-01-27T18:42:53+0000 lvl=info msg="creating cluster and controller clients" component=scheduler fn=main
t=2016-01-27T18:42:53+0000 lvl=info msg="started scheduler" component=scheduler fn=main backoffPeriod=10m0s
t=2016-01-27T18:42:53+0000 lvl=info msg="starting scheduler loop" component=scheduler fn=Run
t=2016-01-27T18:42:53+0000 lvl=info msg="connecting host event stream" component=scheduler fn=streamHostEvents
t=2016-01-27T18:42:53+0000 lvl=info msg="serving HTTP requests" component=scheduler fn=startHTTPServer addr=:5000
t=2016-01-27T18:42:53+0000 lvl=info msg="handling host event" component=scheduler fn=HandleHostEvent event.type=up
t=2016-01-27T18:42:53+0000 lvl=info msg="host is up, starting job event stream" component=scheduler fn=handleNewHost host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="connecting job event stream" component=scheduler fn=StreamEventsTo host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="getting active jobs" component=scheduler fn=StreamEventsTo host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="got 19 active job(s) for host host0" component=scheduler fn=StreamEventsTo host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-20b31a08-b5db-4a1b-835f-26e95e27ec52 app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=web from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 processes="map[postgres:1 web:1]"
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-77c933bd-fad3-43f2-b9c2-fce6b3635dcc app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=postgres from= to=running
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-c0633657-9a56-447d-ad41-93538a4c7f3c app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae job.type=web from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae processes=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-050cbd59-7db3-4a34-ad1a-6b01b6c04f0a app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app from= to=running
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-0909ad09-f929-43d9-a6a5-147894b1c0c9 app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f job.type=app from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-bc81887b-82a6-4f3a-9716-9f2fab4500eb app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=web from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 processes="map[scheduler:1 web:1 worker:1]"
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-050cbd59-7db3-4a34-ad1a-6b01b6c04f0a app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app from=running to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-22d88854-4cf4-4c88-a9e4-0d37c2db7c15 app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 job.type=web from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 processes=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b169a590-6e1c-4f0e-82cc-c5ab72867414 app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=scheduler from= to=running
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e0fbed0f-274f-4a3e-8a6a-7cff0d607e2c app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 job.type=app from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e41a6ee6-b8e9-49f3-9cb2-3300e80e9771 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from= to=running
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e460e84e-03fc-4e92-bfe9-aa921e2164d7 app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=postgres from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-60df20b3-b8de-4189-a882-04da7d89c1b3 app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=scheduler from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b058156e-d83f-4123-ad79-418c33c8218a app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 job.type=web from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 processes=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e41a6ee6-b8e9-49f3-9cb2-3300e80e9771 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from=running to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b419dedb-5afa-4889-a269-370195141e71 app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=web from= to=running
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-fbf845d8-bf95-4936-bc44-278940652797 app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=worker from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-37ab1943-2b3e-47e6-894d-68e94063c999 app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 job.type=app from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-a046bb4c-b076-4db0-bfb2-093a1ba39407 app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 job.type=web from= to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 processes=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="registering with service discovery" component=scheduler fn=discoverd.Register
t=2016-01-27T18:42:53+0000 lvl=info msg="connecting service leader stream" component=scheduler fn=discoverd.Register self.addr=100.100.87.4:5000
t=2016-01-27T18:42:53+0000 lvl=info msg="received leader event" component=scheduler fn=discoverd.Register self.addr=100.100.87.4:5000 leader.addr=100.100.87.4:5000
t=2016-01-27T18:42:53+0000 lvl=info msg="handling leader promotion" component=scheduler fn=HandleLeaderChange
t=2016-01-27T18:42:53+0000 lvl=info msg="syncing hosts" component=scheduler fn=SyncHosts
t=2016-01-27T18:42:53+0000 lvl=info msg="syncing formations" component=scheduler fn=SyncFormations
t=2016-01-27T18:42:53+0000 lvl=info msg="syncing jobs" component=scheduler fn=SyncJobs
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-050cbd59-7db3-4a34-ad1a-6b01b6c04f0a app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app from=stopped to=running
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e41a6ee6-b8e9-49f3-9cb2-3300e80e9771 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from=stopped to=running
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e41a6ee6-b8e9-49f3-9cb2-3300e80e9771 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from=running to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d expected=map[app:1] actual=map[] diff=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="scheduling job restart" component=scheduler fn=restartJob job.id=308d7c27-f5ca-40c0-bb3a-e20b44b4d4f9 attempts=1 delay=0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-050cbd59-7db3-4a34-ad1a-6b01b6c04f0a app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app from=running to=stopped
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 expected=map[app:1] actual=map[] diff=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="scheduling job restart" component=scheduler fn=restartJob job.id=d69c0c19-cb6e-4f00-b670-b6eb7ee37977 attempts=1 delay=0
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="connecting formation event stream" component=scheduler fn=streamFormationEvents
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae processes=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 processes=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=cb486b49-cf94-4834-a6b1-ea9fd9b58a89 release.id=7e962f27-027c-4cb9-9bfc-87610c789bfc processes=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="adding new formation" component=scheduler fn=handleFormation app.id=cb486b49-cf94-4834-a6b1-ea9fd9b58a89 release.id=7e962f27-027c-4cb9-9bfc-87610c789bfc processes=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 processes=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 processes=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 processes="map[scheduler:1 web:1 worker:1]"
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d processes=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="handling formation change" component=scheduler fn=HandleFormationChange app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 processes="map[postgres:1 web:1]"
t=2016-01-27T18:42:53+0000 lvl=info msg="starting sync jobs ticker" component=scheduler duration=30s
t=2016-01-27T18:42:53+0000 lvl=info msg="starting sync formations ticker" component=scheduler duration=1m0s
t=2016-01-27T18:42:53+0000 lvl=info msg="starting sync hosts ticker" component=scheduler duration=10s
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least app jobs" component=scheduler fn=HandlePlacementRequest app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least app jobs" component=scheduler fn=HandlePlacementRequest app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="syncing formations" component=scheduler fn=SyncFormations
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job persistence loop" component=scheduler fn=RunPutJobs
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app host.id=host0 job.id=host0-308d7c27-f5ca-40c0-bb3a-e20b44b4d4f9
t=2016-01-27T18:42:53+0000 lvl=info msg="provisioning data volume" component=scheduler fn=StartJob app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-308d7c27-f5ca-40c0-bb3a-e20b44b4d4f9 event.type=create
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-308d7c27-f5ca-40c0-bb3a-e20b44b4d4f9 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from=pending to=starting
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae expected=map[web:1] actual=map[] diff=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae diff=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new web jobs" component=scheduler fn=handleFormationDiff app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f expected=map[app:1] actual=map[] diff=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f diff=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new app jobs" component=scheduler fn=handleFormationDiff app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 expected=map[web:1] actual=map[] diff=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 diff=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new web jobs" component=scheduler fn=handleFormationDiff app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 expected=map[app:1] actual=map[] diff=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 diff=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new app jobs" component=scheduler fn=handleFormationDiff app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 expected=map[app:1] actual=map[] diff=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 diff=map[app:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new app jobs" component=scheduler fn=handleFormationDiff app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 expected=map[web:1] actual=map[] diff=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 diff=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new web jobs" component=scheduler fn=handleFormationDiff app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 expected="map[postgres:1 web:1]" actual=map[postgres:1] diff="map[postgres:0 web:1]"
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 diff="map[postgres:0 web:1]"
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new web jobs" component=scheduler fn=handleFormationDiff app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 expected="map[scheduler:1 web:1 worker:1]" actual="map[scheduler:1 web:1]" diff="map[web:0 worker:1 scheduler:0]"
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 diff="map[web:0 worker:1 scheduler:0]"
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new worker jobs" component=scheduler fn=handleFormationDiff app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872
t=2016-01-27T18:42:53+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 expected=map[web:1] actual=map[] diff=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 diff=map[web:1]
t=2016-01-27T18:42:53+0000 lvl=info msg="starting 1 new web jobs" component=scheduler fn=handleFormationDiff app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 job.type=app
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=worker
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=worker
t=2016-01-27T18:42:53+0000 lvl=info msg="starting job" component=scheduler fn=StartJob app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="placing job in the cluster" component=scheduler fn=StartJob app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 job.type=web
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae job.type=web job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least web jobs" component=scheduler fn=HandlePlacementRequest app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae job.type=web job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f job.type=app job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least app jobs" component=scheduler fn=HandlePlacementRequest app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f job.type=app job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 job.type=web job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least web jobs" component=scheduler fn=HandlePlacementRequest app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 job.type=web job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 job.type=app job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least app jobs" component=scheduler fn=HandlePlacementRequest app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 job.type=app job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 job.type=app job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least app jobs" component=scheduler fn=HandlePlacementRequest app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 job.type=app job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 job.type=web job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least web jobs" component=scheduler fn=HandlePlacementRequest app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 job.type=web job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=web job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least web jobs" component=scheduler fn=HandlePlacementRequest app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=web job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=worker job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least worker jobs" component=scheduler fn=HandlePlacementRequest app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=worker job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="handling placement request" component=scheduler fn=HandlePlacementRequest app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 job.type=web job.tags=map[]
t=2016-01-27T18:42:53+0000 lvl=info msg="placed job on host with least web jobs" component=scheduler fn=HandlePlacementRequest app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 job.type=web job.tags=map[] host.id=host0
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae job.type=web host.id=host0 job.id=host0-24e9642c-a931-49e6-ace2-4a7529755d51
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f job.type=app host.id=host0 job.id=host0-b7077e03-ae6e-4a21-8191-385606df2a78
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 job.type=web host.id=host0 job.id=host0-533b05a0-9869-4db0-af25-8a5c7a3a4d34
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 job.type=app host.id=host0 job.id=host0-00de9e67-a58b-4855-88f1-687f3e8306ee
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 job.type=app host.id=host0 job.id=host0-b11828dd-2baf-4997-a930-593e63dbcf4a
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 job.type=web host.id=host0 job.id=host0-3d42afcb-d40d-4537-b2d2-88403fd006a8
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=web host.id=host0 job.id=host0-b70930c4-1bb5-4496-8757-2aa340cda8d8
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=worker host.id=host0 job.id=host0-e7d9a6dd-9305-498e-ab07-2159b9726194
t=2016-01-27T18:42:53+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 job.type=web host.id=host0 job.id=host0-673b3925-58b7-4288-89f5-90643e7202e6
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-673b3925-58b7-4288-89f5-90643e7202e6 event.type=create
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-673b3925-58b7-4288-89f5-90643e7202e6 app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 job.type=web from=pending to=starting
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-e7d9a6dd-9305-498e-ab07-2159b9726194 event.type=create
t=2016-01-27T18:42:53+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e7d9a6dd-9305-498e-ab07-2159b9726194 app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=worker from=pending to=starting
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-b70930c4-1bb5-4496-8757-2aa340cda8d8 event.type=create
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b70930c4-1bb5-4496-8757-2aa340cda8d8 app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=web from=pending to=starting
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-24e9642c-a931-49e6-ace2-4a7529755d51 event.type=create
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-24e9642c-a931-49e6-ace2-4a7529755d51 app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae job.type=web from=pending to=starting
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-b7077e03-ae6e-4a21-8191-385606df2a78 event.type=create
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b7077e03-ae6e-4a21-8191-385606df2a78 app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f job.type=app from=pending to=starting
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-533b05a0-9869-4db0-af25-8a5c7a3a4d34 event.type=create
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-533b05a0-9869-4db0-af25-8a5c7a3a4d34 app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 job.type=web from=pending to=starting
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-00de9e67-a58b-4855-88f1-687f3e8306ee event.type=create
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-00de9e67-a58b-4855-88f1-687f3e8306ee app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 job.type=app from=pending to=starting
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-b11828dd-2baf-4997-a930-593e63dbcf4a event.type=create
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b11828dd-2baf-4997-a930-593e63dbcf4a app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 job.type=app from=pending to=starting
t=2016-01-27T18:42:54+0000 lvl=info msg="adding job to the cluster" component=scheduler fn=StartJob app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app host.id=host0 job.id=host0-d69c0c19-cb6e-4f00-b670-b6eb7ee37977
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-3d42afcb-d40d-4537-b2d2-88403fd006a8 event.type=create
t=2016-01-27T18:42:54+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-3d42afcb-d40d-4537-b2d2-88403fd006a8 app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 job.type=web from=pending to=starting
t=2016-01-27T18:42:55+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-d69c0c19-cb6e-4f00-b670-b6eb7ee37977 event.type=create
t=2016-01-27T18:42:55+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-d69c0c19-cb6e-4f00-b670-b6eb7ee37977 app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app from=pending to=starting
t=2016-01-27T18:42:55+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-308d7c27-f5ca-40c0-bb3a-e20b44b4d4f9 event.type=start
t=2016-01-27T18:42:55+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-308d7c27-f5ca-40c0-bb3a-e20b44b4d4f9 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from=starting to=running
t=2016-01-27T18:42:56+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-308d7c27-f5ca-40c0-bb3a-e20b44b4d4f9 event.type=stop
t=2016-01-27T18:42:56+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-308d7c27-f5ca-40c0-bb3a-e20b44b4d4f9 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from=running to=stopped
t=2016-01-27T18:42:56+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d expected=map[app:1] actual=map[] diff=map[app:1]
t=2016-01-27T18:42:56+0000 lvl=info msg="scheduling job restart" component=scheduler fn=restartJob job.id=3e567c03-f48d-4688-9ae9-ff1c6d7f63d3 attempts=2 delay=10m0s
t=2016-01-27T18:42:58+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-b11828dd-2baf-4997-a930-593e63dbcf4a event.type=start
t=2016-01-27T18:42:58+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b11828dd-2baf-4997-a930-593e63dbcf4a app.id=778e8813-ab4c-416f-a3a6-88eb9e6e3576 release.id=70ec2a23-0c7c-406f-88d6-fe502a07bd09 job.type=app from=starting to=running
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-673b3925-58b7-4288-89f5-90643e7202e6 event.type=start
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-673b3925-58b7-4288-89f5-90643e7202e6 app.id=837a0627-3896-4ca5-a3af-361b718ac03b release.id=ab53b6df-f52d-4510-a810-b7feef3533b9 job.type=web from=starting to=running
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-b7077e03-ae6e-4a21-8191-385606df2a78 event.type=start
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b7077e03-ae6e-4a21-8191-385606df2a78 app.id=423549d3-a67b-4505-a09f-d417beca41ff release.id=fca808ca-0d1f-4c5d-87c7-2b3293e4a76f job.type=app from=starting to=running
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-24e9642c-a931-49e6-ace2-4a7529755d51 event.type=start
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-24e9642c-a931-49e6-ace2-4a7529755d51 app.id=79ccf665-7493-4bb7-8044-505b419d1cc0 release.id=86fe703e-7df3-4470-8e96-594c6186b4ae job.type=web from=starting to=running
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-533b05a0-9869-4db0-af25-8a5c7a3a4d34 event.type=start
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-533b05a0-9869-4db0-af25-8a5c7a3a4d34 app.id=31bd7ab7-0ad6-4ca5-b048-5cdda516b8cf release.id=745cb283-32f3-4fbb-a05e-b845aac8b850 job.type=web from=starting to=running
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-b70930c4-1bb5-4496-8757-2aa340cda8d8 event.type=start
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-b70930c4-1bb5-4496-8757-2aa340cda8d8 app.id=7341eb28-c0d7-43d8-beec-f89f5966e0fa release.id=ec463d8d-9811-4a70-8ed1-b52907dd8239 job.type=web from=starting to=running
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-e7d9a6dd-9305-498e-ab07-2159b9726194 event.type=start
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e7d9a6dd-9305-498e-ab07-2159b9726194 app.id=0641b77a-380d-4558-80ce-eada76b65d0b release.id=77bf2702-7e94-489a-8a66-42124e654872 job.type=worker from=starting to=running
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-00de9e67-a58b-4855-88f1-687f3e8306ee event.type=start
t=2016-01-27T18:43:00+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-00de9e67-a58b-4855-88f1-687f3e8306ee app.id=42c5eda6-9581-4f7e-9744-6cd61a9f2b0c release.id=74f49ef0-b249-4b58-a827-0acfcee55fb4 job.type=app from=starting to=running
t=2016-01-27T18:43:01+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-d69c0c19-cb6e-4f00-b670-b6eb7ee37977 event.type=start
t=2016-01-27T18:43:01+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-d69c0c19-cb6e-4f00-b670-b6eb7ee37977 app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app from=starting to=running
t=2016-01-27T18:43:01+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-d69c0c19-cb6e-4f00-b670-b6eb7ee37977 event.type=stop
t=2016-01-27T18:43:01+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-d69c0c19-cb6e-4f00-b670-b6eb7ee37977 app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app from=running to=stopped
t=2016-01-27T18:43:01+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 expected=map[app:1] actual=map[] diff=map[app:1]
t=2016-01-27T18:43:01+0000 lvl=info msg="scheduling job restart" component=scheduler fn=restartJob job.id=fbd76c05-1c33-49d0-8d72-7ae988ae2290 attempts=2 delay=10m0s
t=2016-01-27T18:43:01+0000 lvl=info msg="handling job event" component=scheduler fn=HandleJobEvent job.id=host0-3d42afcb-d40d-4537-b2d2-88403fd006a8 event.type=start
t=2016-01-27T18:43:01+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-3d42afcb-d40d-4537-b2d2-88403fd006a8 app.id=d8ce7d16-7307-4611-b821-63be2898eaca release.id=7de68014-1598-4c94-b626-7b1fa6ce1f15 job.type=web from=starting to=running
t=2016-01-27T18:43:03+0000 lvl=info msg="syncing hosts" component=scheduler fn=SyncHosts
t=2016-01-27T18:43:13+0000 lvl=info msg="syncing hosts" component=scheduler fn=SyncHosts
t=2016-01-27T18:43:23+0000 lvl=info msg="syncing jobs" component=scheduler fn=SyncJobs
t=2016-01-27T18:43:23+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e41a6ee6-b8e9-49f3-9cb2-3300e80e9771 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from=stopped to=running
t=2016-01-27T18:43:23+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-050cbd59-7db3-4a34-ad1a-6b01b6c04f0a app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app from=stopped to=running
t=2016-01-27T18:43:23+0000 lvl=info msg="handling job status change" component=scheduler fn=handleJobStatus job.id=host0-e41a6ee6-b8e9-49f3-9cb2-3300e80e9771 app.id=3ab77b58-6fa2-4f21-acaf-bf737f354a72 release.id=069591be-7782-418a-9cf7-3a5e7559ec1d job.type=app from=running to=stopped
t=2016-01-27T18:43:23+0000 lvl=info msg="syncing hosts" component=scheduler fn=SyncHosts
t=2016-01-27T18:43:23+0000 lvl=info msg="expected different from actual" component=scheduler fn=formationDiff app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 expected=map[app:1] actual=map[app:2] diff=map[app:-1]
t=2016-01-27T18:43:23+0000 lvl=info msg="formation in incorrect state" component=scheduler fn=handleFormationDiff app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 diff=map[app:-1]
t=2016-01-27T18:43:23+0000 lvl=info msg="stopping 1 app jobs" component=scheduler fn=handleFormationDiff app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579
t=2016-01-27T18:43:23+0000 lvl=info msg="stopping app job" component=scheduler fn=stopJobOfType app.id=fbe3b618-2ee0-4de7-a80e-8497556a5ece release.id=1e3deba7-4218-463a-bf96-88ca42923579 job.type=app
t=2016-01-27T18:43:23+0000 lvl=info msg="stopping job" component=scheduler fn=stopJob job.id=fbd76c05-1c33-49d0-8d72-7ae988ae2290 job.type=app job.state=pending
t=2016-01-27T18:43:23+0000 lvl=info msg="stopping pending job" component=scheduler fn=stopJob job.id=fbd76c05-1c33-49d0-8d72-7ae988ae2290 job.type=app job.state=pending job.id=fbd76c05-1c33-49d0-8d72-7ae988ae2290
t=2016-01-27T18:43:33+0000 lvl=info msg="syncing hosts" component=scheduler fn=SyncHosts
t=2016-01-27T18:43:43+0000 lvl=info msg="syncing hosts" component=scheduler fn=SyncHosts