"500 Internal Server Error" when trying to delete instances.

[sangeethah]

Server version - Built from master - Aug 4

"500 Internal Server Error" returned when trying to delete an instance. Following exception is seen in the logs:

2015-08-05 00:07:56,357 INFO  [9c58fec4-afab-4ed1-b5a7-2ef500e58d32:109513] [nic:2089] [nic.purge->(NicPurge)] [] [utorService-565] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [ipaddressnicmap.remove:null] on resource [4007] 
2015-08-05 00:07:56,360 INFO  [3294746f-cf18-4ac6-a40b-4b9f6796f5be:109464] [instance:2110] [instance.purge->(InstancePurge)] [] [utorService-535] [c.p.e.p.i.DefaultProcessInstanceImpl] Exiting [DONE] process [instance.deallocate:null] on resource [2110] 
2015-08-05 00:07:56,360 INFO  [3294746f-cf18-4ac6-a40b-4b9f6796f5be:109464] [instance:2110] [instance.purge->(InstancePurge)] [] [utorService-535] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [InstancePurge] 
2015-08-05 00:07:56,361 INFO  [3294746f-cf18-4ac6-a40b-4b9f6796f5be:109464] [instance:2110] [instance.purge->(PostInstancePurge)] [] [utorService-535] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [PostInstancePurge] 
2015-08-05 00:07:56,362 INFO  [249b25e3-b084-4a10-9a22-6a216a00a57d:109534] [nic:2729] [nic.purge->(NicPurge)] [] [utorService-585] [i.c.p.r.p.i.ResourcePoolManagerImpl ] Releasing [02:10:08:52:36:36] id [5352] to pool [network:1] from owner [nic:2729] 
2015-08-05 00:07:56,363 INFO  [601b6518-c911-484b-aa11-a4d39b77e714:109630] [containerEvent:11632] [containerevent.create->(ContainerEventPreCreate)] [] [utorService-599] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [ContainerEventPreCreate] 
2015-08-05 00:07:56,364 INFO  [827b1eb1-c540-4191-8599-fe3c1c7e7e1e:109484] [instance:2755->port:4461] [instance.purge->(InstancePurge)->port.remove->(PortRemove)] [] [utorService-579] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished handler [PortRemove] 
2015-08-05 00:07:56,365 INFO  [581761fe-00d1-4c24-ae39-e9998538dd71:109590] [volume:4242->volumeStoragePoolMap:4242] [volume.purge->(VolumePurge)->volume.deallocate->(VolumeDeallocate)->volumestoragepoolmap.remove->(SetRemovedFields)] [] [utorService-595] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [SetRemovedFields] 
2015-08-05 00:07:56,366 INFO  [32d2ad6a-a4d4-4dd4-a725-ec13fc3b5d26:109591] [volume:4246->volumeStoragePoolMap:4245] [volume.purge->(VolumePurge)->volume.deallocate->(VolumeDeallocate)->volumestoragepoolmap.remove->(SetRemovedFields)] [] [utorService-596] [c.p.e.p.i.DefaultProcessInstanceImpl] Finished post listener [SetRemovedFields] 
2015-08-05 00:07:56,367 INFO  [00f5c17a-a13d-4626-b028-d74a04ee97ec:109622] [containerEvent:11630] [containerevent.create->(ContainerEventCreate)] [] [utorService-527] [c.p.e.p.i.DefaultProcessInstanceImpl] Running handler [ContainerEventCreate] 
2015-08-05 00:07:56,368 INFO  [014f100f-745b-432e-8ca3-09bd221fd720:109631] [containerEvent:11637] [containerevent.create->(ContainerEventPreCreate)] [] [utorService-603] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [ContainerEventPreCreate] 
2015-08-05 00:07:56,373 ERROR [9ddc2f22-909a-49eb-b766-05c0d253d4bf:109472] [instance:2358] [instance.purge] [] [utorService-567] [c.p.e.p.i.DefaultProcessInstanceImpl] Unknown exception io.cattle.platform.eventing.exception.EventExecutionException: 6ba433c1-9101-4d2e-915b-91c8327df15f : HTTPConnectionPool(host='104.197.76.173', port=8080): Read timed out. (read timeout=5)
        at io.cattle.platform.eventing.exception.EventExecutionException.fromEvent(EventExecutionException.java:53) ~[cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:72) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.agent.impl.RemoteAgentImpl.callSync(RemoteAgentImpl.java:158) ~[cattle-iaas-agent-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.common.handler.AgentBasedProcessHandler.handleEvent(AgentBasedProcessHandler.java:156) ~[cattle-iaas-logic-common-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.process.instance.PostInstancePurge.handle(PostInstancePurge.java:38) ~[cattle-iaas-logic-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandler(DefaultProcessInstanceImpl.java:455) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:395) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$4.execute(DefaultProcessInstanceImpl.java:389) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.idempotent.Idempotent.execute(Idempotent.java:42) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runHandlers(DefaultProcessInstanceImpl.java:389) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runLogic(DefaultProcessInstanceImpl.java:519) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runWithProcessLock(DefaultProcessInstanceImpl.java:322) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$2.doWithLockNoResult(DefaultProcessInstanceImpl.java:258) ~[cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:3) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.acquireLockAndRun(DefaultProcessInstanceImpl.java:255) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.runDelegateLoop(DefaultProcessInstanceImpl.java:188) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.executeWithProcessInstanceLock(DefaultProcessInstanceImpl.java:161) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:110) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl$1.doWithLock(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl$3.doWithLock(AbstractLockManagerImpl.java:40) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.LockManagerImpl.doLock(LockManagerImpl.java:33) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:13) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.impl.AbstractLockManagerImpl.lock(AbstractLockManagerImpl.java:37) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.process.impl.DefaultProcessInstanceImpl.execute(DefaultProcessInstanceImpl.java:107) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.engine.eventing.impl.ProcessEventListenerImpl.processExecute(ProcessEventListenerImpl.java:66) [cattle-framework-engine-0.5.0-SNAPSHOT.jar:na]
        at sun.reflect.GeneratedMethodAccessor464.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_79]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_79]
        at io.cattle.platform.eventing.annotation.MethodInvokingListener$1.doWithLockNoResult(MethodInvokingListener.java:76) [cattle-framework-eventing-0.5.0-SNAPSHOT.jar:na]
        at io.cattle.platform.lock.LockCallbackNoReturn.doWithLock(LockCallbackNoReturn.java:7) [cattle-framework-lock-0.5.0-SNAPSHOT.jar:na]
