New best practices for logging and filtering out queued tasks

jarvis_tasks/tasks/ban.py

@@ -1,7 +1,7 @@
 """JARVIS ban tasks."""
 import asyncio
+import logging
 from datetime import datetime, timedelta, timezone
-from logging import Logger
 
 from dis_snek import Snake
 from dis_snek.client.errors import NotFound
@@ -13,9 +13,10 @@ from jarvis_core.db.models import Ban, Unban
 from jarvis_tasks.util import runat
 
 queue = []
+logger = logging.getLogger(__name__)
 
 
-async def _unban(bot: int, guild: Guild, user: User, ban: Ban, logger: Logger) -> None:
+async def _unban(bot: int, guild: Guild, user: User, ban: Ban) -> None:
     if guild and user:
         logger.debug(f"Unbanning user {user.id} from guild {guild.id}")
         try:
@@ -35,7 +36,7 @@ async def _unban(bot: int, guild: Guild, user: User, ban: Ban, logger: Logger) -
     queue.remove(ban.id)
 
 
-async def unban(bot: Snake, logger: Logger) -> None:
+async def unban(bot: Snake) -> None:
     """
     Unban users when ban expires.
 
@@ -43,6 +44,7 @@ async def unban(bot: Snake, logger: Logger) -> None:
         bot: Snake instance
         logger: Global logger
     """
+    logger.debug("Starting Task-ban")
     while True:
         max_ts = datetime.now(tz=timezone.utc) + timedelta(minutes=9)
         bans = Ban.find(q(type="temp", active=True, duration__lte=max_ts))

jarvis_tasks/tasks/lock.py

@@ -1,7 +1,7 @@
 """JARVIS Lock background task."""
 import asyncio
+import logging
 from datetime import datetime, timedelta, timezone
-from logging import Logger
 
 from dis_snek import Snake
 from dis_snek.client.utils.misc_utils import get
@@ -12,9 +12,10 @@ from jarvis_core.db.models import Lock
 from jarvis_tasks.util import runat
 
 queue = []
+logger = logging.getLogger(__name__)
 
 
-async def _unlock(channel: GuildChannel, lock: Lock, logger: Logger) -> None:
+async def _unlock(channel: GuildChannel, lock: Lock) -> None:
     logger.debug(f"Deactivating lock {lock.id}")
     try:
         overwrite = get(channel.permission_overwrites, id=lock.guild)
@@ -36,7 +37,7 @@ async def _unlock(channel: GuildChannel, lock: Lock, logger: Logger) -> None:
     queue.remove(lock.id)
 
 
-async def unlock(bot: Snake, logger: Logger) -> None:
+async def unlock(bot: Snake) -> None:
     """
     Unlock locked channels.
 
@@ -44,6 +45,7 @@ async def unlock(bot: Snake, logger: Logger) -> None:
         bot: Bot instance
         logger: Global logger
     """
+    logger.debug("Starting Task-lock")
     while True:
         max_ts = datetime.now(tz=timezone.utc) + timedelta(seconds=55)
         locks = Lock.find(q(active=True, created_at__lte=max_ts))
@@ -52,7 +54,7 @@ async def unlock(bot: Snake, logger: Logger) -> None:
                 continue
             guild = await bot.fetch_guild(lock.guild)
             channel = await guild.fetch_channel(lock.channel)
-            coro = _unlock(channel, lock, logger)
+            coro = _unlock(channel, lock)
             when = lock.created_at + timedelta(minutes=lock.duration)
             asyncio.create_task(runat(when, coro, logger))
             queue.append(lock.id)

jarvis_tasks/tasks/lockdown.py

@@ -1,7 +1,7 @@
 """JARVIS Lockdown background task."""
 import asyncio
+import logging
 from datetime import datetime, timedelta, timezone
-from logging import Logger
 
 from dis_snek import Snake
 from dis_snek.models.discord.enums import Permissions
@@ -12,9 +12,10 @@ from jarvis_core.db.models import Lockdown
 from jarvis_tasks.util import runat
 
 queue = []
+logger = logging.getLogger(__name__)
 
 
-async def _lift(role: Role, lock: Lockdown, logger: Logger) -> None:
+async def _lift(role: Role, lock: Lockdown) -> None:
     logger.debug(f"Lifting lockdown {lock.id}")
     original_perms = Permissions(lock.original_perms)
     await role.edit(permissions=original_perms)
@@ -23,7 +24,7 @@ async def _lift(role: Role, lock: Lockdown, logger: Logger) -> None:
     queue.remove(lock.id)
 
 
-async def lift(bot: Snake, logger: Logger) -> None:
+async def lift(bot: Snake) -> None:
     """
     Lift a lockdown.
 
@@ -31,6 +32,7 @@ async def lift(bot: Snake, logger: Logger) -> None:
         bot: Bot instance
         logger: Global logger
     """
+    logger.debug("Starting Task-lift")
     while True:
         max_ts = datetime.now(tz=timezone.utc) + timedelta(seconds=55)
         locks = Lockdown.find(q(active=True, created_at__lte=max_ts))
@@ -39,7 +41,7 @@ async def lift(bot: Snake, logger: Logger) -> None:
                 continue
             guild = await bot.fetch_guild(lock.guild)
             role = await guild.fetch_role(guild.id)
