search

cortictechnology / cep

CEP is a software platform designed for users that want to learn or rapidly prototype using standard A.I. components.
MIT License
166 stars 21 forks source link

CAIT Setup page looping #19

Closed acommuni closed 2 years ago

acommuni commented 2 years ago

The setup page of CAIT remains in an infinite loop on message "Retreiving device information ..."

image

image

The only AJAX Request in error is the /getwifi page.

There is the following message in syslog

Feb  9 20:28:16 raspberrypi bash[467]: ERROR:flask.app:Exception on /getwifi [GET]
Feb  9 20:28:16 raspberrypi bash[467]: Traceback (most recent call last):
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/local/lib/python3.7/dist-packages/wifi/scan.py", line 39, in all
Feb  9 20:28:16 raspberrypi bash[467]:     stderr=subprocess.STDOUT)
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/lib/python3.7/subprocess.py", line 395, in check_output
Feb  9 20:28:16 raspberrypi bash[467]:     **kwargs).stdout
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/lib/python3.7/subprocess.py", line 487, in run
Feb  9 20:28:16 raspberrypi bash[467]:     output=stdout, stderr=stderr)
Feb  9 20:28:16 raspberrypi bash[467]: subprocess.CalledProcessError: Command '['/sbin/iwlist', 'wlan0', 'scan']' returned non-zero exit status 255.
Feb  9 20:28:16 raspberrypi bash[467]: During handling of the above exception, another exception occurred:
Feb  9 20:28:16 raspberrypi bash[467]: Traceback (most recent call last):
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/lib/python3/dist-packages/flask/app.py", line 2292, in wsgi_app
Feb  9 20:28:16 raspberrypi bash[467]:     response = self.full_dispatch_request()
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/lib/python3/dist-packages/flask/app.py", line 1815, in full_dispatch_request
Feb  9 20:28:16 raspberrypi bash[467]:     rv = self.handle_user_exception(e)
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/local/lib/python3.7/dist-packages/flask_cors/extension.py", line 165, in wrapped_function
Feb  9 20:28:16 raspberrypi bash[467]:     return cors_after_request(app.make_response(f(*args, **kwargs)))
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/lib/python3/dist-packages/flask/app.py", line 1718, in handle_user_exception
Feb  9 20:28:16 raspberrypi bash[467]:     reraise(exc_type, exc_value, tb)
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/lib/python3/dist-packages/flask/_compat.py", line 35, in reraise
Feb  9 20:28:16 raspberrypi bash[467]:     raise value
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/lib/python3/dist-packages/flask/app.py", line 1813, in full_dispatch_request
Feb  9 20:28:16 raspberrypi bash[467]:     rv = self.dispatch_request()
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/lib/python3/dist-packages/flask/app.py", line 1799, in dispatch_request
Feb  9 20:28:16 raspberrypi bash[467]:     return self.view_functions[rule.endpoint](**req.view_args)
Feb  9 20:28:16 raspberrypi bash[467]:   File "/home/pi/ia/cep/src/cait/cortic_webapp/main.py", line 180, in getwifi
Feb  9 20:28:16 raspberrypi bash[467]:     cells = list(Cell.all("wlan0"))
Feb  9 20:28:16 raspberrypi bash[467]:   File "/usr/local/lib/python3.7/dist-packages/wifi/scan.py", line 41, in all
Feb  9 20:28:16 raspberrypi bash[467]:     raise InterfaceError(e.output.strip())
Feb  9 20:28:16 raspberrypi bash[467]: wifi.exceptions.InterfaceError: b"wlan0     Interface doesn't support scanning : Device or resource busy"

When I run the command : iwlist wlan0 scan

There is no error : 

wlan0     Scan completed :
          Cell 01 - Address: XX:XX:XX:XX:XX
                    Channel:6
                    Frequency:2.437 GHz (Channel 6)
                    Quality=70/70  Signal level=-31 dBm
                    Encryption key:on
                    ESSID:"XZ"
                    Bit Rates:1 Mb/s; 2 Mb/s; 5.5 Mb/s; 11 Mb/s; 6 Mb/s
                    ....
