backup: fix double logs and add tests for socket scheme

backup/README.md

@@ -11,7 +11,8 @@ Related info about backup solutions: https://github.com/ElementsProject/lightnin
 ## Installation
 
 You need [uv](https://docs.astral.sh/uv/getting-started/installation/) to run this
-plugin like a binary. After `uv` is installed you can simply run
+plugin and `backup-cli` like a binary. After `uv` is installed and you followed the 
+[Setup](#setup) step you can simply run
 
 ```
 lightning-cli plugin start /path/to/backup.py
@@ -30,7 +31,7 @@ which makes sure no two instances are using the same backup. (Make sure to stop
 your Lightning node before running this command)
 
 ```bash
-uv run ./backup-cli init --lightning-dir ~/.lightning/bitcoin file:///mnt/external/location/file.bkp
+./backup-cli init --lightning-dir ~/.lightning/bitcoin file:///mnt/external/location/file.bkp
 ```
 
 Notes:
@@ -40,7 +41,8 @@ Notes:
  - You should use some non-local SSH or NFS mount as destination,
    otherwise any failure of the disk may result in both the original
    as well as the backup being corrupted.
- - Currently only the `file:///` URL scheme is supported.
+ - There is support for local filesystems with the `file:///` URL scheme and
+   remote support with the `socket:` URL scheme (see [remote](remote.md)).
 
 ## IMPORTANT note about hsm_secret
 

backup/backends.py

@@ -1,6 +1,6 @@
 """Create a backend instance based on URI scheme dispatch."""
 
-from typing import Type
+from typing import Mapping, Type
 from urllib.parse import urlparse
 
 from backend import Backend

backup/backup-cli

@@ -1,4 +1,13 @@
-#!/usr/bin/env python3
+#!/usr/bin/env -S uv run --script
+
+# /// script
+# requires-python = ">=3.9.2"
+# dependencies = [
+#   "click>=8.0.4",
+#   "requests[socks]>=2.32.4",
+# ]
+# ///
+
 from backends import get_backend
 from backend import Change
 from server import SocketServer, setup_server_logging
@@ -15,13 +24,19 @@ root.setLevel(logging.INFO)
 
 handler = logging.StreamHandler(sys.stdout)
 handler.setLevel(logging.DEBUG)
-formatter = logging.Formatter('%(message)s')
+formatter = logging.Formatter("%(message)s")
 handler.setFormatter(formatter)
 root.addHandler(handler)
 
+
 @click.command()
 @click.argument("backend-url")
-@click.option('--lightning-dir', type=click.Path(exists=True), default=None, help='Use an existing lightning directory (default: initialize an empty backup).')
+@click.option(
+    "--lightning-dir",
+    type=click.Path(exists=True),
+    default=None,
+    help="Use an existing lightning directory (default: initialize an empty backup).",
+)
 def init(lightning_dir, backend_url):
     destination = backend_url
     backend = get_backend(destination, create=True)
@@ -31,13 +46,21 @@ def init(lightning_dir, backend_url):
         db_file = os.path.join(lightning_dir, "lightningd.sqlite3")
 
         with open(lock_file, "w") as f:
-            f.write(json.dumps({
-                'backend_url': destination,
-            }))
+            f.write(
+                json.dumps(
+                    {
+                        "backend_url": destination,
+                    }
+                )
+            )
 
         data_version = 0
         if os.path.exists(db_file):
-            print("Found an existing database at {db_file}, initializing the backup with a snapshot".format(db_file=db_file))
+            print(
+                "Found an existing database at {db_file}, initializing the backup with a snapshot".format(
+                    db_file=db_file
+                )
+            )
             # Peek into the DB to see if we have
             db = sqlite3.connect(db_file)
             cur = db.cursor()
@@ -46,20 +69,26 @@ def init(lightning_dir, backend_url):
 
             snapshot = Change(
                 version=data_version,
-                snapshot=open(db_file, 'rb').read(),
-                transaction=None
+                snapshot=open(db_file, "rb").read(),
+                transaction=None,
             )
             if not backend.add_change(snapshot):
                 print("Could not write snapshot to backend")
                 sys.exit(1)
             else:
-                print("Successfully written initial snapshot to {destination}".format(destination=destination))
+                print(
+                    "Successfully written initial snapshot to {destination}".format(
+                        destination=destination
+                    )
+                )
         else:
             print("Database does not exist yet, created an empty backup file")
 
-    print("Initialized backup backend {destination}, you can now start Core-Lightning".format(
-        destination=destination,
-    ))
+    print(
+        "Initialized backup backend {destination}, you can now start Core-Lightning".format(
+            destination=destination,
+        )
+    )
 
 
 @click.command()
@@ -74,11 +103,24 @@ def restore(backend_url, restore_destination):
 @click.command()
 @click.argument("backend-url")
 @click.argument("addr")
-@click.option('--log-mode', type=click.Choice(['plain', 'systemd'], case_sensitive=False), default='plain', help='Debug log mode, defaults to plain')
-@click.option('--log-level', type=click.Choice(['debug', 'info', 'notice', 'warning', 'error', 'critical'], case_sensitive=False), default='info', help='Debug log level, defaults to info')
+@click.option(
+    "--log-mode",
+    type=click.Choice(["plain", "systemd"], case_sensitive=False),
+    default="plain",
+    help="Debug log mode, defaults to plain",
+)
+@click.option(
+    "--log-level",
+    type=click.Choice(
+        ["debug", "info", "notice", "warning", "error", "critical"],
+        case_sensitive=False,
+    ),
+    default="info",
+    help="Debug log level, defaults to info",
+)
 def server(backend_url, addr, log_mode, log_level):
     backend = get_backend(backend_url)
-    addr, port = addr.split(':')
+    addr, port = addr.split(":")
     port = int(port)
 
     setup_server_logging(log_mode, log_level)

backup/backup.py

@@ -4,10 +4,7 @@
 # requires-python = ">=3.9.2"
 # dependencies = [
 #   "pyln-client>=25.2.2",
-#   "click>=8.0.4",
 #   "psutil>=5.9.4",
-#   "flask>=2.2",
-#   "werkzeug<4",
 # ]
 # ///
 
@@ -24,14 +21,7 @@
 
 plugin = Plugin()
 
-root = logging.getLogger()
-root.setLevel(logging.INFO)
-
-handler = logging.StreamHandler(sys.stdout)
-handler.setLevel(logging.DEBUG)
-formatter = logging.Formatter("%(message)s")
-handler.setFormatter(formatter)
-root.addHandler(handler)
+logging.getLogger().setLevel(logging.INFO)
 
 
 def check_first_write(plugin, data_version):
@@ -49,18 +39,18 @@ def check_first_write(plugin, data_version):
     """
     backend = plugin.backend
 
-    logging.info(
+    plugin.log(
         "Comparing backup version {} versus first write version {}".format(
             backend.version, data_version
         )
     )
 
     if backend.version == data_version - 1:
-        logging.info("Versions match up")
+        plugin.log("Versions match up")
         return True
 
     elif backend.prev_version == data_version - 1 and plugin.backend.rewind():
-        logging.info("Last changes not applied, rewinding non-committed transaction")
+        plugin.log("Last changes not applied, rewinding non-committed transaction")
         return True
 
     elif backend.prev_version > data_version - 1:
@@ -154,5 +144,5 @@ def kill(message: str):
         plugin.backend = get_backend(destination, require_init=True)
         plugin.run()
     except Exception:
-        logging.exception("Exception while initializing backup plugin")
+        plugin.log("Exception while initializing backup plugin", level="error")
         kill("Exception while initializing plugin, terminating lightningd")

backup/conftest.py

@@ -0,0 +1,86 @@
+import pytest
+import os
+import subprocess
+import time
+import socket
+import asyncio
+import threading
+
+from pyln.testing.fixtures import *  # noqa: F403
+from asysocks.server import SOCKSServer
+
+cli_path = os.path.join(os.path.dirname(__file__), "backup-cli")
+
+
+def wait_for_port(host, port, timeout=5.0):
+    """Poll until a TCP port starts accepting connections."""
+    start = time.time()
+    while time.time() - start < timeout:
+        with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s:
+            s.settimeout(0.2)
+            try:
+                s.connect((host, port))
+                return
+            except (ConnectionRefusedError, OSError):
+                time.sleep(0.05)
+    raise RuntimeError(f"Backup server did not start listening on {host}:{port}")
+
+
+@pytest.fixture
+def running_backup_server(node_factory, directory):
+    """
+    Spins up a local backup server on a random port for testing.
+    Yields (host, port).
+    """
+
+    file_url = "file://" + os.path.join(directory, "backup.dbak")
+
+    subprocess.check_call([cli_path, "init", file_url])
+
+    host = "127.0.0.1"
+    port = node_factory.get_unused_port()
+
+    # Start server
+    server_proc = subprocess.Popen(
+        [cli_path, "server", file_url, f"{host}:{port}"],
+        stdout=subprocess.PIPE,
+        stderr=subprocess.PIPE,
+    )
+
+    try:
+        # Wait until server is actually listening
+        wait_for_port(host, port, timeout=5)
+        yield host, port
+    finally:
+        server_proc.terminate()
+        try:
+            server_proc.wait(timeout=2)
+        except subprocess.TimeoutExpired:
+            server_proc.kill()
+
+
+@pytest.fixture
+def socks5_proxy(node_factory):
+    """
+    Spins up a local SOCKS5 proxy server on a random port for testing.
+    Yields (host, port) as a plain tuple.
+    """
+    host = "127.0.0.1"
+    port = node_factory.get_unused_port()
+
+    server = SOCKSServer(host, port)
+
+    def run_server():
+        loop = asyncio.new_event_loop()
+        asyncio.set_event_loop(loop)
+        try:
+            loop.run_until_complete(server.run())
+        finally:
+            loop.close()
+
+    thread = threading.Thread(target=run_server, daemon=True)
+    thread.start()
+
+    wait_for_port(host, port)
+
+    yield host, port

backup/filebackend.py

@@ -167,7 +167,7 @@ def compact(self):
             },
         }
 
-        print("Starting compaction: stats={}".format(stats))
+        logging.info("Starting compaction: stats={}".format(stats))
         self.db = self._db_open(snapshotpath)
 
         for change in self.stream_changes():
@@ -205,7 +205,7 @@ def compact(self):
             snapshot=open(snapshotpath, "rb").read(),
             transaction=None,
         )
-        print(
+        logging.info(
             "Adding intial snapshot with {} bytes for version {}".format(
                 len(snapshot.snapshot), snapshot.version
             )
@@ -224,7 +224,7 @@ def compact(self):
             "backupsize": os.stat(clonepath).st_size,
         }
 
-        print(
+        logging.info(
             "Compacted {} changes, saving {} bytes, swapping backups".format(
                 stats["before"]["version_count"] - stats["after"]["version_count"],
                 stats["before"]["backupsize"] - stats["after"]["backupsize"],

backup/pyproject.toml

@@ -9,14 +9,15 @@ dependencies = [
     "pyln-client>=25.2.2",
     "click>=8.0.4",
     "psutil>=5.9.4",
-    "flask>=2.2",
-    "werkzeug<4",
+    "requests[socks]>=2.32.4",
 ]
 
 [dependency-groups]
 dev = [
     "pyln-testing>=25.2.2",
     "pytest-timeout>=2.2.0",
     "pytest-xdist>=3.1.0",
+    "pytest-asyncio>=0.23.8,<2",
     "flaky>=3.7.0",
+    "asysocks<0.3",
 ]

backup/remote.md

@@ -28,8 +28,8 @@ Usage
 First initialize an empty file backend on the server side, then start the server:
 
 ```bash
-backup-cli init file:///path/to/backup
-backup-cli server file:///path/to/backup 127.0.0.1:8700
+./backup-cli init file:///path/to/backup
+./backup-cli server file:///path/to/backup 127.0.0.1:8700
 ```
 
 On the client side:
@@ -38,7 +38,7 @@ On the client side:
 # Make sure Core-Lightning is not running
 lightning-cli stop
 # Initialize the socket backend (this makes an initial snapshot, and creates a configuration file for the plugin)
-backup-cli init socket:127.0.0.1:8700 --lightning-dir "$HOME/.lightning/bitcoin"
+./backup-cli init socket:127.0.0.1:8700 --lightning-dir "$HOME/.lightning/bitcoin"
 # Start c-lighting, with the backup plugin as important plugin so that any issue with it stops the daemon
 lightningd ... \
     --important-plugin /path/to/plugins/backup/backup.py

backup/socketbackend.py

@@ -3,6 +3,7 @@
 import logging
 import socket
 import re
+import socks
 import struct
 import time
 from typing import Tuple, Iterator
@@ -124,7 +125,6 @@ def connect(self):
                 self.sock = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
         else:
             assert self.url.proxytype == ProxyType.SOCKS5
-            import socks
 
             self.sock = socks.socksocket()
             self.sock.set_proxy(