-            coro = _lift(role, lock, logger)
+            coro = _lift(role, lock)
             when = lock.created_at + timedelta(minutes=lock.duration)
             asyncio.create_task(runat(when, coro, logger))
             queue.append(lock.id)

jarvis_tasks/tasks/reminder.py

@@ -1,7 +1,7 @@
 """JARVIS reminders."""
 import asyncio
+import logging
 from datetime import datetime, timedelta, timezone
-from logging import Logger
 from typing import Optional
 
 from dis_snek import Snake
@@ -10,18 +10,17 @@ from dis_snek.models.discord.embed import Embed
 from dis_snek.models.discord.user import User
 from jarvis_core.db import q
 from jarvis_core.db.models import Reminder
-from jarvis_core.util import build_embed
 
-from jarvis_tasks.util import runat
+from jarvis_tasks.util import build_embed, runat
 
 queue = []
+logger = logging.getLogger(__name__)
 
 
 async def _remind(
     user: User,
     reminder: Reminder,
     embed: Embed,
-    logger: Logger,
     channel: Optional[GuildText] = None,
 ) -> None:
     delete = True
@@ -57,7 +56,7 @@ async def _remind(
     queue.remove(reminder.id)
 
 
-async def remind(bot: Snake, logger: Logger) -> None:
+async def remind(bot: Snake) -> None:
     """
     Run reminders in the background.
 
@@ -65,11 +64,13 @@ async def remind(bot: Snake, logger: Logger) -> None:
         bot: Snake instance
         logger: Global logger
     """
+    logger.debug("Starting Task-remind")
     while True:
         max_ts = datetime.now(tz=timezone.utc) + timedelta(seconds=5)
-        reminders = Reminder.find(q(remind_at__lte=max_ts, active=True))
+        reminders = Reminder.find(q(id__nin=queue, remind_at__lte=max_ts, active=True))
         async for reminder in reminders:
             if reminder.id in queue:
+                logger.debug(f"Reminder {reminder.id} was found despite filter")
                 continue
             user = await bot.fetch_user(reminder.user)
             if not user:
@@ -87,7 +88,7 @@ async def remind(bot: Snake, logger: Logger) -> None:
             embed.set_thumbnail(url=user.avatar.url)
 
             channel = await bot.fetch_channel(reminder.channel)
-            coro = _remind(user, reminder, embed, logger, channel)
+            coro = _remind(user, reminder, embed, channel)
             asyncio.create_task(runat(reminder.remind_at, coro, logger))
             queue.append(reminder.id)
 

jarvis_tasks/tasks/twitter.py

@@ -1,7 +1,7 @@
 """JARVIS Twitter sync."""
 import asyncio
+import logging
 from datetime import datetime, timedelta, timezone
-from logging import Logger
 from typing import List
 
 import tweepy
@@ -14,6 +14,7 @@ from jarvis_tasks.config import TaskConfig
 from jarvis_tasks.util import build_embed
 
 config = TaskConfig.from_yaml()
+logger = logging.getLogger(__name__)
 
 
 def tweet_embeds(tweet: tweepy.models.Status) -> List[Embed]:
@@ -21,8 +22,9 @@ def tweet_embeds(tweet: tweepy.models.Status) -> List[Embed]:
     Build a tweet embeds.
 
     Args:
-        tweet: Tweet to build embed
+        tweet: Tweet to build embeds
     """
+    logger.debug("Starting Task-twitter")
     url = f"https://twitter.com/{tweet.user.screen_name}/status/{tweet.id}"
     entities = tweet.__dict__.get("extended_entities", {})
     media = entities.get("media", [])
@@ -72,7 +74,7 @@ def tweet_embeds(tweet: tweepy.models.Status) -> List[Embed]:
     return embeds
 
 
-async def twitter(bot: Snake, logger: Logger) -> None:
+async def twitter(bot: Snake) -> None:
     """
     Sync tweets in the background.
 

jarvis_tasks/tasks/warning.py

@@ -1,7 +1,7 @@
 """JARVIS warnings tasks."""
 import asyncio
+import logging
 from datetime import datetime, timedelta, timezone
-from logging import Logger
 
 from dis_snek import Snake
 from jarvis_core.db import q
@@ -10,16 +10,17 @@ from jarvis_core.db.models import Warning
 from jarvis_tasks.util import runat
 
 queue = []
+logger = logging.getLogger(__name__)
 
 
-async def _unwarn(warn: Warning, logger: Logger) -> None:
+async def _unwarn(warn: Warning) -> None:
     logger.debug(f"Deactivating warning {warn.id}")
     warn.active = False
     await warn.commit()
     queue.remove(warn.id)
 
 
-async def unwarn(bot: Snake, logger: Logger) -> None:
+async def unwarn(bot: Snake) -> None:
     """
     Deactivate warnings when they expire.
 
@@ -27,13 +28,14 @@ async def unwarn(bot: Snake, logger: Logger) -> None:
         bot: Snake instance
         logger: Global logger
     """
+    logger.debug("Starting Task-unwarn")
     while True:
         max_ts = datetime.now(tz=timezone.utc) + timedelta(minutes=55)
         warns = Warning.find(q(active=True, created_at__lte=max_ts))
         async for warn in warns:
             if warn.id in queue:
                 continue
-            coro = _unwarn(warn, logger)
+            coro = _unwarn(warn)
             when = warn.created_at + timedelta(hours=warn.duration)
             asyncio.create_task(runat(when, coro, logger))
             queue.append(warn.id)