Add metrics logging and output on close (#1059)

* Add metrics logging and output on close

Output looks like the following:

[17:10:07] Exiting PokemonGo Bot
[17:10:07]
[17:10:07] Ran for 0:00:20
[17:10:07] Total XP Earned: 210 Averaging: 36534.47/h
[17:10:07] Travelled 0.01km
[17:10:07] Visited 0 stops
[17:10:07] Encountered 1 pokemon, 1 caught, 0 released, 0 evolved, 0
never seen before
[17:10:07] Threw 1 pokeball
[17:10:07] Earned 100 Stardust
[17:10:07]
[17:10:07] Highest CP Pokemon: Nidoran M [CP: 75] [IV: 1/10/5]
Potential: 0.36
[17:10:07] Most Perfect Pokemon: Nidoran M [CP: 75] [IV: 1/10/5]
Potential: 0.36

* Added Metrics class to collect end of run stats

Tried to come up with a reasonable division of labour for how to gather
the information.

Open to feedback!

* Revert logging changes

Didn’t mean to affect this message any more.

pokecli.py

@@ -33,6 +33,7 @@
 import ssl
 import sys
 import time
+from datetime import timedelta
 from getpass import getpass
 from pgoapi.exceptions import NotLoggedInException
 
@@ -240,6 +241,7 @@ def main():
         try:
             bot = PokemonGoBot(config)
             bot.start()
+            bot.metrics.capture_stats()
 
             logger.log('Starting PokemonGo Bot....', 'green')
 
@@ -249,8 +251,28 @@ def main():
         except KeyboardInterrupt:
             logger.log('Exiting PokemonGo Bot', 'red')
             finished = True
-            # TODO Add number of pokemon catched, pokestops visited, highest CP
-            # pokemon catched, etc.
+            if bot.metrics.start_time is None:
+                return  # Bot didn't actually start, no metrics to show.
+
+            metrics = bot.metrics
+            metrics.capture_stats()
+            logger.log('')
+            logger.log('Ran for {}'.format(metrics.runtime()), 'red')
+            logger.log('Total XP Earned: {}  Average: {:.2f}/h'.format(metrics.xp_earned, metrics.xp_per_hour()), 'red')
+            logger.log('Travelled {:.2f}km'.format(metrics.distance_travelled()), 'red')
+            logger.log('Visited {} stops'.format(metrics.visits['latest'] - metrics.visits['start']), 'red')
+            logger.log('Encountered {} pokemon, {} caught, {} released, {} evolved, {} never seen before'
+                       .format(metrics.num_encounters(), metrics.num_captures(), metrics.releases,
+                               metrics.num_evolutions(), metrics.num_new_mons()), 'red')
+            logger.log('Threw {} pokeball{}'.format(metrics.num_throws(), '' if metrics.num_throws() == 1 else 's'),
+                       'red')
+            logger.log('Earned {} Stardust'.format(metrics.earned_dust()), 'red')
+            logger.log('')
+            if metrics.highest_cp is not None:
+                logger.log('Highest CP Pokemon: {}'.format(metrics.highest_cp['desc']), 'red')
+            if metrics.most_perfect is not None:
+                logger.log('Most Perfect Pokemon: {}'.format(metrics.most_perfect['desc']), 'red')
+
 
         except NotLoggedInException:
             logger.log('[x] Error while connecting to the server, please wait %s minutes' % config.reconnecting_timeout, 'red')

pokemongo_bot/__init__.py

@@ -18,6 +18,7 @@
 from cell_workers.utils import distance, get_cellid, encode, i2f
 from human_behaviour import sleep
 from item_list import Item
+from metrics import Metrics
 from spiral_navigator import SpiralNavigator
 
 
@@ -31,6 +32,7 @@ def __init__(self, config):
         self.config = config
         self.pokemon_list = json.load(open(os.path.join('data', 'pokemon.json')))
         self.item_list = json.load(open(os.path.join('data', 'items.json')))
+        self.metrics = Metrics(self)
 
     def start(self):
         self._setup_logging()

pokemongo_bot/cell_workers/pokemon_catch_worker.py

@@ -188,6 +188,8 @@ def work(self):
 
                                     id_list2 = self.count_pokemon_inventory()
 
+                                    self.bot.metrics.captured_pokemon(pokemon_name, cp, iv_display, pokemon_potential)
+
                                     logger.log('Captured {}! [CP {}] [{}]'.format(
                                         pokemon_name,
                                         cp,
@@ -196,6 +198,7 @@ def work(self):
 
                                     if self.config.evolve_captured:
                                         pokemon_to_transfer = list(Set(id_list2) - Set(id_list1))
+                                        # No need to capture this even for metrics, player stats includes it.
                                         self.api.evolve_pokemon(pokemon_id=pokemon_to_transfer[0])
                                         response_dict = self.api.call()
                                         status = response_dict['responses']['EVOLVE_POKEMON']['result']

pokemongo_bot/metrics.py

@@ -0,0 +1,114 @@
+import time
+
+from datetime import timedelta
+
+
+class Metrics(object):
+
+    def __init__(self, bot):
+        self.bot = bot
+        self.start_time = None
+        self.dust = {'start': None, 'latest': None}
+        self.xp = {'start': None, 'latest': None}
+        self.distance = {'start': None, 'latest': None}
+        self.encounters = {'start': None, 'latest': None}
+        self.throws = {'start': None, 'latest': None}
+        self.captures = {'start': None, 'latest': None}
+        self.visits = {'start': None, 'latest': None}
+        self.unique_mons = {'start': None, 'latest': None}
+        self.evolutions = {'start': None, 'latest': None}
+
+        self.releases = 0
+        self.highest_cp = {'cp': 0, 'desc': ''}
+        self.most_perfect = {'potential': 0, 'desc': ''}
+
+    def runtime(self):
+        return str(timedelta(seconds=round(time.time() - self.start_time)))
+
+    def xp_earned(self):
+        return self.xp['latest'] - self.xp['start']
+
+    def xp_per_hour(self):
+        return self.xp_earned/(time.time() - self.start_time/60/60)
+
+    def distance_travelled(self):
+        return self.distance['latest'] - self.distance['start']
+
+    def num_encounters(self):
+        return self.encounters['latest'] - self.encounters['start']
+
+    def num_throws(self):
+        return self.throws['latest'] - self.throws['start']
+
+    def num_captures(self):
+        return self.captures['latest'] - self.captures['start']
+
+    def num_visits(self):
+        return self.visits['latest'] - self.visits['start']
+
+    def num_new_mons(self):
+        return self.unique_mons['latest'] - self.unique_mons['start']
+
+    def num_evolutions(self):
+        return self.evolutions['latest'] - self.evolutions['start']
+
+    def earned_dust(self):
+        return self.dust['latest'] - self.dust['start']
+
+    def captured_pokemon(self, name, cp, iv_display, potential):
+        if cp > self.highest_cp['cp']:
+            self.highest_cp = \
+                {'cp': cp, 'desc': '{} [CP: {}] [IV: {}] Potential: {} '
+                    .format(name, cp, iv_display, potential)}
+
+        if potential > self.most_perfect['potential']:
+            self.most_perfect = \
+                {'potential': cp, 'desc': '{} [CP: {}] [IV: {}] Potential: {} '
+                    .format(name, cp, iv_display, potential)}
+        return
+
+    def released_pokemon(self, count=1):
+        self.releases += count
+
+    def capture_stats(self):
+        if self.start_time is None: self.start_time = time.time()
+        self.bot.api.get_inventory()
+        self.bot.api.get_player()
+        response_dict = self.bot.api.call()
+        try:
+            self.dust['latest'] = response_dict['responses']['GET_PLAYER']['player_data']['currencies'][1]['amount']
+            if self.dust['start'] is None: self.dust['start'] = self.dust['latest']
+            for item in response_dict['responses']['GET_INVENTORY']['inventory_delta']['inventory_items']:
+                if 'inventory_item_data' in item:
+                    if 'player_stats' in item['inventory_item_data']:
+                        playerdata = item['inventory_item_data']['player_stats']
+
+                        self.xp['latest'] = playerdata.get('experience', 0)
+                        if self.xp['start'] is None: self.xp['start'] = self.xp['latest']
+
+                        self.visits['latest'] = playerdata.get('poke_stop_visits', 0)
+                        if self.visits['start'] is None: self.visits['start'] = self.visits['latest']
+
+                        self.captures['latest'] = playerdata.get('pokemons_captured', 0)
+                        if self.captures['start'] is None: self.captures['start'] = self.captures['latest']
+
+                        self.distance['latest'] = playerdata.get('km_walked', 0)
+                        if self.distance['start'] is None: self.distance['start'] = self.distance['latest']
+
+                        self.encounters['latest'] = playerdata.get('pokemons_encountered', 0)
+                        if self.encounters['start'] is None: self.encounters['start'] = self.encounters['latest']
+
+                        self.throws['latest'] = playerdata.get('pokeballs_thrown', 0)
+                        if self.throws['start'] is None: self.throws['start'] = self.throws['latest']
+
+                        self.unique_mons['latest'] = playerdata.get('unique_pokedex_entries', 0)
+                        if self.unique_mons['start'] is None: self.unique_mons['start'] = self.unique_mons['latest']
+
+                        self.visits['latest'] = playerdata.get('poke_stop_visits', 0)
+                        if self.visits['start'] is None: self.visits['start'] = self.visits['latest']
+
+                        self.evolutions['latest'] = playerdata.get('evolutions', 0)
+                        if self.evolutions['start'] is None: self.evolutions['start'] = self.evolutions['latest']
+        except KeyError:
+            # Nothing we can do if there's no player info.
+            return