Improve the logging system

This creates a `get_logger` function which sets up a standard,
better-looking logging format without fuss.
To log from an entity, we now do self.log() (or self.logger.debug()).

Author: jleclanche

fireplace/actions.py

@@ -1,8 +1,11 @@
-import logging
 from enum import IntEnum
 from .dsl import LazyNum, Picker, Selector
 from .enums import CardType, Mulligan, PowSubType, Zone
 from .entity import Entity
+from .utils import get_logger
+
+
+logger = get_logger("fireplace.Action")
 
 
 def _eval_card(source, card):
@@ -76,7 +79,7 @@ def _broadcast(self, entity, source, at, *args):
 			if event.at != at:
 				continue
 			if isinstance(event.trigger, self.__class__) and event.trigger.matches(entity, args):
-				logging.info("%r triggers off %r from %r", entity, self, source)
+				logger.info("%r triggers off %r from %r", entity, self, source)
 				entity.trigger_event(source, event, args)
 
 	def broadcast(self, source, at, *args):
@@ -129,7 +132,7 @@ def do(self, source, attacker, defender):
 		defender.defending = True
 		source.game.proposed_attacker = attacker
 		source.game.proposed_defender = defender
-		logging.info("%r attacks %r", attacker, defender)
+		logger.info("%r attacks %r", attacker, defender)
 		self.broadcast(source, EventListener.ON, attacker, defender)
 		source.game._attack()
 
@@ -165,7 +168,7 @@ class Args(Action.Args):
 		ENTITY = 0
 
 	def do(self, source, target):
-		logging.info("Processing Death for %r", target)
+		logger.info("Processing Death for %r", target)
 		self.broadcast(source, EventListener.ON, target)
 		if target.deathrattles:
 			source.game.queue_actions(source, [Deathrattle(target)])
@@ -238,7 +241,7 @@ def do(self, source, player, card, target=None, choose=None):
 		if choose is not None:
 			# Choose One cards replace the action on the played card
 			chosen = player.card(choose)
-			logging.info("Choose One from %r: %r", card, chosen)
+			logger.info("Choose One from %r: %r", card, chosen)
 			if chosen.has_target():
 				chosen.target = target
 			card.chosen = chosen
@@ -332,7 +335,7 @@ def trigger(self, source):
 			targets = self.get_targets(source, args[0])
 			args = args[1:]
 			source.game.manager.action(self.type, source, targets, *args)
-			logging.info("%r triggering %r targeting %r", source, self, targets)
+			logger.info("%r triggering %r targeting %r", source, self, targets)
 			for target in targets:
 				target_args = self.get_target_args(source, target)
 				ret.append(self.do(source, target, *target_args))
@@ -396,7 +399,7 @@ def do(self, source, target):
 			source.game.queue_actions(target, actions)
 
 			if target.controller.extra_deathrattles:
-				logging.info("Triggering deathrattles for %r again", target)
+				logger.info("Triggering deathrattles for %r again", target)
 				source.game.queue_actions(target, actions)
 
 
@@ -499,11 +502,11 @@ class Args(Action.Args):
 		CARDS = 1
 
 	def do(self, source, target, cards):
-		logging.debug("Giving %r to %s", cards, target)
+		logger.info("Giving %r to %s", cards, target)
 		ret = []
 		for card in cards:
 			if len(target.hand) >= target.max_hand_size:
-				logging.info("Give(%r) fails because %r's hand is full", card, target)
+				logger.info("Give(%r) fails because %r's hand is full", card, target)
 				continue
 			card.controller = target
 			card.zone = Zone.HAND
@@ -544,7 +547,7 @@ def do(self, source, target, amount):
 		amount = min(amount, target.damage)
 		if amount:
 			# Undamaged targets do not receive heals
-			logging.info("%r heals %r for %i", source, target, amount)
+			logger.info("%r heals %r for %i", source, target, amount)
 			target.damage -= amount
 			self.broadcast(source, EventListener.ON, target, amount)
 
@@ -589,7 +592,7 @@ def get_target_args(self, source, target):
 		return (card, )
 
 	def do(self, source, target, card):
-		logging.info("Morphing %r into %r", target, card)
+		logger.info("Morphing %r into %r", target, card)
 		target.clear_buffs()
 		target.zone = Zone.SETASIDE
 		card.zone = Zone.PLAY
@@ -621,7 +624,7 @@ class Reveal(TargetedAction):
 	Reveal secret targets.
 	"""
 	def do(self, source, target):
-		logging.info("Revealing secret %r", target)
+		logger.info("Revealing secret %r", target)
 		self.broadcast(source, EventListener.ON, target)
 		target.zone = Zone.GRAVEYARD
 
@@ -635,7 +638,7 @@ class Args(Action.Args):
 		AMOUNT = 1
 
 	def do(self, source, target, amount):
-		logging.info("Setting current health on %r to %i", target, amount)
+		logger.info("Setting current health on %r to %i", target, amount)
 		maxhp = target.max_health
 		target.damage = max(0, maxhp - amount)
 
@@ -678,7 +681,7 @@ def _broadcast(self, entity, source, at, *args):
 		return super()._broadcast(entity, source, at, *args)
 
 	def do(self, source, target, cards):
-		logging.info("%s summons %r", target, cards)
+		logger.info("%s summons %r", target, cards)
 		if not isinstance(cards, list):
 			cards = [cards]
 
@@ -704,7 +707,7 @@ class Args(Action.Args):
 		CARDS = 1
 
 	def do(self, source, target, cards):
-		logging.info("%r shuffles into %s's deck", cards, target)
+		logger.info("%r shuffles into %s's deck", cards, target)
 		if not isinstance(cards, list):
 			cards = [cards]
 
@@ -744,7 +747,7 @@ class Steal(TargetedAction):
 	The controller is the controller of the source of the action.
 	"""
 	def do(self, source, target):
