Update utils.py

utils.py

@@ -9,17 +9,22 @@ from datetime import datetime, timedelta
 from database.users_chats_db import db
 from bs4 import BeautifulSoup
 
+# Initialize logger with enhanced configuration
 logger = logging.getLogger(__name__)
 logger.setLevel(logging.INFO)
 
+# Log regex pattern compilation
 BTN_URL_REGEX = re.compile(r"(\[([^\[]+?)\]\((buttonurl|buttonalert):(?:/{0,2})(.+?)(:same)?\))")
+logger.debug("Button URL regex pattern compiled successfully")
+
 BANNED = {}
 SMART_OPEN = '“'
 SMART_CLOSE = '”'
 START_CHAR = ('\'', '"', SMART_OPEN)
 
-# temp db for banned 
+# Temporary database class with logging
 class temp(object):
+    logger.info("Initializing temporary storage for banned users/chats and settings")
     BANNED_USERS = []
     BANNED_CHATS = []
     CURRENT = 0
@@ -34,246 +39,278 @@ class temp(object):
     GP_SPELL = {}
 
 async def is_subscribed(bot, query):
-    logger.info(f"Checking subscription for user_id: {query.from_user.id} in AUTH_CHANNEL: {AUTH_CHANNEL}")
+    """Check if user is subscribed to auth channel with detailed logging"""
+    logger.debug(f"Checking subscription status for user {query.from_user.id}")
     try:
         user = await bot.get_chat_member(AUTH_CHANNEL, query.from_user.id)
-        logger.debug(f"User {query.from_user.id} is subscribed.")
-    except UserNotParticipant:
-        logger.debug(f"User {query.from_user.id} is not subscribed.")
-        pass
-    except Exception as e:
-        logger.error(f"Error checking subscription: {e}")
-        print(e)
-    else:
+        logger.info(f"User {query.from_user.id} membership status: {user.status}")
+        
         if user.status != enums.ChatMemberStatus.BANNED:
-            logger.debug(f"User {query.from_user.id} is not banned.")
+            logger.info(f"User {query.from_user.id} is valid subscriber")
             return True
-    logger.debug(f"User {query.from_user.id} is not subscribed.")
+        logger.warning(f"User {query.from_user.id} is banned in auth channel")
+    except UserNotParticipant:
+        logger.warning(f"User {query.from_user.id} not in auth channel")
+    except Exception as e:
+        logger.error(f"Subscription check error for {query.from_user.id}: {str(e)}")
     return False
 
 async def get_poster(query, bulk=False, id=False, file=None):
-    logger.info(f"Fetching poster for query: {query}, bulk: {bulk}, id: {id}, file: {file}")
-    imdb = Cinemagoer() 
-    if not id:   
-        query = (query.strip()).lower()
-        title = query
-        year = re.findall(r'[1-2]\d{3}$', query, re.IGNORECASE)
-        if year:
-            year = list_to_str(year[:1])
-            title = (query.replace(year, "")).strip()
-            logger.debug(f"Extracted year: {year}, title: {title}")
-        elif file is not None:
-            year = re.findall(r'[1-2]\d{3}', file, re.IGNORECASE)
+    """Fetch movie details from IMDb with comprehensive logging"""
+    logger.info(f"Starting IMDb lookup for: {query}")
+    imdb = Cinemagoer()
+    
+    try:
+        if not id:
+            logger.debug("Processing title-based search")
+            query = (query.strip()).lower()
+            title = query
+            year = re.findall(r'[1-2]\d{3}$', query, re.IGNORECASE)
+            
             if year:
-                year = list_to_str(year[:1]) 
-                logger.debug(f"Extracted year from file: {year}")
-        else:
-            year = None
-            logger.debug("Year not found.")
-        try:
+                logger.debug(f"Year found in query: {year}")
+                year = list_to_str(year[:1])
+                title = (query.replace(year, "")).strip()
+            elif file is not None:
+                logger.debug("Extracting year from filename")
+                year = re.findall(r'[1-2]\d{3}', file, re.IGNORECASE)
+                if year:
+                    year = list_to_str(year[:1])
+            else:
+                year = None
+                logger.debug("No year information found")
+
+            logger.info(f"Searching IMDb for: {title} ({year if year else 'no year'})")
             movieid = imdb.search_movie(title.lower(), results=10)
