CLOUDSTACK-9285 for 4.7.x by kiwiflyer · Pull Request #1430 · apache/cloudstack

kiwiflyer · 2016-03-07T22:25:51Z

Per Daan's request, here is a pull request for the 4.7.x release.

ustcweizhou · 2016-03-07T22:45:05Z

 _connection.start();
 } catch (final NioConnectionException e) {
- throw new CloudRuntimeException("Unable to start the connection!", e);
+ s_logger.info("Attempted to connect to the server, but received an unexpected exception, trying again...");


I think you should fix line 230/238, that's the root cause of the issue. line 415 is not.
line 416 can be removed.

kiwiflyer · 2016-03-07T23:38:37Z

@ustcweizhou Thanks for the advice. Maybe I can catch you on the slack channel tomorrow to discuss a little, so I better understand the logic between start and reconnect.

ustcweizhou · 2016-03-08T07:33:35Z

@kiwiflyer this is the log in jira:

2016-02-15 10:46:21,611 INFO [utils.exception.CSExceptionErrorCode] (main:null) (logid:) Could not find exception: com.cloud.utils.exception.NioConnectionException in error code list for exceptions
2016-02-15 10:46:21,612 ERROR [cloud.agent.AgentShell] (main:null) (logid:) Unable to start agent:
com.cloud.utils.exception.CloudRuntimeException: Unable to start the connection!
at com.cloud.agent.Agent.start(Agent.java:230)
at com.cloud.agent.AgentShell.launchAgent(AgentShell.java:399)
at com.cloud.agent.AgentShell.launchAgentFromClassInfo(AgentShell.java:367)

@wilderrodrigues this issue was introduced by your commit 79a3f8c, can you please have a look?

commit 79a3f8c5774c50dc128968c29da5096dc3dde39e
Refs: 4.5.1-2982-g79a3f8c
Author: wilderrodrigues <wrodrigues@schubergphilis.com>
AuthorDate: Tue Sep 8 12:12:55 2015 +0200
Commit: wilderrodrigues <wrodrigues@schubergphilis.com>
CommitDate: Fri Sep 11 11:28:40 2015 +0200
CLOUDSTACK-8822 - Replacing Runnable by Callable in the Taks and NioConnection classes
- All the sub-classes were also updated according to the changes in the super-classes
- There were also code formatting changes

kiwiflyer · 2016-03-08T14:05:12Z

@ustcweizhou
So after looking at our issue and the one reported originally in 9285, I think they're two different issues. One related to initial connection on agent startup and our one, related to a re-connection event where the connection is terminated unexpectedly.

ustcweizhou · 2016-03-08T14:55:29Z

@kiwiflyer Simon, I agree with you. Besides your change, we also need to fix similar issue in line 230/238.
Actually line 230 caused the issue described in the ticket.

…cleanup

kiwiflyer · 2016-03-08T15:16:42Z

@ustcweizhou I've cleaned up the other 2 exceptions and also removed the newline you pointed out eariler.

ustcweizhou · 2016-03-08T15:39:53Z

@kiwiflyer code LGTM.
can you
(1) squash the commits,
(2) add a space before s_logger.info ? We use 4 space indentation in java.

kiwiflyer · 2016-03-08T16:31:03Z

@ustcweizhou Does 3683dff work?

ustcweizhou · 2016-03-16T21:27:34Z

@kiwiflyer 3683dff LGTM

ustcweizhou · 2016-03-18T07:27:36Z

stop the management server, and restart cloudstack-agent during the stopping.

without the commit 3683dff :

2016-03-17 21:25:26,359 ERROR [utils.nio.NioConnection] (main:null) Unable to initialize the threads.
java.io.IOException: Connection closed with -1 on reading size.
at com.cloud.utils.nio.Link.doHandshake(Link.java:513)
at com.cloud.utils.nio.NioClient.init(NioClient.java:80)
at com.cloud.utils.nio.NioConnection.start(NioConnection.java:88)
at com.cloud.agent.Agent.start(Agent.java:228)
at com.cloud.agent.AgentShell.launchAgent(AgentShell.java:401)
at com.cloud.agent.AgentShell.launchAgentFromClassInfo(AgentShell.java:369)
at com.cloud.agent.AgentShell.launchAgent(AgentShell.java:353)
at com.cloud.agent.AgentShell.start(AgentShell.java:463)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.commons.daemon.support.DaemonLoader.start(DaemonLoader.java:243)
2016-03-17 21:25:26,362 INFO [utils.exception.CSExceptionErrorCode] (main:null) Could not find exception: com.cloud.utils.exception.NioConnectionException in error code list for exceptions
2016-03-17 21:25:26,362 ERROR [cloud.agent.AgentShell] (main:null) Unable to start agent:
com.cloud.utils.exception.CloudRuntimeException: Unable to start the connection!
at com.cloud.agent.Agent.start(Agent.java:230)
at com.cloud.agent.AgentShell.launchAgent(AgentShell.java:401)
at com.cloud.agent.AgentShell.launchAgentFromClassInfo(AgentShell.java:369)
at com.cloud.agent.AgentShell.launchAgent(AgentShell.java:353)
at com.cloud.agent.AgentShell.start(AgentShell.java:463)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.commons.daemon.support.DaemonLoader.start(DaemonLoader.java:243)
Caused by: com.cloud.utils.exception.NioConnectionException: Connection closed with -1 on reading size.
at com.cloud.utils.nio.NioConnection.start(NioConnection.java:94)
at com.cloud.agent.Agent.start(Agent.java:228)
... 9 more
Caused by: java.io.IOException: Connection closed with -1 on reading size.
at com.cloud.utils.nio.Link.doHandshake(Link.java:513)
at com.cloud.utils.nio.NioClient.init(NioClient.java:80)
at com.cloud.utils.nio.NioConnection.start(NioConnection.java:88)
... 10 more
2016-03-17 21:25:26,363 INFO [cloud.agent.Agent] (AgentShutdownThread:null) Stopping the agent: Reason = sig.kill
2016-03-17 21:25:26,364 DEBUG [cloud.agent.Agent] (AgentShutdownThread:null) Sending shutdown to management server

with the commit 3683dff ,
agent.log show the following log every 5 seconds, until agent connects to management server:

2016-03-18 08:10:45,518 INFO [utils.nio.NioClient] (main:null) Connecting to 172.16.15.10:8250
2016-03-18 08:10:45,529 ERROR [utils.nio.NioConnection] (main:null) Unable to initialize the threads.
java.io.IOException: Connection closed with -1 on reading size.
at com.cloud.utils.nio.Link.doHandshake(Link.java:513)
at com.cloud.utils.nio.NioClient.init(NioClient.java:80)
at com.cloud.utils.nio.NioConnection.start(NioConnection.java:88)
at com.cloud.agent.Agent.start(Agent.java:236)
at com.cloud.agent.AgentShell.launchAgent(AgentShell.java:401)
at com.cloud.agent.AgentShell.launchAgentFromClassInfo(AgentShell.java:369)
at com.cloud.agent.AgentShell.launchAgent(AgentShell.java:353)
at com.cloud.agent.AgentShell.start(AgentShell.java:463)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.apache.commons.daemon.support.DaemonLoader.start(DaemonLoader.java:243)
2016-03-18 08:10:45,530 INFO [utils.exception.CSExceptionErrorCode] (main:null) Could not find exception: com.cloud.utils.exception.NioConnectionException in error code list for exceptions
2016-03-18 08:10:45,530 INFO [cloud.agent.Agent] (main:null) Attempted to connect to the server, but received an unexpected exception, trying again...

kiwiflyer · 2016-03-22T12:27:42Z

Test log for reconnect scenerio:

Agent throws an exception that can never be recovered from when the agent attempts to reconnect and is sent a RST. This case occurs when a load balancer (haproxy) is proxying the traffic and there is no management server active to serve the request on the backend.

Original issue logs from agent.log:

2016-03-03 17:15:36,527 INFO utils.nio.NioClient (logid:) NioClient connection closed
2016-03-03 17:15:36,527 INFO cloud.agent.Agent (logid:) Reconnecting...
2016-03-03 17:15:36,527 INFO utils.nio.NioClient (logid:) Connecting to 10.103.0.154:8250
2016-03-03 17:15:36,540 ERROR utils.nio.NioConnection (logid:) Unable to initialize the threads.
java.io.IOException: Connection closed with -1 on reading size.
at com.cloud.utils.nio.Link.doHandshake(Link.java:513)
at com.cloud.utils.nio.NioClient.init(NioClient.java:80)
at com.cloud.utils.nio.NioConnection.start(NioConnection.java:88)
at com.cloud.agent.Agent.reconnect(Agent.java:413)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:868)
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:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2016-03-03 17:15:36,545 INFO utils.exception.CSExceptionErrorCode (logid:) Could not find exception: com.cloud.utils.exception.NioConnectionException in error code list for exceptions
After the patch is applied:

2016-03-03 17:50:05,190 INFO utils.nio.NioClient (logid:) NioClient connection closed
2016-03-03 17:50:05,190 INFO cloud.agent.Agent (logid:) Reconnecting...
2016-03-03 17:50:05,190 INFO utils.nio.NioClient (logid:) Connecting to 10.103.0.154:8250
2016-03-03 17:50:05,206 ERROR utils.nio.NioConnection (logid:) Unable to initialize the threads.
java.io.IOException: Connection closed with -1 on reading size.
at com.cloud.utils.nio.Link.doHandshake(Link.java:513)
at com.cloud.utils.nio.NioClient.init(NioClient.java:80)
at com.cloud.utils.nio.NioConnection.start(NioConnection.java:88)
at com.cloud.agent.Agent.reconnect(Agent.java:413)
at com.cloud.agent.Agent$ServerHandler.doTask(Agent.java:869)
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:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2016-03-03 17:50:05,210 INFO utils.exception.CSExceptionErrorCode (logid:) Could not find exception: com.cloud.utils.exception.NioConnectionException in error code list for exceptions
2016-03-03 17:50:05,211 INFO cloud.agent.Agent (logid:) Attempted to connect to the server, but received an unexpected exception, trying again...
2016-03-03 17:50:10,211 INFO cloud.agent.Agent (logid:) Reconnecting...
2016-03-03 17:50:10,211 INFO utils.nio.NioClient (logid:) Connecting to 10.103.0.154:8250