-		logging.info("%s takes control of %r", self, target)
+		logger.info("%s takes control of %r", self, target)
 		zone = target.zone
 		target.zone = Zone.SETASIDE
 		target.controller = source.controller
@@ -756,6 +759,6 @@ class UnlockOverload(TargetedAction):
 	Unlock the target player's overload, both current and owed.
 	"""
 	def do(self, source, target):
-		logging.info("%s overload gets cleared", target)
+		logger.info("%s overload gets cleared", target)
 		target.overloaded = 0
 		target.overload_locked = 0

fireplace/aura.py

@@ -1,5 +1,7 @@
-import logging
-from .utils import CardList
+from .utils import CardList, get_logger
+
+
+logger = get_logger("fireplace.Aura")
 
 
 class Aura:
@@ -30,7 +32,7 @@ def targets(self):
 		return CardList(self.selector.eval(self.source.game, self.source))
 
 	def summon(self):
-		logging.info("Summoning Aura %r", self)
+		logger.info("Summoning Aura %r", self)
 		self.source.auras.append(self)
 		self.source.game.auras.append(self)
 		self.source.game.refresh_auras()
@@ -65,7 +67,7 @@ def update(self):
 				self._buffed.remove(target)
 
 	def destroy(self):
-		logging.info("Removing %r affecting %r", self, self._buffed)
+		logger.info("Removing %r affecting %r", self, self._buffed)
 		self.source.game.auras.remove(self)
 		for buff in self._buffs[:]:
 			buff.destroy()

fireplace/card.py

@@ -1,4 +1,3 @@
-import logging
 from itertools import chain
 from . import cards as CardDB, rules
 from .actions import Damage, Deaths, Destroy, Heal, Morph, Play, Shuffle, SetCurrentHealth
@@ -79,7 +78,7 @@ def zone(self, value):
 	def _set_zone(self, value):
 		old = self.zone
 		assert old != value
-		logging.debug("%r moves from %r to %r" % (self, old, value))
+		self.logger.debug("%r moves from %r to %r" % (self, old, value))
 		caches = {
 			Zone.HAND: self.controller.hand,
 			Zone.DECK: self.controller.deck,
@@ -183,24 +182,24 @@ def _set_zone(self, zone):
 
 	def action(self):
 		if self.cant_play:
-			logging.info("%r play action cannot continue", self)
+			self.log("%r play action cannot continue", self)
 			return
 
 		kwargs = {}
 		if self.target:
 			kwargs["target"] = self.target
 		elif self.has_target():
-			logging.info("%r has no target, action exits early" % (self))
+			self.log("%r has no target, action exits early", self)
 			return
 
 		if self.has_combo and self.controller.combo:
-			logging.info("Activating %r combo targeting %r" % (self, self.target))
+			self.log("Activating %r combo targeting %r", self, self.target)
 			actions = self.data.scripts.combo
 		elif hasattr(self.data.scripts, "play"):
-			logging.info("Activating %r action targeting %r" % (self, self.target))
+			self.log("Activating %r action targeting %r", self, self.target)
 			actions = self.data.scripts.play
 		elif self.choose:
-			logging.info("Activating %r Choose One: %r", self, self.chosen)
+			self.log("Activating %r Choose One: %r", self, self.chosen)
 			actions = self.chosen.data.scripts.play
 		else:
 			actions = []
@@ -215,12 +214,12 @@ def action(self):
 			self.game.process_deaths()
 
 		if self.overload:
-			logging.info("%r overloads %s for %i", self, self.controller, self.overload)
+			self.log("%r overloads %s for %i", self, self.controller, self.overload)
 			self.controller.overloaded += self.overload
 
 	def clear_buffs(self):
 		if self.buffs:
-			logging.info("Clearing buffs from %r" % (self))
+			self.log("Clearing buffs from %r", self)
 			for buff in self.buffs[:]:
 				buff.destroy()
 
@@ -234,21 +233,21 @@ def _destroy(self):
 		be moved to the GRAVEYARD on the next Death event.
 		"""
 		if self.zone == Zone.PLAY:
-			logging.info("Marking %r for imminent death", self)
+			self.log("Marking %r for imminent death", self)
 			self.to_be_destroyed = True
 		else:
 			self.zone = Zone.GRAVEYARD
 
 	def discard(self):
