Agent LB for CloudStack failed

[div8cn]

ISSUE TYPE

• Bug Report

COMPONENT NAME

Agent

CLOUDSTACK VERSION

4.11
4.11.1
4.11.2

CONFIGURATION

indirect.agent.lb.algorithm=roundrobin
indirect.agent.lb.check.interval=60

OS / ENVIRONMENT

SUMMARY

When deploying multiple management nodes, the preferred managment node is forced to power off, the agent will not immediately connect to the second management node.

Wait 15 minutes, the agent issues a "No route to host" error and connects to the second management node.

STEPS TO REPRODUCE

1.Deploying multiple management nodes

2.Modify global settings: 
   indirect.agent.lb.algorithm=roundrobin
   indirect.agent.lb.check.interval=60
   host={all management node ips}

3.Restart all KVM agents

4.View the connection status of each agent through Mysql
    select host.id ,host.name,host.mgmt_server_id,host.status,mshost.name from host,mshost where host.mgmt_server_id=mshost.msid;

5.close a management node randomly (Forced power off)

6.Observe whether the agent connected to the failure management node will reconnect the new managment node in a very short time

EXPECTED RESULTS

Agent quickly reconnects to the new management node

ACTUAL RESULTS

wait15 minutes, the agent issues a "No route to host" error and connects to the second management node.

[nvazquez]

I'm not able to replicate the issue:

• 4x KVM hosts

• 2x Mgmt servers: 10.2.2.71 and 10.2.2.72

• indirect.agent.lb.algorithm=roundrobin

• indirect.agent.lb.check.interval=60

Host connected to mgmt server 10.2.2.72. When rebooting mgmt server 10.2.2.72 I observe it connects to the next management server as expected:

2019-07-19 15:37:47,349 INFO  [cloud.agent.Agent] (Host LB Timer:null) (logid:3f187a6a) Connected to the host: 10.2.2.72
2019-07-19 15:37:50,604 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Proccess agent startup answer, agent id = 0
2019-07-19 15:37:50,605 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Set agent id 0
2019-07-19 15:37:50,606 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Startup Response Received: agent id = 0
2019-07-19 15:37:50,763 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:67bd0e1d) Attempting to create storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109 (NetworkFilesystem) in libvirt
2019-07-19 15:37:50,763 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:67bd0e1d) Found existing defined storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109, using it.
2019-07-19 15:37:50,764 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:67bd0e1d) Trying to fetch storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109 from libvirt
2019-07-19 15:37:50,952 INFO  [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:67bd0e1d) Processing agent ready command, agent id = 4
2019-07-19 15:37:50,953 INFO  [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:67bd0e1d) Set agent id 4
2019-07-19 15:37:50,953 INFO  [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:67bd0e1d) Ready command is processed for agent id = 4
2019-07-19 15:37:51,045 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Processing agent ready command, agent id = 4
2019-07-19 15:37:51,045 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Set agent id 4
2019-07-19 15:37:51,047 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Processed new management server list: 10.2.2.72,10.2.2.71@roundrobin
2019-07-19 15:37:51,047 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Scheduling preferred host timer task with host.lb.interval=60000ms
2019-07-19 15:37:51,047 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Ready command is processed for agent id = 4
2019-07-19 15:38:01,541 INFO  [cloud.agent.Agent] (Agent-Handler-3:null) (logid:3f187a6a) Lost connection to host: 10.2.2.72. Attempting reconnection while we still have 0 commands in progress.
2019-07-19 15:38:01,543 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) NioClient connection closed
2019-07-19 15:38:01,543 INFO  [cloud.agent.Agent] (Agent-Handler-3:null) (logid:3f187a6a) Reconnecting to host:10.2.2.72
2019-07-19 15:38:01,543 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) Connecting to 10.2.2.72:8250
2019-07-19 15:38:01,543 WARN  [utils.nio.NioConnection] (Agent-Handler-3:null) (logid:3f187a6a) Unable to connect to remote: is there a server running on port 8250
2019-07-19 15:38:06,544 INFO  [cloud.agent.Agent] (Agent-Handler-3:null) (logid:3f187a6a) Reconnecting to host:10.2.2.71
2019-07-19 15:38:06,544 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) Connecting to 10.2.2.71:8250
2019-07-19 15:38:06,545 INFO  [utils.nio.Link] (Agent-Handler-3:null) (logid:3f187a6a) Conf file found: /etc/cloudstack/agent/agent.properties
2019-07-19 15:38:06,666 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) SSL: Handshake done
2019-07-19 15:38:06,667 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) Connected to 10.2.2.71:8250
2019-07-19 15:38:06,670 WARN  [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:3f187a6a) Could not read cpuinfo_max_freq
2019-07-19 15:38:06,737 INFO  [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:3f187a6a) Attempting to create storage pool 597ef70d-f468-44d1-bccd-b307ded05802 (Filesystem) in libvirt
2019-07-19 15:38:06,738 INFO  [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:3f187a6a) Found existing defined storage pool 597ef70d-f468-44d1-bccd-b307ded05802, using it.
2019-07-19 15:38:06,738 INFO  [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:3f187a6a) Trying to fetch storage pool 597ef70d-f468-44d1-bccd-b307ded05802 from libvirt
2019-07-19 15:38:07,622 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Proccess agent startup answer, agent id = 0
2019-07-19 15:38:07,622 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Set agent id 0
2019-07-19 15:38:07,623 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Startup Response Received: agent id = 0
2019-07-19 15:38:07,668 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:2079e6bf) Attempting to create storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109 (NetworkFilesystem) in libvirt
2019-07-19 15:38:07,669 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:2079e6bf) Found existing defined storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109, using it.
2019-07-19 15:38:07,669 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:2079e6bf) Trying to fetch storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109 from libvirt
2019-07-19 15:38:07,756 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:2079e6bf) Processing agent ready command, agent id = 4
2019-07-19 15:38:07,756 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:2079e6bf) Set agent id 4
2019-07-19 15:38:07,756 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:2079e6bf) Ready command is processed for agent id = 4
2019-07-19 15:38:07,845 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Processing agent ready command, agent id = 4
2019-07-19 15:38:07,846 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Set agent id 4
2019-07-19 15:38:07,849 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Processed new management server list: 10.2.2.72,10.2.2.71@roundrobin
2019-07-19 15:38:07,849 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Scheduling preferred host timer task with host.lb.interval=60000ms
2019-07-19 15:38:07,850 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Ready command is processed for agent id = 4
2019-07-19 15:38:11,668 INFO  [cloud.agent.Agent] (Agent-Handler-3:null) (logid:3f187a6a) Connected to the host: 10.2.2.71

