Merge pull request #52 from abrahammurciano/internal-logging

Internal logging

.github/workflows/pypi.yml

@@ -28,18 +28,32 @@ jobs:
         run: |
           python setup.py sdist bdist_wheel
           twine upload dist/*
+      - name: Get current version
+        id: get-current-version
+        run: |
+          echo ::set-output name=current-version::$(python setup.py --version)
+      - name: Close Current Milestone
+        uses: Beakyn/[email protected]
+        env:
+          GITHUB_TOKEN: ${{ github.token }}
+        with:
+          repository: ${{ github.repository }}
+          milestone-title: v${{ steps.get-current-version.outputs.current-version }}
       - name: Get next version
         id: get-next-version
         run: |
           echo ::set-output name=next-version::$(python -c 'from discord_lumberjack import __version__ as v;s=v.rsplit(".",1);print(s[0],".",int(s[1])+1,sep="")')
       - name: Bump version
         run: |
           sed -i 's/^__version__ .*$/__version__ = "${{ steps.get-next-version.outputs.next-version }}"/g' discord_lumberjack/__init__.py
-      - name: Check for modified files
-        id: git-check
-        run: echo ::set-output name=modified::$(if git diff-index --quiet HEAD --; then echo "false"; else echo "true"; fi)
+      - name: Create Milestone
+        id: create-milestone
+        uses: WyriHaximus/[email protected]
+        with:
+          title: v${{ steps.get-next-version.outputs.next-version }}
+        env:
+          GITHUB_TOKEN: ${{ secrets.PERSONAL_GH_TOKEN }}
       - name: Create Pull Request
-        if: steps.git-check.outputs.modified == 'true'
         uses: peter-evans/create-pull-request@v3
         with:
           title: Set version to ${{ steps.get-next-version.outputs.next-version }}
@@ -48,9 +62,4 @@ jobs:
           token: ${{ secrets.PERSONAL_GH_TOKEN }}
           base: main
           labels: automerge
-      - name: Create Milestone
-        uses: WyriHaximus/[email protected]
-        with:
-          title: v${{ steps.get-next-version.outputs.next-version }}
-        env:
-          GITHUB_TOKEN: ${{ secrets.PERSONAL_GH_TOKEN }}
+          milestone: ${{ steps.create-milestone.outputs.number }}

discord_lumberjack/__init__.py

@@ -2,7 +2,7 @@
 .. include:: ../README.md
 """
 
-__version__ = "1.0.5"
+__version__ = "1.0.6"
 __author__ = "Abraham Murciano"
 
 from . import handlers

discord_lumberjack/handlers/discord_handler.py

@@ -6,9 +6,16 @@
 from discord_lumberjack.message_creators import BasicMessageCreator, MessageCreator
 from queue import Queue
 
+logger = logging.getLogger(__name__)
+
 _default_message_creator = BasicMessageCreator()
 
 
+def _record_str(record: logging.LogRecord) -> str:
+	msg = record.getMessage()
+	return f'"{msg[50:]}"{"..." if len(msg) > 50 else ""}'
+
+
 class DiscordHandler(logging.Handler):
 	"""A base class for logging handlers that send messages to Discord.
 
@@ -52,6 +59,7 @@ def emit(self, record: logging.LogRecord) -> None:
 		Args:
 			record (logging.LogRecord): The log record to send.
 		"""
+		logger.debug(f"Enqueuing message {_record_str(record)}")
 		self.__queue.put(record)
 
 	def transform_message(self, message: Dict[str, Any]) -> Dict[str, Any]:
@@ -98,7 +106,9 @@ def flush(self, raise_exceptions=True):
 		Raises:
 			Exception: If an exception was raised while sending a message, and `raise_exceptions` is True.
 		"""
+		logger.debug("Flushing: Waiting for queue to empty...")
 		self.__queue.join()
+		logger.debug("Flushing: Queue has been emptied.")
 		if self.__exception and raise_exceptions:
 			raise self.__exception
 
@@ -108,12 +118,15 @@ def __consume(self) -> None:
 			try:
 				record = self.__queue.get()
 				if record is self.__sentinel:
-					# Main thread has exited and all messages have been sent.
-					# We can exit the thread.
+					logger.debug("Consumer: Sentinel record received, exiting thread.")
 					return
+				logger.debug(f"Consumer: Got message from queue: {_record_str(record)}")
 				for msg in self.prepare_messages(record):
 					self.__send_message(msg)
 			except Exception as e:
+				logger.exception(
+					f"Consumer: Exception while consuming: {_record_str(record)}."
+				)
 				self.__exception = e
 				self.handleError(record)
 			finally:
@@ -146,12 +159,18 @@ def __retry_send(
 		retry_interval = initial_interval
 		response = self.__session.post(self.__url, json=message)
 		while response.status_code == 429:
+			logger.warning(
+				"Message was rejected due to too many requests. Waiting"
+				f" {retry_interval} seconds..."
+			)
 			time.sleep(retry_interval)
 			retry_interval *= 2
 			response = self.__session.post(self.__url, json=message)
 		return response
 
 	def __cleanup(self):
 		"""Waits for main thread to exit, then enqueues a sentinel to indicate that all messages have been sent."""
+		logger.debug("Cleanup: Waiting for main thread to exit...")
 		threading.main_thread().join()
+		logger.debug("Cleanup: Main thread exited. Signaling consumer to exit.")
 		self.__queue.put(self.__sentinel)

tests/conftest.py

@@ -2,7 +2,7 @@
 from typing import Callable
 import os
 import logging
-from logging import LogRecord, Logger
+from logging import FileHandler, LogRecord, Logger
 from tests import utils
 from dotenv import load_dotenv
 from discord_lumberjack.handlers import DiscordHandler, DiscordDMHandler
@@ -13,6 +13,14 @@
 )
 
 load_dotenv()
+dl_logger = logging.getLogger("discord_lumberjack")
+dl_logger.setLevel(logging.DEBUG)
+dl_handler = FileHandler("discord_lumberjack.tests.log", mode="w")
+dl_handler.setLevel(logging.DEBUG)
+dl_handler.setFormatter(
+	logging.Formatter("%(asctime)s: %(name)s: %(levelname)s: %(message)s")
+)
+dl_logger.addHandler(dl_handler)
 
 
 @fixture(