Timeout management and other improvements

src/cryptoadvance/specter/bitcoind.py

@@ -17,6 +17,9 @@
 from .rpc import RpcError
 from .rpc import BitcoinRPC
 from .helpers import load_jsons
+from .specter_error import ExtProcTimeoutException
+from urllib3.exceptions import NewConnectionError, MaxRetryError
+from requests.exceptions import ConnectionError
 
 logger = logging.getLogger(__name__)
 
@@ -52,9 +55,13 @@ def get_rpc(self):
         rpc.getblockchaininfo()
         return rpc
 
-    def render_url(self):
+    def render_url(self, password_mask=False):
+        if password_mask == True:
+            password = "xxxxxx"
+        else:
+            password = self.rpcpassword
         return "http://{}:{}@{}:{}/wallet/".format(
-            self.rpcuser, self.rpcpassword, self.ipaddress, self.rpcport
+            self.rpcuser, password, self.ipaddress, self.rpcport
         )
 
     def as_data(self):
@@ -170,34 +177,52 @@ def testcoin_faucet(self, address, amount=20, mine_tx=False):
             rpc.generatetoaddress(1, test3rdparty_address)
 
     @staticmethod
-    def check_bitcoind(rpcconn):
+    def check_bitcoind(rpcconn, raise_exception=False):
         """ returns true if bitcoind is running on that address/port """
+        if raise_exception:
+            rpcconn.get_rpc()  # that call will also check the connection
+            return True
         try:
             rpcconn.get_rpc()  # that call will also check the connection
             return True
-        except ConnectionRefusedError as e:
+        except RpcError as e:
+            # E.g. "Loading Index ..." #ToDo: check it here
+            return False
+        except ConnectionError as e:
+            return False
+        except MaxRetryError as e:
             return False
         except TypeError as e:
             return False
+        except NewConnectionError as e:
+            return False
         except Exception as e:
-            print(f"couldn't reach bitcoind - message returned: {e}")
+            # We should avoid this:
+            # If you see it in the logs, catch that new exception above
+            logger.error("Unexpected Exception, THIS SHOULD NOT HAPPEN " + str(type(e)))
+            logger.debug(f"could not reach bitcoind - message returned: {e}")
             return False
 
     @staticmethod
-    def wait_for_bitcoind(rpcconn, timeout=60):
+    def wait_for_bitcoind(rpcconn, timeout=15):
         """ tries to reach the bitcoind via rpc. Timeout after n seconds """
         i = 0
         while True:
             if BitcoindController.check_bitcoind(rpcconn):
                 break
             time.sleep(0.5)
             i = i + 1
+            if i % 10 == 0:
+                logger.info(f"Timeout reached in {timeout - i/2} seconds")
             if i > (2 * timeout):
-                raise Exception(
-                    "Timeout while trying to reach bitcoind at rpcport {} !".format(
-                        rpcconn
+                try:
+                    BitcoindController.check_bitcoind(rpcconn, raise_exception=True)
+                except Exception as e:
+                    raise ExtProcTimeoutException(
+                        f"Timeout while trying to reach bitcoind {rpcconn.render_url(password_mask=True)} because {e}".format(
+                            rpcconn
+                        )
                     )
-                )
 
     @staticmethod
     def render_rpc_options(rpcconn):
@@ -290,7 +315,7 @@ def _start_bitcoind(
         )
 
         if cleanup_at_exit:
-            logger.debug("Register function cleanup_bitcoind for SIGINT and SIGTERM")
+            logger.info("Register function cleanup_bitcoind for SIGINT and SIGTERM")
             # atexit.register(cleanup_bitcoind)
             # This is for CTRL-C --> SIGINT
             signal.signal(signal.SIGINT, self.cleanup_bitcoind)

src/cryptoadvance/specter/server_endpoints/controller.py

@@ -16,7 +16,7 @@
     notify_upgrade,
 )
 from ..specter import Specter