[div8cn]

I'm not able to replicate the issue:

• 4x KVM hosts
• 2x Mgmt servers: 10.2.2.71 and 10.2.2.72
• indirect.agent.lb.algorithm=roundrobin
• indirect.agent.lb.check.interval=60

Host connected to mgmt server 10.2.2.72. When rebooting mgmt server 10.2.2.72 I observe it connects to the next management server as expected:

2019-07-19 15:37:47,349 INFO  [cloud.agent.Agent] (Host LB Timer:null) (logid:3f187a6a) Connected to the host: 10.2.2.72
2019-07-19 15:37:50,604 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Proccess agent startup answer, agent id = 0
2019-07-19 15:37:50,605 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Set agent id 0
2019-07-19 15:37:50,606 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Startup Response Received: agent id = 0
2019-07-19 15:37:50,763 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:67bd0e1d) Attempting to create storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109 (NetworkFilesystem) in libvirt
2019-07-19 15:37:50,763 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:67bd0e1d) Found existing defined storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109, using it.
2019-07-19 15:37:50,764 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-1:null) (logid:67bd0e1d) Trying to fetch storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109 from libvirt
2019-07-19 15:37:50,952 INFO  [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:67bd0e1d) Processing agent ready command, agent id = 4
2019-07-19 15:37:50,953 INFO  [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:67bd0e1d) Set agent id 4
2019-07-19 15:37:50,953 INFO  [cloud.agent.Agent] (agentRequest-Handler-1:null) (logid:67bd0e1d) Ready command is processed for agent id = 4
2019-07-19 15:37:51,045 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Processing agent ready command, agent id = 4
2019-07-19 15:37:51,045 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Set agent id 4
2019-07-19 15:37:51,047 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Processed new management server list: 10.2.2.72,10.2.2.71@roundrobin
2019-07-19 15:37:51,047 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Scheduling preferred host timer task with host.lb.interval=60000ms
2019-07-19 15:37:51,047 INFO  [cloud.agent.Agent] (agentRequest-Handler-2:null) (logid:67bd0e1d) Ready command is processed for agent id = 4
2019-07-19 15:38:01,541 INFO  [cloud.agent.Agent] (Agent-Handler-3:null) (logid:3f187a6a) Lost connection to host: 10.2.2.72. Attempting reconnection while we still have 0 commands in progress.
2019-07-19 15:38:01,543 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) NioClient connection closed
2019-07-19 15:38:01,543 INFO  [cloud.agent.Agent] (Agent-Handler-3:null) (logid:3f187a6a) Reconnecting to host:10.2.2.72
2019-07-19 15:38:01,543 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) Connecting to 10.2.2.72:8250
2019-07-19 15:38:01,543 WARN  [utils.nio.NioConnection] (Agent-Handler-3:null) (logid:3f187a6a) Unable to connect to remote: is there a server running on port 8250
2019-07-19 15:38:06,544 INFO  [cloud.agent.Agent] (Agent-Handler-3:null) (logid:3f187a6a) Reconnecting to host:10.2.2.71
2019-07-19 15:38:06,544 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) Connecting to 10.2.2.71:8250
2019-07-19 15:38:06,545 INFO  [utils.nio.Link] (Agent-Handler-3:null) (logid:3f187a6a) Conf file found: /etc/cloudstack/agent/agent.properties
2019-07-19 15:38:06,666 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) SSL: Handshake done
2019-07-19 15:38:06,667 INFO  [utils.nio.NioClient] (Agent-Handler-3:null) (logid:3f187a6a) Connected to 10.2.2.71:8250
2019-07-19 15:38:06,670 WARN  [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:3f187a6a) Could not read cpuinfo_max_freq
2019-07-19 15:38:06,737 INFO  [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:3f187a6a) Attempting to create storage pool 597ef70d-f468-44d1-bccd-b307ded05802 (Filesystem) in libvirt
2019-07-19 15:38:06,738 INFO  [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:3f187a6a) Found existing defined storage pool 597ef70d-f468-44d1-bccd-b307ded05802, using it.
2019-07-19 15:38:06,738 INFO  [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:3f187a6a) Trying to fetch storage pool 597ef70d-f468-44d1-bccd-b307ded05802 from libvirt
2019-07-19 15:38:07,622 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Proccess agent startup answer, agent id = 0
2019-07-19 15:38:07,622 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Set agent id 0
2019-07-19 15:38:07,623 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:3f187a6a) Startup Response Received: agent id = 0
2019-07-19 15:38:07,668 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:2079e6bf) Attempting to create storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109 (NetworkFilesystem) in libvirt
2019-07-19 15:38:07,669 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:2079e6bf) Found existing defined storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109, using it.
2019-07-19 15:38:07,669 INFO  [kvm.storage.LibvirtStorageAdaptor] (agentRequest-Handler-5:null) (logid:2079e6bf) Trying to fetch storage pool e03f4cba-17cd-3b04-b6ad-c3e916237109 from libvirt
2019-07-19 15:38:07,756 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:2079e6bf) Processing agent ready command, agent id = 4
2019-07-19 15:38:07,756 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:2079e6bf) Set agent id 4
2019-07-19 15:38:07,756 INFO  [cloud.agent.Agent] (agentRequest-Handler-3:null) (logid:2079e6bf) Ready command is processed for agent id = 4
2019-07-19 15:38:07,845 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Processing agent ready command, agent id = 4
2019-07-19 15:38:07,846 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Set agent id 4
2019-07-19 15:38:07,849 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Processed new management server list: 10.2.2.72,10.2.2.71@roundrobin
2019-07-19 15:38:07,849 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Scheduling preferred host timer task with host.lb.interval=60000ms
2019-07-19 15:38:07,850 INFO  [cloud.agent.Agent] (agentRequest-Handler-4:null) (logid:2079e6bf) Ready command is processed for agent id = 4
2019-07-19 15:38:11,668 INFO  [cloud.agent.Agent] (Agent-Handler-3:null) (logid:3f187a6a) Connected to the host: 10.2.2.71

When reboot or systemctl stop cloudstack-management is executed in os, the agent responds immediately and completes the switch.

When the simulated management node hardware fails and suddenly loses power, the agent does not immediately discover and switch, it needs to wait about 15 minutes.

[nvazquez]

@div8cn thanks, copy. As per simulated you mean your mgmt node is a VM? How are you simulating the power loss - simply shutdown the VM?

[div8cn]

@div8cn thanks, copy. As per simulated you mean your mgmt node is a VM? How are you simulating the power loss - simply shutdown the VM?

I created 2 linux guest os on KVM and run management on it.

Power off simulation using the command virsh destroy

[yadvr]

@nvazquez any comments, is this a valid bug?

[nvazquez]

Thanks, @div8cn. @rhtyd we'll to address this issue as it takes 15 minutes to connect to the next mgmt server

[nvazquez]

@rhtyd do you have the bandwidth to handle this issue? If not I'll work on a fix

[yadvr]

sorry not today can have a look tomorrow or the day after @nvazquez

[yadvr]

I couldn't reproduce it

[div8cn]

You can try the following steps to reproduce

1, create 2 VMs
2. Deploy mgt on 2 VMs
3, modify the global settings host=vm1ip, vm2ip
4, forced to close VM1 (virsh destroy vm1)
5, observe the agent log of the host

