prairiedogbeer / fermenator

Fermentation monitoring and management software
0 stars 0 forks source link

Uncaught exceptions terminate threads during internet connection problems #8

Open prairiedogbeer opened 7 years ago

prairiedogbeer commented 7 years ago

I recently changed the code to handle HTTPError and SSLError exceptions by nulling the firebase handle so that a new connection would be established, but the code for the initial firebase database connection is not properly trapping those errors and handling them gracefully, terminating threads.

Examples of errors:

Sep 29 16:33:52 raspberrypi python3[23986]: WARNING  fermenator.beer.DampenedBeer.PB0069 exception reading/parsing gravity from datastore: read from firebase failed: [Errno 503 Server Error: Service Unavailable for url: https://brewconsole.firebaseio.com/brewery/PFV01/readings/gravity/.json] {
Sep 29 16:33:52 raspberrypi python3[23986]: "error" : "Firebase database instance is inactive"
Sep 29 16:33:52 raspberrypi python3[23986]: }
Sep 29 16:33:56 raspberrypi python3[23986]: Exception in thread Thread-32:
Sep 29 16:33:56 raspberrypi python3[23986]: Traceback (most recent call last):
Sep 29 16:33:56 raspberrypi python3[23986]: File "/usr/local/lib/python3.4/dist-packages/pyrebase/pyrebase.py", line 444, in raise_detailed_error
Sep 29 16:33:56 raspberrypi python3[23986]: request_object.raise_for_status()
Sep 29 16:33:56 raspberrypi python3[23986]: File "/usr/local/lib/python3.4/dist-packages/requests/models.py", line 937, in raise_for_status
Sep 29 16:33:56 raspberrypi python3[23986]: raise HTTPError(http_error_msg, response=self)
Sep 29 16:33:56 raspberrypi python3[23986]: requests.exceptions.HTTPError: 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/fermenator/state/PFV03/heartbeat.json
Sep 29 16:33:56 raspberrypi python3[23986]: During handling of the above exception, another exception occurred:
Sep 29 16:33:56 raspberrypi python3[23986]: Traceback (most recent call last):
Sep 29 16:33:56 raspberrypi python3[23986]: File "/home/gerad/fermenator/fermenator/datasource/firebase.py", line 75, in set
Sep 29 16:33:56 raspberrypi python3[23986]: obj.set(value)
Sep 29 16:33:56 raspberrypi python3[23986]: File "/usr/local/lib/python3.4/dist-packages/pyrebase/pyrebase.py", line 301, in set
Sep 29 16:33:56 raspberrypi python3[23986]: raise_detailed_error(request_object)
Sep 29 16:33:56 raspberrypi python3[23986]: File "/usr/local/lib/python3.4/dist-packages/pyrebase/pyrebase.py", line 448, in raise_detailed_error
Sep 29 16:33:56 raspberrypi python3[23986]: raise HTTPError(e, request_object.text)
Sep 29 16:33:56 raspberrypi python3[23986]: requests.exceptions.HTTPError: [Errno 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/fermenator/state/PFV03/heartbeat.json] {
Sep 29 16:33:56 raspberrypi python3[23986]: "error" : "Internal server error."
Sep 29 16:33:56 raspberrypi python3[23986]: }
Sep 29 16:33:56 raspberrypi python3[23986]: During handling of the above exception, another exception occurred:
Sep 29 16:33:56 raspberrypi python3[23986]: Traceback (most recent call last):
Sep 29 16:33:56 raspberrypi python3[23986]: File "/usr/lib/python3.4/threading.py", line 920, in _bootstrap_inner
Sep 29 16:33:56 raspberrypi python3[23986]: self.run()
Sep 29 16:33:56 raspberrypi python3[23986]: File "/usr/lib/python3.4/threading.py", line 868, in run
Sep 29 16:33:56 raspberrypi python3[23986]: self._target(*self._args, **self._kwargs)
Sep 29 16:33:56 raspberrypi python3[23986]: File "/home/gerad/fermenator/fermenator/manager.py", line 200, in run
Sep 29 16:33:56 raspberrypi python3[23986]: self._log_state()
Sep 29 16:33:56 raspberrypi python3[23986]: File "/home/gerad/fermenator/fermenator/manager.py", line 284, in _log_state
Sep 29 16:33:56 raspberrypi python3[23986]: self.state_path_prefix + (self.name, "heartbeat"), now)
Sep 29 16:33:56 raspberrypi python3[23986]: File "/home/gerad/fermenator/fermenator/datasource/firebase.py", line 78, in set
Sep 29 16:33:56 raspberrypi python3[23986]: raise DataWriteError("write to firebase failed: {}".format(err))
Sep 29 16:33:56 raspberrypi python3[23986]: fermenator.exception.DataWriteError: write to firebase failed: [Errno 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/fermenator/state/PFV03/heartbeat.json] {
Sep 29 16:33:56 raspberrypi python3[23986]: "error" : "Internal server error."
Sep 29 16:33:56 raspberrypi python3[23986]: }
Sep 29 16:33:56 raspberrypi python3[23986]: WARNING  fermenator.beer.DampenedBeer.PB0069 exception reading/parsing gravity from datastore: read from firebase failed: [Errno 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/brewery/PFV01/readings/gravity/.json] {
Sep 29 16:33:56 raspberrypi python3[23986]: "error" : "Internal server error."
Sep 29 16:33:56 raspberrypi python3[23986]: }
Sep 29 16:33:56 raspberrypi python3[23986]: ERROR    fermenator.config.FirebaseConfig.brewconsoleconfig error checking for config changes: read from firebase failed: [Errno 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/config/fermenator/log_level/.json] {
Sep 29 16:33:56 raspberrypi python3[23986]: "error" : "Internal server error."
Sep 29 16:33:56 raspberrypi python3[23986]: }
Sep 29 16:33:57 raspberrypi python3[23986]: WARNING  fermenator.beer.DampenedBeer.PB0069 exception reading/parsing gravity from datastore: read from firebase failed: [Errno 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/brewery/PFV01/readings/gravity/.json] {
Sep 29 16:33:57 raspberrypi python3[23986]: "error" : "Internal server error."
Sep 29 16:33:57 raspberrypi python3[23986]: }
Sep 29 16:33:57 raspberrypi python3[23986]: ERROR    fermenator.manager.ManagerThread.PFV01.PB0069 TEMPERATURE MANAGEMENT DISABLED: unable to fetch gravity from read_datasource after 3 tries
Sep 29 16:34:41 raspberrypi python3[23986]: Exception in thread Thread-29:
Sep 29 16:34:41 raspberrypi python3[23986]: Traceback (most recent call last):
Sep 29 16:34:41 raspberrypi python3[23986]: File "/usr/local/lib/python3.4/dist-packages/pyrebase/pyrebase.py", line 444, in raise_detailed_error
Sep 29 16:34:41 raspberrypi python3[23986]: request_object.raise_for_status()
Sep 29 16:34:41 raspberrypi python3[23986]: File "/usr/local/lib/python3.4/dist-packages/requests/models.py", line 937, in raise_for_status
Sep 29 16:34:41 raspberrypi python3[23986]: raise HTTPError(http_error_msg, response=self)
Sep 29 16:34:41 raspberrypi python3[23986]: requests.exceptions.HTTPError: 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/fermenator/state/PFV01/heartbeat.json
Sep 29 16:34:41 raspberrypi python3[23986]: During handling of the above exception, another exception occurred:
Sep 29 16:34:41 raspberrypi python3[23986]: Traceback (most recent call last):
Sep 29 16:34:41 raspberrypi python3[23986]: File "/home/gerad/fermenator/fermenator/datasource/firebase.py", line 75, in set
Sep 29 16:34:41 raspberrypi python3[23986]: obj.set(value)
Sep 29 16:34:41 raspberrypi python3[23986]: File "/usr/local/lib/python3.4/dist-packages/pyrebase/pyrebase.py", line 301, in set
Sep 29 16:34:41 raspberrypi python3[23986]: raise_detailed_error(request_object)
Sep 29 16:34:41 raspberrypi python3[23986]: File "/usr/local/lib/python3.4/dist-packages/pyrebase/pyrebase.py", line 448, in raise_detailed_error
Sep 29 16:34:41 raspberrypi python3[23986]: raise HTTPError(e, request_object.text)
Sep 29 16:34:41 raspberrypi python3[23986]: requests.exceptions.HTTPError: [Errno 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/fermenator/state/PFV01/heartbeat.json] {
Sep 29 16:34:41 raspberrypi python3[23986]: "error" : "Internal server error."
Sep 29 16:34:41 raspberrypi python3[23986]: }
Sep 29 16:34:41 raspberrypi python3[23986]: During handling of the above exception, another exception occurred:
Sep 29 16:34:41 raspberrypi python3[23986]: Traceback (most recent call last):
Sep 29 16:34:41 raspberrypi python3[23986]: File "/usr/lib/python3.4/threading.py", line 920, in _bootstrap_inner
Sep 29 16:34:41 raspberrypi python3[23986]: self.run()
Sep 29 16:34:41 raspberrypi python3[23986]: File "/usr/lib/python3.4/threading.py", line 868, in run
Sep 29 16:34:41 raspberrypi python3[23986]: self._target(*self._args, **self._kwargs)
Sep 29 16:34:41 raspberrypi python3[23986]: File "/home/gerad/fermenator/fermenator/manager.py", line 200, in run
Sep 29 16:34:41 raspberrypi python3[23986]: self._log_state()
Sep 29 16:34:41 raspberrypi python3[23986]: File "/home/gerad/fermenator/fermenator/manager.py", line 284, in _log_state
Sep 29 16:34:41 raspberrypi python3[23986]: self.state_path_prefix + (self.name, "heartbeat"), now)
Sep 29 16:34:41 raspberrypi python3[23986]: File "/home/gerad/fermenator/fermenator/datasource/firebase.py", line 78, in set
Sep 29 16:34:41 raspberrypi python3[23986]: raise DataWriteError("write to firebase failed: {}".format(err))
Sep 29 16:34:41 raspberrypi python3[23986]: fermenator.exception.DataWriteError: write to firebase failed: [Errno 502 Server Error: Bad Gateway for url: https://brewconsole.firebaseio.com/fermenator/state/PFV01/heartbeat.json] {
Sep 29 16:34:41 raspberrypi python3[23986]: "error" : "Internal server error."
Sep 29 16:34:41 raspberrypi python3[23986]: }

