Attempting to update a service (scale down) after few instances are deleted, results in "500 Internal server Error" #1996

sangeethah · 2015-09-08T18:51:44Z

Server version - Build from master - sep 8

Create a service with scale 4.
Delete one of the instances.
Update the service to scale down. API throws a "Internal Server Error" message.

I do not see any exception being logged in the server logs and not able to locate a service/container with the id being returned in the API.

Note - In my test scripts , I do not wait for the service to get to "active" state when service update is attempted.

I should be allowed to update service while it is still in "update-activating" state ? Even if we do not allow for this , API should throws action not allowed error message in this case.

self = <cattle.Client object at 0x7f3c6d819f50>
text = '{"id":"2753ba77-939b-4910-a5b2-4434cee75360","type":"error","links":{},"actions":{},"status":500,"code":"Internal Server Error","message":"Internal Server Error","detail":null}'

    def _error(self, text):
>       raise ApiError(self._unmarshall(text))
E       ApiError: (ApiError(...), "Internal Server Error : Internal Server Error\n{'actions': {}, 'detail': None, 'code': u'Internal Server Error', 'type': u'error', 'id': u'2753ba77-939b-4910-a5b2-4434cee75360', 'links': {}, 'message': u'Internal Server Error', 'status': 500}")

The text was updated successfully, but these errors were encountered:

alena1108 · 2015-09-21T22:28:07Z

@sangeethah you should be allowed to update the service which is in updating-active state. I'm going to look whats going on here

alena1108 · 2015-09-22T00:00:35Z

@sangeethah could you update your validation test test_services.py/check_service_activate_delete_instance_scale to print out the service.name as if the line below fails, the random uuid gets printed instead of a real service name:

    service = client.update(service, name=service.name, scale=final_scale)

sangeethah · 2015-09-22T23:38:20Z

@alena1108 , added logging of service name and id before service update is done - addressed in - rancher/validation-tests#118

alena1108 · 2015-09-22T23:56:06Z

@sangeethah awesome, please update this bug with the info once it happens again.

alena1108 · 2015-09-23T22:43:05Z

Here is the error message from the latest log file happening on the failure:

Exiting with code [RESOURCE_BUSY] : RESOURCE_BUSY io.cattl
e.platform.lock.exception.FailedToAcquireLockException: Failed to acquire lock [schedule/service.28465.CHANGE]

Looks like the process failed to schedule, therefore error was returned to the API immediately. Going to look at the code and update the bug with findings.

aruneli · 2015-10-01T22:59:55Z

Component   Version
Rancher     v0.40.0-rc1
Cattle  v0.96.0
User Interface  v0.53.0
Rancher Compose     beta/latest

Verified by deleting instance followed by scale down. Able to update the service which is in updating-active state

sangeethah · 2015-10-07T14:31:20Z

This issue is seen again when testing on latest build on master - Oct 6

The same error is seen when service was attempted to scale up after one of the instance was stopped:

ApiError: (ApiError(...), "Internal Server Error : Internal Server Error\n{'links': {}, 'detail': None, 'code': u'Internal Server Error', 'actions': {}, 'type': u'error', 'id': u'b0e34c40-b0a2-4414-8080-26cfe59e4206', 'status': 500, 'message': u'Internal Server Error'}")

Following exception seen in logs:

Caused by: io.cattle.platform.lock.exception.FailedToAcquireLockException: Failed to acquire lock [schedule/service.42277.CHANGE]