[yadvr]

Thanks @div8cn I'll try your steps.

[yadvr]

From email thread on dev@:

2019-07-18 15:26:23,420 INFO  [utils.nio.NioClient] (Agent-Handler-2:null) (logid:) Connecting to 172.17.1.142:8250
2019-07-18 15:26:26,427 ERROR [utils.nio.NioConnection] (Agent-Handler-2:null) (logid:) Unable to initialize the threads.
java.net.NoRouteToHostException: No route to host
      at sun.nio.ch.Net.connect0(Native Method)
      at sun.nio.ch.Net.connect(Net.java:454)
      at sun.nio.ch.Net.connect(Net.java:446)
      at sun.nio.ch.SocketChannelImpl.connect(SocketChannelImpl.java:648)
      at com.cloud.utils.nio.NioClient.init(NioClient.java:56)
      at com.cloud.utils.nio.NioConnection.start(NioConnection.java:95)
      at com.cloud.agent.Agent.reconnect(Agent.java:517)
      at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:1091)
      at com.cloud.utils.nio.Task.call(Task.java:83)
      at com.cloud.utils.nio.Task.call(Task.java:29)
      at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
      at java.lang.Thread.run(Thread.java:748)
2019-07-18 15:26:26,432 INFO  [utils.exception.CSExceptionErrorCode] (Agent-Handler-2:null) (logid:) Could not find exception: com.cloud.utils.exception.NioConnectionException in error code list for exceptions
2019-07-18 15:26:26,432 WARN  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) NIO Connection Exception  com.cloud.utils.exception.NioConnectionException: No route to host
2019-07-18 15:26:26,432 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Attempted to connect to the server, but received an unexpected exception, trying again...
2019-07-18 15:26:26,432 INFO  [utils.nio.NioClient] (Agent-Handler-2:null) (logid:) NioClient connection closed
2019-07-18 15:26:31,433 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Reconnecting to host:172.17.1.141

The exception is thrown after attempting for 3seconds which is a reasonable timeout, next after it decides to reconnect it sleeps for up to 3seconds depending on the configured backoff/sleep algorithm and sleeps: https://github.com/apache/cloudstack/blob/master/agent/src/main/java/com/cloud/agent/Agent.java#L528

From the logs, it seems the KVM host was disconnected from the managements server host for only 6 seconds before it tries to find the route again. I think it's perfectly reasonable to wait for few seconds-mins before kvm agent decides to switch, the instantaneous switching between mgmt server without proper socket and sleep timeouts can cause a large number of ownership switches and mgmt traffic. The default constant backoff algorithm has 5seconds as sleep time.

[yadvr]

I looked at the original log again:

2019-07-15 23:22:39,340 DEBUG [cloud.agent.Agent] (UgentTask-5:null) (logid:) Sending ping: Seq 1-19: { Cmd , MgmtId: -1, via: 1, Ver : v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"_hostVmStateReport":{},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType ":"Routing","hostId":1,"wait":0}}] }
2019-07-15 23:23:09,960 DEBUG [utils.nio.NioConnection] (Agent-NioConnectionHandler-1:null) (logid:) Location 1: Socket Socket[addr=/172.17.1.142,port=8250,localport= 34854] closed on read. Probably -1 returned: No route to host

This happens only initially, after the exception is hit usually when trying to send request (ping) to the management server, it calls upon the StartupTask cancel() that kicks in the reconnection task the next time it runs. This means that thereotically 2x the ping interval time it will fail the watch task, then 2x the wait time will be about 180s (default/hard coded) or 3mins. After every mgmt server connection failure, it doubles the time it takes to check if mgmt server is UP that means on each failure the value doubles. If you try to reproduce the force failure once it will run time for 6 mins, and the overall wait doubles to 12 mins. This checks out with your observation of ~15mins of reconnection.

Here's what you can try: lower the ping.interval configured in your environment, this will ensure that failures are kicked in quickly. On the downside the waitime for the timer is hardcoded to 3mins which can be tuned in future minor version: https://github.com/apache/cloudstack/blob/master/agent/src/main/java/com/cloud/agent/Agent.java#L141