Proper argparse and better logging system

.vscode/launch.json

@@ -29,5 +29,14 @@
             "console": "integratedTerminal",
             "justMyCode": false
         },
+        {
+            "name": "Run App (DEBUG+WS)",
+            "type": "python",
+            "request": "launch",
+            "program": "main.py",
+            "args": ["-vvv", "--debug-ws"],
+            "console": "integratedTerminal",
+            "justMyCode": false
+        },
     ]
-}
+}

constants.py

@@ -1,6 +1,5 @@
 from __future__ import annotations
 
-import logging
 from copy import copy
 from datetime import timedelta
 from typing import Any, Optional, Union, Dict, Callable
@@ -9,7 +8,6 @@ from typing import Any, Optional, Union, Dict, Callable
 JsonType = Dict[str, Any]
 TopicProcess = Callable[[JsonType], Any]
 # Values
-DEBUG_RAW = logging.DEBUG - 1
 MAX_WEBSOCKETS = 8
 WS_TOPICS_LIMIT = 50
 # URLs

main.py

@@ -7,13 +7,14 @@ import json
 import ctypes
 import logging
 import asyncio
+import argparse
 import warnings
 import traceback
 import threading
-from typing import NoReturn
+from typing import Literal, NoReturn
 
 from twitch import Twitch
-from constants import JsonType, SETTINGS_PATH, TERMINATED_STR, DEBUG_RAW
+from constants import JsonType, SETTINGS_PATH, TERMINATED_STR
 
 try:
     import win32api
@@ -41,29 +42,55 @@ def terminate() -> NoReturn:
     raise RuntimeError("Uh oh")  # this will never run, solely for MyPy
 
 
-# extra debug logging level
-logging.addLevelName(DEBUG_RAW, "DEBUG_RAW")
-# handle extra stackable '-v' parameter, that switches the logging level
-logging_level = logging.ERROR
-if len(sys.argv) > 1:
-    arg = sys.argv[1]
-    if arg == ("-v", "-v1"):
-        logging_level = logging.WARNING
-    elif arg in ("-vv", "-v2"):
-        logging_level = logging.INFO
-    elif arg in ("-vvv", "-v3"):
-        logging_level = logging.DEBUG
-    elif arg in ("-vvvv", "-v4"):
-        # enables debugging raw messages
-        logging_level = DEBUG_RAW
+class ParsedArgs(argparse.Namespace):
+    _verbose: int
+    debug_ws: Literal[Literal[0], Literal[10]]
+    debug_gql: Literal[Literal[0], Literal[10]]
+
+    @property
+    def logging_level(self) -> int:
+        return {
+            0: logging.ERROR,
+            1: logging.WARNING,
+            2: logging.INFO,
+            3: logging.DEBUG,
+        }.get(self._verbose, logging.DEBUG)
+
+
+# handle input parameters
+parser = argparse.ArgumentParser(
+    f"TwitchDropsMiner.v{__version__}.exe",
+    description="A program that allows you to mine timed drops on Twitch.",
+)
+parser.add_argument("-V", "--version", action="version", version=f"v{__version__}")
+parser.add_argument("-v", dest="_verbose", action="count", default=0)
+parser.add_argument(
+    "--debug-ws",
+    dest="debug_ws",
+    action="store_const",
+    const=logging.DEBUG,
+    default=logging.NOTSET,
+)
+parser.add_argument(
+    "--debug-gql",
+    dest="debug_gql",
+    action="store_const",
+    const=logging.DEBUG,
+    default=logging.NOTSET,
+)
+options: ParsedArgs = parser.parse_args(namespace=ParsedArgs())
 # handle logging stuff
-root_logger = logging.getLogger()
-root_logger.addHandler(logging.NullHandler())
+if options.logging_level > logging.DEBUG:
+    # redirect the root logger into a NullHandler, effectively ignoring all logging calls
+    # that aren't ours. This always runs, unless the main logging level is DEBUG or below.
+    logging.getLogger().addHandler(logging.NullHandler())
 logger = logging.getLogger("TwitchDrops")
 handler = logging.StreamHandler(sys.stdout)
 handler.setFormatter(logging.Formatter("{levelname}: {message}", style='{'))
 logger.addHandler(handler)
-logger.setLevel(logging_level)
+logger.setLevel(options.logging_level)
+logging.getLogger("TwitchDrops.gql").setLevel(options.debug_gql)
+logging.getLogger("TwitchDrops.websocket").setLevel(options.debug_ws)
 # handle settings
 try:
     with open(SETTINGS_PATH, 'r', encoding="utf8") as file:

twitch.py

@@ -21,7 +21,6 @@ from constants import (
     JsonType,
     WebsocketTopic,
     CLIENT_ID,
-    DEBUG_RAW,
     USER_AGENT,
     COOKIES_PATH,
     AUTH_URL,
@@ -34,6 +33,7 @@ from constants import (
 
 
 logger = logging.getLogger("TwitchDrops")
+gql_logger = logging.getLogger("TwitchDrops.gql")
 
 
 class Twitch:
@@ -417,10 +417,10 @@ class Twitch:
             "Authorization": f"OAuth {self._access_token}",
             "Client-Id": CLIENT_ID,
         }
-        logger.log(DEBUG_RAW, f"GQL Request: {op}")
+        gql_logger.debug(f"GQL Request: {op}")
         async with self._session.post(GQL_URL, json=op, headers=headers) as response:
             response_json = await response.json()
-            logger.log(DEBUG_RAW, f"GQL Response: {response_json}")
+            gql_logger.debug(f"GQL Response: {response_json}")
             return response_json
 
     async def get_inventory(self) -> List[DropsCampaign]:

websocket.py

@@ -18,7 +18,6 @@ from exceptions import MinerException
 from constants import (
     JsonType,
     WebsocketTopic,
-    DEBUG_RAW,
     WEBSOCKET_URL,
     PING_INTERVAL,
     MAX_WEBSOCKETS,
@@ -29,7 +28,7 @@ if TYPE_CHECKING:
     from twitch import Twitch
 
 
-logger = logging.getLogger("TwitchDrops")
+ws_logger = logging.getLogger("TwitchDrops.websocket")
 NONCE_CHARS = string.ascii_letters + string.digits
 
 
@@ -43,7 +42,7 @@ def task_wrapper(afunc):
         try:
             await afunc(self, *args, **kwargs)
         except Exception:
-            logger.exception("Exception in websocket task")
+            ws_logger.exception("Exception in websocket task")
             raise  # raise up to the wrapping task
     return wrapper
 
@@ -79,6 +78,7 @@ class Websocket:
         return self._connected_flag.wait()
 
     def request_reconnect(self):
+        ws_logger.warning(f"Websocket[{self._idx}] requested reconnect.")
         self._reconnect_requested.set()
 
     async def start(self):
@@ -114,7 +114,7 @@ class Websocket:
     async def _handle(self):
         # ensure we're logged in before connecting
         await self._twitch.wait_until_login()
-        logger.info("Connecting to Websocket")
+        ws_logger.info(f"Websocket[{self._idx}] connecting...")
         # Connect/Reconnect loop
         async for websocket in websocket_connect(WEBSOCKET_URL, ssl=True, ping_interval=None):
             websocket.BACKOFF_MAX = 3 * 60  # type: ignore  # 3 minutes
@@ -131,21 +131,25 @@ class Websocket:
                     self._submitted.clear()
                     self._connected_flag.clear()
                 # A reconnect was requested
-                continue
             except ConnectionClosed as exc:
                 if isinstance(exc, ConnectionClosedOK):
                     if exc.rcvd_then_sent:
                         # server closed the connection, not us - reconnect
-                        logger.warning("Server Disconnected - Reconnecting")
-                        continue
-                    # we closed it - exit
-                    return
-                # otherwise, reconnect
-                logger.warning("Websocket Closed - Reconnecting")
-                continue
+                        ws_logger.warning(f"Websocket[{self._idx}] disconnected.")
+                    else:
+                        # we closed it - exit
+                        ws_logger.info(f"Websocket[{self._idx}] stopped.")
+                        return
+                if exc.rcvd is not None:
+                    code = exc.rcvd.code
+                elif exc.sent is not None:
+                    code = exc.sent.code
+                else:
+                    code = -1
+                ws_logger.warning(f"Websocket[{self._idx}] closed unexpectedly: {code}")
             except Exception:
-                logger.exception("Exception in Websocket - Reconnecting")
-                continue
+                ws_logger.exception(f"Exception in Websocket[{self._idx}]")
+            ws_logger.warning(f"Websocket[{self._idx}] reconnecting...")
 
     async def _handle_ping(self):
         now = time()
@@ -166,7 +170,7 @@ class Websocket:
         removed = self._submitted.difference(current)
         if removed:
             topics_list = list(map(str, removed))
-            logger.debug(f"Websocket[{self._idx}]: Removing topics: {', '.join(topics_list)}")
+            ws_logger.debug(f"Websocket[{self._idx}]: Removing topics: {', '.join(topics_list)}")
             await self.send(
                 {
                     "type": "UNLISTEN",
@@ -181,7 +185,7 @@ class Websocket:
         added = current.difference(self._submitted)
         if added:
             topics_list = list(map(str, added))
-            logger.debug(f"Websocket[{self._idx}]: Adding topics: {', '.join(topics_list)}")
+            ws_logger.debug(f"Websocket[{self._idx}]: Adding topics: {', '.join(topics_list)}")
             await self.send(
                 {
                     "type": "LISTEN",
@@ -202,7 +206,7 @@ class Websocket:
         while True:
             raw_message = await self._ws.recv()
             message = json.loads(raw_message)
-            logger.log(DEBUG_RAW, f"Websocket received: {message}")
+            ws_logger.debug(f"Websocket[{self._idx}] received: {message}")
             messages.append(message)
 
     def _handle_message(self, message):
@@ -233,10 +237,9 @@ class Websocket:
                 pass
             elif msg_type == "RECONNECT":
                 # We've received a reconnect request
-                logger.warning("Received a Websocket Reconnect Request")
                 self.request_reconnect()
             else:
-                logger.error(f"Received unknown websocket payload: {message}")
+                ws_logger.warning(f"Websocket[{self._idx}] received unknown payload: {message}")
 
     def add_topics(self, topics_set: Set[WebsocketTopic]):
         while topics_set and len(self.topics) < WS_TOPICS_LIMIT:
@@ -260,7 +263,7 @@ class Websocket:
         if message["type"] != "PING":
             message["nonce"] = create_nonce()
         await self._ws.send(json.dumps(message, separators=(',', ':')))
-        logger.log(DEBUG_RAW, f"Websocket sent: {message}")
+        ws_logger.debug(f"Websocket[{self._idx}] sent: {message}")
 
 
 class WebsocketPool:
@@ -350,7 +353,7 @@ class WebsocketPool:
             if drop is not None:
                 break
         else:
-            logger.error(f"Drop with ID of {drop_id} not found!")
+            ws_logger.warning(f"Drop with ID of {drop_id} not found!")
             return
         drop.update(message)
         msg_type = message["type"]