websocket disconnecting

[geranol]

Description of Issue/Question

websocket is disconnected by server after sending: websocket client ready

Setup

I added a 'traceback.print_ex()' in the exception handling, to get more detail.

Steps to Reproduce Issue

[INFO    ] 101 GET /all_events/f9a702402d87b5e6f2fdf7cc01aa4b9e883fe41425cea80578eb94f1d3918a98 (10.130.10.56) 1.55ms
[DEBUG   ] Got websocket message websocket client ready
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/salt/netapi/rest_tornado/saltnado_websockets.py", line 358, in on_message
    event = yield self.application.event_listener.get_event(self)
  File "/usr/lib/python3/dist-packages/tornado/gen.py", line 1055, in run
    value = future.result()
  File "/usr/lib/python3/dist-packages/tornado/concurrent.py", line 238, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 4, in raise_exc_info
salt.loaded.int.netapi.rest_tornado.saltnado.TimeoutException
[INFO    ] Error! Ending server side websocket connection. Reason = 
[DEBUG   ] In the websocket close method

Versions Report

Salt Version:
           Salt: 2018.3.3
 
Dependency Versions:
           cffi: Not Installed
       cherrypy: unknown
       dateutil: 2.6.1
      docker-py: Not Installed
          gitdb: 2.0.3
      gitpython: 2.1.8
          ioflo: Not Installed
         Jinja2: 2.10
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 3.6.7 (default, Oct 22 2018, 11:32:17)
   python-gnupg: 0.4.1
         PyYAML: 3.12
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: 2.0.3
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.2.5
 
System Versions:
           dist: Ubuntu 18.04 bionic
         locale: UTF-8
        machine: x86_64
        release: 4.15.0-38-generic
         system: Linux
        version: Ubuntu 18.04 bionic

[Ch3LL]

to help replicate the issue can you include a sanitized version of your configurations and the command you are running?

[geranol]

external auth:

external_auth:
  ldap:
    user:
      - .*
      - '@runner'
      - '@wheel'

REST configuration

rest_tornado:
  port: 8001
  debug: False
  disable_ssl: True
  websockets: True

server:

interface: 0.0.0.0
transport: tcp
presence_events: True

pidfile: /var/run/salt/salt-master.pid

file_roots:
  base:
    - /srv/salt/prod

Django management command, to show all events..

import websocket

class Command(BaseCommand):
            
    def handle(self, *args, **options):
        # regex used to check whether an event is a return event
        return_event_regex = re.compile("salt/job/(.*)/ret/(.*)")
        self.listen()

    @staticmethod        
    def on_message(ws, message):
        print("message recieved: %s" % message)

    @staticmethod        
    def on_close(ws):
        print("channel closed")

    @staticmethod
    def on_open(ws):
        # enable salt event stream
        ws.send("websocket client ready")
        
    @staticmethod
    def on_error(ws, error):
        print(error)
        
    def listen(self):
        token = get_token()
        connecturl = "%s/all_events/%s" % (settings.SALT_WS_URL, token)
        
        print("Connect to: %s" % (connecturl))
         
        websocket.enableTrace(True)
        ws = websocket.WebSocketApp(connecturl,
                                  on_message = self.on_message,
                                  on_error = self.on_error,
                                  on_close = self.on_close)
        ws.on_open = self.on_open
        ws.run_forever()

[geranol]

result of 'python manage.py testws'

Connect to: ws://test.local:8001/all_events/3f23c910697828c6478c26d4e267cb74f11ce9e7eef0bebf2b3d761086fc6d48
--- request header ---
GET /all_events/3f23c910697828c6478c26d4e267cb74f11ce9e7eef0bebf2b3d761086fc6d48 HTTP/1.1
Upgrade: websocket
Connection: Upgrade
Host: test.local:8001
Origin: http://test.local:8001
Sec-WebSocket-Key: BjXRrPpOAGq6VM3CTELtjg==
Sec-WebSocket-Version: 13


-----------------------
--- response header ---
HTTP/1.1 101 Switching Protocols
Server: TornadoServer/4.5.3
Date: Wed, 05 Dec 2018 07:35:16 GMT
Upgrade: websocket
Connection: Upgrade
Sec-Websocket-Accept: 4YdRqogJSCuXdEt2FFZncmggjfI=
-----------------------
send: b'\x81\x96j\xe6\x94H\x1d\x83\xf6;\x05\x85\xff-\x1e\xc6\xf7$\x03\x83\xfa<J\x94\xf1)\x0e\x9f'
send: b'\x88\x82\x0f\xdb6>\x0c3'
channel closed

[Ch3LL]

I am seeing these errors in the api logs after i run a command salt '*' test.ping and an event goes through, but never on startup:

2018-12-05 16:40:11,011 [salt.loaded.int.netapi.rest_tornado.saltnado_websockets:320 ][DEBUG   ][19385] In the websocket get method
2018-12-05 16:40:11,013 [salt.loaded.int.netapi.rest_tornado.saltnado_websockets:345 ][DEBUG   ][19385] Got websocket message websocket client ready
2018-12-05 16:40:31,596 [salt.loaded.int.netapi.rest_tornado.saltnado_websockets:360 ][INFO    ][19385] Error! Ending server side websocket connection. Reason = 

