diff --git a/tests/test_echelon.py b/tests/test_echelon.py index 6728c96..f1a1546 100644 --- a/tests/test_echelon.py +++ b/tests/test_echelon.py @@ -123,41 +123,41 @@ 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')), (['-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 +169,6 @@ def test_valid(self, cmd_args, expected_args): @parameterized.expand([ (['-f'],), (['--foo'],), - (['--debug', '--quiet'],), - (['--quiet', '--verbose'],), - (['--debug', '--verbose'],), - (['--debug', '--quiet', '--verbose'],), ]) def test_invalid(self, cmd_args): """Test invalid parameter combinations.""" @@ -193,7 +189,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..3da0d28 100644 --- a/tests/test_xpartamupp.py +++ b/tests/test_xpartamupp.py @@ -92,37 +92,37 @@ 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')), (['-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 +134,6 @@ def test_valid(self, cmd_args, expected_args): @parameterized.expand([ (['-f'],), (['--foo'],), - (['--debug', '--quiet'],), - (['--quiet', '--verbose'],), - (['--debug', '--verbose'],), - (['--debug', '--quiet', '--verbose'],), ]) def test_invalid(self, cmd_args): """Test invalid parameter combinations.""" @@ -156,7 +152,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..5e214d9 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(): @@ -803,16 +805,6 @@ 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) - parser.add_argument('-m', '--domain', help="XMPP server to connect to", default='lobby.wildfiregames.com') parser.add_argument('-l', '--login', help="username for login", default='EcheLOn') @@ -823,10 +815,12 @@ def parse_args(): default='sqlite:///lobby_rankings.sqlite3') parser.add_argument('-s', '--server', help='address of the ejabberd server', action='store', dest='xserver', default=None) + 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") parser.add_argument('--no-verify', help="Don't verify the TLS server certificate when connecting", action='store_true') - return parser.parse_args() @@ -834,9 +828,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..b3e69dd 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] @@ -658,16 +660,6 @@ 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) - parser.add_argument("-m", "--domain", help="XMPP server to connect to", default="lobby.wildfiregames.com") parser.add_argument("-l", "--login", help="username for login", default="modbot") @@ -681,10 +673,12 @@ def parse_args(): default="sqlite:///lobby_moderation.sqlite3") parser.add_argument("-s", "--server", help="address of the ejabberd server", action="store", dest="xserver", default=None) + 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") parser.add_argument("--no-verify", help="Don't verify the TLS server certificate when connecting", action="store_true") - return parser.parse_args() @@ -692,9 +686,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..68ef635 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(): @@ -382,16 +384,6 @@ 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) - parser.add_argument('-m', '--domain', help="XMPP server to connect to", default='lobby.wildfiregames.com') parser.add_argument('-l', '--login', help="username for login", default='xpartamupp') @@ -400,10 +392,12 @@ def parse_args(): parser.add_argument('-r', '--room', help="XMPP MUC room to join", default='arena') parser.add_argument('-s', '--server', help='address of the ejabberd server', action='store', dest='xserver', default=None) + 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") parser.add_argument('--no-verify', help="Don't verify the TLS server certificate when connecting", action='store_true') - return parser.parse_args() @@ -411,9 +405,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,