From f4035ac0b17b0f96d3ef55a737b101d395f6aa5c Mon Sep 17 00:00:00 2001 From: Daniel Roschka Date: Fri, 12 Apr 2024 13:42:00 +0200 Subject: [PATCH] Refactor logging for more granularity This changes the use of the logger used for logging by the bots from the root logger to a module specific logger, which provides more flexibility in terms of configuration. It also changes the command line options of the bots to configure the verbosity of logging. This allows introducing an additional verbosity level which uses debug logging for the bots themselves, but doesn't do the same for third-party libraries used by them. This helps reducing often undesired high-volume debug logs by libraries like Slixmpp, while still generating debug logs for our custom code. --- tests/test_echelon.py | 45 ++++++++++---------- tests/test_xpartamupp.py | 37 +++++++++-------- xpartamupp/echelon.py | 89 ++++++++++++++++++++++------------------ xpartamupp/modbot.py | 61 ++++++++++++++++----------- xpartamupp/xpartamupp.py | 65 +++++++++++++++++------------ 5 files changed, 166 insertions(+), 131 deletions(-) diff --git a/tests/test_echelon.py b/tests/test_echelon.py index 6728c96..e43956e 100644 --- a/tests/test_echelon.py +++ b/tests/test_echelon.py @@ -123,41 +123,45 @@ class TestArgumentParsing(TestCase): @parameterized.expand([ ([], - Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', log_level=30, xserver=None, + Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', xserver=None, no_verify=False, nickname='RatingsBot', password='XXXXXX', room='arena', - database_url='sqlite:///lobby_rankings.sqlite3')), - (['--debug'], - Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', log_level=10, xserver=None, + verbosity=0, database_url='sqlite:///lobby_rankings.sqlite3')), + (['-v'], + Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', xserver=None, no_verify=False, nickname='RatingsBot', password='XXXXXX', room='arena', - database_url='sqlite:///lobby_rankings.sqlite3')), - (['--quiet'], - Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', log_level=40, xserver=None, + verbosity=1, database_url='sqlite:///lobby_rankings.sqlite3')), + (['-vv'], + Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', xserver=None, no_verify=False, nickname='RatingsBot', password='XXXXXX', room='arena', - database_url='sqlite:///lobby_rankings.sqlite3')), - (['--verbose'], - Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', log_level=20, xserver=None, + verbosity=2, database_url='sqlite:///lobby_rankings.sqlite3')), + (['-vvv'], + Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', xserver=None, no_verify=False, nickname='RatingsBot', password='XXXXXX', room='arena', - database_url='sqlite:///lobby_rankings.sqlite3')), + verbosity=3, database_url='sqlite:///lobby_rankings.sqlite3')), + (['--verbosity', '3'], + Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', xserver=None, + no_verify=False, nickname='RatingsBot', password='XXXXXX', room='arena', + verbosity=3, database_url='sqlite:///lobby_rankings.sqlite3')), (['-m', 'lobby.domain.tld'], - Namespace(domain='lobby.domain.tld', login='EcheLOn', log_level=30, nickname='RatingsBot', + Namespace(domain='lobby.domain.tld', login='EcheLOn', verbosity=0, nickname='RatingsBot', xserver=None, no_verify=False, password='XXXXXX', room='arena', database_url='sqlite:///lobby_rankings.sqlite3')), (['--domain=lobby.domain.tld'], - Namespace(domain='lobby.domain.tld', login='EcheLOn', log_level=30, nickname='RatingsBot', + Namespace(domain='lobby.domain.tld', login='EcheLOn', verbosity=0, nickname='RatingsBot', xserver=None, no_verify=False, password='XXXXXX', room='arena', database_url='sqlite:///lobby_rankings.sqlite3')), (['-m', 'lobby.domain.tld', '-l', 'bot', '-p', '123456', '-n', 'Bot', '-r', 'arena123', '-v'], - Namespace(domain='lobby.domain.tld', login='bot', log_level=20, nickname='Bot', + Namespace(domain='lobby.domain.tld', login='bot', verbosity=1, nickname='Bot', xserver=None, no_verify=False, password='123456', room='arena123', database_url='sqlite:///lobby_rankings.sqlite3')), (['--domain=lobby.domain.tld', '--login=bot', '--password=123456', '--nickname=Bot', - '--room=arena123', '--database-url=sqlite:////tmp/db.sqlite3', '--verbose'], - Namespace(domain='lobby.domain.tld', login='bot', log_level=20, nickname='Bot', + '--room=arena123', '--database-url=sqlite:////tmp/db.sqlite3'], + Namespace(domain='lobby.domain.tld', login='bot', verbosity=0, nickname='Bot', xserver=None, no_verify=False, password='123456', room='arena123', database_url='sqlite:////tmp/db.sqlite3')), (['--no-verify'], - Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', log_level=30, xserver=None, + Namespace(domain='lobby.wildfiregames.com', login='EcheLOn', verbosity=0, xserver=None, no_verify=True, nickname='RatingsBot', password='XXXXXX', room='arena', database_url='sqlite:///lobby_rankings.sqlite3')), ]) @@ -169,10 +173,7 @@ def test_valid(self, cmd_args, expected_args): @parameterized.expand([ (['-f'],), (['--foo'],), - (['--debug', '--quiet'],), - (['--quiet', '--verbose'],), - (['--debug', '--verbose'],), - (['--debug', '--quiet', '--verbose'],), + (['-v', '--verbosity', '1'],) ]) def test_invalid(self, cmd_args): """Test invalid parameter combinations.""" @@ -193,7 +194,7 @@ def test_success(self): domain='lobby.wildfiregames.com', password='XXXXXX', room='arena', nickname='RatingsBot', database_url='sqlite:///lobby_rankings.sqlite3', - xserver=None, no_verify=False) + xserver=None, no_verify=False, verbosity=0) main() args_mock.assert_called_once_with() leaderboard_mock.assert_called_once_with('sqlite:///lobby_rankings.sqlite3') diff --git a/tests/test_xpartamupp.py b/tests/test_xpartamupp.py index 28cf74e..31f2bd8 100644 --- a/tests/test_xpartamupp.py +++ b/tests/test_xpartamupp.py @@ -92,37 +92,41 @@ class TestArgumentParsing(TestCase): """Test handling of parsing command line parameters.""" @parameterized.expand([ - ([], Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', log_level=30, + ([], Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', verbosity=0, xserver=None, no_verify=False, nickname='WFGBot', password='XXXXXX', room='arena')), - (['--debug'], - Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', log_level=10, + (['-v'], + Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', verbosity=1, xserver=None, no_verify=False, nickname='WFGBot', password='XXXXXX', room='arena')), - (['--quiet'], - Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', log_level=40, + (['-vv'], + Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', verbosity=2, xserver=None, no_verify=False, nickname='WFGBot', password='XXXXXX', room='arena')), - (['--verbose'], - Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', log_level=20, + (['-vvv'], + Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', verbosity=3, + xserver=None, no_verify=False, + nickname='WFGBot', password='XXXXXX', room='arena')), + (['--verbosity', '3'], + Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', verbosity=3, xserver=None, no_verify=False, nickname='WFGBot', password='XXXXXX', room='arena')), (['-m', 'lobby.domain.tld'], - Namespace(domain='lobby.domain.tld', login='xpartamupp', log_level=30, nickname='WFGBot', + Namespace(domain='lobby.domain.tld', login='xpartamupp', verbosity=0, nickname='WFGBot', xserver=None, no_verify=False, password='XXXXXX', room='arena')), (['--domain=lobby.domain.tld'], - Namespace(domain='lobby.domain.tld', login='xpartamupp', log_level=30, nickname='WFGBot', + Namespace(domain='lobby.domain.tld', login='xpartamupp', verbosity=0, nickname='WFGBot', xserver=None, no_verify=False, password='XXXXXX', room='arena')), (['-m', 'lobby.domain.tld', '-l', 'bot', '-p', '123456', '-n', 'Bot', '-r', 'arena123', '-v'], - Namespace(domain='lobby.domain.tld', login='bot', log_level=20, xserver=None, + Namespace(domain='lobby.domain.tld', login='bot', verbosity=1, xserver=None, no_verify=False, nickname='Bot', password='123456', room='arena123')), (['--domain=lobby.domain.tld', '--login=bot', '--password=123456', '--nickname=Bot', - '--room=arena123', '--verbose'], - Namespace(domain='lobby.domain.tld', login='bot', log_level=20, xserver=None, + '--room=arena123'], + Namespace(domain='lobby.domain.tld', login='bot', verbosity=0, xserver=None, no_verify=False, nickname='Bot', password='123456', room='arena123')), (['--no-verify'], - Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', log_level=30, + Namespace(domain='lobby.wildfiregames.com', login='xpartamupp', verbosity=0, xserver=None, no_verify=True, nickname='WFGBot', password='XXXXXX', room='arena')), ]) @@ -134,10 +138,7 @@ def test_valid(self, cmd_args, expected_args): @parameterized.expand([ (['-f'],), (['--foo'],), - (['--debug', '--quiet'],), - (['--quiet', '--verbose'],), - (['--debug', '--verbose'],), - (['--debug', '--quiet', '--verbose'],), + (['-v', '--verbosity', '1'],) ]) def test_invalid(self, cmd_args): """Test invalid parameter combinations.""" @@ -156,7 +157,7 @@ def test_success(self): args_mock.return_value = Mock(log_level=30, login='xpartamupp', domain='lobby.wildfiregames.com', password='XXXXXX', room='arena', nickname='WFGBot', - xserver=None, no_verify=False) + xserver=None, no_verify=False, verbosity=0) main() args_mock.assert_called_once_with() xmpp_mock().register_plugin.assert_has_calls([call('xep_0004'), call('xep_0030'), diff --git a/xpartamupp/echelon.py b/xpartamupp/echelon.py index d08602f..dc3f200 100755 --- a/xpartamupp/echelon.py +++ b/xpartamupp/echelon.py @@ -51,6 +51,8 @@ # to a mention. INFO_MSG_COOLDOWN_SECONDS = 120 +logger = logging.getLogger(__name__) + class Leaderboard: """Class that provides and manages leaderboard data.""" @@ -88,7 +90,7 @@ def get_or_create_player(self, jid): player = Player(jid=str(jid), rating=-1) self.db.add(player) self.db.commit() - logging.debug("Created player %s", jid) + logger.debug("Created player %s", jid) return player def get_profile(self, jid): @@ -105,14 +107,14 @@ def get_profile(self, jid): player = self.db.query(Player).filter(func.lower(Player.jid) == str(jid).lower()).first() if not player: - logging.debug("Couldn't find profile for player %s", jid) + logger.debug("Couldn't find profile for player %s", jid) return {} games_played = self.db.query(PlayerInfo).filter_by(player_id=player.id).count() wins = self.db.query(Game).filter_by(winner_id=player.id).count() if player.rating == -1: - logging.debug("Player %s hasn't played any rated games yet", jid) + logger.debug("Player %s hasn't played any rated games yet", jid) return {'rating': '-', 'rank': '-', 'highestRating': '-', 'totalGamesPlayed': games_played, 'wins': wins, 'losses': games_played - wins} @@ -138,7 +140,7 @@ def _add_game(self, game_report): # pylint: disable=too-many-locals # Discard any games still in progress. We shouldn't get # reports from those games anyway. if 'active' in dict.values(game_report['playerStates']): - logging.warning("Received a game report for an unfinished game") + logger.warning("Received a game report for an unfinished game") return None players = self.db.query(Player).filter(func.lower(Player.jid).in_( @@ -382,19 +384,19 @@ def add_report(self, jid, raw_game_report): current_match = self.interim_report_tracker[match_id] if raw_game_report != current_match['report']: report_diff = self._get_report_diff(raw_game_report, current_match['report']) - logging.warning("Retrieved reports for match %s differ:\n %s", match_id, - report_diff) + logger.warning("Retrieved reports for match %s differ:\n %s", match_id, + report_diff) return player_jids = current_match['jids'] if player_index in player_jids: if player_jids[player_index] == jid: - logging.warning("Received a report for match %s from player %s twice.", - match_id, jid) + logger.warning("Received a report for match %s from player %s twice.", + match_id, jid) else: - logging.warning("Retrieved a report for match %s for the same player twice, " - "but from two different XMPP accounts: %s vs. %s", match_id, - player_jids[player_index], jid) + logger.warning("Retrieved a report for match %s for the same player twice, " + "but from two different XMPP accounts: %s vs. %s", match_id, + player_jids[player_index], jid) return else: player_jids[player_index] = str(JID(jid).bare + "/0ad") @@ -406,13 +408,13 @@ def add_report(self, jid, raw_game_report): self.leaderboard.add_and_rate_game(self._expand_report( current_match)) except Exception: - logging.exception("Failed to add and rate a game.") + logger.exception("Failed to add and rate a game.") del current_match elif num_retrieved_reports < num_players: - logging.warning("Haven't received all reports for the game yet. %i/%i", - num_retrieved_reports, num_players) + logger.warning("Haven't received all reports for the game yet. %i/%i", + num_retrieved_reports, num_players) elif num_retrieved_reports > num_players: - logging.warning("Retrieved more reports than players. This shouldn't happen.") + logger.warning("Retrieved more reports than players. This shouldn't happen.") @staticmethod def _expand_report(game_report): @@ -542,7 +544,7 @@ async def _session_start(self, event): # pylint: disable=unused-argument await self.plugin['xep_0045'].join_muc_wait(self.room, self.nick) self.send_presence() self.get_roster() - logging.info("EcheLOn started") + logger.info("EcheLOn started") async def _shutdown(self, event): # pylint: disable=unused-argument """Shut down EcheLOn. @@ -555,7 +557,7 @@ async def _shutdown(self, event): # pylint: disable=unused-argument event (dict): empty dummy dict """ - logging.error("Can't log in. Aborting reconnects.") + logger.error("Can't log in. Aborting reconnects.") self.abort() self.shutdown.set_result(True) @@ -598,7 +600,7 @@ def _muc_online(self, presence): self._broadcast_rating_list() - logging.debug("Client '%s' connected with a nick of '%s'.", jid, nick) + logger.debug("Client '%s' connected with a nick of '%s'.", jid, nick) def _muc_offline(self, presence): """Remove leaving players from the list of players. @@ -614,7 +616,7 @@ def _muc_offline(self, presence): if not jid.resource.startswith('0ad'): return - logging.debug("Client '%s' with nick '%s' disconnected", jid, nick) + logger.debug("Client '%s' with nick '%s' disconnected", jid, nick) def _muc_message(self, msg): """Process messages in the MUC room. @@ -663,8 +665,8 @@ def _iq_board_list_handler(self, iq): try: self._send_leaderboard(iq) except Exception: - logging.exception("Failed to process get leaderboard request from %s", - iq['from'].bare) + logger.exception("Failed to process get leaderboard request from %s", + iq['from'].bare) def _iq_game_report_handler(self, iq): """Handle end of game reports from clients. @@ -679,7 +681,7 @@ def _iq_game_report_handler(self, iq): try: self.report_manager.add_report(iq['from'], iq['gamereport']['game']) except Exception: - logging.exception("Failed to update game statistics for %s", iq['from'].bare) + logger.exception("Failed to update game statistics for %s", iq['from'].bare) rating_messages = self.leaderboard.get_rating_messages() if rating_messages: @@ -701,8 +703,8 @@ def _iq_profile_handler(self, iq): try: self._send_profile(iq, iq['profile']['command']) except Exception: - logging.exception("Failed to send profile about %s to %s", iq['profile']['command'], - iq['from'].bare) + logger.exception("Failed to send profile about %s to %s", iq['profile']['command'], + iq['from'].bare) def _send_leaderboard(self, iq): """Send the whole leaderboard. @@ -723,7 +725,7 @@ def _send_leaderboard(self, iq): try: iq.send() except Exception: - logging.exception("Failed to send leaderboard to %s", iq['to']) + logger.exception("Failed to send leaderboard to %s", iq['to']) def _broadcast_rating_list(self): """Broadcast the ratings of all online players.""" @@ -748,7 +750,7 @@ def _broadcast_rating_list(self): try: iq.send() except Exception: - logging.exception("Failed to send rating list to %s", jid) + logger.exception("Failed to send rating list to %s", jid) def _send_profile(self, iq, player_nick): """Send the player profile to a specified target. @@ -774,7 +776,7 @@ def _send_profile(self, iq, player_nick): try: stats = self.leaderboard.get_profile(player_jid) except Exception: - logging.exception("Failed to get leaderboard profile for player %s", player_jid) + logger.exception("Failed to get leaderboard profile for player %s", player_jid) stats = {} iq = iq.reply() @@ -791,7 +793,7 @@ def _send_profile(self, iq, player_nick): try: iq.send() except Exception: - logging.exception("Failed to send profile to %s", iq['to']) + logger.exception("Failed to send profile to %s", iq['to']) def parse_args(): @@ -804,14 +806,13 @@ def parse_args(): parser = argparse.ArgumentParser(formatter_class=argparse.ArgumentDefaultsHelpFormatter, description="EcheLOn - XMPP Rating Bot") - log_settings = parser.add_mutually_exclusive_group() - log_settings.add_argument('-q', '--quiet', help="only log errors", action='store_const', - dest='log_level', const=logging.ERROR) - log_settings.add_argument('-d', '--debug', help="log debug messages", action='store_const', - dest='log_level', const=logging.DEBUG) - log_settings.add_argument('-v', '--verbose', help="log more informative messages", - action='store_const', dest='log_level', const=logging.INFO) - log_settings.set_defaults(log_level=logging.WARNING) + verbosity_parser = parser.add_mutually_exclusive_group() + verbosity_parser.add_argument("-v", action="count", dest="verbosity", default=0, + help="Increase verbosity of logging. Can be provided up to " + "three times to get full debug logging") + verbosity_parser.add_argument("--verbosity", type=int, + help="Increase verbosity of logging. Supported values are 0 to 3" + ) parser.add_argument('-m', '--domain', help="XMPP server to connect to", default='lobby.wildfiregames.com') @@ -834,9 +835,19 @@ def main(): """Entry point a console script.""" args = parse_args() - logging.basicConfig(level=args.log_level, - format='%(asctime)s %(levelname)-8s %(message)s', - datefmt='%Y-%m-%d %H:%M:%S') + log_level = logging.WARNING + if args.verbosity == 1: + log_level = logging.INFO + elif args.verbosity == 2: + log_level = logging.DEBUG + elif args.verbosity >= 3: + log_level = logging.DEBUG + root_logger = logging.getLogger() + root_logger.setLevel(log_level) + + logging.basicConfig(format='%(asctime)s %(levelname)-8s %(message)s', + datefmt='%Y-%m-%dT%H:%M:%S%z') + logger.setLevel(log_level) leaderboard = Leaderboard(args.database_url) xmpp = EcheLOn(JID('%s@%s/%s' % (args.login, args.domain, 'CC')), args.password, diff --git a/xpartamupp/modbot.py b/xpartamupp/modbot.py index fe1d884..4a54e05 100755 --- a/xpartamupp/modbot.py +++ b/xpartamupp/modbot.py @@ -43,6 +43,8 @@ from xpartamupp.lobby_moderation_db import (JIDNickWhitelist, KickEvent, Moderator, MuteEvent, UnmuteEvent) +logger = logging.getLogger(__name__) + class ModCmdParser(ArgumentParser): """Custom argument parser for commands via XMPP.""" @@ -174,7 +176,7 @@ def get_cmd_parser() -> ArgumentParser: def coroutine_exception_handler(task: Task) -> None: """Log asyncio task exceptions.""" if task.exception(): - logging.error("asyncio task failed", exc_info=task.exception()) + logger.error("asyncio task failed", exc_info=task.exception()) def create_task(*args, **kwargs) -> Task: @@ -258,7 +260,7 @@ async def _session_start(self, _) -> None: task = create_task(self._unmute_after_mute_ended(mute.mute_end, JID(mute.player))) self.unmute_tasks[mute.player] = task - logging.info("ModBot started") + logger.info("ModBot started") async def _shutdown(self, _) -> None: """Shut down ModBot. @@ -267,7 +269,7 @@ async def _shutdown(self, _) -> None: configured credentials are wrong, as further connection tries won't succeed in this case. """ - logging.error("Can't log in. Aborting reconnects.") + logger.error("Can't log in. Aborting reconnects.") self.abort() self.shutdown.set_result(True) @@ -313,7 +315,7 @@ async def _muc_presence_change(self, presence: MUCPresence) -> None: jid = JID(presence["muc"]["jid"]) role = presence["muc"]["role"] room = presence["muc"]["room"] - logging.debug("User \"%s\" connected with a nick \"%s\".", jid, nick) + logger.debug("User \"%s\" connected with a nick \"%s\".", jid, nick) if not await self._check_matching_nick(jid, nick, JID(presence["muc"]["room"])): return @@ -331,12 +333,12 @@ async def _muc_presence_change(self, presence: MUCPresence) -> None: await self.plugin["xep_0045"].set_role(room, nick, "visitor", reason=mute_event.reason) except IqError: - logging.exception("Muting %s (%s) on join failed.", nick, jid) + logger.exception("Muting %s (%s) on join failed.", nick, jid) elif not mute_event and role == "visitor": try: await self.plugin["xep_0045"].set_role(room, nick, "participant") except IqError: - logging.exception("Unmuting %s (%s) on join failed.", nick, jid) + logger.exception("Unmuting %s (%s) on join failed.", nick, jid) async def _muc_command_message(self, msg: Message) -> None: """Process messages in the command MUC room. @@ -361,8 +363,8 @@ async def _muc_command_message(self, msg: Message) -> None: with self.db_session() as db: if not db.get(Moderator, moderator): - logging.warning("User %s, who is not a moderator, tried to execute a command", - msg["from"]) + logger.warning("User %s, who is not a moderator, tried to execute a command", + msg["from"]) return try: @@ -438,7 +440,7 @@ async def mute_user(self, user: JID, duration: str, moderator: JID, reason: str) await self.plugin["xep_0045"].set_role(room, nick, "visitor", reason=reason) except IqError: msg = f"Muting \"{nick}\" in {room} failed." - logging.exception(msg) + logger.exception(msg) self.send_message(mto=self.command_room, mbody=msg, mtype="groupchat") task = create_task(self._unmute_after_mute_ended(mute_end, user)) @@ -506,7 +508,7 @@ async def unmute_user(self, user: JID, moderator: JID, reason: str) -> None: await self.plugin["xep_0045"].set_role(room, nick, "participant", reason=reason) except IqError: msg = f"Unmuting \"{nick}\" in {room} failed." - logging.exception(msg) + logger.exception(msg) self.send_message(mto=self.command_room, mbody=msg, mtype="groupchat") try: @@ -542,7 +544,7 @@ async def kick_user(self, user: JID, moderator: JID, reason: str) -> None: try: await self.plugin["xep_0045"].set_role(room, nick, "none", reason=reason) except IqError: - logging.exception("Kicking \"%s\" from %s failed", user, room) + logger.exception("Kicking \"%s\" from %s failed", user, room) rooms_kick_failed.append(room) continue @@ -594,13 +596,13 @@ async def _check_matching_nick(self, jid: JID, nick: str, room: JID) -> bool: return True reason = f"User {jid} connected with a nick different to their JID: {nick}" - logging.info(reason) + logger.info(reason) try: await self.plugin["xep_0045"].set_role(room, nick, "none", reason="Don't try to impersonate other users") except IqError: - logging.warning("Something failed when trying to kick a user for JID nick mismatch.") + logger.warning("Something failed when trying to kick a user for JID nick mismatch.") return False @@ -641,7 +643,7 @@ async def _unmute_after_mute_ended(self, unmute_dt: datetime, user: JID) -> None try: await self.plugin["xep_0045"].set_role(room, nick, "participant") except IqError: - logging.exception("Automatically unmuting %s in %s failed.", nick, room) + logger.exception("Automatically unmuting %s in %s failed.", nick, room) try: del self.unmute_tasks[user] @@ -659,14 +661,13 @@ def parse_args(): parser = ArgumentParser(formatter_class=ArgumentDefaultsHelpFormatter, description="ModBot - XMPP Moderation Bot") - log_settings = parser.add_mutually_exclusive_group() - log_settings.add_argument("-q", "--quiet", help="only log errors", action="store_const", - dest="log_level", const=logging.ERROR) - log_settings.add_argument("-d", "--debug", help="log debug messages", action="store_const", - dest="log_level", const=logging.DEBUG) - log_settings.add_argument("-v", "--verbose", help="log more informative messages", - action="store_const", dest="log_level", const=logging.INFO) - log_settings.set_defaults(log_level=logging.WARNING) + verbosity_parser = parser.add_mutually_exclusive_group() + verbosity_parser.add_argument("-v", action="count", dest="verbosity", default=0, + help="Increase verbosity of logging. Can be provided up to " + "three times to get full debug logging") + verbosity_parser.add_argument("--verbosity", dest="verbosity", type=int, + help="Increase verbosity of logging. Supported values are 0 to 3" + ) parser.add_argument("-m", "--domain", help="XMPP server to connect to", default="lobby.wildfiregames.com") @@ -692,9 +693,19 @@ def main(): """Entry point a console script.""" args = parse_args() - logging.basicConfig(level=args.log_level, - format="%(asctime)s %(levelname)-8s %(message)s", - datefmt="%Y-%m-%d %H:%M:%S") + log_level = logging.WARNING + if args.verbosity == 1: + log_level = logging.INFO + elif args.verbosity == 2: + log_level = logging.DEBUG + elif args.verbosity >= 3: + log_level = logging.DEBUG + root_logger = logging.getLogger() + root_logger.setLevel(log_level) + + logging.basicConfig(format='%(asctime)s %(levelname)-8s %(message)s', + datefmt='%Y-%m-%dT%H:%M:%S%z') + logger.setLevel(log_level) xmpp = ModBot(JID("%s@%s/%s" % (args.login, args.domain, "CC")), args.password, args.nickname, [JID(room + "@conference." + args.domain) for room in args.rooms], diff --git a/xpartamupp/xpartamupp.py b/xpartamupp/xpartamupp.py index 5940913..2d64777 100755 --- a/xpartamupp/xpartamupp.py +++ b/xpartamupp/xpartamupp.py @@ -40,6 +40,8 @@ # to a mention. INFO_MSG_COOLDOWN_SECONDS = 120 +logger = logging.getLogger(__name__) + class Games: """Class to tracks all games in the lobby.""" @@ -64,7 +66,7 @@ def add_game(self, jid, data): data['nbp-init'] = data['nbp'] data['state'] = 'init' except (KeyError, TypeError, ValueError): - logging.warning("Received invalid data for add game from 0ad: %s", data) + logger.warning("Received invalid data for add game from 0ad: %s", data) return False else: self.games[jid] = data @@ -83,7 +85,7 @@ def remove_game(self, jid): try: del self.games[jid] except KeyError: - logging.warning("Game for jid %s didn't exist", jid) + logger.warning("Game for jid %s didn't exist", jid) return False else: return True @@ -110,22 +112,22 @@ def change_game_state(self, jid, data): """ if jid not in self.games: - logging.warning("Tried to change state for non-existent game %s", jid) + logger.warning("Tried to change state for non-existent game %s", jid) return False try: if self.games[jid]['nbp-init'] > data['nbp']: - logging.debug("change game (%s) state from %s to %s", jid, - self.games[jid]['state'], 'waiting') + logger.debug("change game (%s) state from %s to %s", jid, + self.games[jid]['state'], 'waiting') self.games[jid]['state'] = 'waiting' else: - logging.debug("change game (%s) state from %s to %s", jid, - self.games[jid]['state'], 'running') + logger.debug("change game (%s) state from %s to %s", jid, + self.games[jid]['state'], 'running') self.games[jid]['state'] = 'running' self.games[jid]['nbp'] = data['nbp'] self.games[jid]['players'] = data['players'] except (KeyError, ValueError): - logging.warning("Received invalid data for change game state from 0ad: %s", data) + logger.warning("Received invalid data for change game state from 0ad: %s", data) return False else: if 'startTime' not in self.games[jid]: @@ -190,7 +192,7 @@ async def _session_start(self, event): # pylint: disable=unused-argument await self.plugin['xep_0045'].join_muc_wait(self.room, self.nick) self.send_presence() self.get_roster() - logging.info("XpartaMuPP started") + logger.info("XpartaMuPP started") async def _shutdown(self, event): # pylint: disable=unused-argument """Shut down XpartaMuPP. @@ -203,7 +205,7 @@ async def _shutdown(self, event): # pylint: disable=unused-argument event (dict): empty dummy dict """ - logging.error("Can't log in. Aborting reconnects.") + logger.error("Can't log in. Aborting reconnects.") self.abort() self.shutdown.set_result(True) @@ -245,7 +247,7 @@ def _muc_online(self, presence): self._send_game_list(jid) - logging.debug("Client '%s' connected with a nick '%s'.", jid, nick) + logger.debug("Client '%s' connected with a nick '%s'.", jid, nick) def _muc_offline(self, presence): """Remove leaving players from the list of players. @@ -267,7 +269,7 @@ def _muc_offline(self, presence): if self.games.remove_game(jid): self._send_game_list() - logging.debug("Client '%s' with nick '%s' disconnected", jid, nick) + logger.debug("Client '%s' with nick '%s' disconnected", jid, nick) def _muc_message(self, msg): """Process messages in the MUC room. @@ -318,7 +320,7 @@ def _iq_game_list_handler(self, iq): elif command == 'changestate': success = self.games.change_game_state(iq['from'], iq['gamelist']['game']) else: - logging.info('Received unknown game command: "%s"', command) + logger.info('Received unknown game command: "%s"', command) iq = iq.reply(clear=not success) if not success: @@ -329,7 +331,7 @@ def _iq_game_list_handler(self, iq): try: self._send_game_list() except Exception: - logging.exception('Failed to send game list after "%s" command', command) + logger.exception('Failed to send game list after "%s" command', command) def _send_game_list(self, to=None): """Send a massive stanza with the whole game list. @@ -363,14 +365,14 @@ def _send_game_list(self, to=None): try: iq.send() except Exception: - logging.exception("Failed to send game list to %s", jid) + logger.exception("Failed to send game list to %s", jid) else: iq = self.make_iq_result(ito=to) iq.set_payload(stanza) try: iq.send() except Exception: - logging.exception("Failed to send game list to %s", to) + logger.exception("Failed to send game list to %s", to) def parse_args(): @@ -383,14 +385,13 @@ def parse_args(): parser = argparse.ArgumentParser(formatter_class=argparse.ArgumentDefaultsHelpFormatter, description="XpartaMuPP - XMPP Multiplayer Game Manager") - log_settings = parser.add_mutually_exclusive_group() - log_settings.add_argument('-q', '--quiet', help="only log errors", action='store_const', - dest='log_level', const=logging.ERROR) - log_settings.add_argument('-d', '--debug', help="log debug messages", action='store_const', - dest='log_level', const=logging.DEBUG) - log_settings.add_argument('-v', '--verbose', help="log more informative messages", - action='store_const', dest='log_level', const=logging.INFO) - log_settings.set_defaults(log_level=logging.WARNING) + verbosity_parser = parser.add_mutually_exclusive_group() + verbosity_parser.add_argument("-v", action="count", dest="verbosity", default=0, + help="Increase verbosity of logging. Can be provided up to " + "three times to get full debug logging") + verbosity_parser.add_argument("--verbosity", type=int, + help="Increase verbosity of logging. Supported values are 0 to 3" + ) parser.add_argument('-m', '--domain', help="XMPP server to connect to", default='lobby.wildfiregames.com') @@ -411,9 +412,19 @@ def main(): """Entry point a console script.""" args = parse_args() - logging.basicConfig(level=args.log_level, - format='%(asctime)s %(levelname)-8s %(message)s', - datefmt='%Y-%m-%d %H:%M:%S') + log_level = logging.WARNING + if args.verbosity == 1: + log_level = logging.INFO + elif args.verbosity == 2: + log_level = logging.DEBUG + elif args.verbosity >= 3: + log_level = logging.DEBUG + root_logger = logging.getLogger() + root_logger.setLevel(log_level) + + logging.basicConfig(format='%(asctime)s %(levelname)-8s %(message)s', + datefmt='%Y-%m-%dT%H:%M:%S%z') + logger.setLevel(log_level) xmpp = XpartaMuPP(JID('%s@%s/%s' % (args.login, args.domain, 'CC')), args.password, JID(args.room + '@conference.' + args.domain), args.nickname,