But i never get the channel closed as you can see here:

[root@d52cd9bf0d04 /]# python manage.py testws
Connect to: wss://localhost:8001/all_events/44459dc12b765fc51671220fe35a43252fcade9bccbad5a4f773a20332a3fcef
--- request header ---
GET /all_events/44459dc12b765fc51671220fe35a43252fcade9bccbad5a4f773a20332a3fcef HTTP/1.1
Upgrade: websocket
Connection: Upgrade
Host: localhost:8001
Origin: http://localhost:8001
Sec-WebSocket-Key: 367BzmkIfiUiyJ6m8J6muw==
Sec-WebSocket-Version: 13


-----------------------
--- response header ---
HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Accept: F7jSsLuyLccZ0V51aBWqbSsCRpU=
-----------------------
send: '\x81\x96\xf9\xf0\x84\x02\x8e\x95\xe6q\x96\x93\xefg\x8d\xd0\xe7n\x90\x95\xeav\xd9\x82\xe1c\x9d\x89'
message recieved: {"tag": "salt/job/20181205164031595269/new", "data": {"tgt_type": "glob", "jid": "20181205164031595269", "tgt": "*", "missing": [], "_stamp": "2018-12-05T16:40:31.596286", "user": "root", "arg": [], "fun": "test.ping", "minions": ["c6c2e89d6b0b"]}}
message recieved: {"tag": "salt/job/20181205164031595269/ret/c6c2e89d6b0b", "data": {"fun_args": [], "jid": "20181205164031595269", "return": true, "retcode": 0, "success": true, "cmd": "_return",
"_stamp": "2018-12-05T16:40:31.644166", "fun": "test.ping", "id": "c6c2e89d6b0b"}}

Are you running this script outside of Django as well when you see this behavior?

[geranol]

Yes, I see the same behaviour when a scipt that has no dependencies to django.

[Ch3LL]

thanks for clarifying. and can you verify the salt-api is functional and the master is running? In your exception there you are receiving a timeout when trying to get the events, so i'm wondering if the event bus on the master is not up all the way or if there is an error on that end.

[geranol]

I can confirm that the Salt-api is functional, because authorization provides a token, sending commands through /minion url is also fine.

As a temp workaround until the websocket is working again for me (PS. on a previous release 2017xx and python 2.7 ws did work) I hook up on the event bus on the master (salt.utils.event.get_event) and publish events with MQTT. Therefore I can confirm that nothing seems wrong with the even bus.

[Ch3LL]

thanks for confirming. Since i am having a hard time replicating this is it possible for you to bisect the issue since you said it was working on 2017.7?

[dbellavista]

The culprit is Tornado: 4.5.3 doing pip3 install tornado==4.4.3 solves the issue.

I was experiencing the same issue with:

> salt-master -V
Salt Version:
           Salt: 2019.2.2
 
Dependency Versions:
           cffi: Not Installed
       cherrypy: 8.9.1
       dateutil: 2.6.1
      docker-py: 4.1.0
          gitdb: 2.0.6
      gitpython: 3.0.5
          ioflo: Not Installed
         Jinja2: 2.10
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 3.6.8 (default, Oct  7 2019, 12:59:55)
   python-gnupg: 0.4.1
         PyYAML: 3.12
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: 2.0.5
        timelib: Not Installed
        Tornado: 4.5.3
            ZMQ: 4.2.5
 
System Versions:
           dist: Ubuntu 18.04 bionic
         locale: UTF-8
        machine: x86_64
        release: 4.15.0-55-generic
         system: Linux
        version: Ubuntu 18.04 bionic

But solved with

Salt Version:
           Salt: 2019.2.2
 
Dependency Versions:
           cffi: Not Installed
       cherrypy: 8.9.1
       dateutil: 2.6.1
      docker-py: 4.1.0
          gitdb: 2.0.6
      gitpython: 3.0.5
          ioflo: Not Installed
         Jinja2: 2.10
        libgit2: Not Installed
        libnacl: Not Installed
       M2Crypto: Not Installed
           Mako: Not Installed
   msgpack-pure: Not Installed
 msgpack-python: 0.5.6
   mysql-python: Not Installed
      pycparser: Not Installed
       pycrypto: 2.6.1
   pycryptodome: Not Installed
         pygit2: Not Installed
         Python: 3.6.8 (default, Oct  7 2019, 12:59:55)
   python-gnupg: 0.4.1
         PyYAML: 3.12
          PyZMQ: 16.0.2
           RAET: Not Installed
          smmap: 2.0.5
        timelib: Not Installed
        Tornado: 4.4.3
            ZMQ: 4.2.5
 
System Versions:
           dist: Ubuntu 18.04 bionic
         locale: UTF-8
        machine: x86_64
        release: 4.15.0-55-generic
         system: Linux
        version: Ubuntu 18.04 bionic

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

If this issue is closed prematurely, please leave a comment and we will gladly reopen the issue.