This has been tested on 4.7.1 and master.

DaanHoogland · 2016-03-22T12:27:53Z

LGTM based on field experience and code inspection

DaanHoogland · 2016-03-22T12:30:02Z

@swill dear RM, can we merge this in 4.7 and merge forward

CLOUDSTACK-9285 for 4.7.xPer Daan's request, here is a pull request for the 4.7.x release. * pr/1430: Cloudstack 9285 for 4.7.x CLOUDSTACK-9285 - Address original on start exception(s) and newline cleanup Cloudstack 9285 for 4.7.x Signed-off-by: Will Stevens <williamstevens@gmail.com>

rafaelweingartner · 2016-03-24T15:17:09Z

this was merged without functional tests (integration tests)?

swill · 2016-03-24T15:20:26Z

output was posted for test run against master and 4.7. maybe I jumped the gun?

swill · 2016-03-24T15:22:40Z

i will make sure that integration test are run against everything going forward. this judgment call may have been premature.

rafaelweingartner · 2016-03-24T15:32:53Z

The test output you mean was the one posted by @kiwiflyer ?
I had not reviewed this PR (sorry for that), but there are two (2) things here that called my attention.

At class “Agent.java” lines, 230, 238 and 451, (despite being the very same piece of code) I worry about the exception that is not being logged. I mean, we will see that message, but the exception stack that might be useful for debugging will not be logged.

Additionally, the code between lines 232 and 239, it seems that it might occur an infinite loop there (before the commit the throw new CloudRuntimeException would break it). I know that when we deal with a connection to a resource, there are hundreds of things that can go wrong and sometimes if we try once or twice it might solve the problem. However, a code that may enter into an infinite loop with a hidden exception does not sound a neat solution for me.

Would not it be better to retry a few times and then, if nothing changes, let an exception happens to break that flow of execution?

swill · 2016-03-24T15:50:16Z

I see your point and I agree with you. What do you think is a reasonable amount of time to check before we throw the error?

kiwiflyer · 2016-03-24T16:01:47Z

I want to point out that this is taking care of the case where you have a load balancer between the agents and the management server (see original issue notes). I'm personally not convinced that letting an exception be thrown that causes the agent to fail, that is most likely caused by an underlying network connectivity issue is a great solution either. Tomcat doesn't get taken down, so the agent container is functional, but the application is dead.

If a set number of retries is added, there has to be a clean termination of the agent so some other health checking application can restart the agent, without requiring manual intervention (very painful if you have lots of hosts).

swill · 2016-03-24T16:05:01Z

so you are basically saying that if the connection can not be established, it is not functional anyway, so there is no point in this timing out?

rafaelweingartner · 2016-03-24T16:12:28Z

That is it;
Well, giving that the “_shell.getBackoffAlgorithm().waitBeforeRetry()” uses a parameter that indicates the amount of time between retries, I would try for 10-20 times before throwing an exception.
If after “n” times the error keeps happening, I see no reason to keep trying. The administrator should be able to see that error and act to solve it.

@ kiwiflyer, I do not know that class. Is that the agent we use in system VMs? Or the ones we install in some hypervisors?

kiwiflyer · 2016-03-24T16:16:26Z

@rafaelweingartner This is used in both the system VM agent and the host (hypervisor) agent.

kiwiflyer · 2016-03-24T16:20:34Z

@swill This exception is thrown when the NIO operations used to establish the connection to the management server on port 8250 fail.When this exception gets thrown, the agent is dead and has to be manually restarted. The tomcat container, however, is still up.

rafaelweingartner · 2016-03-24T16:33:29Z