-		logging.info("Discarding %r" % (self))
+		self.log("Discarding %r" % (self))
 		self.zone = Zone.DISCARD
 
 	def draw(self):
 		if len(self.controller.hand) >= self.controller.max_hand_size:
-			logging.info("%s overdraws and loses %r!", self.controller, self)
+			self.log("%s overdraws and loses %r!", self.controller, self)
 			self.discard()
 		else:
-			logging.info("%s draws %r", self.controller, self)
+			self.log("%s draws %r", self.controller, self)
 			self.zone = Zone.HAND
 			self.controller.cards_drawn_this_turn += 1
 
@@ -430,15 +429,9 @@ def damage(self):
 	def damage(self, amount):
 		amount = max(0, amount)
 		dmg = self.damage
-		if amount < dmg:
-			logging.info("%r healed for %i health" % (self, dmg - amount))
-		elif amount == dmg:
-			logging.info("%r receives a no-op health change" % (self))
-		else:
-			logging.info("%r damaged for %i health" % (self, amount - dmg))
 
 		if self.min_health:
-			logging.info("%r has HEALTH_MINIMUM of %i", self, self.min_health)
+			self.log("%r has HEALTH_MINIMUM of %i", self, self.min_health)
 			amount = min(amount, self.max_health - self.min_health)
 
 		self._damage = amount
@@ -449,7 +442,7 @@ def health(self):
 
 	def _hit(self, source, amount):
 		if self.immune:
-			logging.info("%r is immune to %i damage from %r", self, amount, source)
+			self.log("%r is immune to %i damage from %r", self, amount, source)
 			return 0
 		self.damage += amount
 		return amount
@@ -576,17 +569,17 @@ def _set_zone(self, value):
 			self.controller.field.append(self)
 
 		if self.zone == Zone.PLAY:
-			logging.info("%r is removed from the field" % (self))
+			self.log("%r is removed from the field", self)
 			self.controller.field.remove(self)
 			if self.damage:
 				self.damage = 0
 
 		super()._set_zone(value)
 
 	def bounce(self):
-		logging.info("%r is bounced back to %s's hand" % (self, self.controller))
+		self.log("%r is bounced back to %s's hand", self, self.controller)
 		if len(self.controller.hand) == self.controller.max_hand_size:
-			logging.info("%s's hand is full and bounce fails" % (self.controller))
+			self.log("%s's hand is full and bounce fails", self.controller)
 			self.destroy()
 		else:
 			self.zone = Zone.HAND
@@ -599,7 +592,7 @@ def hit(self, target, amount):
 	def _hit(self, source, amount):
 		if self.divine_shield:
 			self.divine_shield = False
-			logging.info("%r's divine shield prevents %i damage.", self, amount)
+			self.log("%r's divine shield prevents %i damage.", self, amount)
 			return
 
 		return super()._hit(source, amount)
@@ -614,7 +607,7 @@ def is_playable(self):
 		return playable
 
 	def silence(self):
-		logging.info("%r has been silenced" % (self))
+		self.log("Silencing %r", self)
 		for aura in self.auras:
 			aura.to_be_destroyed = True
 		self.clear_buffs()
@@ -692,20 +685,20 @@ def _set_zone(self, zone):
 		super()._set_zone(zone)
 
 	def apply(self, target):
-		logging.info("Applying %r to %r" % (self, target))
+		self.log("Applying %r to %r", self, target)
 		self.owner = target
 		if self.attack_health_swap:
 			self._swapped_atk = target.health
 			self._swapped_health = target.atk
 		if hasattr(self.data.scripts, "apply"):
 			self.data.scripts.apply(self, target)
 		if hasattr(self.data.scripts, "max_health") or self.attack_health_swap:
-			logging.info("%r removes all damage from %r", self, target)
+			self.log("%r removes all damage from %r", self, target)
 			target.damage = 0
 		self.zone = Zone.PLAY
 
 	def destroy(self):
-		logging.info("Destroying buff %r from %r" % (self, self.owner))
+		self.log("Destroying buff %r from %r", self, self.owner)
 		if hasattr(self.data.scripts, "destroy"):
 			self.data.scripts.destroy(self)
 		self.zone = Zone.REMOVEDFROMGAME
@@ -810,7 +803,7 @@ def play(self, target=None):
 
 	def use(self, target=None):
 		assert self.is_usable()
-		logging.info("%s uses hero power %r on %r", self.controller, self, target)
+		self.log("%s uses hero power %r on %r", self.controller, self, target)
 
 		if self.has_target():
 			assert target

fireplace/dsl/evaluator.py

@@ -1,5 +1,8 @@
 import copy
-import logging
+from ..utils import get_logger
+
+
+logger = get_logger("fireplace.DSL")
 
 
 class Evaluator:
@@ -81,5 +84,5 @@ def evaluate(self, source):
 		t1 = self.selector1.eval(source.game, source)
 		t2 = self.selector2.eval(source.game, source)
 		diff = sum(t.cost for t in t1) - sum(t.cost for t in t2)
-		logging.info("Jousting %r vs %r -> %i difference", t1, t2, diff)
+		logger.info("Jousting %r vs %r -> %i difference", t1, t2, diff)
 		return diff > 0