As you can see, the error is properly handled at the DampenedBeer level, meaning the exception was caught and dealt with by nulling the handle. Four seconds later, the _log_state code in manager.py tries to use the handle, which results in a connection attempt for a new handle, but the requests HTTPError is raised and unhandled, terminating the thread.

prairiedogbeer commented 7 years ago

I fixed this by creating a new DataSourceError exception type that all firebase-related errors, including a new DSConnectionError class, inherit from. I changed the firebase handle creation code to catch the same exceptions as the get and set code, which is working well, and raise the DSConnectionError in that event. Then I updated the _log_state code to catch all DataSourceError types and handle them gracefully (with a log message).

prairiedogbeer commented 7 years ago

As you can see above, I also updated the beer code to catch the proper exceptions instead of BaseException, when reading/writing from/to datasources.

prairiedogbeer commented 6 years ago

This is still happening, now with a different type of exception:

Nov 22 13:10:27 raspberrypi python3[6160]: Exception in thread Thread-4:
Nov 22 13:10:27 raspberrypi python3[6160]: Traceback (most recent call last):
Nov 22 13:10:27 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/urllib3/connectionpool.py", line 600, in urlopen
Nov 22 13:10:27 raspberrypi python3[6160]: chunked=chunked)
Nov 22 13:10:27 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/urllib3/connectionpool.py", line 345, in _make_request
Nov 22 13:10:27 raspberrypi python3[6160]: self._validate_conn(conn)
Nov 22 13:10:27 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/urllib3/connectionpool.py", line 844, in _validate_conn
Nov 22 13:10:27 raspberrypi python3[6160]: conn.connect()
Nov 22 13:10:27 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/urllib3/connection.py", line 326, in connect
Nov 22 13:10:27 raspberrypi python3[6160]: ssl_context=context)
Nov 22 13:10:27 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/urllib3/util/ssl_.py", line 325, in ssl_wrap_socket
Nov 22 13:10:27 raspberrypi python3[6160]: return context.wrap_socket(sock, server_hostname=server_hostname)
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/lib/python3.4/ssl.py", line 364, in wrap_socket
Nov 22 13:10:28 raspberrypi python3[6160]: _context=self)
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/lib/python3.4/ssl.py", line 577, in __init__
Nov 22 13:10:28 raspberrypi python3[6160]: self.do_handshake()
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/lib/python3.4/ssl.py", line 804, in do_handshake
Nov 22 13:10:28 raspberrypi python3[6160]: self._sslobj.do_handshake()
Nov 22 13:10:28 raspberrypi python3[6160]: ssl.SSLEOFError: EOF occurred in violation of protocol (_ssl.c:600)
Nov 22 13:10:28 raspberrypi python3[6160]: During handling of the above exception, another exception occurred:
Nov 22 13:10:28 raspberrypi python3[6160]: Traceback (most recent call last):
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/requests/adapters.py", line 440, in send
Nov 22 13:10:28 raspberrypi python3[6160]: timeout=timeout
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/urllib3/connectionpool.py", line 630, in urlopen
Nov 22 13:10:28 raspberrypi python3[6160]: raise SSLError(e)
Nov 22 13:10:28 raspberrypi python3[6160]: urllib3.exceptions.SSLError: EOF occurred in violation of protocol (_ssl.c:600)
Nov 22 13:10:28 raspberrypi python3[6160]: During handling of the above exception, another exception occurred:
Nov 22 13:10:28 raspberrypi python3[6160]: Traceback (most recent call last):
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/lib/python3.4/threading.py", line 920, in _bootstrap_inner
Nov 22 13:10:28 raspberrypi python3[6160]: self.run()
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/lib/python3.4/threading.py", line 868, in run
Nov 22 13:10:28 raspberrypi python3[6160]: self._target(*self._args, **self._kwargs)
Nov 22 13:10:28 raspberrypi python3[6160]: File "/home/gerad/fermenator/fermenator/manager.py", line 197, in run
Nov 22 13:10:28 raspberrypi python3[6160]: self._log_state()
Nov 22 13:10:28 raspberrypi python3[6160]: File "/home/gerad/fermenator/fermenator/manager.py", line 388, in _log_state
Nov 22 13:10:28 raspberrypi python3[6160]: self.state_path_prefix + (self.name, "heartbeat"), now)
Nov 22 13:10:28 raspberrypi python3[6160]: File "/home/gerad/fermenator/fermenator/datasource/firebase.py", line 85, in set
Nov 22 13:10:28 raspberrypi python3[6160]: obj.set(value)
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/pyrebase/pyrebase.py", line 300, in set
Nov 22 13:10:28 raspberrypi python3[6160]: request_object = self.requests.put(request_ref, headers=headers, data=json.dumps(data, **json_kwargs).encode("utf-8"))
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/requests/sessions.py", line 560, in put
Nov 22 13:10:28 raspberrypi python3[6160]: return self.request('PUT', url, data=data, **kwargs)
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/requests/sessions.py", line 502, in request
Nov 22 13:10:28 raspberrypi python3[6160]: resp = self.send(prep, **send_kwargs)
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/requests/sessions.py", line 612, in send
Nov 22 13:10:28 raspberrypi python3[6160]: r = adapter.send(request, **kwargs)
Nov 22 13:10:28 raspberrypi python3[6160]: File "/usr/local/lib/python3.4/dist-packages/requests/adapters.py", line 514, in send
Nov 22 13:10:28 raspberrypi python3[6160]: raise SSLError(e, request=request)