Bug 1567620 - [Driver] WebSocket connection keeps dropping
Summary: [Driver] WebSocket connection keeps dropping
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: python-networking-odl
Version: 13.0 (Queens)
Hardware: Unspecified
OS: Unspecified
low
low
Target Milestone: ---
: 13.0 (Queens)
Assignee: Mike Kolesnik
QA Contact: Itzik Brown
URL:
Whiteboard: Driver
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-04-15 14:45 UTC by Sai Sindhur Malleni
Modified: 2019-03-06 16:17 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-03-06 16:16:54 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)

Description Sai Sindhur Malleni 2018-04-15 14:45:12 UTC 
Description of problem:
We frequently see the following error messages in neutron-server logs
2018-04-14 21:40:00.902 50 WARNING networking_odl.common.websocket_client [req-dfd5b668-55de-4a85-bd74-02c4c43d86eb - - - - -] websocket connection closed or IO error: WebSocketConnectionClosedException: Connection is already closed.
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client Traceback (most recent call last):
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/networking_odl/common/websocket_client.py", line 124, in run_websocket_thread
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     data = ws.recv()
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_core.py", line 348, in recv
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     opcode, data = self.recv_data()
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_core.py", line 365, in recv_data
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     opcode, frame = self.recv_data_frame(control_frame)
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_core.py", line 378, in recv_data_frame
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     frame = self.recv_frame()
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_core.py", line 410, in recv_frame
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     return self.frame_buffer.recv_frame()
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_abnf.py", line 300, in recv_frame
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     self.recv_header()
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_abnf.py", line 249, in recv_header
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     header = self.recv_strict(2)
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_abnf.py", line 334, in recv_strict
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     bytes = self.recv(min(16384, shortage))
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_core.py", line 476, in _recv
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     return recv(self.sock, bufsize)
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_socket.py", line 89, in recv
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client     raise WebSocketConnectionClosedException("Connection is already closed.")
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client WebSocketConnectionClosedException: Connection is already closed.
2018-04-14 21:40:00.902 50 ERROR networking_odl.common.websocket_client
2018-04-14 21:40:00.902 50 INFO networking_odl.common.websocket_client [req-dfd5b668-55de-4a85-bd74-02c4c43d86eb - - - - -] websocket transition to status ODL_WEBSOCKET_DISCONNECTED
2018-04-14 21:40:00.903 50 INFO networking_odl.common.websocket_client [req-dfd5b668-55de-4a85-bd74-02c4c43d86eb - - - - -] websocket transition to status ODL_WEBSOCKET_CONNECTING
2018-04-14 21:40:00.920 50 INFO networking_odl.common.websocket_client [req-dfd5b668-55de-4a85-bd74-02c4c43d86eb - - - - -] websocket transition to status ODL_WEBSOCKET_CONNECTED


Version-Release number of selected component (if applicable):
OSP 13
python-networking-odl-12.0.1-0.20180228140714.8733cf6.el7ost.noarch
opendaylight-8.0.0-5.el7ost.noarch

How reproducible: 100%


Steps to Reproduce:
1. Install OSP 13 with ODL
2. Run scale tests
3.

Actual results:
WebSocket connection dropped messages in logs

Expected results:
No connection drops

Additional info:
Comment 1 Josh Hershberg 2018-04-16 06:40:47 UTC 
As far as I know, this issue no longer occurs. IIRC, Tim solved this.
Comment 2 Sai Sindhur Malleni 2018-04-16 12:43:15 UTC 
Josh,

This is a very recent puddle, from April 10th. 


Tim, was this fixed?
Comment 3 Tim Rozet 2018-04-16 15:52:02 UTC 
I can't tell from the log, but this is OK as long as it is happening once an hour in an idle state.  The tunnel timeout is 3600s. So if you do not change any ports in an hour the timeout will fire and networking-odl will reconnect.  That should be normal.  Are you seeing it more often than every hour?
Comment 4 Sai Sindhur Malleni 2018-04-17 19:03:56 UTC 
No. seeing it about once every hour. However, wondering if need to throw the stack trace in the log?
Comment 5 Tim Rozet 2018-04-17 19:15:37 UTC 
Yeah we could remove the stack trace to make the log cleaner, since this is only a warning and the output from the trace is in the websocket library and does not really help much anyway.
Comment 6 Ricardo Noriega 2018-11-08 08:56:45 UTC 
Hello guys,

I've just deployed OSP13 with ODL in a customer, and I'm still seeing the following stack traces every hour, which makes it very confusing for the user. 

neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client     frame = self.recv_frame()
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_core.py", line 410, in recv_frame
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client     return self.frame_buffer.recv_frame()
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_abnf.py", line 300, in recv_frame
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client     self.recv_header()
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_abnf.py", line 249, in recv_header
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client     header = self.recv_strict(2)
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_abnf.py", line 334, in recv_strict
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client     bytes = self.recv(min(16384, shortage))
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_core.py", line 476, in _recv
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client     return recv(self.sock, bufsize)
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client   File "/usr/lib/python2.7/site-packages/websocket/_socket.py", line 89, in recv
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client     raise WebSocketConnectionClosedException("Connection is already closed.")
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client WebSocketConnectionClosedException: Connection is already closed.
neutron/server.log:2018-11-08 08:11:05.752 52 ERROR networking_odl.common.websocket_client

Are we removing this trace in the code?
Comment 7 Tim Rozet 2018-11-09 14:35:47 UTC 
It's actually haproxy closing the connection. So networking-odl thinks it is an error and raising an exception. We could perhaps change the haproxy config to never timeout.
Comment 8 Franck Baudin 2019-03-06 16:16:54 UTC 
As per depreciation notice [1], closing this bug. Please reopen if relevant for RHOSP13, as this is the only version shipping ODL.

[1] https://access.redhat.com/documentation/en-us/red_hat_openstack_platform/14/html-single/release_notes/index#deprecated_functionality
Comment 9 Franck Baudin 2019-03-06 16:17:52 UTC 
As per depreciation notice [1], closing this bug. Please reopen if relevant for RHOSP13, as this is the only version shipping ODL.

[1] https://access.redhat.com/documentation/en-us/red_hat_openstack_platform/14/html-single/release_notes/index#deprecated_functionality
Note You need to log in before you can comment on or make changes to this bug.