-            logger.debug(f"Found movie IDs: {movieid}")
-        except Exception as e:
-            logger.error(f"Error searching movie: {e}")
-            return None
-        if not movieid:
-            logger.debug("No movie IDs found.")
-            return None
-        if year:
-            filtered=list(filter(lambda k: str(k.get('year')) == str(year), movieid))
-            if not filtered:
+            
+            if not movieid:
+                logger.warning("No IMDb results found")
+                return None
+                
+            logger.debug(f"Found {len(movieid)} potential matches")
+            
+            if year:
+                logger.debug("Filtering results by year")
+                filtered = list(filter(lambda k: str(k.get('year')) == str(year), movieid))
+                if not filtered:
+                    logger.warning("No year matches, using original results")
+                    filtered = movieid
+            else:
                 filtered = movieid
-                logger.debug("No filtered results. Using original results.")
-            logger.debug(f"Filtered results: {filtered}")
+                
+            logger.debug("Filtering by media type")
+            movieid = list(filter(lambda k: k.get('kind') in ['movie', 'tv series'], filtered))
+            
+            if not movieid:
+                logger.warning("No valid media types found, using raw results")
+                movieid = filtered
+                
+            if bulk:
+                logger.info("Returning bulk results")
+                return movieid
+                
+            movieid = movieid[0].movieID
+            logger.info(f"Selected IMDb ID: {movieid}")
         else:
-            filtered = movieid
-            logger.debug("Using original results.")
-        movieid=list(filter(lambda k: k.get('kind') in ['movie', 'tv series'], filtered))
-        if not movieid:
-            movieid = filtered
-            logger.debug("No movie or tv series results. Using original results.")
-        logger.debug(f"Final movie IDs: {movieid}")
-        if bulk:
-            logger.debug("Returning bulk results.")
-            return movieid
-        movieid = movieid[0].movieID
-        logger.debug(f"Selected movie ID: {movieid}")
-    else:
-        movieid = query
-        logger.debug(f"Using provided movie ID: {movieid}")
-    movie = imdb.get_movie(movieid)
-    if movie.get("original air date"):
-        date = movie["original air date"]
-        logger.debug(f"Original air date: {date}")
-    elif movie.get("year"):
-        date = movie.get("year")
-        logger.debug(f"Year: {date}")
-    else:
-        date = "N/A"
-        logger.debug("Date not found. Setting to N/A.")
-    plot = ""
-    if not LONG_IMDB_DESCRIPTION:
-        plot = movie.get('plot')
-        if plot and len(plot) > 0:
-            plot = plot[0]
-            logger.debug(f"Plot: {plot}")
-    else:
-        plot = movie.get('plot outline')
-        logger.debug(f"Plot outline: {plot}")
-    if plot and len(plot) > 800:
-        plot = plot[0:800] + "..."
-        logger.debug(f"Truncated plot: {plot}")
-    return {
-        'title': movie.get('title'),
-        'votes': movie.get('votes'),
-        "aka": list_to_str(movie.get("akas")),
-        "seasons": movie.get("number of seasons"),
-        "box_office": movie.get('box office'),
-        'localized_title': movie.get('localized title'),
-        'kind': movie.get("kind"),
-        "imdb_id": f"tt{movie.get('imdbID')}",
-        "cast": list_to_str(movie.get("cast")),
-        "runtime": list_to_str(movie.get("runtimes")),
-        "countries": list_to_str(movie.get("countries")),
-        "certificates": list_to_str(movie.get("certificates")),
-        "languages": list_to_str(movie.get("languages")),
-        "director": list_to_str(movie.get("director")),
-        "writer":list_to_str(movie.get("writer")),
-        "producer":list_to_str(movie.get("producer")),
-        "composer":list_to_str(movie.get("composer")) ,
-        "cinematographer":list_to_str(movie.get("cinematographer")),
-        "music_team": list_to_str(movie.get("music department")),
-        "distributors": list_to_str(movie.get("distributors")),
-        'release_date': date,
-        'year': movie.get('year'),
-        'genres': list_to_str(movie.get("genres")),
-        'poster': movie.get('full-size cover url'),
-        'plot': plot,
-        'rating': str(movie.get("rating")),
-        'url':f'https://www.imdb.com/title/tt{movieid}'
-    }
+            logger.info(f"Using provided IMDb ID: {query}")
+            movieid = query
+
+        logger.debug("Fetching detailed movie information")
+        movie = imdb.get_movie(movieid)
+        
+        logger.debug("Processing movie metadata")
+        date = movie.get("original air date") or movie.get("year") or "N/A"
+        plot = ""
+        
+        if not LONG_IMDB_DESCRIPTION:
+            plot = movie.get('plot')
+            if plot and len(plot) > 0:
+                plot = plot[0]
+                logger.debug("Using short plot description")
+        else:
+            plot = movie.get('plot outline')
+            logger.debug("Using long plot outline")
+            
+        if plot and len(plot) > 800:
+            logger.debug("Trimming plot description")
+            plot = plot[0:800] + "..."
+
+        logger.info("Successfully processed IMDb data")
+        return {
+            'title': movie.get('title'),
+            'votes': movie.get('votes'),
+            "aka": list_to_str(movie.get("akas")),
+            "seasons": movie.get("number of seasons"),
+            "box_office": movie.get('box office'),
+            'localized_title': movie.get('localized title'),
+            'kind': movie.get("kind"),
+            "imdb_id": f"tt{movie.get('imdbID')}",
+            "cast": list_to_str(movie.get("cast")),
+            "runtime": list_to_str(movie.get("runtimes")),
+            "countries": list_to_str(movie.get("countries")),
+            "certificates": list_to_str(movie.get("certificates")),
+            "languages": list_to_str(movie.get("languages")),
+            "director": list_to_str(movie.get("director")),
+            "writer":list_to_str(movie.get("writer")),
+            "producer":list_to_str(movie.get("producer")),
+            "composer":list_to_str(movie.get("composer")) ,
+            "cinematographer":list_to_str(movie.get("cinematographer")),
+            "music_team": list_to_str(movie.get("music department")),
+            "distributors": list_to_str(movie.get("distributors")),
+            'release_date': date,
+            'year': movie.get('year'),
+            'genres': list_to_str(movie.get("genres")),
+            'poster': movie.get('full-size cover url'),
+            'plot': plot,
+            'rating': str(movie.get("rating")),
+            'url':f'https://www.imdb.com/title/tt{movieid}'
+        }
+    except Exception as e:
+        logger.error(f"IMDb processing failed: {str(e)}")
+        return None
 
 def list_to_str(k):
-    logger.debug(f"Converting list to string: {k}")
+    """Convert list to formatted string with logging"""
+    logger.debug("Converting list to string")
     if not k: 
-        logger.debug("List is empty. Returning 'N/A'.")
+        logger.debug("Empty list received")
         return "N/A"
     elif len(k) == 1: 
-        logger.debug(f"List has one element. Returning: {k[0]}")
+        logger.debug("Single-item list converted")
         return str(k[0])
     elif MAX_LIST_ELM:
+        logger.debug(f"Truncating list to {MAX_LIST_ELM} elements")
         k = k[:int(MAX_LIST_ELM)]
-        result = ' '.join(f'{elem}, ' for elem in k)
-        logger.debug(f"Truncated list to {MAX_LIST_ELM} elements. Returning: {result}")
-        return result
+        return ' '.join(f'{elem}, ' for elem in k)
     else:
-        result = ' '.join(f'{elem}, ' for elem in k)
-        logger.debug(f"Returning full list as string: {result}")
-        return result
+        logger.debug("Converting full list")
+        return ' '.join(f'{elem}, ' for elem in k)
 
 __repo__ = "https://github.com/MrMKN/PROFESSOR-BOT"
-logger.debug(f"Repository URL: {__repo__}")
 __version__ = "PROFESSOR-BOT ᴠ4.5.0"
-logger.debug(f"Version: {__version__}")
 __license__ = "GNU GENERAL PUBLIC LICENSE V2"
-logger.debug(f"License: {__license__}")
 __copyright__ = "Copyright (C) 2023-present MrMKN <https://github.com/MrMKN>"
-logger.debug(f"Copyright: {__copyright__}")
 
 async def search_gagala(text):
-    logger.info(f"Searching Google for text: {text}")
+    """Perform Google search with logging"""
+    logger.info(f"Initializing search for: {text}")
     usr_agent = {
-        'User-Agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36'
-    }
-    text = text.replace(" ", '+')
-    url = f'https://www.google.com/search?q={text}'
-    response = requests.get(url, headers=usr_agent)
-    response.raise_for_status()
-    soup = BeautifulSoup(response.text, 'html.parser')
-    titles = soup.find_all('h3')
-    result = [title.getText() for title in titles]
-    logger.debug(f"Found titles: {result}")
-    return result
+        'User-Agent': 'Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) '
+        'Chrome/61.0.3163.100 Safari/537.36'
+        }
+    try:
+        text = text.replace(" ", '+')
+        url = f'https://www.google.com/search?q={text}'
+        logger.debug(f"Requesting URL: {url}")
+        
+        response = requests.get(url, headers=usr_agent)
+        response.raise_for_status()
+        logger.info("Google search successful")
+        
+        soup = BeautifulSoup(response.text, 'html.parser')
+        titles = soup.find_all('h3')
+        logger.debug(f"Found {len(titles)} search results")
+        
+        return [title.getText() for title in titles]
+    except Exception as e:
+        logger.error(f"Search failed: {str(e)}")
+        return []
 
 async def get_settings(group_id):
-    logger.info(f"Getting settings for group_id: {group_id}")
+    """Retrieve group settings with caching and logging"""
+    logger.debug(f"Fetching settings for group {group_id}")
     settings = temp.SETTINGS.get(group_id)
+    
     if not settings:
+        logger.info("Cache miss - loading from database")
         settings = await db.get_settings(group_id)
         temp.SETTINGS[group_id] = settings
-        logger.debug(f"Settings retrieved from database: {settings}")
     else:
-        logger.debug(f"Settings retrieved from cache: {settings}")
+        logger.debug("Using cached settings")
+        
     return settings
     
 async def save_group_settings(group_id, key, value):
-    logger.info(f"Saving setting {key} with value {value} for group_id: {group_id}")
+    """Update group settings with transaction logging"""
+    logger.info(f"Updating setting {key} for group {group_id}")
     current = await get_settings(group_id)
     current[key] = value
     temp.SETTINGS[group_id] = current
-    await db.update_settings(group_id, current)
-    logger.debug(f"Updated settings: {current}")
+    
+    try:
+        await db.update_settings(group_id, current)
+        logger.debug("Database update successful")
+    except Exception as e:
+        logger.error(f"Settings update failed: {str(e)}")
+        raise
 
 def get_size(size):
-    logger.debug(f"Converting size: {size}")
+    """Convert bytes to human-readable format with logging"""
+    logger.debug(f"Converting size: {size} bytes")
     units = ["Bytes", "KB", "MB", "GB", "TB", "PB", "EB"]
     size = float(size)
     i = 0
+    
     while size >= 1024.0 and i < len(units):
         i += 1
         size /= 1024.0
+        
     result = "%.2f %s" % (size, units[i])
     logger.debug(f"Converted size: {result}")
     return result
 
 def get_file_id(msg: Message):
-    logger.debug(f"Getting file ID from message: {msg}")
-    if not msg.media: 
-        logger.debug("No media in message.")
+    """Extract file ID from message with media type detection"""
+    logger.debug("Extracting file ID from message")
+    if not msg.media:
+        logger.warning("No media found in message")
         return None
+        
     for message_type in ("photo", "animation", "audio", "document", "video", "video_note", "voice", "sticker"):
         obj = getattr(msg, message_type)
         if obj:
+            logger.info(f"Extracted media type: {message_type}")
             setattr(obj, "message_type", message_type)
-            logger.debug(f"Found file ID: {obj.file_id}")
             return obj
 
 def extract_user(message: Message) -> Union[int, str]:
-    logger.debug(f"Extracting user from message: {message}")
+    """Extract user ID and name from message with logging"""
+    logger.debug("Extracting user information from message")
     user_id = None
     user_first_name = None
+    
     if message.reply_to_message:
         user_id = message.reply_to_message.from_user.id
         user_first_name = message.reply_to_message.from_user.first_name