2015-10-07 04:41:08,840 INFO  [f44195d4-c193-4cd8-844d-bbbbbfb99f11:3658837] [service:42277] [service.create] [] [tp689447742-144] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->registering] on [service:42277] 
2015-10-07 04:41:08,843 DEBUG [f44195d4-c193-4cd8-844d-bbbbbfb99f11:3658837] [service:42277] [service.create] [] [tp689447742-144] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
2015-10-07 04:41:08,867 DEBUG [7fe721b3-02eb-4f76-949e-9ab9557c27b2:3658837] [service:42277] [service.create->(ServiceCreate)] [] [cutorService-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceCreate] 
2015-10-07 04:41:08,873 INFO  [7fe721b3-02eb-4f76-949e-9ab9557c27b2:3658837] [service:42277] [service.create->(ServiceCreate)] [] [cutorService-17] [i.c.p.r.p.i.ResourcePoolManagerImpl ] Assigning [169.254.68.72] from pool [subnet:2] to owner [service:42277] 
2015-10-07 04:41:08,876 DEBUG [7fe721b3-02eb-4f76-949e-9ab9557c27b2:3658837] [service:42277] [service.create->(ServiceCreate)] [] [cutorService-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ServiceCreate] 
2015-10-07 04:41:08,877 DEBUG [7fe721b3-02eb-4f76-949e-9ab9557c27b2:3658837] [service:42277] [service.create->(ActivateByDefault)] [] [cutorService-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ActivateByDefault] 
2015-10-07 04:41:08,877 DEBUG [7fe721b3-02eb-4f76-949e-9ab9557c27b2:3658837] [service:42277] [service.create->(ActivateByDefault)] [] [cutorService-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ActivateByDefault] 
2015-10-07 04:41:08,877 DEBUG [7fe721b3-02eb-4f76-949e-9ab9557c27b2:3658837] [service:42277] [service.create->(ServiceDiscoveryLoadBalancerTargetAddPostListener)] [] [cutorService-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [ServiceDiscoveryLoadBalancerTargetAddPostListener] 
2015-10-07 04:41:08,877 DEBUG [7fe721b3-02eb-4f76-949e-9ab9557c27b2:3658837] [service:42277] [service.create->(ServiceDiscoveryLoadBalancerTargetAddPostListener)] [] [cutorService-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [ServiceDiscoveryLoadBalancerTargetAddPostListener] 
2015-10-07 04:41:08,880 INFO  [7fe721b3-02eb-4f76-949e-9ab9557c27b2:3658837] [service:42277] [service.create] [] [cutorService-17] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [registering->inactive] on [service:42277] 
2015-10-07 04:41:08,901 INFO  [1e5807cc-f08d-49b5-b4c8-3b25af4d11d0:3658839] [service:42277] [service.activate] [] [tp689447742-156] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [inactive->activating] on [service:42277] 
2015-10-07 04:41:08,902 DEBUG [1e5807cc-f08d-49b5-b4c8-3b25af4d11d0:3658839] [service:42277] [service.activate] [] [tp689447742-156] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
2015-10-07 04:41:08,916 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(LoadBalancerServiceActivatePreListener)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [LoadBalancerServiceActivatePreListener] 
2015-10-07 04:41:08,916 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(LoadBalancerServiceActivatePreListener)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [LoadBalancerServiceActivatePreListener] 
2015-10-07 04:41:08,917 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceUpdateActivate] 
2015-10-07 04:41:08,921 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive, instanceTriggeredStop=stop}] to [InstanceRecord:null] 
2015-10-07 04:41:08,940 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:3658841] on resource [95625] 
2015-10-07 04:41:08,943 INFO  [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->instance:95625] [service.activate->(ServiceUpdateActivate)->instance.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->creating] on [instance:95625] 
2015-10-07 04:41:08,943 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->instance:95625] [service.activate->(ServiceUpdateActivate)->instance.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
2015-10-07 04:41:08,945 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [instance.create:3658841] on resource [95625] 
2015-10-07 04:41:08,947 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [cutorService-11] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:3658841] on resource [95625] 
2015-10-07 04:41:08,955 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:3658842] on resource [89676] 
2015-10-07 04:41:08,965 INFO  [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->serviceExposeMap:89676] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [serviceExposeMap:89676] 
2015-10-07 04:41:08,966 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->serviceExposeMap:89676] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
2015-10-07 04:41:08,971 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceexposemap.create:3658842] on resource [89676] 
2015-10-07 04:41:08,973 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [cutorService-13] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:3658842] on resource [89676] 
2015-10-07 04:41:08,990 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive, instanceTriggeredStop=stop}] to [InstanceRecord:null] 
2015-10-07 04:41:09,013 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:3658845] on resource [95626] 
2015-10-07 04:41:09,026 INFO  [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->instance:95626] [service.activate->(ServiceUpdateActivate)->instance.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->creating] on [instance:95626] 
2015-10-07 04:41:09,033 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->instance:95626] [service.activate->(ServiceUpdateActivate)->instance.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
2015-10-07 04:41:09,050 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [instance.create:3658845] on resource [95626] 
2015-10-07 04:41:09,057 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [cutorService-10] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:3658845] on resource [95626] 
2015-10-07 04:41:09,067 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:3658847] on resource [89677] 
2015-10-07 04:41:09,080 INFO  [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->serviceExposeMap:89677] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [serviceExposeMap:89677] 
2015-10-07 04:41:09,085 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->serviceExposeMap:89677] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
2015-10-07 04:41:09,092 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceexposemap.create:3658847] on resource [89677] 
2015-10-07 04:41:09,094 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [cutorService-23] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:3658847] on resource [89677] 
2015-10-07 04:41:09,119 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [jectDefaultsPostInstantiationHandler] Applying defaults [{allocationState=inactive, instanceTriggeredStop=stop}] to [InstanceRecord:null] 
2015-10-07 04:41:09,152 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:3658849] on resource [95627] 
2015-10-07 04:41:09,158 INFO  [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->instance:95627] [service.activate->(ServiceUpdateActivate)->instance.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->creating] on [instance:95627] 
2015-10-07 04:41:09,159 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->instance:95627] [service.activate->(ServiceUpdateActivate)->instance.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
2015-10-07 04:41:09,169 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [instance.create:3658849] on resource [95627] 
2015-10-07 04:41:09,172 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [cutorService-24] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [instance.create:3658849] on resource [95627] 
2015-10-07 04:41:09,182 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:3658850] on resource [89678] 
2015-10-07 04:41:09,189 INFO  [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->serviceExposeMap:89678] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [requested->activating] on [serviceExposeMap:89678] 
2015-10-07 04:41:09,190 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277->serviceExposeMap:89678] [service.activate->(ServiceUpdateActivate)->serviceexposemap.create] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
2015-10-07 04:41:09,197 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [SCHEDULED] process [serviceexposemap.create:3658850] on resource [89678] 
2015-10-07 04:41:09,200 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [cutorService-19] [c.p.e.p.i.DefaultProcessInstanceImpl] Attempting to run process [serviceexposemap.create:3658850] on resource [89678] 
2015-10-07 04:41:13,637 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(ServiceUpdateActivate)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ServiceUpdateActivate] 
2015-10-07 04:41:13,639 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(AgentInstanceApplyItems)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceApplyItems] 
2015-10-07 04:41:13,695 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(AgentInstanceApplyItems)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceApplyItems] 
2015-10-07 04:41:13,695 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(LoadBalancerServiceActivatePostListener)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [LoadBalancerServiceActivatePostListener] 
2015-10-07 04:41:13,695 DEBUG [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate->(LoadBalancerServiceActivatePostListener)] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [LoadBalancerServiceActivatePostListener] 
2015-10-07 04:41:13,697 INFO  [23028e59-721b-4fb2-a05e-33fd7ab66719:3658839] [service:42277] [service.activate] [] [ecutorService-3] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [activating->active] on [service:42277] 
2015-10-07 04:41:18,892 INFO  [:] [] [] [] [ecutorService-6] [.p.c.v.i.ConfigItemStatusManagerImpl] Requesting update of item(s) [reconcile] on [service:42277] 
2015-10-07 04:41:18,894 INFO  [:] [] [] [] [ecutorService-6] [.p.c.v.i.ConfigItemStatusManagerImpl] Waiting on [service:42277] on [reconcile], not in sync requested [1] != applied [-1] 
2015-10-07 04:41:19,524 DEBUG [1938c2b0-72be-40c5-a09d-a98e16035572:3658868] [service:42277] [service.update] [] [tp689447742-166] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [RESOURCE_BUSY] : RESOURCE_BUSY 
2015-10-07 04:41:19,528 INFO  [33521847-3d16-4996-9543-fc5be31b4a72:3658867] [service:42277] [service.update] [] [cutorService-19] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [active->updating-active] on [service:42277] 
2015-10-07 04:41:19,530 DEBUG [33521847-3d16-4996-9543-fc5be31b4a72:3658867] [service:42277] [service.update] [] [cutorService-19] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting with code [SCHEDULED] : SCHEDULED 
Caused by: io.cattle.platform.lock.exception.FailedToAcquireLockException: Failed to acquire lock [schedule/service.42277.CHANGE]
2015-10-07 04:41:22,631 INFO  [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [updating-active->updating-active] on [service:42277] 
2015-10-07 04:41:22,638 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(LoadBalancerServiceUpdate)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [LoadBalancerServiceUpdate] 
2015-10-07 04:41:22,639 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(LoadBalancerServiceUpdate)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [LoadBalancerServiceUpdate] 
2015-10-07 04:41:22,643 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(ServiceUpdateActivate)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServiceUpdateActivate] 
2015-10-07 04:41:22,687 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(ServiceUpdateActivate)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ServiceUpdateActivate] 
2015-10-07 04:41:22,687 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(ServicesReconcileTrigger)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ServicesReconcileTrigger] 
2015-10-07 04:41:22,693 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(ServicesReconcileTrigger)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [ServicesReconcileTrigger] 
2015-10-07 04:41:22,695 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(LoadBalancerServiceUpdate)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [LoadBalancerServiceUpdate] 
2015-10-07 04:41:22,695 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(LoadBalancerServiceUpdate)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished pre listener [LoadBalancerServiceUpdate] 
2015-10-07 04:41:22,696 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(AgentInstanceApplyItems)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [AgentInstanceApplyItems] 
2015-10-07 04:41:22,825 DEBUG [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update->(AgentInstanceApplyItems)] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [AgentInstanceApplyItems] 
2015-10-07 04:41:22,838 INFO  [7e4fcaae-1dd8-40d9-8a90-70f55a395f17:3658867] [service:42277] [service.update] [] [ecutorService-9] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [updating-active->active] on [service:42277] 
2015-10-07 04:41:22,926 INFO  [:] [] [] [] [ecutorService-1] [i.c.p.c.v.impl.ConfigUpdatePublisher]         Finished work item service:42277 [74665298] 
2015-10-07 04:41:22,927 INFO  [:] [] [] [] [ecutorService-1] [i.c.p.c.v.impl.ConfigUpdatePublisher]         Finished work item service:42277 [769213638] 
2015-10-07 04:41:23,894 INFO  [:] [] [] [] [ecutorService-1] [i.c.p.c.v.impl.ConfigUpdatePublisher]         Finished work item service:42277 [403500906]

sangeethah · 2016-02-11T22:53:59Z

Server version - V0.59.0-rc1

Attempting to update a service (scale up) after few instances are stopped results in "Internal Server Error"

cattlevalidationtest.core.test_services.test_service_activate_stop_instance_scale_up
 Error Details
ApiError: (ApiError(...), "Internal Server Error : Internal Server Error\n{'status': 500, 'code': u'Internal Server Error', 'links': {}, 'detail': None, 'actions': {}, 'message': u'Internal Server Error', 'type': u'error', 'id': u'ab793f8e-c4f7-4d3a-9d20-31d6098645e8'}")
 Stack Trace
super_client = <cattle.Client object at 0x7fc5a6cbba10>
client = <cattle.Client object at 0x7fc5a6c4be10>, socat_containers = None

    def test_service_activate_stop_instance_scale_up(
            super_client, client, socat_containers):
        check_service_activate_stop_instance_scale(
>           super_client, client, socat_containers, 3, 4, [1])

tests/validation/cattlevalidationtest/core/test_services.py:507: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
tests/validation/cattlevalidationtest/core/test_services.py:1378: in check_service_activate_stop_instance_scale
    service = client.update(service, name=service.name, scale=final_scale)
/usr/local/lib/python2.7/dist-packages/gdapi.py:358: in update
    return self._put(url, data=self._to_dict(*args, **kw))
/usr/local/lib/python2.7/dist-packages/gdapi.py:62: in wrapped
    return fn(*args, **kw)
/usr/local/lib/python2.7/dist-packages/gdapi.py:282: in _put
    self._error(r.text)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <cattle.Client object at 0x7fc5a6c4be10>
text = '{"id":"ab793f8e-c4f7-4d3a-9d20-31d6098645e8","type":"error","links":{},"actions":{},"status":500,"code":"Internal Server Error","message":"Internal Server Error","detail":null}'

    def _error(self, text):
>       raise ApiError(self._unmarshall(text))
E       ApiError: (ApiError(...), "Internal Server Error : Internal Server Error\n{'status': 500, 'code': u'Internal Server Error', 'links': {}, 'detail': None, 'actions': {}, 'message': u'Internal Server Error', 'type': u'error', 'id': u'ab793f8e-c4f7-4d3a-9d20-31d6098645e8'}")

/usr/local/lib/python2.7/dist-packages/gdapi.py:253: ApiError

alena1108 · 2016-07-08T22:03:23Z

Same issue as #2493, closing as a duplicate

sangeethah added the kind/bug Issues that are defects reported by users or that we know have reached a real release label Sep 8, 2015

sangeethah assigned alena1108 Sep 8, 2015

sangeethah added the setup/automation label Sep 15, 2015

alena1108 assigned sangeethah and unassigned alena1108 Sep 22, 2015

alena1108 assigned alena1108 and unassigned sangeethah Sep 23, 2015

alena1108 mentioned this issue Sep 25, 2015

Increased ResourceLockChange timeout rancher/cattle#900

Merged

alena1108 added this to the Milestone 9/30/2015 milestone Sep 30, 2015

alena1108 added the status/to-test label Sep 30, 2015

alena1108 assigned sangeethah and unassigned alena1108 Sep 30, 2015

will-chan assigned aruneli and unassigned sangeethah Oct 1, 2015

aruneli closed this as completed Oct 1, 2015

sangeethah reopened this Oct 7, 2015

sangeethah assigned alena1108 and unassigned aruneli Oct 7, 2015

deniseschannon added status/reopened and removed status/to-test labels Oct 9, 2015

deniseschannon modified the milestones: Milestone 10/14/2015, Milestone 9/30/2015 Oct 9, 2015

alena1108 mentioned this issue Oct 9, 2015

Service Scaleup down error. #2294

Closed

alena1108 modified the milestones: Release 1.0, Milestone 10/14/2015 Oct 15, 2015

will-chan added the release/v1.0.0 label Mar 5, 2016

alena1108 removed this from the Release 1.0 milestone Mar 7, 2016

alena1108 added release/future and removed release/v1.0.0 labels Mar 7, 2016

deniseschannon modified the milestone: Unscheduled Jun 28, 2016

deniseschannon removed the release/future label Jun 28, 2016

alena1108 closed this as completed Jul 8, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Attempting to update a service (scale down) after few instances are deleted, results in "500 Internal server Error" #1996

Attempting to update a service (scale down) after few instances are deleted, results in "500 Internal server Error" #1996

sangeethah commented Sep 8, 2015

alena1108 commented Sep 21, 2015

alena1108 commented Sep 22, 2015

sangeethah commented Sep 22, 2015

alena1108 commented Sep 22, 2015

alena1108 commented Sep 23, 2015

aruneli commented Oct 1, 2015

sangeethah commented Oct 7, 2015

sangeethah commented Feb 11, 2016

alena1108 commented Jul 8, 2016

Attempting to update a service (scale down) after few instances are deleted, results in "500 Internal server Error" #1996

Attempting to update a service (scale down) after few instances are deleted, results in "500 Internal server Error" #1996

Comments

sangeethah commented Sep 8, 2015

alena1108 commented Sep 21, 2015

alena1108 commented Sep 22, 2015

sangeethah commented Sep 22, 2015

alena1108 commented Sep 22, 2015

alena1108 commented Sep 23, 2015

aruneli commented Oct 1, 2015

sangeethah commented Oct 7, 2015

sangeethah commented Feb 11, 2016

alena1108 commented Jul 8, 2016