michaelhwn commented 2 years ago

Hi @acommuni, there is one more reason that can also cause the never-ending spinning, that is the setup page is failing to receive heartbeat messages from the CAIT interface https://github.com/cortictechnology/cep/blob/d3fb4bdbca744d4ae4e6a97c001a85506d67bd8b/src/cait/cait/core.py#L71, it can either be the device's MQTT broker is not running, or the CAIT interface failed to start. I will also look into the WiFi scanning error. I will let you know once I figure out the root cause of this issue.

acommuni commented 2 years ago

Hi Michael,

MQTT seems to be OK (First extract of logs). getwIfi seems to be sometimes to ok and sometimes not (See second extract of logs). gewifi is requested very often (less than 1s), it could be the reason of the failure. One request could be sent before the previous is correctly ended. 

Feb 10 22:39:57 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m TensorFlow: v2.3.0-6-g23ad988
Feb 10 22:39:57 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m DeepSpeech: v0.9.1-0-gab8bd3e
Feb 10 22:39:58 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m pygame 1.9.6
Feb 10 22:39:58 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m Hello from the pygame community. https://www.pygame.org/contribute.html
Feb 10 22:39:59 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Loading model lib now
Feb 10 22:39:59 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Model lib successfully loaded
Feb 10 22:39:59 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Loading model lib now
Feb 10 22:40:00 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Model lib successfully loaded
Feb 10 22:40:00 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Loading model lib now
Feb 10 22:40:00 raspberrypi bash[468]: #033[32mcurt_homeassistant_1  |#033[0m #033[33m2022-02-10 13:40:00 WARNING (Recorder) [homeassistant.components.recorder.util] The system could not validate that the sqlite3 database at //config/home-assistant_v2.db was shutdown cleanly#033[0m
Feb 10 22:40:00 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Model lib successfully loaded
Feb 10 22:40:01 raspberrypi bash[468]: #033[32mcurt_homeassistant_1  |#033[0m #033[33m2022-02-10 13:40:01 WARNING (Recorder) [homeassistant.components.recorder.util] Ended unfinished session (id=427 from 2022-02-09 20:51:18.503241)#033[0m
Feb 10 22:40:01 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Loading model lib now
Feb 10 22:40:01 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Model lib successfully loaded
Feb 10 22:40:04 raspberrypi bash[468]: #033[32mcurt_homeassistant_1  |#033[0m #033[33m2022-02-10 13:40:04 WARNING (MainThread) [homeassistant.components.met] Skip setting up met.no integration; No Home location has been set#033[0m
Feb 10 22:40:09 raspberrypi bash[468]: #033[36mcurt_broker_1         |#033[0m EMQ X Broker v4.1.0-alpha.1 is started successfully!
Feb 10 22:40:09 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m WARNING:root:Found a curt broker at: 192.168.1.28
Feb 10 22:40:09 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m WARNING:root:Found a curt broker at: 192.168.1.28
Feb 10 22:40:09 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m WARNING:root:Found a curt broker at: 192.168.1.28
Feb 10 22:40:09 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m voice module initialized.
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m WARNING:root:Found a curt broker at: 192.168.1.28
Feb 10 22:40:09 raspberrypi bash[468]: #033[34mcurt_smarthome_1      |#033[0m WARNING:root:Found a curt broker at: 192.168.1.28
Feb 10 22:40:09 raspberrypi bash[468]: #033[34mcurt_smarthome_1      |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[34mcurt_smarthome_1      |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m INFO:root:Connected to broker
Feb 10 22:40:09 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m INFO:root:voice connected to broker with result code 0
Feb 10 22:40:09 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m INFO:root:voice subscribed to: cait/config/raspberrypi/voice
Feb 10 22:40:09 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m INFO:root:vision connected to broker with result code 0
Feb 10 22:40:09 raspberrypi bash[468]: #033[33;1mcurt_voice_1          |#033[0m INFO:root:voice subscribed to: cait/task/raspberrypi/voice
Feb 10 22:40:09 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m INFO:root:vision subscribed to: cait/config/raspberrypi/vision
Feb 10 22:40:09 raspberrypi bash[468]: #033[36;1mcurt_vision_1         |#033[0m INFO:root:vision subscribed to: cait/task/raspberrypi/vision
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m INFO:root:control connected to broker with result code 0
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m INFO:root:nlp connected to broker with result code 0
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m INFO:root:control subscribed to: cait/config/raspberrypi/control
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m INFO:root:control subscribed to: cait/task/raspberrypi/control
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m INFO:root:nlp subscribed to: cait/config/raspberrypi/nlp
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m INFO:root:nlp subscribed to: cait/task/raspberrypi/nlp
Feb 10 22:40:09 raspberrypi bash[468]: #033[34mcurt_smarthome_1      |#033[0m INFO:root:smarthome connected to broker with result code 0
Feb 10 22:40:09 raspberrypi bash[468]: #033[34mcurt_smarthome_1      |#033[0m INFO:root:smarthome subscribed to: cait/config/raspberrypi/smarthome
Feb 10 22:40:09 raspberrypi bash[468]: #033[34mcurt_smarthome_1      |#033[0m INFO:root:smarthome subscribed to: cait/task/raspberrypi/smarthome
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m ERROR:root:Traceback (most recent call last):
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m   File "/data/curt/base_module.py", line 147, in on_message
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m     data = json.loads(data)
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m   File "/usr/local/lib/python3.5/json/__init__.py", line 319, in loads
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m     return _default_decoder.decode(s)
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m   File "/usr/local/lib/python3.5/json/decoder.py", line 339, in decode
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m   File "/usr/local/lib/python3.5/json/decoder.py", line 357, in raw_decode
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m     raise JSONDecodeError("Expecting value", s, err.value) from None
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m ERROR:root:Traceback (most recent call last):
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m   File "/data/curt/base_module.py", line 147, in on_message
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m     data = json.loads(data)
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m   File "/usr/local/lib/python3.7/json/__init__.py", line 348, in loads
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m     return _default_decoder.decode(s)
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m   File "/usr/local/lib/python3.7/json/decoder.py", line 337, in decode
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m   File "/usr/local/lib/python3.7/json/decoder.py", line 355, in raw_decode
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m     raise JSONDecodeError("Expecting value", s, err.value) from None
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Feb 10 22:40:09 raspberrypi bash[468]: #033[35mcurt_nlp_1            |#033[0m
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m ERROR:root:Traceback (most recent call last):
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m   File "/data/curt/base_module.py", line 147, in on_message
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m     data = json.loads(data)
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m   File "/usr/local/lib/python3.5/json/__init__.py", line 319, in loads
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m     return _default_decoder.decode(s)
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m   File "/usr/local/lib/python3.5/json/decoder.py", line 339, in decode
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m   File "/usr/local/lib/python3.5/json/decoder.py", line 357, in raw_decode
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m     raise JSONDecodeError("Expecting value", s, err.value) from None
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Feb 10 22:40:09 raspberrypi bash[468]: #033[33mcurt_control_1        |#033[0m
Feb 10 22:40:11 raspberrypi bash[479]: WARNING:root:*********Creating Device Manager*********
Feb 10 22:40:11 raspberrypi bash[479]: WARNING:root:++++++++++++Starting USB device scanning thread++++++++++++
Feb 10 22:40:11 raspberrypi bash[479]: WARNING:root:++++++++++++Starting video device scanning thread++++++++++++
Feb 10 22:40:11 raspberrypi bash[479]: WARNING:root:++++++++++++Starting audio device scanning thread++++++++++++
Feb 10 22:40:11 raspberrypi bash[479]: WARNING:root:++++++++++++Starting control device scanning thread++++++++++++
Feb 10 22:40:11 raspberrypi bash[479]: WARNING:root:++++++++++++All scanning threads started++++++++++++
Feb 10 22:40:11 raspberrypi bash[479]: WARNING:root:*********Core heartbeat thread started*********
Feb 10 22:40:11 raspberrypi bash[479]: WARNING:root:*********Core imported*********