-        logger.debug(f"User extracted from reply: {user_id}, {user_first_name}")
+        logger.info(f"User extracted from reply: {user_id} - {user_first_name}")
     elif len(message.command) > 1:
         if (len(message.entities) > 1 and message.entities[1].type == enums.MessageEntityType.TEXT_MENTION):
             required_entity = message.entities[1]
             user_id = required_entity.user.id
             user_first_name = required_entity.user.first_name
-            logger.debug(f"User extracted from text mention: {user_id}, {user_first_name}")
+            logger.info(f"User extracted from mention: {user_id} - {user_first_name}")
         else:
             user_id = message.command[1]
             user_first_name = user_id
-            logger.debug(f"User extracted from command: {user_id}, {user_first_name}")
             try:
                 user_id = int(user_id)
-                logger.debug(f"Converted user_id to integer: {user_id}")
-            except ValueError: 
-                logger.debug("Failed to convert user_id to integer.")
-                pass
+                logger.info(f"User ID converted to int: {user_id}")
+            except ValueError:
+                logger.warning("Failed to convert user ID to int")
     else:
         user_id = message.from_user.id
         user_first_name = message.from_user.first_name
-        logger.debug(f"User extracted from message sender: {user_id}, {user_first_name}")
+        logger.info(f"User extracted from message sender: {user_id} - {user_first_name}")
+        
     return (user_id, user_first_name)
 
 def split_quotes(text: str) -> List:
-    logger.debug(f"Splitting quotes from text: {text}")
+    """Split quoted text into key and value with logging"""
+    logger.debug("Splitting quotes from text")
     if not any(text.startswith(char) for char in START_CHAR):
-        result = text.split(None, 1)
-        logger.debug(f"No quotes found. Split result: {result}")
-        return result
+        logger.debug("No starting quote found, splitting by space")
+        return text.split(None, 1)
+    
     counter = 1  # ignore first char -> is some kind of quote
     while counter < len(text):
         if text[counter] == "\\":
@@ -282,77 +319,73 @@ def split_quotes(text: str) -> List:
             break
         counter += 1
     else:
-        result = text.split(None, 1)
-        logger.debug(f"No closing quote found. Split result: {result}")
-        return result
+        logger.debug("No ending quote found, returning split")
+        return text.split(None, 1)
 
-    # 1 to avoid starting quote, and counter is exclusive so avoids ending
     key = remove_escapes(text[1:counter].strip())
-    # index will be in range, or `else` would have been executed and returned
     rest = text[counter + 1:].strip()
     if not key:
         key = text[0] + text[0]
-        logger.debug(f"No key found. Using default key: {key}")
-    result = list(filter(None, [key, rest]))
-    logger.debug(f"Split result: {result}")
-    return result
+        
+    logger.debug(f"Split result: key='{key}', rest='{rest}'")
+    return list(filter(None, [key, rest]))
 
 def parser(text, keyword, cb_data):
-    logger.debug(f"Parsing text: {text}, keyword: {keyword}, cb_data: {cb_data}")
+    """Parse buttons and alerts from text with logging"""
+    logger.debug("Parsing buttons and alerts from text")
     if "buttonalert" in text: 
         text = (text.replace("\n", "\\n").replace("\t", "\\t"))
-        logger.debug(f"Text after replacing newline and tab: {text}")
+        
     buttons = []
     note_data = ""
     prev = 0
     i = 0
     alerts = []
+    
     for match in BTN_URL_REGEX.finditer(text):
         n_escapes = 0
         to_check = match.start(1) - 1
         while to_check > 0 and text[to_check] == "\\":
             n_escapes += 1
             to_check -= 1
-        # if even, not escaped -> create button
+            
         if n_escapes % 2 == 0:
             note_data += text[prev:match.start(1)]
             prev = match.end(1)
             if match.group(3) == "buttonalert":
-                # create a thruple with button label, url, and newline status
                 if bool(match.group(5)) and buttons:
                     buttons[-1].append(InlineKeyboardButton(match.group(2), callback_data=f"{cb_data}:{i}:{keyword}"))
-                    logger.debug(f"Added buttonalert button: {match.group(2)}, {match.group(4)}, {match.group(5)}")
                 else:
                     buttons.append([InlineKeyboardButton(match.group(2), callback_data=f"{cb_data}:{i}:{keyword}")])
-                    logger.debug(f"Created buttonalert button: {match.group(2)}, {match.group(4)}, {match.group(5)}")
                 i += 1
                 alerts.append(match.group(4))
-                logger.debug(f"Added alert: {match.group(4)}")
+                logger.debug(f"Button alert added: {match.group(2)}")
             elif bool(match.group(5)) and buttons:
                 buttons[-1].append(InlineKeyboardButton(match.group(2), url=match.group(4).replace(" ", "")))
-                logger.debug(f"Added button: {match.group(2)}, {match.group(4)}")
+                logger.debug(f"Button URL added: {match.group(2)}")
             else:
                 buttons.append([InlineKeyboardButton(match.group(2), url=match.group(4).replace(" ", ""))])
-                logger.debug(f"Created button: {match.group(2)}, {match.group(4)}")
+                logger.debug(f"Button added: {match.group(2)}")
         else:
             note_data += text[prev:to_check]
             prev = match.start(1) - 1
-            logger.debug(f"Escaped button: {match.group(2)}")
+            
     else: 
         note_data += text[prev:]
-        logger.debug(f"Note data after parsing: {note_data}")
+        
     try: 
-        result = (note_data, buttons, alerts)
-        logger.debug(f"Parsing successful. Result: {result}")
-        return result
+        logger.info("Parsing completed successfully")
+        return note_data, buttons, alerts
     except Exception as e:
-        logger.error(f"Parsing failed: {e}")
+        logger.error(f"Parsing error: {str(e)}")
         return note_data, buttons, None
 
 def remove_escapes(text: str) -> str:
-    logger.debug(f"Removing escapes from text: {text}")
+    """Remove escape characters from text with logging"""
+    logger.debug("Removing escape characters from text")
     res = ""
     is_escaped = False
+    
     for counter in range(len(text)):
         if is_escaped:
             res += text[counter]
@@ -361,100 +394,128 @@ def remove_escapes(text: str) -> str:
             is_escaped = True
         else:
             res += text[counter]
-            logger.debug(f"Processed character: {text[counter]}, result so far: {res}")
-    logger.debug(f"Final result after removing escapes: {res}")
+    
+    logger.debug("Escape characters removed successfully")
     return res
-   
+
 def humanbytes(size):
+    """Convert bytes to human-readable format with logging"""
     logger.debug(f"Converting size to human-readable format: {size}")
     if not size:
-        logger.debug("Size is zero. Returning empty string.")
+        logger.warning("No size provided for conversion")
         return ""
+    
     power = 2**10
     n = 0
     Dic_powerN = {0: ' ', 1: 'Ki', 2: 'Mi', 3: 'Gi', 4: 'Ti'}
+    
     while size > power:
         size /= power
         n += 1
-        logger.debug(f"Converted size: {size}, power: {power}, n: {n}")
+        
     result = str(round(size, 2)) + " " + Dic_powerN[n] + 'B'
-    logger.debug(f"Human-readable size: {result}")
+    logger.debug(f"Converted size: {result}")
     return result
+
+def get_time(seconds):
+    """Convert seconds to human-readable time format with logging"""
+    logger.debug(f"Converting seconds to time format: {seconds}")
+    periods = [('ᴅ', 86400), ('ʜ', 3600), ('ᴍ', 60), ('ꜱ', 1)]
+    result = ''
     
+    for period_name, period_seconds in periods:
+        if seconds >= period_seconds:
+            period_value, seconds = divmod(seconds, period_seconds)
+            result += f'{int(period_value)}{period_name}'
+    
+    logger.debug(f"Converted time: {result}")
+    return result
+
 async def get_shortlink(link):
-    logger.info(f"Generating shortlink for link: {link}")
+    """Get shortened link using API with logging"""
+    logger.info(f"Requesting short link for: {link}")
     url = f'{SHORT_URL}/api'
     params = {'api': SHORT_API, 'url': link}
+    
     try:
         async with aiohttp.ClientSession() as session:
             async with session.get(url, params=params, raise_for_status=True, ssl=False) as response:
                 data = await response.json()
-                logger.debug(f"Shortlink API response: {data}")
                 if data["status"] == "success":