Ok,
So, this agent class is executed as a service in the operating system (OS) of hosts and system VMs, the OS will call a service that calls the main method that instantiates and executes that agent right?

If an exception is thrown and it is not handled properly the agent dies. If the agent dies, ACS does not deal with it, right?

In that case, I would be inclined to accept the infinite loop when starting a connection. I would only suggest not hiding the exception there, and logging it together with messages at lines 239, 238 and 415.

I just wonder why we need to maintain a connection like this one always open. For me, it seems that if we only opened it when sending a command/message, then we could send the command/message, and after that we could close the connection. Therefore, if it is not possible to open a connection we could just lose a command/message (just thoughts, nothing that we would do right now).

kiwiflyer · 2016-03-24T16:44:40Z

@rafaelweingartner Yes, you are correct. I like your suggestion. I'll log the exception with the failure.

In terms of the persistent connections, I believe the management server pushes to the agents. It also relies on the agent connection to determine health information for the agent and the VMs located on each host.

rafaelweingartner · 2016-03-24T16:49:45Z

@kiwiflyer, it is nice that we achieved a consensus.
What do you think @swill?

How do we proceed now? This PR has already been merged and forwarded.
I believe the easiest approach would be to open a new one just adding the exceptions to the log.

swill · 2016-03-24T16:59:37Z

@rafaelweingartner I agree. I think it makes the most sense to open a new PR to add the exception log. @kiwiflyer would you mind doing that for us? Would you mind giving the output as you did before to show what is displayed in the logs when this code is hit?

Thanks for the quick and quality discussion on this guys.

rafaelweingartner · 2016-03-24T17:11:14Z

You are welcome.
I try to go over as many PRs as I can, but I always end up overlooking some. You can always ping me on slack or mail to check a PR before a merge.

swill · 2016-03-24T17:24:37Z

Thank you sir. I really appreciate it. Once I get my CI online I will be able to start getting through this backlog in a much more efficient manner.

kiwiflyer · 2016-03-24T18:15:40Z

@swill Yes, I'll work on this either today or tomorrow and get a new PR submitted.

Thanks guys.

Cloudstack 9285 for 4.7.x
5b6fbe6

ustcweizhou reviewed Mar 7, 2016
View reviewed changes

CLOUDSTACK-9285 - Address original on start exception(s) and newline …
c69a242
…cleanup

Simon Weller added 2 commits March 8, 2016 09:48

Cloudstack 9285 for 4.7.x
3683dff

Cloudstack-9285
454ea4a

kiwiflyer mentioned this pull request Mar 18, 2016
CLOUDSTACK-9285 - Agent throws an exception on reconnect and fails #1429
Closed

asfgit merged commit 454ea4a into apache:4.7Mar 24, 2016

Uh oh!

Conversation

kiwiflyer commented Mar 7, 2016

Uh oh!

ustcweizhouMar 7, 2016

Choose a reason for hiding this comment

Uh oh!

kiwiflyer commented Mar 7, 2016

Uh oh!

ustcweizhou commented Mar 8, 2016

Uh oh!

kiwiflyer commented Mar 8, 2016

Uh oh!

ustcweizhou commented Mar 8, 2016

Uh oh!

kiwiflyer commented Mar 8, 2016

Uh oh!

ustcweizhou commented Mar 8, 2016

Uh oh!

kiwiflyer commented Mar 8, 2016

Uh oh!

ustcweizhou commented Mar 16, 2016

Uh oh!

ustcweizhou commented Mar 18, 2016

Uh oh!

kiwiflyer commented Mar 22, 2016

Uh oh!

DaanHoogland commented Mar 22, 2016

Uh oh!

DaanHoogland commented Mar 22, 2016

Uh oh!

rafaelweingartner commented Mar 24, 2016

Uh oh!

swill commented Mar 24, 2016

Uh oh!

swill commented Mar 24, 2016

Uh oh!

rafaelweingartner commented Mar 24, 2016

Uh oh!

swill commented Mar 24, 2016

Uh oh!

kiwiflyer commented Mar 24, 2016

Uh oh!

swill commented Mar 24, 2016

Uh oh!

rafaelweingartner commented Mar 24, 2016

Uh oh!

kiwiflyer commented Mar 24, 2016

Uh oh!

kiwiflyer commented Mar 24, 2016

Uh oh!

rafaelweingartner commented Mar 24, 2016

Uh oh!

kiwiflyer commented Mar 24, 2016

Uh oh!

rafaelweingartner commented Mar 24, 2016

Uh oh!

swill commented Mar 24, 2016

Uh oh!

rafaelweingartner commented Mar 24, 2016

Uh oh!

swill commented Mar 24, 2016

Uh oh!

kiwiflyer commented Mar 24, 2016

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants