Description of problem: Getting continuous errors as below in vdsm logs: Detector thread::DEBUG::2015-04-10 11:33:40,938::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof Detector thread::DEBUG::2015-04-10 11:33:40,938::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof Detector thread::DEBUG::2015-04-10 11:33:40,938::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof Detector thread::DEBUG::2015-04-10 11:33:40,938::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof Detector thread::DEBUG::2015-04-10 11:33:40,938::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof Detector thread::DEBUG::2015-04-10 11:33:40,938::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof Can we get some clarification on functioning of the code mentioned in additional information. Version-Release number of selected component (if applicable): vdsm-4.16.8.1-8.el6ev.x86_64 Actual results: errors are continuous. Expected results: errors should not occur. Additional info: We have checked the code and think that we do not handle the exception correctly. We close the related socket "socket.close()", but shouldn't we also remove the connection by calling "self._remove_connection(socket)" when handling the exception? This would prevent the protocol detector from flooding the logs. Related code: vdsm/protocoldetector.py: ============================================================================= 42 class MultiProtocolAcceptor: ... 214 def _process_handshake(self, socket): 215 try: 216 socket.is_handshaking = (socket.accept_ssl() == 0) 217 except Exception as e: 218 self.log.debug("Error during handshake: %s", e) 219 socket.close() 220 else: 221 if not socket.is_handshaking: 222 self._poller.modify(socket, self.READ_ONLY_MASK) =============================================================================
Seems to be related to BZ #1211236
Have you done recent upgrades of the engine or a host?
Is this related to bug #1211236 ? may be the same steps lead to that ? please check that and close if yes. I changed the title as this bug is not about the logging reports - the log prints are relevant and must be reported (as debug level) for each fail incoming attempt to communicate with vdsm (each log related to different incoming connection). If the attempts should be limited when this exception raises it should be fixed in engine side by recognizing the exception and stop trying to send requires to vdsm.
(In reply to Yaniv Bronhaim from comment #5) > Is this related to bug #1211236 ? may be the same steps lead to that ? > please check that and close if yes. > > I changed the title as this bug is not about the logging reports - the log > prints are relevant and must be reported (as debug level) for each fail > incoming attempt to communicate with vdsm (each log related to different > incoming connection). > > If the attempts should be limited when this exception raises it should be > fixed in engine side by recognizing the exception and stop trying to send > requires to vdsm. I will clarify the problem. I suppose there is a misunderstanding. The problem is not related to communication between the engine and the vdsm. This is caused by any connection to port 54321. For instance run telnet # telnet <IP> 54321 Then send a couple of strings. The vdsm logs will get flooded by messages. This will take 30 sec and then the connection is ended. This particular issue is related to nagios that is monitoring port 54321. We for sure should log the event, but we should not flood the logs. The client does not send anything when the logs are being flooded. Shouldn't we close the connection if we know that the connection is correct?
I have same error when I upgrade ovirt form 3.5rc1 to 3.5.2,then I install node, the console always say "installation failed. Network error during communication with the host" And I found in kvm node , vdsm use high cpu 100%,and /var/log/vdsm/vdsm.log print continue very quickly Detector thread::DEBUG::2015-05-08 09:11:04,954::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof Detector thread::DEBUG::2015-05-08 09:11:04,954::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof In node, "lsof | grep 54321" show many CLOSE_WAIT vdsm 17351 vdsm 23u IPv4 414289 0t0 TCP *:54321 (LISTEN) vdsm 17351 vdsm 33u IPv4 495074 0t0 TCP kvmnode-60-1:54321->kvmstack-60-1.zue.alipay.com:50243 (CLOSE_WAIT) vdsm 17351 vdsm 35u IPv4 495135 0t0 TCP kvmnode-60-1:54321->kvmstack-60-1.zue.alipay.com:41322 (CLOSE_WAIT) vdsm 17351 vdsm 36u IPv4 495165 0t0 TCP kvmnode-60-1:54321->kvmstack-60-1.zue.alipay.com:41546 (CLOSE_WAIT) In Console, /var/log/ovirt-engine/engine.log show 2015-05-08 10:18:45,229 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand] (DefaultQuartzScheduler_Worker-36) Command GetCapabilitiesVDSCommand(HostName = kvmnode-60-1, HostId = 4f15a0a6-1039-41bd-a328-1ccf51881f5e, vds=Host[kvmnode-60-1,4f15a0a6-1039-41bd-a328-1ccf51881f5e]) execution failed. Exception: VDSNetworkException: javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate) 2015-05-08 10:18:45,231 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-36) Host kvmnode-60-1 is not responding. It will stay in Connecting state for a grace period of $60 seconds and after that an attempt to fence the host will be issued. 2015-05-08 10:18:45,233 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-36) Failure to refresh Vds runtime info: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate) at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createNetworkException(VdsBrokerCommand.java:126) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:101) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:56) [vdsbroker.jar:] at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:31) [dal.jar:] at org.ovirt.engine.core.vdsbroker.VdsManager.refreshCapabilities(VdsManager.java:566) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVdsRunTimeInfo(VdsUpdateRunTimeInfo.java:628) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refresh(VdsUpdateRunTimeInfo.java:485) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:235) [vdsbroker.jar:] at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source) [:1.7.0_79] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_79] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_79] at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:60) [scheduler.jar:] at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:] at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz.jar:] Caused by: javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate) at sun.security.ssl.Handshaker.activate(Handshaker.java:470) [jsse.jar:1.7.0_79] at sun.security.ssl.SSLSocketImpl.kickstartHandshake(SSLSocketImpl.java:1438) [jsse.jar:1.7.0_79] at sun.security.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1308) [jsse.jar:1.7.0_79] at sun.security.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:709) [jsse.jar:1.7.0_79] at sun.security.ssl.AppOutputStream.write(AppOutputStream.java:122) [jsse.jar:1.7.0_79] at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) [rt.jar:1.7.0_79] at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) [rt.jar:1.7.0_79] at java.io.FilterOutputStream.flush(FilterOutputStream.java:140) [rt.jar:1.7.0_79] at org.apache.xmlrpc.client.XmlRpcCommonsTransport$1$1.close(XmlRpcCommonsTransport.java:204) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcHttpTransport$ByteArrayReqWriter.write(XmlRpcHttpTransport.java:55) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcCommonsTransport$1.writeRequest(XmlRpcCommonsTransport.java:214) [xmlrpc-client.jar:3.1.3] at org.apache.commons.httpclient.methods.EntityEnclosingMethod.writeRequestBody(EntityEnclosingMethod.java:499) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpMethodBase.writeRequest(HttpMethodBase.java:2114) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpMethodBase.execute(HttpMethodBase.java:1096) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:398) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323) [commons-httpclient.jar:] at org.apache.xmlrpc.client.XmlRpcCommonsTransport.writeRequest(XmlRpcCommonsTransport.java:227) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcStreamTransport.sendRequest(XmlRpcStreamTransport.java:151) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcHttpTransport.sendRequest(XmlRpcHttpTransport.java:143) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcClientWorker.execute(XmlRpcClientWorker.java:56) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcClient.execute(XmlRpcClient.java:167) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcClient.execute(XmlRpcClient.java:137) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcClient.execute(XmlRpcClient.java:126) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.util.ClientFactory$1.invoke(ClientFactory.java:140) [xmlrpc-client.jar:3.1.3] at com.sun.proxy.$Proxy80.getVdsCapabilities(Unknown Source) at sun.reflect.GeneratedMethodAccessor19.invoke(Unknown Source) [:1.7.0_79] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_79] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_79] at org.ovirt.engine.core.vdsbroker.xmlrpc.XmlRpcUtils$AsyncProxy$InternalCallable.call(XmlRpcUtils.java:242) [vdsbroker.jar:] at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_79] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_79] at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_79] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_79] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_79] at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_79] 2015-05-08 10:18:45,538 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetCapabilitiesVDSCommand] (DefaultQuartzScheduler_Worker-29) Command GetCapabilitiesVDSCommand(HostName = kvmnode-80-2, HostId = 9f21952f-a8df-4db1-944c-254494f094ca, vds=Host[kvmnode-80-2,9f21952f-a8df-4db1-944c-254494f094ca]) execution failed. Exception: VDSNetworkException: java.net.ConnectException: Connection refused 2015-05-08 10:18:45,541 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (DefaultQuartzScheduler_Worker-29) Host kvmnode-80-2 is not responding. It will stay in Connecting state for a grace period of $160 seconds and after that an attempt to fence the host will be issued. 2015-05-08 10:18:45,544 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-29) Failure to refresh Vds runtime info: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: java.net.ConnectException: Connection refused at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createNetworkException(VdsBrokerCommand.java:126) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:101) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:56) [vdsbroker.jar:] at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:31) [dal.jar:] at org.ovirt.engine.core.vdsbroker.VdsManager.refreshCapabilities(VdsManager.java:566) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refreshVdsRunTimeInfo(VdsUpdateRunTimeInfo.java:628) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo.refresh(VdsUpdateRunTimeInfo.java:485) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VdsManager.onTimer(VdsManager.java:235) [vdsbroker.jar:] at sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source) [:1.7.0_79] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_79] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_79] at org.ovirt.engine.core.utils.timer.JobWrapper.execute(JobWrapper.java:60) [scheduler.jar:] at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz.jar:] at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz.jar:] Caused by: java.net.ConnectException: Connection refused at java.net.PlainSocketImpl.socketConnect(Native Method) [rt.jar:1.7.0_79] at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) [rt.jar:1.7.0_79] at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) [rt.jar:1.7.0_79] at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) [rt.jar:1.7.0_79] at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) [rt.jar:1.7.0_79] at java.net.Socket.connect(Socket.java:579) [rt.jar:1.7.0_79] at sun.security.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:625) [jsse.jar:1.7.0_79] at org.ovirt.engine.core.utils.ssl.AuthSSLProtocolSocketFactory.createSocket(AuthSSLProtocolSocketFactory.java:288) [utils.jar:] at org.apache.commons.httpclient.HttpConnection.open(HttpConnection.java:707) [commons-httpclient.jar:] at org.apache.commons.httpclient.MultiThreadedHttpConnectionManager$HttpConnectionAdapter.open(MultiThreadedHttpConnectionManager.java:1361) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpMethodDirector.executeWithRetry(HttpMethodDirector.java:387) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpMethodDirector.executeMethod(HttpMethodDirector.java:171) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:397) [commons-httpclient.jar:] at org.apache.commons.httpclient.HttpClient.executeMethod(HttpClient.java:323) [commons-httpclient.jar:] at org.apache.xmlrpc.client.XmlRpcCommonsTransport.writeRequest(XmlRpcCommonsTransport.java:227) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcStreamTransport.sendRequest(XmlRpcStreamTransport.java:151) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcHttpTransport.sendRequest(XmlRpcHttpTransport.java:143) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcClientWorker.execute(XmlRpcClientWorker.java:56) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcClient.execute(XmlRpcClient.java:167) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcClient.execute(XmlRpcClient.java:137) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.XmlRpcClient.execute(XmlRpcClient.java:126) [xmlrpc-client.jar:3.1.3] at org.apache.xmlrpc.client.util.ClientFactory$1.invoke(ClientFactory.java:140) [xmlrpc-client.jar:3.1.3] at com.sun.proxy.$Proxy80.getVdsCapabilities(Unknown Source) at sun.reflect.GeneratedMethodAccessor19.invoke(Unknown Source) [:1.7.0_79] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_79] at java.lang.reflect.Method.invoke(Method.java:606) [rt.jar:1.7.0_79] at org.ovirt.engine.core.vdsbroker.xmlrpc.XmlRpcUtils$AsyncProxy$InternalCallable.call(XmlRpcUtils.java:242) [vdsbroker.jar:] at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_79] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [rt.jar:1.7.0_79] at java.util.concurrent.FutureTask.run(FutureTask.java:262) [rt.jar:1.7.0_79] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [rt.jar:1.7.0_79] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [rt.jar:1.7.0_79] at java.lang.Thread.run(Thread.java:745) [rt.jar:1.7.0_79]
I have found my template solution from https://access.redhat.com/discussions/1326793 This reason is openjdk 1.7 SSLv3 has been disabled by default, but VDSM is use SSLv3 Temporary workaround until vdsm is fixed to work with TLS is to comment out jdk.tls.disabledAlgorithms=SSLv3 from /usr/lib/jvm/java-1.7.0-openjdk-1.7.0.79.x86_64/jre/lib/security/java.security then restart ovirt-engine /etc/init.d/ovirt-engine restart then I can use node install smoothly.
So afaiu this issue is still about the flooding logs and cpu load. Modifying the topic again - Pioter, please investigate if the high cpu load is related to the prints, and if so how we can avoid this dos - it doesn't sound so reasonable
in second thought - the ticket is related to the communication itself so if Andy's comment #8 is the solution for that please close that bug and open another one regarding the log
You can set ssl algorithm on both sides: - engine - set VdsmSSLProtocol to "TLSv1" - vdsm - in config.py set ssl_protocol to "tlsv1"
This bug applies for 3.5 only and in 3.6 there is completely different. It was fixed for BZ 1229859. *** This bug has been marked as a duplicate of bug 1229859 ***
ok, vdsm-4.16.27-1.el7ev.x86_64 test - 1st just connecting port vdsm port (first 2 lines), then the 2nd test is sending plaintext to port (next 3 lines); thus no flood per connection. # tail -f /var/log/vdsm/vdsm.log | grep -Ei "detector|handshake" Detector thread::DEBUG::2015-09-30 15:59:42,755::protocoldetector::187::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:34845 Detector thread::DEBUG::2015-09-30 16:00:38,992::protocoldetector::201::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:34845 Detector thread::DEBUG::2015-09-30 16:00:53,430::protocoldetector::187::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 127.0.0.1:34846 Detector thread::DEBUG::2015-09-30 16:00:53,430::protocoldetector::207::vds.MultiProtocolAcceptor::(_process_handshake) Error during handshake: unexpected eof Detector thread::DEBUG::2015-09-30 16:00:53,430::protocoldetector::201::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 127.0.0.1:34846
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHBA-2015-1937.html