:
2015-08-05 00:07:56,353 INFO  [c13ec00e-ce67-40ed-b349-7b8131492547:109503] [nic:1950] [nic.purge] [] [utorService-631] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [purging->purged] on [nic:1950] 
2015-08-05 00:07:56,354 INFO  [434d6c14-0b1d-4261-a5e2-17d38818456c:109536] [nic:2739] [nic.purge] [] [utorService-587] [c.p.e.p.i.DefaultProcessInstanceImpl] Changing state [purging->purged] on [nic:2739] 
2015-08-05 00:07:56,354 INFO  [27956add-73f7-434a-817c-06e33f6ac571:109535] [nic:2735->ipAddressNicMap:5247] [nic.purge->(NicPurge)->ipaddressnicmap.remove->(SetRemovedFields)] [] [utorService-586] [c.p.e.p.i.DefaultProcessInstanceImpl] Running post listener [SetRemovedFields] 
2015-08-05 00:07:56,355 INFO  [6db7be41-3a00-4c0b-aefa-07407bad841b:109636] [containerEvent:11644] [containerevent.create->(ContainerEventPreCreate)] [] [utorService-526] [c.p.e.p.i.DefaultProcessInstanceImpl] Running pre listener [ContainerEventPreCreate]

[cjellick]

Not sure what to do with this one. The stacktrace isn't directly related to the API 500 because it is from a process that happens independently of API requests.

I'm not going to be able to reproduce this in order to fix it as I have no context for the 500 error.

However, the stacktrace does indicate that an agent was having trouble communicating with cattle and specifically that the communication time out. I suspect that cattle was more generally broken for some reason.

I suggest not pursuing this bug anytime soon unless it starts happening more regularly.
@will-chan @ibuildthecloud @sangeethah: two cents?

[cjellick]

Additional update on the stacktrace in this issue: there was a timeout after 5 seconds. We increased the timeout to 60 seconds last week.

So, still don't know about the 500 error in the UI/API, but the stacktrace should be solved or at least mitigated.

[cjellick]

This issue does not happen regularly enough to stay open and we made a lot of stability improvements since august. Can we close @sangeethah

[sangeethah]

Closing this issue for now. I have not seen this issue when running automated validation tests for a while now.