-from ..specter_error import SpecterError
+from ..specter_error import SpecterError, ExtProcTimeoutException
 from ..util.tor import start_hidden_service, stop_hidden_services
 from ..util.bitcoind_setup_tasks import (
     setup_bitcoind_thread,
@@ -91,6 +91,17 @@ def server_error(e):
     return render_template("500.jinja", error=e, traceback=trace), 500
 
 
+@app.errorhandler(ExtProcTimeoutException)
+def server_error_timeout(e):
+    """ Unspecific Exceptions get a 500 Error-Page """
+    # if rpc is not available
+    if app.specter.rpc is None or not app.specter.rpc.test_connection():
+        # make sure specter knows that rpc is not there
+        app.specter.check()
+    app.logger.error("ExternalProcessTimeoutException: %s" % e)
+    return render_template("500_timeout.jinja", error=e, loglines=e.loglines), 500
+
+
 ########## on every request ###############
 @app.before_request
 def selfcheck():

src/cryptoadvance/specter/server_endpoints/settings.py

@@ -25,7 +25,7 @@
 from ..user import hash_password
 from ..util.tor import start_hidden_service, stop_hidden_services
 from ..util.sha256sum import sha256sum
-from ..specter_error import handle_exception
+from ..specter_error import handle_exception, ExtProcTimeoutException
 
 rand = random.randint(0, 1e32)  # to force style refresh
 
@@ -144,10 +144,17 @@ def bitcoin_core():
                     flash(f"Failed to stop Bitcoin Core {e}", "error")
         elif action == "startbitcoind":
             node_view = "internal"
-            app.specter.bitcoind.start_bitcoind(
-                datadir=os.path.expanduser(app.specter.config["rpc"]["datadir"])
-            )
-            app.specter.set_bitcoind_pid(app.specter.bitcoind.bitcoind_proc.pid)
+            try:
+                app.specter.bitcoind.start_bitcoind(
+                    datadir=os.path.expanduser(app.specter.config["rpc"]["datadir"])
+                )
+            except ExtProcTimeoutException as e:
+                e.check_logfile(
+                    os.path.join(app.specter.config["rpc"]["datadir"], "debug.log")
+                )
+                raise e
+            finally:
+                app.specter.set_bitcoind_pid(app.specter.bitcoind.bitcoind_proc.pid)
             time.sleep(15)
             flash("Specter has started Bitcoin Core")
 

src/cryptoadvance/specter/specter.py

@@ -29,7 +29,8 @@
 import threading
 from urllib.parse import urlparse
 from stem.control import Controller
-from .specter_error import SpecterError
+from .specter_error import SpecterError, ExtProcTimeoutException
+from sys import exit
 
 logger = logging.getLogger(__name__)
 
@@ -201,15 +202,23 @@ def __init__(self, data_folder="./data", config={}):
 
             if os.path.isfile(self.torbrowser_path):
                 self.tor_daemon.start_tor_daemon()
+        except Exception as e:
+            logger.error(e)
 
-            if not self.config["rpc"].get("external_node", True):
+        if not self.config["rpc"].get("external_node", True):
+            try:
                 self.bitcoind.start_bitcoind(
-                    datadir=os.path.expanduser(self.config["rpc"]["datadir"])
+                    datadir=os.path.expanduser(self.config["rpc"]["datadir"]),
+                    timeout=15,  # At the initial startup, we don't wait on bitcoind
+                )
+            except ExtProcTimeoutException as e:
+                logger.error(e)
+                e.check_logfile(
+                    os.path.join(self.config["rpc"]["datadir"], "debug.log")
                 )
+                logger.error(e.get_logger_friendly())
+            finally:
                 self.set_bitcoind_pid(self.bitcoind.bitcoind_proc.pid)
-                time.sleep(15)
-        except Exception as e:
-            logger.error(e)
         self.update_tor_controller()
         self.checker = Checker(lambda: self.check(check_all=True), desc="health")
         self.checker.start()
@@ -234,9 +243,8 @@ def cleanup_on_exit(self, signum=0, frame=0):
             self._bitcoind.stop_bitcoind()
 
         logger.info("Closing Specter after cleanup")
-
-        # End cleaning process by raising an exception to ensure the process stops after the cleanup is complete
-        raise SpecterError("Specter closed")
+        # For some reason we need to explicitely exit here. Otherwise it will hang
+        exit(0)
 
     def check(self, user=None, check_all=False):
         """

src/cryptoadvance/specter/specter_error.py

@@ -1,4 +1,5 @@
 import logging
+from .util.shell import get_last_lines_from_file
 
 logger = logging.getLogger(__name__)
 
@@ -12,6 +13,30 @@ def __init__(self, message):
         # potentially, we could add own stuff now here:
 
 
+class ExtProcTimeoutException(Exception):
+    """A Exception which is thrown because an external process timed out
+    use check_logfile to get some lines in loglines
+    probably improvable for processes which don't have a logfile
+    """
+
+    def __init__(self, message):
+        # Call the base class constructor with the parameters it needs
+        super(ExtProcTimeoutException, self).__init__(message)
+
+    def check_logfile(self, logfile_location):
+        try:
+            self.logfile_location = logfile_location
+            self.loglines = "     ".join(get_last_lines_from_file(logfile_location))
+        except IOError as ioe:
+            self.message = self.message + f" ({ioe})"
+            self.loglines = ""
+
+    def get_logger_friendly(self):
+        return f"""----------- {self.logfile_location} -----------
+        {self.loglines}
+        ------------------------------------------------------"""
+
+
 def handle_exception(exception, user=None):
     """ prints the exception and most important the stacktrace """
     logger.error("Unexpected error:")

src/cryptoadvance/specter/templates/500_timeout.jinja

@@ -0,0 +1,35 @@
+<!DOCTYPE html>
+<html>
+<head>
+    <link rel="shortcut icon" type="image/png" href="{{ url_for('static', filename='img/icon.png') }}"/>
+    <title>Specter Desktop</title>
+    <meta name="viewport" content="width=device-width, initial-scale=1.0">
+    <link rel="stylesheet" type="text/css" href="{{ url_for('static', filename='styles.css') }}">
+    <style type="text/css">
+        a{
+            color: #fff;
+        }
+    </style>
+</head>
+<body>
+    <main>
+        <br><br><br>
+        <div class="card" style="width:90%; max-width: 800px;">
+            <h1>Timeout Error!</h1>
+            Exception: <b>{{ error }}</b><br><br>
+            <div><br>
+                <a class="btn" href="{{ url_for('index') }}">Back to the main page</a>
+            <br></div>
+            Please have a look in the below log. There are effectively two ways to resolve this:
+            <ul>
+                <li>Either the process was just slow and specter too impatient</li>
+                <li>The process is in trouble which should be reflexted by the content of the logs below</li>
+            </ul>
+            Details from the Log-File:
+            <pre><code>{{ loglines }}</code></pre>
+            <br>
+            <div>Please let us know! Create an <a href="https://github.com/cryptoadvance/specter-desktop/issues" target="_blank">issue</a> or ping us on <a href="https://t.me/spectersupport" target="_blank">Telegram</a> to fix it.</div>
+        </div>
+    </main>
+</body>
+</html>

src/cryptoadvance/specter/templates/node_setup_wizard.jinja

@@ -352,7 +352,7 @@
                     }
                     document.getElementById('stage-progress-details').innerHTML = `${stage}<br>`;
                     if (progress > 0) {
-                        document.getElementById('stage-progress-details').innerHTML += `<br><br><b style="font-size:0.8em;">Progress: ${progress}%</b>`;
+                        document.getElementById('stage-progress-details').innerHTML += `<br><br><b style="font-size:0.8em;">Download Progress: ${progress}%</b>`;
                     }
                     setTimeout(fetchStageProgress, 1000);
                 } catch(e) {
@@ -363,7 +363,7 @@
             document.getElementById('stage-progress-details').classList.remove('hidden');
             document.getElementById('show-progress-details').classList.remove('hidden');
             showPageOverlay('stage-progress-details');
-            document.getElementById('stage-progress-details').innerHTML = 'Stating up...';
+            document.getElementById('stage-progress-details').innerHTML = 'Starting up...';
 
             setTimeout(fetchStageProgress, 1000);
         }

src/cryptoadvance/specter/templates/settings/tor_settings.jinja

@@ -155,7 +155,7 @@
                     }
                     document.getElementById('stage-progress-details').innerHTML = `${stage}<br>`;
                     if (progress > 0) {
-                        document.getElementById('stage-progress-details').innerHTML += `<br><br><b style="font-size:0.8em;">Progress: ${progress}%</b>`;
+                        document.getElementById('stage-progress-details').innerHTML += `<br><br><b style="font-size:0.8em;">Download Progress: ${progress}%</b>`;
                     }
                     setTimeout(fetchStageProgress, 1000);
                 } catch(e) {
@@ -165,7 +165,7 @@
             }
             document.getElementById('stage-progress-details').classList.remove('hidden');
             showPageOverlay('stage-progress-details');
-            document.getElementById('stage-progress-details').innerHTML = 'Stating up...';
+            document.getElementById('stage-progress-details').innerHTML = 'Starting up...';
             setTimeout(fetchStageProgress, 1000);
         }
 	</script>