Feb 10 23:44:06 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:06] "GET /getwifi HTTP/1.1" 500 -
Feb 10 23:44:07 raspberrypi bash[458]: 192.168.1.24 - - [10/Feb/2022 23:44:07] "GET /isconnected HTTP/1.1" 200 -
Feb 10 23:44:07 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:07] "GET /isconnected HTTP/1.1" 200 -
Feb 10 23:44:07 raspberrypi bash[458]: 192.168.1.24 - - [10/Feb/2022 23:44:07] "GET /getvideodev HTTP/1.1" 200 -
Feb 10 23:44:07 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:07] "GET /getvideodev HTTP/1.1" 200 -
Feb 10 23:44:08 raspberrypi bash[458]: 192.168.1.24 - - [10/Feb/2022 23:44:08] "GET /isconnected HTTP/1.1" 200 -
Feb 10 23:44:08 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:08] "GET /isconnected HTTP/1.1" 200 -
Feb 10 23:44:08 raspberrypi bash[458]: 192.168.1.24 - - [10/Feb/2022 23:44:08] "GET /getwifi HTTP/1.1" 200 -
Feb 10 23:44:08 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:08] "GET /getwifi HTTP/1.1" 200 -
Feb 10 23:44:08 raspberrypi bash[458]: 192.168.1.24 - - [10/Feb/2022 23:44:08] "GET /getaudiodev HTTP/1.1" 200 -
Feb 10 23:44:08 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:08] "GET /getaudiodev HTTP/1.1" 200 -
Feb 10 23:44:09 raspberrypi bash[458]: 192.168.1.24 - - [10/Feb/2022 23:44:09] "GET /isconnected HTTP/1.1" 200 -
Feb 10 23:44:09 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:09] "GET /isconnected HTTP/1.1" 200 -
Feb 10 23:44:09 raspberrypi bash[458]: 192.168.1.24 - - [10/Feb/2022 23:44:09] "GET /getusbdev HTTP/1.1" 200 -
Feb 10 23:44:09 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:09] "GET /getusbdev HTTP/1.1" 200 -
Feb 10 23:44:09 raspberrypi bash[458]: 192.168.1.24 - - [10/Feb/2022 23:44:09] "GET /getvideodev HTTP/1.1" 200 -
Feb 10 23:44:09 raspberrypi bash[458]: INFO:werkzeug:192.168.1.24 - - [10/Feb/2022 23:44:09] "GET /getvideodev HTTP/1.1" 200 -
acommuni commented 2 years ago