-                    logger.debug(f"Shortlink generated: {data['shortenedUrl']}")
+                    logger.info("Short link retrieved successfully")
                     return data['shortenedUrl']
                 else:
-                    logger.error(f"Error generating shortlink: {data['message']}")
+                    logger.error(f"Error from short link API: {data['message']}")
                     return link
     except Exception as e:
-        logger.error(f"Exception generating shortlink: {e}")
+        logger.error(f"Short link request failed: {str(e)}")
         return link
 
 def extract_time(time_val):
-    logger.debug(f"Extracting time from time_val: {time_val}")
+    """Extract time from string with logging"""
+    logger.debug(f"Extracting time from value: {time_val}")
     if any(time_val.endswith(unit) for unit in ("s", "m", "h", "d")):
         unit = time_val[-1]
         time_num = time_val[:-1]  # type: str
+        
         if not time_num.isdigit():
-            logger.debug("Time value is not a digit.")
+            logger.warning("Invalid time number provided")
             return None
 
         if unit == "s":
             bantime = datetime.now() + timedelta(seconds=int(time_num)) 
-            logger.debug(f"Bantime set for seconds: {bantime}")
         elif unit == "m":
             bantime = datetime.now() + timedelta(minutes=int(time_num))
-            logger.debug(f"Bantime set for minutes: {bantime}")
         elif unit == "h":
             bantime = datetime.now() + timedelta(hours=int(time_num))
-            logger.debug(f"Bantime set for hours: {bantime}")
         elif unit == "d":
             bantime = datetime.now() + timedelta(days=int(time_num))
-            logger.debug(f"Bantime set for days: {bantime}")
         else:
-            logger.debug("Invalid time unit.")
+            logger.error("Unknown time unit provided")
             return None
-        logger.debug(f"Extracted bantime: {bantime}")
+            
+        logger.info(f"Extracted ban time: {bantime}")
         return bantime
     else:
-        logger.debug("Time value does not end with s, m, h, or d.")
+        logger.warning("No valid time unit found")
         return None
 
 async def admin_check(message: Message) -> bool:
-    logger.info(f"Checking admin status for message: {message}")
+    """Check if user is an admin with logging"""
+    logger.debug("Checking admin status for user")
     if not message.from_user: 
-        logger.debug("Message does not have a from_user.")
+        logger.warning("Message has no user information")
         return False
+    
     if message.chat.type not in [enums.ChatType.GROUP, enums.ChatType.SUPERGROUP]: 
-        logger.debug("Chat type is not GROUP or SUPERGROUP.")
+        logger.warning("Message is not from a group or supergroup")
         return False
+    
     if message.from_user.id in [777000, 1087968824]: 
-        logger.debug("User is a system user.")
+        logger.info("User  is a bot admin")
         return True
+    
     client = message._client
     chat_id = message.chat.id
     user_id = message.from_user.id
-    check_status = await client.get_chat_member(chat_id=chat_id,user_id=user_id)
-    admin_strings = [enums.ChatMemberStatus.OWNER, enums.ChatMemberStatus.ADMINISTRATOR]
-    if check_status.status not in admin_strings: 
-        logger.debug("User is not an admin.")
+    
+    try:
+        check_status = await client.get_chat_member(chat_id=chat_id, user_id=user_id)
+        admin_strings = [enums.ChatMemberStatus.OWNER, enums.ChatMemberStatus.ADMINISTRATOR]
+        
+        if check_status.status not in admin_strings: 
+            logger.info(f"User  {user_id} is not an admin")
+            return False
+        else: 
+            logger.info(f"User  {user_id} is an admin")
+            return True
+    except Exception as e:
+        logger.error(f"Admin check failed for user {user_id}: {str(e)}")
         return False
-    else: 
-        logger.debug("User is an admin.")
-        return True
 
 async def admin_filter(filt, client, message):
-    logger.info(f"Applying admin filter for message: {message}")
-    result = await admin_check(message)
-    logger.debug(f"Admin filter result: {result}")
-    return result
+    """Filter for admin messages with logging"""
+    logger.debug("Applying admin filter")
+    is_admin = await admin_check(message)
+    logger.info(f"Admin filter result: {is_admin}")
+    return is_admin