It suscribe to wrong topic :

image

The hostname is filled with "192" by default but it's not the hostname. When I change the hostname, it does not subscribe to the new topic (no trace in the console

I reach the setup page with the IP address : http://192.X.X.X/setup

michaelhwn commented 2 years ago

Ah I see, I know the cause of this issue then. Since the setup page is hosted on the raspberry pi, so when you access this page on a web browser, the hostname (of the raspberry pi) is extracted from the URL. If an IP address is used to access the web app, the extracted hostname will be incorrect. And since the MQTT topic subscription is based on the incorrectly extracted hostname, this explains why the "CAIT UP" MQTT message is not received and you are seeing an incorrect hostname in the field. This is a bug in the setup web app.

I will fix this by making sure the hostname is obtained by the Pi itself and not by the web app using the web browser.

michaelhwn commented 2 years ago

Meanwhile, can you try to access the setup page using http://.local/setup? If the spinning issue does not happen, then it confirms the bug.

acommuni commented 2 years ago

I use the hostname of the raspberry now in the url and it works ! Filling the field with the hostname faciliate the setup. Thanks

Remark : The subscription to MQTT topics should be done after clicking on the "next" button it could let the user changing the hostname (I don't know if they are use cases that need to change the hostname or having multiple topics).

michaelhwn commented 2 years ago

You are welcome @acommuni, I will also fix this issue for users who use the IP address to access this page by incorporating your suggestion too.

michaelhwn commented 2 years ago

This commit in the dev branch has fixed the hostname issue. This change will be merged to main branch after some testings.