From b2983f7100fb6f1b4c9db833bc09a7820fea634a Mon Sep 17 00:00:00 2001 From: Douglas Camata Date: Wed, 3 Aug 2016 22:54:44 +0200 Subject: [PATCH] Replace all `logger.log` calls with events! (#2173) * bye bye `logger.log`, hello event system! * fixing travis build * trying to fix travis build * test fixes * updating remaining `logger.log` calls that should be replaced * typo * typos in IncubateEggs event * improved fort loot event data * fixing update_location event's distance unit * fixing some events and log stuff * adding missing fort_name parameter to lured_pokemon_found event * fixing a variable inside an event formatted string * fixing typos and utf8 * trying to fix tests with regards to float precision * adding command to print all registered events and their parameters * fixing tests yet again * trying to fix unicode issues, arrgh!!! * added a move to lured fort event * better distance text in move to fort and fixing utf8 in spin fort task * removing print from websocket server * start embedded server before creating the socketio_handler * I hate unicode * rename and sleep events * refactoring in how we emit events to avoid code repetition * PokemonCatch task inherits from BaseTask * go away, dirty logger.log! * pep8 and removed logging handler name attribute * good bye for the remaining logger.log calls * bye logger module * no more logger imports! * removed last few loggers * removing secret file and fixed variable name in follow cluster * fixing kwargs for event emit * trying to fix unicode handling one more time * now it works! * fixing more logs and removing debug unicode string * no logs on websocket server yet * adding a script to start a standalone websocket server * more adjusted in websocket to support multiuser * adding a fallback to logger.log issues a very verbose deprecation warning * putting back compatibility with json based web ui --- pokecli.py | 98 +++- pokemongo_bot/__init__.py | 497 +++++++++++++++--- pokemongo_bot/api_wrapper.py | 9 +- pokemongo_bot/cell_workers/base_task.py | 16 + .../cell_workers/catch_lured_pokemon.py | 16 +- .../cell_workers/catch_visible_pokemon.py | 18 +- .../cell_workers/collect_level_up_reward.py | 23 +- pokemongo_bot/cell_workers/evolve_pokemon.py | 44 +- pokemongo_bot/cell_workers/follow_cluster.py | 39 +- pokemongo_bot/cell_workers/follow_path.py | 13 +- pokemongo_bot/cell_workers/follow_spiral.py | 15 +- pokemongo_bot/cell_workers/handle_soft_ban.py | 25 +- pokemongo_bot/cell_workers/incubate_eggs.py | 80 ++- pokemongo_bot/cell_workers/move_to_fort.py | 36 +- .../cell_workers/nickname_pokemon.py | 54 +- .../cell_workers/pokemon_catch_worker.py | 199 +++++-- pokemongo_bot/cell_workers/recycle_items.py | 21 +- pokemongo_bot/cell_workers/sleep_schedule.py | 18 +- pokemongo_bot/cell_workers/spin_fort.py | 98 ++-- .../cell_workers/transfer_pokemon.py | 56 +- .../event_handlers/logging_handler.py | 7 +- .../event_handlers/socketio_handler.py | 28 +- pokemongo_bot/event_manager.py | 26 +- pokemongo_bot/health_record/bot_event.py | 9 +- pokemongo_bot/logger.py | 50 +- pokemongo_bot/socketio_server/app.py | 28 +- pokemongo_bot/test/follow_cluster_test.py | 12 +- pokemongo_bot/walkers/polyline_walker.py | 9 +- pokemongo_bot/websocket_remote_control.py | 13 +- tests/__init__.py | 5 +- ws_server.py | 26 + 31 files changed, 1179 insertions(+), 409 deletions(-) create mode 100755 ws_server.py diff --git a/pokecli.py b/pokecli.py index 7df9369120..94f8b01ee2 100755 --- a/pokecli.py +++ b/pokecli.py @@ -39,21 +39,26 @@ from geopy.exc import GeocoderQuotaExceeded from pokemongo_bot import PokemonGoBot, TreeConfigBuilder -from pokemongo_bot import logger if sys.version_info >= (2, 7, 9): ssl._create_default_https_context = ssl._create_unverified_context +logging.basicConfig( + level=logging.INFO, + format='%(asctime)s [%(name)10s] [%(levelname)s] %(message)s') +logger = logging.getLogger('cli') +logger.setLevel(logging.INFO) def main(): - logger.log('PokemonGO Bot v1.0', 'green') + + logger.info('PokemonGO Bot v1.0') sys.stdout = codecs.getwriter('utf8')(sys.stdout) sys.stderr = codecs.getwriter('utf8')(sys.stderr) config = init_config() if not config: return - logger.log('Configuration initialized', 'yellow') + logger.info('Configuration initialized') finished = False @@ -65,28 +70,56 @@ def main(): bot.workers = tree bot.metrics.capture_stats() - logger.log('Starting PokemonGo Bot....', 'green') + bot.event_manager.emit( + 'bot_start', + sender=bot, + level='info', + formatted='Starting bot...' + ) while True: bot.tick() except KeyboardInterrupt: - logger.log('Exiting PokemonGo Bot', 'red') + bot.event_manager.emit( + 'bot_exit', + sender=bot, + level='info', + formatted='Exiting bot.' + ) finished = True report_summary(bot) - except (NotLoggedInException, ServerBusyOrOfflineException): - logger.log('[x] Error while connecting to the server, please wait %s minutes' % config.reconnecting_timeout, 'red') - time.sleep(config.reconnecting_timeout * 60) + + except NotLoggedInException: + wait_time = config.reconnecting_timeout * 60 + bot.event_manager.emit( + 'api_error', + sender=bot, + level='info', + formmated='Log logged in, reconnecting in {:s}'.format(wait_time) + ) + time.sleep(wait_time) + except ServerBusyOrOfflineException: + bot.event_manager.emit( + 'api_error', + sender=bot, + level='info', + formatted='Server busy or offline' + ) except ServerSideRequestThrottlingException: - logger.log('Server is throttling, reconnecting in 30sec') + bot.event_manager.emit( + 'api_error', + sender=bot, + level='info', + formatted='Server is throttling, reconnecting in 30 seconds' + ) time.sleep(30) except GeocoderQuotaExceeded: - logger.log('[x] The given maps api key has gone over the requests limit.', 'red') - finished = True - except: + raise "Google Maps API key over requests limit." + except Exception as e: # always report session summary and then raise exception report_summary(bot) - raise + raise e def report_summary(bot): if bot.metrics.start_time is None: @@ -94,22 +127,21 @@ def report_summary(bot): metrics = bot.metrics metrics.capture_stats() - logger.log('') - logger.log('Ran for {}'.format(metrics.runtime()), 'cyan') - logger.log('Total XP Earned: {} Average: {:.2f}/h'.format(metrics.xp_earned(), metrics.xp_per_hour()), 'cyan') - logger.log('Travelled {:.2f}km'.format(metrics.distance_travelled()), 'cyan') - logger.log('Visited {} stops'.format(metrics.visits['latest'] - metrics.visits['start']), 'cyan') - logger.log('Encountered {} pokemon, {} caught, {} released, {} evolved, {} never seen before' + logger.info('') + logger.info('Ran for {}'.format(metrics.runtime())) + logger.info('Total XP Earned: {} Average: {:.2f}/h'.format(metrics.xp_earned(), metrics.xp_per_hour())) + logger.info('Travelled {:.2f}km'.format(metrics.distance_travelled())) + logger.info('Visited {} stops'.format(metrics.visits['latest'] - metrics.visits['start'])) + logger.info('Encountered {} pokemon, {} caught, {} released, {} evolved, {} never seen before' .format(metrics.num_encounters(), metrics.num_captures(), metrics.releases, - metrics.num_evolutions(), metrics.num_new_mons()), 'cyan') - logger.log('Threw {} pokeball{}'.format(metrics.num_throws(), '' if metrics.num_throws() == 1 else 's'), - 'cyan') - logger.log('Earned {} Stardust'.format(metrics.earned_dust()), 'cyan') - logger.log('') + metrics.num_evolutions(), metrics.num_new_mons())) + logger.info('Threw {} pokeball{}'.format(metrics.num_throws(), '' if metrics.num_throws() == 1 else 's')) + logger.info('Earned {} Stardust'.format(metrics.earned_dust())) + logger.info('') if metrics.highest_cp is not None: - logger.log('Highest CP Pokemon: {}'.format(metrics.highest_cp['desc']), 'cyan') + logger.info('Highest CP Pokemon: {}'.format(metrics.highest_cp['desc'])) if metrics.most_perfect is not None: - logger.log('Most Perfect Pokemon: {}'.format(metrics.most_perfect['desc']), 'cyan') + logger.info('Most Perfect Pokemon: {}'.format(metrics.most_perfect['desc'])) def init_config(): parser = argparse.ArgumentParser() @@ -126,11 +158,11 @@ def init_config(): with open(config_arg) as data: load.update(json.load(data)) elif os.path.isfile(config_file): - logger.log('No config argument specified, checking for /configs/config.json', 'yellow') + logger.info('No config argument specified, checking for /configs/config.json') with open(config_file) as data: load.update(json.load(data)) else: - logger.log('Error: No /configs/config.json or specified config', 'red') + logger.info('Error: No /configs/config.json or specified config') # Read passed in Arguments required = lambda x: not x in load @@ -228,7 +260,15 @@ def init_config(): type=str, default=None ) - + add_config( + parser, + load, + short_flag="-e", + long_flag="--show_events", + help="Show events", + type=bool, + default=False + ) add_config( parser, load, diff --git a/pokemongo_bot/__init__.py b/pokemongo_bot/__init__.py index c5cf3d4614..045abd82e9 100644 --- a/pokemongo_bot/__init__.py +++ b/pokemongo_bot/__init__.py @@ -1,4 +1,5 @@ # -*- coding: utf-8 -*- +from __future__ import unicode_literals import datetime import json @@ -14,7 +15,6 @@ from pgoapi.utilities import f2i, get_cell_ids import cell_workers -import logger from api_wrapper import ApiWrapper from cell_workers.utils import distance from event_manager import EventManager @@ -23,6 +23,7 @@ from metrics import Metrics from pokemongo_bot.event_handlers import LoggingHandler, SocketIoHandler from pokemongo_bot.socketio_server.runner import SocketIoRunner +from pokemongo_bot.websocket_remote_control import WebsocketRemoteControl from worker_result import WorkerResult from tree_config_builder import ConfigException, TreeConfigBuilder @@ -52,11 +53,13 @@ def __init__(self, config): self.start_position = None self.last_map_object = None self.last_time_map_object = 0 + self.logger = logging.getLogger(type(self).__name__) # Make our own copy of the workers for this instance self.workers = [] def start(self): + self._setup_event_system() self._setup_logging() self._setup_api() @@ -64,15 +67,26 @@ def start(self): def _setup_event_system(self): handlers = [LoggingHandler()] - if self.config.websocket_server: - websocket_handler = SocketIoHandler(self.config.websocket_server_url) - handlers.append(websocket_handler) - + if self.config.websocket_server_url: if self.config.websocket_start_embedded_server: self.sio_runner = SocketIoRunner(self.config.websocket_server_url) self.sio_runner.start_listening_async() + websocket_handler = SocketIoHandler( + self, + self.config.websocket_server_url + ) + handlers.append(websocket_handler) + + if self.config.websocket_remote_control: + remote_control = WebsocketRemoteControl(self).start() + + self.event_manager = EventManager(*handlers) + self._register_events() + if self.config.show_events: + self.event_manager.event_report() + sys.exit(1) # Registering event: # self.event_manager.register_event("location", parameters=['lat', 'lng']) @@ -81,6 +95,293 @@ def _setup_event_system(self): # message: : # self.event_manager.emit('location', 'level'='info', data={'lat': 1, 'lng':1}), + def _register_events(self): + self.event_manager.register_event( + 'location_found', + parameters=('position', 'location') + ) + self.event_manager.register_event('api_error') + self.event_manager.register_event('config_error') + + self.event_manager.register_event('login_started') + self.event_manager.register_event('login_failed') + self.event_manager.register_event('login_successful') + + self.event_manager.register_event('set_start_location') + self.event_manager.register_event('load_cached_location') + self.event_manager.register_event('location_cache_ignored') + self.event_manager.register_event( + 'position_update', + parameters=( + 'current_position', + 'last_position', + 'distance', # optional + 'distance_unit' # optional + ) + ) + self.event_manager.register_event('location_cache_error') + + self.event_manager.register_event('bot_start') + self.event_manager.register_event('bot_exit') + + # sleep stuff + self.event_manager.register_event( + 'next_sleep', + parameters=('time',) + ) + self.event_manager.register_event( + 'bot_sleep', + parameters=('time_in_seconds',) + ) + + # fort stuff + self.event_manager.register_event( + 'spun_fort', + parameters=( + 'fort_id', + 'latitude', + 'longitude' + ) + ) + self.event_manager.register_event( + 'lured_pokemon_found', + parameters=( + 'fort_id', + 'fort_name', + 'encounter_id', + 'latitude', + 'longitude' + ) + ) + self.event_manager.register_event( + 'moving_to_fort', + parameters=( + 'fort_name', + 'distance' + ) + ) + self.event_manager.register_event( + 'moving_to_lured_fort', + parameters=( + 'fort_name', + 'distance', + 'lure_distance' + ) + ) + self.event_manager.register_event( + 'spun_pokestop', + parameters=( + 'pokestop', 'exp', 'items' + ) + ) + self.event_manager.register_event( + 'pokestop_empty', + parameters=('pokestop',) + ) + self.event_manager.register_event( + 'pokestop_out_of_range', + parameters=('pokestop',) + ) + self.event_manager.register_event( + 'pokestop_on_cooldown', + parameters=('pokestop', 'minutes_left') + ) + self.event_manager.register_event( + 'unknown_spin_result', + parameters=('status_code',) + ) + self.event_manager.register_event('pokestop_searching_too_often') + self.event_manager.register_event('arrived_at_fort') + + # pokemon stuff + self.event_manager.register_event( + 'catchable_pokemon', + parameters=( + 'pokemon_id', + 'spawn_point_id', + 'encounter_id', + 'latitude', + 'longitude', + 'expiration_timestamp_ms' + ) + ) + self.event_manager.register_event( + 'pokemon_appeared', + parameters=( + 'pokemon', + 'cp', + 'iv', + 'iv_display', + ) + ) + self.event_manager.register_event( + 'pokemon_catch_rate', + parameters=( + 'catch_rate', + 'berry_name', + 'berry_count' + ) + ) + self.event_manager.register_event( + 'threw_berry', + parameters=( + 'berry_name', + 'new_catch_rate' + ) + ) + self.event_manager.register_event( + 'threw_pokeball', + parameters=( + 'pokeball', + 'success_percentage', + 'count_left' + ) + ) + self.event_manager.register_event( + 'pokemon_fled', + parameters=('pokemon',) + ) + self.event_manager.register_event( + 'pokemon_vanished', + parameters=('pokemon',) + ) + self.event_manager.register_event( + 'pokemon_caught', + parameters=( + 'pokemon', + 'cp', 'iv', 'iv_display', 'exp' + ) + ) + self.event_manager.register_event( + 'pokemon_evolved', + parameters=('pokemon', 'iv', 'cp') + ) + self.event_manager.register_event( + 'pokemon_evolve_fail', + parameters=('pokemon',) + ) + self.event_manager.register_event('skip_evolve') + self.event_manager.register_event('threw_berry_failed', parameters=('status_code',)) + self.event_manager.register_event('vip_pokemon') + + + # level up stuff + self.event_manager.register_event( + 'level_up', + parameters=( + 'previous_level', + 'current_level' + ) + ) + self.event_manager.register_event( + 'level_up_reward', + parameters=('items',) + ) + + # lucky egg + self.event_manager.register_event( + 'used_lucky_egg', + parameters=('amount_left',) + ) + self.event_manager.register_event('lucky_egg_error') + + # softban + self.event_manager.register_event('softban') + self.event_manager.register_event('softban_fix') + self.event_manager.register_event('softban_fix_done') + + # egg incubating + self.event_manager.register_event( + 'incubate_try', + parameters=( + 'incubator_id', + 'egg_id' + ) + ) + self.event_manager.register_event( + 'incubate', + parameters=('distance_in_km',) + ) + self.event_manager.register_event( + 'next_egg_incubates', + parameters=('distance_in_km',) + ) + self.event_manager.register_event('incubator_already_used') + self.event_manager.register_event('egg_already_incubating') + self.event_manager.register_event( + 'egg_hatched', + parameters=( + 'pokemon', + 'cp', 'iv', 'exp', 'stardust', 'candy' + ) + ) + + # discard item + self.event_manager.register_event( + 'item_discarded', + parameters=( + 'amount', 'item', 'maximum' + ) + ) + self.event_manager.register_event( + 'item_discard_fail', + parameters=('item',) + ) + + # inventory + self.event_manager.register_event('inventory_full') + + # release + self.event_manager.register_event( + 'keep_best_release', + parameters=( + 'amount', 'pokemon', 'criteria' + ) + ) + self.event_manager.register_event( + 'future_pokemon_release', + parameters=( + 'pokemon', 'cp', 'iv', 'below_iv', 'below_cp', 'cp_iv_logic' + ) + ) + self.event_manager.register_event( + 'pokemon_release', + parameters=('pokemon', 'cp', 'iv') + ) + + # polyline walker + self.event_manager.register_event( + 'polyline_request', + parameters=('url',) + ) + + # cluster + self.event_manager.register_event( + 'found_cluster', + parameters=( + 'num_points', 'forts', 'radius', 'distance' + ) + ) + self.event_manager.register_event( + 'arrived_at_cluster', + parameters=( + 'forts', 'radius' + ) + ) + + # rename + self.event_manager.register_event( + 'rename_pokemon', + parameters=( + 'old_name', 'current_name' + ) + ) + self.event_manager.register_event( + 'pokemon_nickname_invalid', + parameters=('nickname',) + ) + self.event_manager.register_event('unset_pokemon_nickname') + def tick(self): self.cell = self.get_meta_cell() self.tick_count += 1 @@ -170,7 +471,7 @@ def update_web_location(self, cells=[], lat=None, lng=None, alt=None): 'cells': cells }, outfile) except IOError as e: - logger.log('[x] Error while opening location file: %s' % e, 'red') + self.logger.info('[x] Error while opening location file: %s' % e) user_data_lastlocation = os.path.join( 'data', 'last-location-%s.json' % self.config.username @@ -179,7 +480,7 @@ def update_web_location(self, cells=[], lat=None, lng=None, alt=None): with open(user_data_lastlocation, 'w') as outfile: json.dump({'lat': lat, 'lng': lng, 'start_position': self.start_position}, outfile) except IOError as e: - logger.log('[x] Error while opening location file: %s' % e, 'red') + self.logger.info('[x] Error while opening location file: %s' % e) def find_close_cells(self, lat, lng): cellid = get_cell_ids(lat, lng) @@ -204,14 +505,11 @@ def find_close_cells(self, lat, lng): return map_cells def _setup_logging(self): - self.log = logging.getLogger(__name__) # log settings # log format - logging.basicConfig( - level=logging.DEBUG, - format='%(asctime)s [%(name)10s] [%(levelname)5s] %(message)s') if self.config.debug: + log_level = logging.DEBUG logging.getLogger("requests").setLevel(logging.DEBUG) logging.getLogger("websocket").setLevel(logging.DEBUG) logging.getLogger("socketio").setLevel(logging.DEBUG) @@ -220,6 +518,7 @@ def _setup_logging(self): logging.getLogger("pgoapi").setLevel(logging.DEBUG) logging.getLogger("rpc_api").setLevel(logging.DEBUG) else: + log_level = logging.ERROR logging.getLogger("requests").setLevel(logging.ERROR) logging.getLogger("websocket").setLevel(logging.ERROR) logging.getLogger("socketio").setLevel(logging.ERROR) @@ -228,20 +527,24 @@ def _setup_logging(self): logging.getLogger("pgoapi").setLevel(logging.ERROR) logging.getLogger("rpc_api").setLevel(logging.ERROR) + logging.basicConfig( + level=log_level, + format='%(asctime)s [%(name)10s] [%(levelname)s] %(message)s' + ) def check_session(self, position): # Check session expiry if self.api._auth_provider and self.api._auth_provider._ticket_expire: # prevent crash if return not numeric value if not self.is_numeric(self.api._auth_provider._ticket_expire): - logger.log("Ticket expired value is not numeric", 'yellow') + self.logger.info("Ticket expired value is not numeric", 'yellow') return remaining_time = \ self.api._auth_provider._ticket_expire / 1000 - time.time() if remaining_time < 60: - logger.log("Session stale, re-logging in", 'yellow') + self.logger.info("Session stale, re-logging in", 'yellow') position = self.position self.api = ApiWrapper() self.position = position @@ -256,7 +559,12 @@ def is_numeric(s): return False def login(self): - logger.log('Attempting login to Pokemon Go.', 'white') + self.event_manager.emit( + 'login_started', + sender=self, + level='info', + formatted="Login procedure started." + ) lat, lng = self.position[0:2] self.api.set_position(lat, lng, 0) @@ -265,11 +573,20 @@ def login(self): str(self.config.username), str(self.config.password)): - logger.log('[X] Login Error, server busy', 'red') - logger.log('[X] Waiting 10 seconds to try again', 'red') + self.event_manager.emit( + 'login_failed', + sender=self, + level='info', + formatted="Login error, server busy. Waiting 10 seconds to try again." + ) time.sleep(10) - logger.log('Login to Pokemon Go successful.', 'green') + self.event_manager.emit( + 'login_successful', + sender=self, + level='info', + formatted="Login successful." + ) def _setup_api(self): # instantiate pgoapi @@ -279,12 +596,11 @@ def _setup_api(self): self._set_starting_position() self.login() - # chain subrequests (methods) into one RPC call self._print_character_info() - logger.log('') + self.logger.info('') self.update_inventory() # send empty map_cells and then our position self.update_web_location() @@ -301,7 +617,7 @@ def _print_character_info(self): self._player = response_dict['responses']['GET_PLAYER']['player_data'] player = self._player else: - logger.log( + self.logger.info( "The API didn't return player info, servers are unstable - " "retrying.", 'red' ) @@ -321,56 +637,56 @@ def _print_character_info(self): pokecoins = player['currencies'][0]['amount'] if 'amount' in player['currencies'][1]: stardust = player['currencies'][1]['amount'] - logger.log('') - logger.log('--- {username} ---'.format(**player), 'cyan') + self.logger.info('') + self.logger.info('--- {username} ---'.format(**player)) self.get_player_info() - logger.log( + self.logger.info( 'Pokemon Bag: {}/{}'.format( self.get_inventory_count('pokemon'), player['max_pokemon_storage'] - ), 'cyan' + ) ) - logger.log( + self.logger.info( 'Items: {}/{}'.format( self.get_inventory_count('item'), player['max_item_storage'] - ), 'cyan' + ) ) - logger.log( + self.logger.info( 'Stardust: {}'.format(stardust) + - ' | Pokecoins: {}'.format(pokecoins), 'cyan' + ' | Pokecoins: {}'.format(pokecoins) ) # Items Output - logger.log( + self.logger.info( 'PokeBalls: ' + str(items_stock[1]) + ' | GreatBalls: ' + str(items_stock[2]) + - ' | UltraBalls: ' + str(items_stock[3]), 'cyan') + ' | UltraBalls: ' + str(items_stock[3])) - logger.log( + self.logger.info( 'RazzBerries: ' + str(items_stock[701]) + ' | BlukBerries: ' + str(items_stock[702]) + - ' | NanabBerries: ' + str(items_stock[703]), 'cyan') + ' | NanabBerries: ' + str(items_stock[703])) - logger.log( + self.logger.info( 'LuckyEgg: ' + str(items_stock[301]) + ' | Incubator: ' + str(items_stock[902]) + - ' | TroyDisk: ' + str(items_stock[501]), 'cyan') + ' | TroyDisk: ' + str(items_stock[501])) - logger.log( + self.logger.info( 'Potion: ' + str(items_stock[101]) + ' | SuperPotion: ' + str(items_stock[102]) + - ' | HyperPotion: ' + str(items_stock[103]), 'cyan') + ' | HyperPotion: ' + str(items_stock[103])) - logger.log( + self.logger.info( 'Incense: ' + str(items_stock[401]) + ' | IncenseSpicy: ' + str(items_stock[402]) + - ' | IncenseCool: ' + str(items_stock[403]), 'cyan') + ' | IncenseCool: ' + str(items_stock[403])) - logger.log( + self.logger.info( 'Revive: ' + str(items_stock[201]) + - ' | MaxRevive: ' + str(items_stock[202]), 'cyan') + ' | MaxRevive: ' + str(items_stock[202])) - logger.log('') + self.logger.info('') def use_lucky_egg(self): return self.api.use_item_xp_boost(item_id=301) @@ -450,6 +766,13 @@ def _all_items_inventory_count(self, inventory_dict): def _set_starting_position(self): + self.event_manager.emit( + 'set_start_location', + sender=self, + level='info', + formatted='Setting start location.' + ) + has_position = False if self.config.test: @@ -457,23 +780,51 @@ def _set_starting_position(self): return if self.config.location: - location_str = self.config.location.encode('utf-8') - location = (self.get_pos_by_name(location_str.replace(" ", ""))) + location_str = self.config.location + location = self.get_pos_by_name(location_str.replace(" ", "")) + msg = "Location found: {location} {position}" + self.event_manager.emit( + 'location_found', + sender=self, + level='info', + formatted=msg, + data={ + 'location': location_str, + 'position': location + } + ) + self.api.set_position(*location) + + self.event_manager.emit( + 'position_update', + sender=self, + level='info', + formatted="Now at {current_position}", + data={ + 'current_position': self.position, + 'last_position': '', + 'distance': '', + 'distance_unit': '' + } + ) + self.start_position = self.position - logger.log('') - logger.log('Location Found: {}'.format(location_str)) - logger.log('GeoPosition: {}'.format(self.position)) - logger.log('') + has_position = True if self.config.location_cache: try: # save location flag used to pull the last known location from # the location.json - logger.log('[x] Parsing cached location...') + self.event_manager.emit( + 'load_cached_location', + sender=self, + level='debug', + formatted='Loading cached location...' + ) with open('data/last-location-%s.json' % - self.config.username) as f: + self.config.username) as f: location_json = json.load(f) location = ( location_json['lat'], @@ -487,22 +838,28 @@ def _set_starting_position(self): # Start position has to have been set on a previous run to do this check if last_start_position and last_start_position != self.start_position: - logger.log('[x] Last location flag used but with a stale starting location', 'yellow') - logger.log('[x] Using new starting location, {}'.format(self.position)) + msg = 'Going to a new place, ignoring cached location.' + self.event_manager.emit( + 'location_cache_ignored', + sender=self, + level='debug', + formatted=msg + ) return self.api.set_position(*location) - - logger.log('') - logger.log( - '[x] Last location flag used. Overriding passed in location' - ) - logger.log( - '[x] Last in-game location was set as: {}'.format( - self.position - ) + self.event_manager.emit( + 'position_update', + sender=self, + level='debug', + formatted='Loaded location {current_position} from cache', + data={ + 'current_position': location, + 'last_position': '', + 'distance': '', + 'distance_unit': '' + } ) - logger.log('') has_position = True except Exception: @@ -510,9 +867,11 @@ def _set_starting_position(self): sys.exit( "No cached Location. Please specify initial location." ) - logger.log( - '[x] Parsing cached location failed, try to use the ' - 'initial location...' + self.event_manager.emit( + 'location_cache_error', + sender=self, + level='debug', + formatted='Parsing cached location failed.' ) def get_pos_by_name(self, location_name): @@ -524,7 +883,7 @@ def get_pos_by_name(self, location_name): if len(possible_coordinates) == 2: # 2 matches, this must be a coordinate. We'll bypass the Google # geocode so we keep the exact location. - logger.log( + self.logger.info( '[x] Coordinates found in passed in location, ' 'not geocoding.' ) @@ -578,22 +937,22 @@ def get_player_info(self): nextlvlxp = (int(playerdata.get('next_level_xp', 0)) - int(playerdata.get('experience', 0))) if 'level' in playerdata and 'experience' in playerdata: - logger.log( + self.logger.info( 'Level: {level}'.format( **playerdata) + ' (Next Level: {} XP)'.format( nextlvlxp) + ' (Total: {experience} XP)' - ''.format(**playerdata), 'cyan') + ''.format(**playerdata)) if 'pokemons_captured' in playerdata and 'poke_stop_visits' in playerdata: - logger.log( + self.logger.info( 'Pokemon Captured: ' '{pokemons_captured}'.format( **playerdata) + ' | Pokestops Visited: ' '{poke_stop_visits}'.format( - **playerdata), 'cyan') + **playerdata)) def has_space_for_loot(self): number_of_things_gained_by_stop = 5 diff --git a/pokemongo_bot/api_wrapper.py b/pokemongo_bot/api_wrapper.py index 17612aceb6..324d645043 100644 --- a/pokemongo_bot/api_wrapper.py +++ b/pokemongo_bot/api_wrapper.py @@ -1,4 +1,5 @@ import time +import logging from pgoapi.exceptions import (ServerSideRequestThrottlingException, NotLoggedInException, ServerBusyOrOfflineException, @@ -7,7 +8,6 @@ from pgoapi.pgoapi import PGoApi, PGoApiRequest, RpcApi from pgoapi.protos.POGOProtos.Networking.Requests_pb2 import RequestType -import pokemongo_bot.logger as logger from human_behaviour import sleep class ApiWrapper(PGoApi): @@ -42,6 +42,7 @@ def login(self, *args): class ApiRequest(PGoApiRequest): def __init__(self, *args): PGoApiRequest.__init__(self, *args) + self.logger = logging.getLogger(__name__) self.request_callers = [] self.last_api_request_time = None self.requests_per_seconds = 2 @@ -119,16 +120,16 @@ def call(self, max_retry=15): if should_unexpected_response_retry: unexpected_response_retry += 1 if unexpected_response_retry >= 5: - logger.log('Server is not responding correctly to our requests. Waiting for 30 seconds to reconnect.', 'red') + self.logger.warning('Server is not responding correctly to our requests. Waiting for 30 seconds to reconnect.') sleep(30) else: sleep(2) continue - + if not self.is_response_valid(result, request_callers): try_cnt += 1 if try_cnt > 3: - logger.log('Server seems to be busy or offline - try again - {}/{}'.format(try_cnt, max_retry), 'red') + self.logger.warning('Server seems to be busy or offline - try again - {}/{}'.format(try_cnt, max_retry)) if try_cnt >= max_retry: raise ServerBusyOrOfflineException() sleep(1) diff --git a/pokemongo_bot/cell_workers/base_task.py b/pokemongo_bot/cell_workers/base_task.py index 4d73a68443..ac48b9a676 100644 --- a/pokemongo_bot/cell_workers/base_task.py +++ b/pokemongo_bot/cell_workers/base_task.py @@ -1,8 +1,13 @@ +import logging + + class BaseTask(object): + def __init__(self, bot, config): self.bot = bot self.config = config self._validate_work_exists() + self.logger = logging.getLogger(type(self).__name__) self.initialize() def _validate_work_exists(self): @@ -10,5 +15,16 @@ def _validate_work_exists(self): if not method or not callable(method): raise NotImplementedError('Missing "work" method') + def emit_event(self, event, sender=None, level='info', formatted='', data={}): + if not sender: + sender=self + self.bot.event_manager.emit( + event, + sender=sender, + level=level, + formatted=formatted, + data=data + ) + def initialize(self): pass diff --git a/pokemongo_bot/cell_workers/catch_lured_pokemon.py b/pokemongo_bot/cell_workers/catch_lured_pokemon.py index d25a8f1728..bf2d45bb4b 100644 --- a/pokemongo_bot/cell_workers/catch_lured_pokemon.py +++ b/pokemongo_bot/cell_workers/catch_lured_pokemon.py @@ -1,8 +1,11 @@ -from pokemongo_bot import logger +# -*- coding: utf-8 -*- +from __future__ import unicode_literals + from pokemongo_bot.cell_workers.utils import fort_details from pokemongo_bot.cell_workers.pokemon_catch_worker import PokemonCatchWorker from pokemongo_bot.cell_workers.base_task import BaseTask + class CatchLuredPokemon(BaseTask): def work(self): lured_pokemon = self.get_lured_pokemon() @@ -24,14 +27,21 @@ def get_lured_pokemon(self): encounter_id = fort.get('lure_info', {}).get('encounter_id', None) if encounter_id: - logger.log('Lured pokemon at fort {}'.format(fort_name)) - return { + result = { 'encounter_id': encounter_id, 'fort_id': fort['id'], + 'fort_name': fort_name, 'latitude': fort['latitude'], 'longitude': fort['longitude'] } + self.emit_event( + 'lured_pokemon_found', + formatted='Lured pokemon at fort {fort_name} ({fort_id})', + data=result + ) + return result + return False def catch_pokemon(self, pokemon): diff --git a/pokemongo_bot/cell_workers/catch_visible_pokemon.py b/pokemongo_bot/cell_workers/catch_visible_pokemon.py index 7fe9df6cb4..c9c6147c0a 100644 --- a/pokemongo_bot/cell_workers/catch_visible_pokemon.py +++ b/pokemongo_bot/cell_workers/catch_visible_pokemon.py @@ -1,6 +1,5 @@ import json -from pokemongo_bot import logger from pokemongo_bot.cell_workers.base_task import BaseTask from pokemongo_bot.cell_workers.pokemon_catch_worker import PokemonCatchWorker from utils import distance @@ -9,17 +8,28 @@ class CatchVisiblePokemon(BaseTask): def work(self): if 'catchable_pokemons' in self.bot.cell and len(self.bot.cell['catchable_pokemons']) > 0: - logger.log('Something rustles nearby!') # Sort all by distance from current pos- eventually this should # build graph & A* it self.bot.cell['catchable_pokemons'].sort( key= - lambda x: distance(self.bot.position[0], self.bot.position[1], x['latitude'], x['longitude'])) + lambda x: distance(self.bot.position[0], self.bot.position[1], x['latitude'], x['longitude']) + ) - user_web_catchable = 'web/catchable-%s.json' % self.bot.config.username for pokemon in self.bot.cell['catchable_pokemons']: with open(user_web_catchable, 'w') as outfile: json.dump(pokemon, outfile) + self.emit_event( + 'catchable_pokemon', + level='debug', + data={ + 'pokemon_id': pokemon['pokemon_id'], + 'spawn_point_id': pokemon['spawn_point_id'], + 'encounter_id': pokemon['encounter_id'], + 'latitude': pokemon['latitude'], + 'longitude': pokemon['longitude'], + 'expiration_timestamp_ms': pokemon['expiration_timestamp_ms'], + } + ) return self.catch_pokemon(self.bot.cell['catchable_pokemons'].pop(0)) diff --git a/pokemongo_bot/cell_workers/collect_level_up_reward.py b/pokemongo_bot/cell_workers/collect_level_up_reward.py index 912a97d197..304818fe2b 100644 --- a/pokemongo_bot/cell_workers/collect_level_up_reward.py +++ b/pokemongo_bot/cell_workers/collect_level_up_reward.py @@ -1,4 +1,3 @@ -from pokemongo_bot import logger from pokemongo_bot.cell_workers.base_task import BaseTask @@ -19,7 +18,14 @@ def work(self): self._collect_level_reward() # level up situation elif self.current_level > self.previous_level: - logger.log('Level up from {} to {}!'.format(self.previous_level, self.current_level), 'green') + self.emit_event( + 'level_up', + formatted='Level up from {previous_level} to {current_level}', + data={ + 'previous_level': self.previous_level, + 'current_level': self.current_level + } + ) self._collect_level_reward() self.previous_level = self.current_level @@ -32,14 +38,19 @@ def _collect_level_reward(self): .get('LEVEL_UP_REWARDS', {}) .get('items_awarded', [])) - if data: - logger.log('Collected level up rewards:', 'green') - for item in data: if 'item_id' in item and str(item['item_id']) in self.bot.item_list: got_item = self.bot.item_list[str(item['item_id'])] + item['name'] = got_item count = 'item_count' in item and item['item_count'] or 0 - logger.log('{} x {}'.format(got_item, count), 'green') + + self.emit_event( + 'level_up_reward', + formatted='Received level up reward: {items}', + data={ + 'items': data + } + ) def _get_current_level(self): level = 0 diff --git a/pokemongo_bot/cell_workers/evolve_pokemon.py b/pokemongo_bot/cell_workers/evolve_pokemon.py index 52013ebbcc..91c9c807cf 100644 --- a/pokemongo_bot/cell_workers/evolve_pokemon.py +++ b/pokemongo_bot/cell_workers/evolve_pokemon.py @@ -1,13 +1,14 @@ -from pokemongo_bot import logger from pokemongo_bot.human_behaviour import sleep from pokemongo_bot.item_list import Item from pokemongo_bot.cell_workers.base_task import BaseTask + class EvolvePokemon(BaseTask): + def initialize(self): self.api = self.bot.api self.evolve_all = self.config.get('evolve_all', []) - self.evolve_speed = self.config.get('evolve_speed', 3.7) + self.evolve_speed = self.config.get('evolve_speed', 2) self.first_evolve_by = self.config.get('first_evolve_by', 'cp') self.evolve_above_cp = self.config.get('evolve_above_cp', 500) self.evolve_above_iv = self.config.get('evolve_above_iv', 0.8) @@ -35,14 +36,9 @@ def work(self): cache = {} candy_list = self._get_candy_list(inventory_items) - evolved = 0 for pokemon in evolve_list: - if self._can_evolve(pokemon, candy_list, cache) \ - and self._execute_pokemon_evolve(pokemon, candy_list, cache): - evolved += 1 - - if evolved > 0: - logger.log('Evolved {} pokemon!'.format(evolved)) + if self._can_evolve(pokemon, candy_list, cache): + self._execute_pokemon_evolve(pokemon, candy_list, cache) def _should_run(self): if not self.evolve_all or self.evolve_all[0] == 'none': @@ -56,19 +52,31 @@ def _should_run(self): # Make sure the user has a lucky egg and skip if not if lucky_egg_count > 0: - logger.log('Using lucky egg ... you have {}'.format(lucky_egg_count)) response_dict_lucky_egg = self.bot.use_lucky_egg() if response_dict_lucky_egg: result = response_dict_lucky_egg.get('responses', {}).get('USE_ITEM_XP_BOOST', {}).get('result', 0) if result is 1: # Request success - logger.log('Successfully used lucky egg... ({} left!)'.format(lucky_egg_count - 1), 'green') + self.emit_event( + 'used_lucky_egg', + formmated='Used lucky egg ({amount_left} left).', + data={ + 'amount_left': lucky_egg_count - 1 + } + ) return True else: - logger.log('Failed to use lucky egg!', 'red') + self.emit_event( + 'lucky_egg_error', + level='error', + formatted='Failed to use lucky egg!' + ) return False else: # Skipping evolve so they aren't wasted - logger.log('No lucky eggs... skipping evolve!', 'yellow') + self.emit_event( + 'skip_evolve', + formatted='Skipping evolve because has no lucky egg.' + ) return False def _get_candy_list(self, inventory_items): @@ -136,7 +144,15 @@ def _execute_pokemon_evolve(self, pokemon, candy_list, cache): response_dict = self.api.evolve_pokemon(pokemon_id=pokemon_id) if response_dict.get('responses', {}).get('EVOLVE_POKEMON', {}).get('result', 0) == 1: - logger.log('Successfully evolved {} with {} CP and {} IV!'.format(pokemon_name, pokemon_cp, pokemon_iv)) + self.emit_event( + 'pokemon_evolved', + formatted="Successfully evolved {pokemon} with CP {cp} and IV {iv}!", + data={ + 'pokemon': pokemon_name, + 'iv': pokemon_iv, + 'cp': pokemon_cp + } + ) candy_list[pokemon["candies_family"]] -= pokemon["candies_amount"] sleep(self.evolve_speed) return True diff --git a/pokemongo_bot/cell_workers/follow_cluster.py b/pokemongo_bot/cell_workers/follow_cluster.py index 9c845404bd..02d3880a7e 100644 --- a/pokemongo_bot/cell_workers/follow_cluster.py +++ b/pokemongo_bot/cell_workers/follow_cluster.py @@ -1,16 +1,14 @@ -from pokemongo_bot import logger from pokemongo_bot.step_walker import StepWalker from pokemongo_bot.cell_workers.utils import distance from pokemongo_bot.cell_workers.utils import find_biggest_cluster +from pokemongo_bot.cell_workers.base_task import BaseTask +class FollowCluster(BaseTask): -class FollowCluster(object): - def __init__(self, bot, config): - self.bot = bot + def initialize(self): self.is_at_destination = False self.announced = False self.dest = None - self.config = config self._process_config() def _process_config(self): @@ -39,11 +37,21 @@ def work(self): cnt = self.dest['num_points'] if not self.is_at_destination: + msg = log_lure_avail_str + ( + "Move to destiny {num_points}. {forts} " + "pokestops will be in range of {radius}. Walking {distance}m." + ) + self.emit_event( + 'found_cluster', + formatted=msg, + data={ + 'num_points': cnt, + 'forts': log_lured_str, + 'radius': str(self.radius), + 'distance': str(distance(self.bot.position[0], self.bot.position[1], lat, lng)) + } + ) - log_str = log_lure_avail_str + 'Move to destiny. ' + str(cnt) + ' ' + log_lured_str + \ - 'pokestops will be in range of ' + str(self.radius) + 'm. Arrive in ' \ - + str(distance(self.bot.position[0], self.bot.position[1], lat, lng)) + 'm.' - logger.log(log_str) self.announced = False if self.bot.config.walk > 0: @@ -61,14 +69,17 @@ def work(self): self.bot.api.set_position(lat, lng) elif not self.announced: - log_str = 'Arrived at destiny. ' + str(cnt) + ' pokestops are in range of ' \ - + str(self.radius) + 'm.' - logger.log(log_str) + self.emit_event( + 'arrived_at_cluster', + formatted="Arrived at cluster. {forts} are in a range of {radius}m radius.", + data={ + 'forts': str(cnt), + 'radius': self.radius + } + ) self.announced = True else: lat = self.bot.position[0] lng = self.bot.position[1] return [lat, lng] - - diff --git a/pokemongo_bot/cell_workers/follow_path.py b/pokemongo_bot/cell_workers/follow_path.py index 81a5d19695..04eb817593 100644 --- a/pokemongo_bot/cell_workers/follow_path.py +++ b/pokemongo_bot/cell_workers/follow_path.py @@ -3,7 +3,6 @@ import gpxpy import gpxpy.gpx import json -import pokemongo_bot.logger as logger from pokemongo_bot.cell_workers.base_task import BaseTask from pokemongo_bot.cell_workers.utils import distance, i2f, format_dist from pokemongo_bot.human_behaviour import sleep @@ -34,11 +33,17 @@ def load_json(self): with open(self.path_file) as data_file: points=json.load(data_file) # Replace Verbal Location with lat&lng. - logger.log("Resolving Navigation Paths (GeoLocating Strings)") for index, point in enumerate(points): - if self.bot.config.debug: - logger.log("Resolving Point {} - {}".format(index, point)) point_tuple = self.bot.get_pos_by_name(point['location']) + self.emit_event( + 'location_found', + level='debug', + formatted="Location found: {location} {position}", + data={ + 'location': point, + 'position': point_tuple + } + ) points[index] = self.lat_lng_tuple_to_dict(point_tuple) return points diff --git a/pokemongo_bot/cell_workers/follow_spiral.py b/pokemongo_bot/cell_workers/follow_spiral.py index bda348490a..28b548d1ca 100644 --- a/pokemongo_bot/cell_workers/follow_spiral.py +++ b/pokemongo_bot/cell_workers/follow_spiral.py @@ -3,7 +3,6 @@ import math -import pokemongo_bot.logger as logger from pokemongo_bot.cell_workers.utils import distance, format_dist from pokemongo_bot.step_walker import StepWalker from pokemongo_bot.cell_workers.base_task import BaseTask @@ -84,10 +83,16 @@ def work(self): ) if self.cnt == 1: - logger.log( - 'Walking from ' + str((self.bot.api._position_lat, - self.bot.api._position_lng)) + " to " + str([point['lat'], point['lng']]) + " " + format_dist(dist, - self.bot.config.distance_unit)) + self.emit_event( + 'position_update', + formatted="Walking from {last_position} to {current_position} ({distance} {distance_unit})", + data={ + 'last_position': self.bot.position, + 'current_position': (point['lat'], point['lng'], 0), + 'distance': dist, + 'distance_unit': 'm' + } + ) if step_walker.step(): step_walker = None diff --git a/pokemongo_bot/cell_workers/handle_soft_ban.py b/pokemongo_bot/cell_workers/handle_soft_ban.py index 25c64f60e9..e266c5c377 100644 --- a/pokemongo_bot/cell_workers/handle_soft_ban.py +++ b/pokemongo_bot/cell_workers/handle_soft_ban.py @@ -2,7 +2,6 @@ from pgoapi.utilities import f2i -from pokemongo_bot import logger from pokemongo_bot.constants import Constants from pokemongo_bot.cell_workers.base_task import BaseTask from pokemongo_bot.cell_workers import MoveToFort @@ -18,9 +17,7 @@ def work(self): forts = self.bot.get_forts(order_by_distance=True) if len(forts) == 0: - logger.log('Found no forts to reset softban, skipping...', 'red') return - logger.log('Got softban, fixing...', 'yellow') fort_distance = distance( self.bot.position[0], @@ -37,13 +34,17 @@ def work(self): return WorkerResult.RUNNING else: spins = randint(50,60) - logger.log('Starting %s spins...' % spins) + self.emit_event( + 'softban_fix', + formatted='Fixing softban.' + ) for i in xrange(spins): - if (i + 1) % 10 == 0: - logger.log('Spin #{}'.format(str(i+1))) self.spin_fort(forts[0]) self.bot.softban = False - logger.log('Softban should be fixed.') + self.emit_event( + 'softban_fix_done', + formatted='Softban should be fixed' + ) def spin_fort(self, fort): self.bot.api.fort_search( @@ -53,6 +54,16 @@ def spin_fort(self, fort): player_latitude=f2i(self.bot.position[0]), player_longitude=f2i(self.bot.position[1]) ) + self.bot.event_handler.emit( + 'spun_fort', + level='debug', + formatted="Spun fort {fort_id}", + data={ + 'fort_id': fort_id, + 'lat': fort['latitude'], + 'lng': fort['longitude'] + } + ) def should_run(self): return self.bot.softban diff --git a/pokemongo_bot/cell_workers/incubate_eggs.py b/pokemongo_bot/cell_workers/incubate_eggs.py index a1e3ce351f..9e21b0d280 100644 --- a/pokemongo_bot/cell_workers/incubate_eggs.py +++ b/pokemongo_bot/cell_workers/incubate_eggs.py @@ -1,4 +1,3 @@ -from pokemongo_bot import logger from pokemongo_bot.human_behaviour import sleep from pokemongo_bot.cell_workers.base_task import BaseTask @@ -31,7 +30,13 @@ def work(self): if km_left <= 0: self._hatch_eggs() else: - logger.log('[x] Current egg hatches in {:.2f} km'.format(km_left),'yellow') + self.emit_event( + 'next_egg_incubates', + formatted='Next egg incubates in {distance_in_km:.2f} km', + data={ + 'distance_in_km': km_left + } + ) IncubateEggs.last_km_walked = self.km_walked sorting = self.longer_eggs_first @@ -45,8 +50,15 @@ def _apply_incubators(self): for egg in self.eggs: if egg["used"] or egg["km"] == -1: continue - if self.bot.config.debug: - logger.log('[x] Attempting to apply incubator {} to egg {}'.format(incubator['id'], egg['id'])) + self.emit_event( + 'incubate_try', + level='debug', + formatted="Attempting to apply incubator {incubator_id} to egg {egg_id}", + data={ + 'incubator_id': incubator['id'], + 'egg_id': egg['id'] + } + ) ret = self.bot.api.use_item_egg_incubator( item_id=incubator["id"], pokemon_id=egg["id"] @@ -54,18 +66,30 @@ def _apply_incubators(self): if ret: code = ret.get("responses", {}).get("USE_ITEM_EGG_INCUBATOR", {}).get("result", 0) if code == 1: - logger.log('[x] Now incubating a ' + str(egg["km"]) + "km egg", 'green') + self.emit_event( + 'incubate', + formatted='Incubating a {distance_in_km} egg.', + data={ + 'distance_in_km': str(egg['km']) + } + ) egg["used"] = True incubator["used"] = True break elif code == 5 or code == 7: - if self.bot.config.debug: - logger.log('[x] Incubator already in use') + self.emit_event( + 'incubator_already_used', + level='debug', + formatted='Incubator in use.', + ) incubator["used"] = True break elif code == 6: - if self.bot.config.debug: - logger.log('[x] Egg already incubating') + self.emit_event( + 'egg_already_incubating', + level='debug', + formatted='Egg already incubating', + ) egg["used"] = True def _check_inventory(self, lookup_ids=[]): @@ -152,16 +176,32 @@ def _hatch_eggs(self): except: pokemon_data = [{"name":"error","cp":"error","iv":"error"}] if not pokemon_ids or pokemon_data[0]['name'] == "error": - logger.log("[!] Eggs hatched, but we had trouble with the response. Please check your inventory to find your new pokemon!",'red') + self.emit_event( + 'egg_hatched', + data={ + 'pokemon': 'error', + 'cp': 'error', + 'iv': 'error', + 'exp': 'error', + 'stardust': 'error', + 'candy': 'error', + } + ) return - logger.log("-"*30, log_color) - logger.log("[!] {} eggs hatched! Received:".format(len(pokemon_data)), log_color) for i in range(len(pokemon_data)): - logger.log("-"*30,log_color) - logger.log("[!] Pokemon: {}".format(pokemon_data[i]['name']), log_color) - logger.log("[!] CP: {}".format(pokemon_data[i].get('cp',0)), log_color) - logger.log("[!] IV: {} ({:.2f})".format("/".join(map(str, pokemon_data[i]['iv'])),(sum(pokemon_data[i]['iv'])/self.max_iv)), log_color) - logger.log("[!] XP: {}".format(xp[i]), log_color) - logger.log("[!] Stardust: {}".format(stardust[i]), log_color) - logger.log("[!] Candy: {}".format(candy[i]), log_color) - logger.log("-"*30, log_color) + msg = "Egg hatched with a {pokemon} (CP {cp} - IV {iv}), {exp} exp, {stardust} stardust and {candy} candies." + self.emit_event( + 'egg_hatched', + formatted=msg, + data={ + 'pokemon': pokemon_data[i]['name'], + 'cp': pokemon_data[i]['cp'], + 'iv': "{} {}".format( + "/".join(map(str, pokemon_data[i]['iv'])), + sum(pokemon_data[i]['iv'])/self.max_iv + ), + 'exp': xp[i], + 'stardust': stardust[i], + 'candy': candy[i], + } + ) diff --git a/pokemongo_bot/cell_workers/move_to_fort.py b/pokemongo_bot/cell_workers/move_to_fort.py index 2313cc504d..f43d1641e6 100644 --- a/pokemongo_bot/cell_workers/move_to_fort.py +++ b/pokemongo_bot/cell_workers/move_to_fort.py @@ -1,4 +1,6 @@ -from pokemongo_bot import logger +# -*- coding: utf-8 -*- +from __future__ import unicode_literals + from pokemongo_bot.constants import Constants from pokemongo_bot.step_walker import StepWalker from pokemongo_bot.worker_result import WorkerResult @@ -16,7 +18,10 @@ def initialize(self): def should_run(self): has_space_for_loot = self.bot.has_space_for_loot() if not has_space_for_loot: - logger.log("Not moving to any forts as there aren't enough space. You might want to change your config to recycle more items if this message appears consistently.", 'yellow') + self.emit_event( + 'inventory_full', + formatted="Not moving to any forts as there aren't enough space. You might want to change your config to recycle more items if this message appears consistently." + ) return has_space_for_loot or self.bot.softban def is_attracted(self): @@ -35,7 +40,7 @@ def work(self): lng = nearest_fort['longitude'] fortID = nearest_fort['id'] details = fort_details(self.bot, fortID, lat, lng) - fort_name = details.get('name', 'Unknown').encode('utf8', 'replace') + fort_name = details.get('name', 'Unknown') unit = self.bot.config.distance_unit # Unit to use when printing formatted distance @@ -47,12 +52,24 @@ def work(self): ) if dist > Constants.MAX_DISTANCE_FORT_IS_REACHABLE: + fort_event_data = { + 'fort_name': u"{}".format(fort_name), + 'distance': format_dist(dist, unit), + } + if self.is_attracted() > 0: - add_str = ' (attraction of lure {})'.format(format_dist(self.lure_distance, unit)) + fort_event_data.update(lure_distance=format_dist(self.lure_distance, unit)) + self.emit_event( + 'moving_to_lured_fort', + formatted="Moving towards pokestop {fort_name} - {distance} (attraction of lure {lure_distance})", + data=fort_event_data + ) else: - add_str = '' - - logger.log('Moving towards fort {}, {} left{}'.format(fort_name, format_dist(dist, unit), add_str)) + self.emit_event( + 'moving_to_fort', + formatted="Moving towards pokestop {fort_name} - {distance}", + data=fort_event_data + ) step_walker = StepWalker( self.bot, @@ -64,7 +81,10 @@ def work(self): if not step_walker.step(): return WorkerResult.RUNNING - logger.log('Arrived at pokestop.') + self.emit_event( + 'arrived_at_fort', + formatted='Arrived at fort.' + ) return WorkerResult.SUCCESS def _get_nearest_fort_on_lure_way(self, forts): diff --git a/pokemongo_bot/cell_workers/nickname_pokemon.py b/pokemongo_bot/cell_workers/nickname_pokemon.py index 2c61d87a9f..29df15ae4a 100644 --- a/pokemongo_bot/cell_workers/nickname_pokemon.py +++ b/pokemongo_bot/cell_workers/nickname_pokemon.py @@ -1,4 +1,3 @@ -from pokemongo_bot import logger from pokemongo_bot.human_behaviour import sleep from pokemongo_bot.cell_workers.base_task import BaseTask @@ -35,7 +34,10 @@ def _nickname_pokemon(self,pokemon): new_name = "" instance_id = pokemon.get('id',0) if not instance_id: - logger.log("Pokemon instance id returned 0. Can't rename.",'red') + self.emit_event( + 'api_error', + formatted='Failed to get pokemon name, will not rename.' + ) return id = pokemon.get('pokemon_id',0)-1 name = self.bot.pokemon_list[id]['Name'] @@ -59,29 +61,41 @@ def _nickname_pokemon(self,pokemon): iv_sum=iv_sum, iv_pct=iv_pct)[:12] except KeyError as bad_key: - logger.log("Unable to nickname {} due to bad template ({})".format(name,bad_key),log_color) - if pokemon.get('nickname', "") == new_name: + self.emit_event( + 'config_error', + formatted="Unable to nickname {} due to bad template ({})".format(name,bad_key) + ) + if pokemon.get('nickname', '') == new_name: return response = self.bot.api.nickname_pokemon(pokemon_id=instance_id,nickname=new_name) sleep(1.2) try: result = reduce(dict.__getitem__, ["responses", "NICKNAME_POKEMON"], response) except KeyError: - logger.log("Attempt to nickname received bad response from server.",log_color) - if self.bot.config.debug: - logger.log(response,log_color) - return + self.emit_event( + 'api_error', + formatted='Attempt to nickname received bad response from server.' + ) result = result['result'] - if new_name == "": - new_name = name - output = { - 0: 'Nickname unset', - 1: 'Nickname set successfully! {} is now {}'.format(name,new_name), - 2: 'Invalid nickname! ({})'.format(new_name), - 3: 'Pokemon not found.', - 4: 'Pokemon is egg' - }[result] - if result==1: - log_color='green' + new_name = new_name or name + if result == 0: + self.emit_event( + 'unset_pokemon_nickname', + formatted="Pokemon nickname unset." + ) + elif result == 1: + self.emit_event( + 'rename_pokemon', + formatted="Pokemon {old_name} renamed to {current_name}", + data={ + 'old_name': name, + 'current_name': new_name + } + ) pokemon['nickname'] = new_name - logger.log(output,log_color) \ No newline at end of file + elif result == 2: + self.emit_event( + 'pokemon_nickname_invalid', + formatted="Nickname {nickname} is invalid", + data={'nickname': new_name} + ) diff --git a/pokemongo_bot/cell_workers/pokemon_catch_worker.py b/pokemongo_bot/cell_workers/pokemon_catch_worker.py index 3f610e7558..afa5578267 100644 --- a/pokemongo_bot/cell_workers/pokemon_catch_worker.py +++ b/pokemongo_bot/cell_workers/pokemon_catch_worker.py @@ -1,11 +1,11 @@ # -*- coding: utf-8 -*- import time -from pokemongo_bot import logger from pokemongo_bot.human_behaviour import (normalized_reticle_size, sleep, spin_modifier) +from pokemongo_bot.cell_workers.base_task import BaseTask -class PokemonCatchWorker(object): +class PokemonCatchWorker(BaseTask): BAG_FULL = 'bag_full' NO_POKEBALLS = 'no_pokeballs' @@ -60,22 +60,33 @@ def work(self, response_dict=None): pokemon_potential = self.pokemon_potential(pokemon_data) pokemon_num = int(pokemon_data['pokemon_id']) - 1 pokemon_name = self.pokemon_list[int(pokemon_num)]['Name'] - logger.log('A Wild {} appeared! [CP {}] [Potential {}]'.format( - pokemon_name, cp, pokemon_potential), 'yellow') - logger.log('IV [Attack/Defense/Stamina] = [{}]'.format(iv_display)) + msg = 'A wild {pokemon} appeared! [CP {cp}] [Potential {iv}] [S/A/D {iv_display}]' + self.emit_event( + 'pokemon_appeared', + formatted=msg, + data={ + 'pokemon': pokemon_name, + 'cp': cp, + 'iv': pokemon_potential, + 'iv_display': iv_display, + } + ) + pokemon_data['name'] = pokemon_name # Simulate app sleep(3) if not self.should_capture_pokemon(pokemon_name, cp, pokemon_potential, response_dict): - # logger.log('[x] Rule prevents capture.') return False flag_VIP = False # @TODO, use the best ball in stock to catch VIP (Very Important Pokemon: Configurable) if self.check_vip_pokemon(pokemon_name, cp, pokemon_potential): - logger.log('[-] {} is a VIP Pokemon! [CP {}] [Potential {}] Nice! Try our best to catch it!'.format(pokemon_name, cp, pokemon_potential),'red') + self.emit_event( + 'vip_pokemon', + formatted='This is a VIP pokemon. Catch!!!' + ) flag_VIP=True items_stock = self.bot.current_inventory() @@ -89,7 +100,16 @@ def work(self, response_dict=None): if flag_VIP: if(berries_count>0 and catch_rate[pokeball-1] < 0.9): success_percentage = '{0:.2f}'.format(catch_rate[pokeball-1]*100) - logger.log('Catch Rate with normal Pokeball is low ({}%). Thinking to throw a {}... ({} left!)'.format(success_percentage,self.item_list[str(berry_id)],berries_count-1)) + self.emit_event( + 'pokemon_catch_rate', + level='debug', + formatted="Catch rate of {catch_rate} is low. Maybe will throw {berry_name} ({berry_count} left)", + data={ + 'catch_rate': success_percentage, + 'berry_name': self.item_list[str(berry_id)], + 'berry_count': berries_count + } + ) # Out of all pokeballs! Let's don't waste berry. if items_stock[1] == 0 and items_stock[2] == 0 and items_stock[3] == 0: break @@ -107,12 +127,29 @@ def work(self, response_dict=None): success_percentage = '{0:.2f}'.format(catch_rate[pokeball-1]*100) berries_count = berries_count -1 berry_used = True - logger.log('Threw a berry! Catch Rate with normal Pokeball has increased to {}%'.format(success_percentage)) + self.emit_event( + 'threw_berry', + formatted="Threw a {berry_name}! Catch rate now: {new_catch_rate}", + data={ + "berry_name": self.item_list[str(berry_id)], + "new_catch_rate": success_percentage + } + ) else: if response_dict['status_code'] is 1: - logger.log('Fail to use berry. Seem like you are softbanned.', 'red') + self.emit_event( + 'softban', + level='warning', + formatted='Failed to use berry. You may be softbanned.' + ) else: - logger.log('Fail to use berry. Status Code: {}'.format(response_dict['status_code']),'red') + self.emit_event( + 'threw_berry_failed', + formatted='Unknown response when throwing berry: {status_code}.', + data={ + 'status_code': response_dict['status_code'] + } + ) #use the best ball to catch current_type = pokeball @@ -130,7 +167,16 @@ def work(self, response_dict=None): break success_percentage = '{0:.2f}'.format(catch_rate[pokeball-1]*100) - logger.log('Catch Rate with normal Pokeball is low ({}%). Thinking to throw a {}... ({} left!)'.format(success_percentage,self.item_list[str(berry_id)],berries_count-1)) + self.emit_event( + 'pokemon_catch_rate', + level='debug', + formatted="Catch rate of {catch_rate} is low. Maybe will throw {berry_name} ({berry_count} left)", + data={ + 'catch_rate': success_percentage, + 'berry_name': self.item_list[str(berry_id)], + 'berry_count': berries_count-1 + } + ) response_dict = self.api.use_item_capture(item_id=berry_id, encounter_id=encounter_id, spawn_point_id=self.spawn_point_guid @@ -142,12 +188,29 @@ def work(self, response_dict=None): success_percentage = '{0:.2f}'.format(catch_rate[pokeball-1]*100) berries_count = berries_count -1 berry_used = True - logger.log('Threw a berry! Catch Rate with normal Pokeball has increased to {}%'.format(success_percentage)) + self.emit_event( + 'threw_berry', + formatted="Threw a {berry_name}! Catch rate now: {new_catch_rate}", + data={ + "berry_name": self.item_list[str(berry_id)], + "new_catch_rate": success_percentage + } + ) else: if response_dict['status_code'] is 1: - logger.log('Fail to use berry. Seem like you are softbanned.', 'red') + self.emit_event( + 'softban', + level='warning', + formatted='Failed to use berry. You may be softbanned.' + ) else: - logger.log('Fail to use berry. Status Code: {}'.format(response_dict['status_code']),'red') + self.emit_event( + 'threw_berry_failed', + formatted='Unknown response when throwing berry: {status_code}.', + data={ + 'status_code': response_dict['status_code'] + } + ) else: #We don't have many berry to waste, pick a good ball first. Save some berry for future VIP pokemon @@ -165,7 +228,16 @@ def work(self, response_dict=None): break success_percentage = '{0:.2f}'.format(catch_rate[pokeball-1]*100) - logger.log('Catch Rate with normal Pokeball is low ({}%). Thinking to throw a {}... ({} left!)'.format(success_percentage,self.item_list[str(berry_id)],berries_count-1)) + self.emit_event( + 'pokemon_catch_rate', + level='debug', + formatted="Catch rate of {catch_rate} is low. Throwing {berry_name} ({berry_count} left)", + data={ + 'catch_rate': success_percentage, + 'berry_name': self.item_list[str(berry_id)], + 'berry_count': berries_count-1 + } + ) response_dict = self.api.use_item_capture(item_id=berry_id, encounter_id=encounter_id, spawn_point_id=self.spawn_point_guid @@ -177,12 +249,29 @@ def work(self, response_dict=None): success_percentage = '{0:.2f}'.format(catch_rate[pokeball-1]*100) berries_count = berries_count -1 berry_used = True - logger.log('Threw a berry! Catch Rate with normal Pokeball has increased to {}%'.format(success_percentage)) + self.emit_event( + 'threw_berry', + formatted="Threw a {berry_name}! Catch rate now: {new_catch_rate}", + data={ + "berry_name": self.item_list[str(berry_id)], + "new_catch_rate": success_percentage + } + ) else: if response_dict['status_code'] is 1: - logger.log('Fail to use berry. Seem like you are softbanned.', 'red') + self.emit_event( + 'softban', + level='warning', + formatted='Failed to use berry. You may be softbanned.' + ) else: - logger.log('Fail to use berry. Status Code: {}'.format(response_dict['status_code']),'red') + self.emit_event( + 'threw_berry_failed', + formatted='Unknown response when throwing berry: {status_code}.', + data={ + 'status_code': response_dict['status_code'] + } + ) # Re-check if berry is used, find a ball for a good capture rate current_type=pokeball @@ -203,12 +292,15 @@ def work(self, response_dict=None): items_stock[pokeball] -= 1 success_percentage = '{0:.2f}'.format(catch_rate[pokeball - 1] * 100) - logger.log('Using {} (chance: {}%)... ({} left!)'.format( - self.item_list[str(pokeball)], - success_percentage, - items_stock[pokeball] - )) - + self.emit_event( + 'threw_pokeball', + formatted='Used {pokeball}, with chance {success_percentage} ({count_left} left)', + data={ + 'pokeball': self.item_list[str(pokeball)], + 'success_percentage': success_percentage, + 'count_left': items_stock[pokeball] + } + ) id_list1 = self.count_pokemon_inventory() reticle_size_parameter = normalized_reticle_size(self.config.catch_randomize_reticle_factor) @@ -231,26 +323,35 @@ def work(self, response_dict=None): status = response_dict['responses'][ 'CATCH_POKEMON']['status'] if status is 2: - logger.log( - '[-] Attempted to capture {} - failed.. trying again!'.format(pokemon_name), - 'red') + self.emit_event( + 'pokemon_fled', + formatted="{pokemon} fled.", + data={'pokemon': pokemon_name} + ) sleep(2) continue if status is 3: - logger.log( - 'Oh no! {} vanished! :('.format(pokemon_name), 'red') + self.emit_event( + 'pokemon_vanished', + formatted="{pokemon} vanished!", + data={'pokemon': pokemon_name} + ) if success_percentage == 100: self.softban = True if status is 1: self.bot.metrics.captured_pokemon(pokemon_name, cp, iv_display, pokemon_potential) - logger.log('Captured {}! [CP {}] [Potential {}] [{}] [+{} exp]'.format( - pokemon_name, - cp, - pokemon_potential, - iv_display, - sum(response_dict['responses']['CATCH_POKEMON']['capture_award']['xp']) - ), 'blue') + self.emit_event( + 'pokemon_caught', + formatted='Captured {pokemon}! [CP {cp}] [Potential {iv}] [{iv_display}] [+{exp} exp]', + data={ + 'pokemon': pokemon_name, + 'cp': cp, + 'iv': pokemon_potential, + 'iv_display': iv_display, + 'exp': sum(response_dict['responses']['CATCH_POKEMON']['capture_award']['xp']) + } + ) self.bot.softban = False if (self.config.evolve_captured @@ -267,11 +368,17 @@ def work(self, response_dict=None): response_dict = self.api.evolve_pokemon(pokemon_id=pokemon_to_transfer[0]) status = response_dict['responses']['EVOLVE_POKEMON']['result'] if status == 1: - logger.log( - '{} has been evolved!'.format(pokemon_name), 'green') + self.emit_event( + 'pokemon_evolved', + formatted="{pokemon} evolved!", + data={'pokemon': pokemon_name} + ) else: - logger.log( - 'Failed to evolve {}!'.format(pokemon_name)) + self.emit_event( + 'pokemon_evolve_fail', + formatted="Failed to evolve {pokemon}!", + data={'pokemon': pokemon_name} + ) break time.sleep(5) @@ -346,15 +453,6 @@ def should_capture_pokemon(self, pokemon_name, cp, iv, response_dict): 'and': lambda x, y: x and y } - # logger.log( - # "Catch config for {}: CP {} {} IV {}".format( - # pokemon_name, - # catch_cp, - # cp_iv_logic, - # catch_iv - # ), 'yellow' - # ) - return logic_to_function[cp_iv_logic](*catch_results.values()) def _get_catch_config_for(self, pokemon): @@ -419,4 +517,3 @@ def check_vip_pokemon(self,pokemon, cp, iv): 'and': lambda x, y: x and y } return logic_to_function[cp_iv_logic](*catch_results.values()) - diff --git a/pokemongo_bot/cell_workers/recycle_items.py b/pokemongo_bot/cell_workers/recycle_items.py index 022a711f1a..c28b2749b1 100644 --- a/pokemongo_bot/cell_workers/recycle_items.py +++ b/pokemongo_bot/cell_workers/recycle_items.py @@ -1,6 +1,5 @@ import json import os -from pokemongo_bot import logger from pokemongo_bot.cell_workers.base_task import BaseTask from pokemongo_bot.tree_config_builder import ConfigException @@ -37,11 +36,23 @@ def work(self): result = response_dict_recycle.get('responses', {}).get('RECYCLE_INVENTORY_ITEM', {}).get('result', 0) if result == 1: # Request success - message_template = "-- Discarded {}x {} (keeps only {} maximum) " - message = message_template.format(str(items_recycle_count), item_name, str(id_filter_keep)) - logger.log(message, 'green') + self.emit_event( + 'item_discarded', + formatted='Discarded {amount}x {item} (maximum {maximum}).', + data={ + 'amount': str(items_recycle_count), + 'item': item_name, + 'maximum': str(id_filter_keep) + } + ) else: - logger.log("-- Failed to discard " + item_name, 'red') + self.emit_event( + 'item_discard_fail', + formatted="Failed to discard {item}", + data={ + 'item': item_name + } + ) def send_recycle_item_request(self, item_id, count): # Example of good request response diff --git a/pokemongo_bot/cell_workers/sleep_schedule.py b/pokemongo_bot/cell_workers/sleep_schedule.py index 221867f0e6..daaf0b8f1e 100644 --- a/pokemongo_bot/cell_workers/sleep_schedule.py +++ b/pokemongo_bot/cell_workers/sleep_schedule.py @@ -1,7 +1,6 @@ from datetime import datetime, timedelta from time import sleep from random import uniform -from pokemongo_bot import logger from pokemongo_bot.cell_workers.base_task import BaseTask @@ -63,7 +62,13 @@ def _process_config(self): def _schedule_next_sleep(self): self._next_sleep = self._get_next_sleep_schedule() self._next_duration = self._get_next_duration() - logger.log('SleepSchedule: next sleep at {}'.format(str(self._next_sleep)), color='green') + self.emit_event( + 'next_sleep', + formatted="Next sleep at {time}", + data={ + 'time': str(self._next_sleep) + } + ) def _get_next_sleep_schedule(self): now = datetime.now() + self.SCHEDULING_MARGIN @@ -87,9 +92,14 @@ def _get_random_offset(self, max_offset): def _sleep(self): sleep_to_go = self._next_duration - logger.log('It\'s time for sleep.') + self.emit_event( + 'bot_sleep', + formatted="Sleeping for {time_in_seconds}", + data={ + 'time_in_seconds': sleep_to_go + } + ) while sleep_to_go > 0: - logger.log('Sleeping for {} more seconds'.format(sleep_to_go), 'yellow') if sleep_to_go < self.LOG_INTERVAL_SECONDS: sleep(sleep_to_go) sleep_to_go = 0 diff --git a/pokemongo_bot/cell_workers/spin_fort.py b/pokemongo_bot/cell_workers/spin_fort.py index f34fc2b8ef..9572008241 100644 --- a/pokemongo_bot/cell_workers/spin_fort.py +++ b/pokemongo_bot/cell_workers/spin_fort.py @@ -1,10 +1,10 @@ # -*- coding: utf-8 -*- +from __future__ import unicode_literals import time from pgoapi.utilities import f2i -from pokemongo_bot import logger from pokemongo_bot.constants import Constants from pokemongo_bot.human_behaviour import sleep from pokemongo_bot.worker_result import WorkerResult @@ -15,7 +15,10 @@ class SpinFort(BaseTask): def should_run(self): if not self.bot.has_space_for_loot(): - logger.log("Not spinning any forts as there aren't enough space. You might want to change your config to recycle more items if this message appears consistently.", 'yellow') + self.emit_event( + 'inventory_full', + formatted="Not moving to any forts as there aren't enough space. You might want to change your config to recycle more items if this message appears consistently." + ) return False return True @@ -29,9 +32,7 @@ def work(self): lng = fort['longitude'] details = fort_details(self.bot, fort['id'], lat, lng) - fort_name = details.get('name', 'Unknown').encode('utf8', 'replace') - logger.log('Now at Pokestop: {0}'.format(fort_name), 'cyan') - logger.log('Spinning ...', 'cyan') + fort_name = details.get('name', 'Unknown') response_dict = self.bot.api.fort_search( fort_id=fort['id'], @@ -47,69 +48,86 @@ def work(self): spin_result = spin_details.get('result', -1) if spin_result == 1: self.bot.softban = False - logger.log("Loot: ", 'green') - experience_awarded = spin_details.get('experience_awarded', - False) - if experience_awarded: - logger.log(str(experience_awarded) + " xp", - 'green') - - items_awarded = spin_details.get('items_awarded', False) + experience_awarded = spin_details.get('experience_awarded', 0) + items_awarded = spin_details.get('items_awarded', {}) if items_awarded: self.bot.latest_inventory = None tmp_count_items = {} for item in items_awarded: item_id = item['item_id'] - if not item_id in tmp_count_items: - tmp_count_items[item_id] = item['item_count'] - else: - tmp_count_items[item_id] += item['item_count'] - - for item_id, item_count in tmp_count_items.iteritems(): item_name = self.bot.item_list[str(item_id)] - logger.log( - '- ' + str(item_count) + "x " + item_name + - " (Total: " + str(self.bot.item_inventory_count(item_id)) + ")", 'yellow' - ) + if not item_name in tmp_count_items: + tmp_count_items[item_name] = item['item_count'] + else: + tmp_count_items[item_name] += item['item_count'] + + if experience_awarded or items_awarded: + self.emit_event( + 'spun_pokestop', + formatted="Spun pokestop {pokestop}. Experience awarded: {exp}. Items awarded: {items}", + data={ + 'pokestop': fort_name, + 'exp': experience_awarded, + 'items': tmp_count_items + } + ) else: - logger.log("[#] Nothing found.", 'yellow') - + self.emit_event( + 'pokestop_empty', + formatted='Found nothing in pokestop {pokestop}.', + data={'pokestop': fort_name} + ) pokestop_cooldown = spin_details.get( 'cooldown_complete_timestamp_ms') self.bot.fort_timeouts.update({fort["id"]: pokestop_cooldown}) - if pokestop_cooldown: - seconds_since_epoch = time.time() - logger.log('PokeStop on cooldown. Time left: ' + str( - format_time((pokestop_cooldown / 1000) - - seconds_since_epoch))) - self.bot.recent_forts = self.bot.recent_forts[1:] + [fort['id']] elif spin_result == 2: - logger.log("[#] Pokestop out of range") + self.emit_event( + 'pokestop_out_of_range', + formatted="Pokestop {pokestop} out of range.", + data={'pokestop': fort_name} + ) elif spin_result == 3: pokestop_cooldown = spin_details.get( 'cooldown_complete_timestamp_ms') if pokestop_cooldown: self.bot.fort_timeouts.update({fort["id"]: pokestop_cooldown}) seconds_since_epoch = time.time() - logger.log('PokeStop on cooldown. Time left: ' + str( - format_time((pokestop_cooldown / 1000) - - seconds_since_epoch))) + minutes_left = format_time( + (pokestop_cooldown / 1000) - seconds_since_epoch + ) + self.emit_event( + 'pokestop_on_cooldown', + formatted="Pokestop {pokestop} on cooldown. Time left: {minutes_left}.", + data={'pokestop': fort_name, 'minutes_left': minutes_left} + ) elif spin_result == 4: - logger.log("Inventory is full", 'red') + self.emit_event( + 'inventory_full', + formatted="Inventory is full!" + ) else: - logger.log("Unknown spin result: " + str(spin_result), 'red') - + self.emit_event( + 'unknown_spin_result', + formatted="Unknown spint result {status_code}", + data={'status_code': str(spin_result)} + ) if 'chain_hack_sequence_number' in response_dict['responses'][ 'FORT_SEARCH']: time.sleep(2) return response_dict['responses']['FORT_SEARCH'][ 'chain_hack_sequence_number'] else: - logger.log('Possibly searching too often - taking a short rest :)', 'yellow') + self.emit_event( + 'pokestop_searching_too_often', + formatted="Possibly searching too often, take a rest." + ) if spin_result == 1 and not items_awarded and not experience_awarded and not pokestop_cooldown: self.bot.softban = True - logger.log('[!] Possibly got softban too...', 'red') + self.emit_event( + 'softban', + formatted='Probably got softban.' + ) else: self.bot.fort_timeouts[fort["id"]] = (time.time() + 300) * 1000 # Don't spin for 5m return 11 diff --git a/pokemongo_bot/cell_workers/transfer_pokemon.py b/pokemongo_bot/cell_workers/transfer_pokemon.py index 374ffa6a87..70c5939c58 100644 --- a/pokemongo_bot/cell_workers/transfer_pokemon.py +++ b/pokemongo_bot/cell_workers/transfer_pokemon.py @@ -1,9 +1,9 @@ import json -from pokemongo_bot import logger from pokemongo_bot.human_behaviour import action_delay from pokemongo_bot.cell_workers.base_task import BaseTask + class TransferPokemon(BaseTask): def work(self): pokemon_groups = self._release_pokemon_get_groups() @@ -41,6 +41,17 @@ def work(self): all_pokemons.remove(pokemon) best_pokemons.append(pokemon) + if best_pokemons and all_pokemons: + self.emit_event( + 'keep_best_release', + formatted="Keeping best {amount} {pokemon}, based on {criteria}", + data={ + 'amount': len(best_pokemons), + 'pokemon': pokemon_name, + 'criteria': order_criteria + } + ) + transfer_pokemons = [pokemon for pokemon in all_pokemons if self.should_release_pokemon(pokemon_name, pokemon['cp'], @@ -48,16 +59,6 @@ def work(self): True)] if transfer_pokemons: - logger.log("Keep {} best {}, based on {}".format(len(best_pokemons), - pokemon_name, - order_criteria), "green") - for best_pokemon in best_pokemons: - logger.log("{} [CP {}] [Potential {}]".format(pokemon_name, - best_pokemon['cp'], - best_pokemon['iv']), 'green') - - logger.log("Transferring {} pokemon".format(len(transfer_pokemons)), "green") - for pokemon in transfer_pokemons: self.release_pokemon(pokemon_name, pokemon['cp'], pokemon['iv'], pokemon['pokemon_data']['id']) else: @@ -167,24 +168,32 @@ def should_release_pokemon(self, pokemon_name, cp, iv, keep_best_mode = False): } if logic_to_function[cp_iv_logic](*release_results.values()): - logger.log( - "Releasing {} with CP {} and IV {}. Matching release rule: CP < {} {} IV < {}. ".format( - pokemon_name, - cp, - iv, - release_cp, - cp_iv_logic.upper(), - release_iv - ), 'yellow' + self.emit_event( + 'future_pokemon_release', + formatted="Releasing {pokemon} (CP {cp}/IV {iv}) based on rule: CP < {below_cp} {cp_iv_logic} IV < {below_iv}", + data={ + 'pokemon': pokemon_name, + 'cp': cp, + 'iv': iv, + 'below_cp': release_cp, + 'cp_iv_logic': cp_iv_logic.upper(), + 'below_iv': release_iv + } ) return logic_to_function[cp_iv_logic](*release_results.values()) def release_pokemon(self, pokemon_name, cp, iv, pokemon_id): - logger.log('Exchanging {} [CP {}] [Potential {}] for candy!'.format(pokemon_name, - cp, - iv), 'green') response_dict = self.bot.api.release_pokemon(pokemon_id=pokemon_id) + self.emit_event( + 'pokemon_release', + formatted='Exchanged {pokemon} [CP {cp}] [IV {iv}] for candy.', + data={ + 'pokemon': pokemon_name, + 'cp': cp, + 'iv': iv + } + ) action_delay(self.bot.config.action_wait_min, self.bot.config.action_wait_max) def _get_release_config_for(self, pokemon): @@ -216,7 +225,6 @@ def _validate_keep_best_config(self, pokemon_name): keep_best_iv = 0 if keep_best_cp < 0 or keep_best_iv < 0: - logger.log("Keep best can't be < 0. Ignore it.", "red") keep_best = False if keep_best_cp == 0 and keep_best_iv == 0: diff --git a/pokemongo_bot/event_handlers/logging_handler.py b/pokemongo_bot/event_handlers/logging_handler.py index c54f435e19..7ad5720f6a 100644 --- a/pokemongo_bot/event_handlers/logging_handler.py +++ b/pokemongo_bot/event_handlers/logging_handler.py @@ -1,13 +1,18 @@ +# -*- coding: utf-8 -*- +from __future__ import unicode_literals + + import logging from pokemongo_bot.event_manager import EventHandler class LoggingHandler(EventHandler): + def handle_event(self, event, sender, level, formatted_msg, data): logger = logging.getLogger(type(sender).__name__) if formatted_msg: - message = formatted_msg + message = "[{}] {}".format(event, formatted_msg) else: message = '{}: {}'.format(event, str(data)) getattr(logger, level)(message) diff --git a/pokemongo_bot/event_handlers/socketio_handler.py b/pokemongo_bot/event_handlers/socketio_handler.py index 3c850ca4c4..05b095313a 100644 --- a/pokemongo_bot/event_handlers/socketio_handler.py +++ b/pokemongo_bot/event_handlers/socketio_handler.py @@ -1,3 +1,7 @@ +# -*- coding: utf-8 -*- +from __future__ import unicode_literals + + from socketIO_client import SocketIO from pokemongo_bot.event_manager import EventHandler @@ -6,19 +10,21 @@ class SocketIoHandler(EventHandler): - def __init__(self, url): - super(EventHandler, self).__init__() + def __init__(self, bot, url): + self.bot = bot self.host, port_str = url.split(':') self.port = int(port_str) + self.sio = SocketIO(self.host, self.port) def handle_event(self, event, sender, level, msg, data): if msg: - date['msg'] = msg - with SocketIO(self.host, self.port) as sio: - sio.emit( - 'bot:broadcast', - { - 'event': event, - 'data': data, - } - ) + data['msg'] = msg + + self.sio.emit( + 'bot:broadcast', + { + 'event': event, + 'account': self.bot.config.username, + 'data': data + } + ) diff --git a/pokemongo_bot/event_manager.py b/pokemongo_bot/event_manager.py index 9af63690e6..3773ec8a9e 100644 --- a/pokemongo_bot/event_manager.py +++ b/pokemongo_bot/event_manager.py @@ -1,3 +1,7 @@ +# -*- coding: utf-8 -*- +from __future__ import unicode_literals + + class EventNotRegisteredException(Exception): pass @@ -7,6 +11,7 @@ class EventMalformedException(Exception): class EventHandler(object): + def __init__(self): pass @@ -15,17 +20,27 @@ def handle_event(self, event, kwargs): class EventManager(object): + def __init__(self, *handlers): self._registered_events = dict() self._handlers = handlers or [] + def event_report(self): + for event, parameters in self._registered_events.iteritems(): + print '-'*80 + print 'Event: {}'.format(event) + if parameters: + print 'Parameters:' + for parameter in parameters: + print '* {}'.format(parameter) + def add_handler(self, event_handler): self._handlers.append(event_handler) - def register_event(self, name, parameters=None): + def register_event(self, name, parameters=[]): self._registered_events[name] = parameters - def emit(self, event, sender=None, level='info', formatted=None, data={}): + def emit(self, event, sender=None, level='info', formatted='', data={}): if not sender: raise ArgumentError('Event needs a sender!') @@ -38,9 +53,10 @@ def emit(self, event, sender=None, level='info', formatted=None, data={}): # verify params match event parameters = self._registered_events[event] - for k, v in data.iteritems(): - if k not in parameters: - raise EventMalformedException("Event %s does not require parameter %s" % (event, k)) + if parameters: + for k, v in data.iteritems(): + if k not in parameters: + raise EventMalformedException("Event %s does not require parameter %s" % (event, k)) formatted_msg = formatted.format(**data) diff --git a/pokemongo_bot/health_record/bot_event.py b/pokemongo_bot/health_record/bot_event.py index dad0b49c42..3160593251 100644 --- a/pokemongo_bot/health_record/bot_event.py +++ b/pokemongo_bot/health_record/bot_event.py @@ -1,25 +1,26 @@ # -*- coding: utf-8 -*- +import logging + from time import sleep from UniversalAnalytics import Tracker -from pokemongo_bot import logger - class BotEvent(object): def __init__(self, bot): self.bot = bot + self.logger = logging.getLogger(__name__) # UniversalAnalytics can be reviewed here: # https://github.com/analytics-pros/universal-analytics-python # For central TensorFlow training, forbiden any personally information # report to server # Review Very Carefully for the following line, forbiden ID changed PR: if bot.config.health_record: - logger.log( + logger.info( 'Send anonymous bot health report to server, ' 'it can be disabled by config \"health_record\":false in config file', 'red' ) - logger.log('Wait for 2 seconds ', 'red') + logger.info('Wait for 2 seconds ', 'red') sleep(3) self.tracker = Tracker.create('UA-81469507-1', use_post=True) diff --git a/pokemongo_bot/logger.py b/pokemongo_bot/logger.py index 36c99c92f5..ebb59b7599 100644 --- a/pokemongo_bot/logger.py +++ b/pokemongo_bot/logger.py @@ -1,36 +1,20 @@ -from __future__ import unicode_literals -import time +import warnings +import logging -try: - import lcd - lcd = lcd.lcd() - # Change this to your i2c address - lcd.set_addr(0x23) -except Exception: - lcd = False +def log(msg, color=None): + warnings.simplefilter('always', DeprecationWarning) + message = ( + "Using logger.log is deprecated and will be removed soon. " + "We recommend that you try to log as little as possible " + "and use the event system to send important messages " + "(they become logs and websocket messages) automatically). " + "If you don't think your message should go to the websocket " + "server but it's really necessary, use the self.logger variable " + "inside any class inheriting from BaseTask to log." -def log(string, color='white'): - color_hex = { - 'red': '91m', - 'green': '92m', - 'yellow': '93m', - 'blue': '94m', - 'cyan': '96m' - } - if color not in color_hex: - print('[{time}] {string}'.format( - time=time.strftime("%H:%M:%S"), - string=string.decode('utf-8') - )) - else: - print( - '[{time}] \033[{color} {string} \033[0m'.format( - time=time.strftime("%H:%M:%S"), - color=color_hex[color], - string=string.decode('utf-8') - ) - ) - if lcd: - if string: - lcd.message(string) + ) + + logger = logging.getLogger('generic') + logger.info(msg) + warnings.warn(message, DeprecationWarning) diff --git a/pokemongo_bot/socketio_server/app.py b/pokemongo_bot/socketio_server/app.py index 4aac36c202..09c237f910 100644 --- a/pokemongo_bot/socketio_server/app.py +++ b/pokemongo_bot/socketio_server/app.py @@ -3,32 +3,30 @@ import socketio from flask import Flask -from pokemongo_bot.event_handlers import LoggingHandler -from pokemongo_bot.event_manager import EventManager sio = socketio.Server(async_mode='eventlet', logging=logging.NullHandler) app = Flask(__name__) -event_manager = EventManager() -event_manager.add_handler(LoggingHandler()) -event_manager.register_event( - "websocket_client_connected", -) - # client asks for data @sio.on('remote:send_request') def remote_control(sid, command): - sio.emit('bot:process_request', data=command) + if not 'account' in command: + return False + bot_name = command.pop('account') + event = 'bot:process_request:{}'.format(bot_name) + sio.emit(event, data=command) # sending bot response to client @sio.on('bot:send_reply') def request_reply(sid, response): - sio.emit(response['command'], response['response']) + event = response.pop('command') + account = response.pop('account') + event = "{}:{}".format(event, account) + sio.emit(event, response) @sio.on('bot:broadcast') def bot_broadcast(sid, env): - sio.emit(env['event'], data=env['data']) - -@sio.on('disconnect') -def disconnect(sid): - print('disconnect ', sid) + event = env.pop('event') + account = env.pop('account') + event_name = "{}:{}".format(event, account) + sio.emit(event_name, data=env['data']) diff --git a/pokemongo_bot/test/follow_cluster_test.py b/pokemongo_bot/test/follow_cluster_test.py index b44cbfc16a..4820a7558a 100644 --- a/pokemongo_bot/test/follow_cluster_test.py +++ b/pokemongo_bot/test/follow_cluster_test.py @@ -15,7 +15,11 @@ def testWorkAway(self, mock_pokemongo_bot): mock_pokemongo_bot.config.walk = 4.16 mock_pokemongo_bot.get_forts.return_value = ex_forts follow_cluster = FollowCluster(mock_pokemongo_bot, config) - assert follow_cluster.work() == [37.39718375014263, -5.9932912500000013] + + expected = (37.397183750142624, -5.9932912500000013) + result = follow_cluster.work() + self.assertAlmostEqual(expected[0], result[0], delta=0.000000000010000) + self.assertAlmostEqual(expected[1], result[1], delta=0.000000000010000) assert follow_cluster.is_at_destination == False assert follow_cluster.announced == False @@ -29,6 +33,10 @@ def testWorkArrived(self, mock_pokemongo_bot): mock_pokemongo_bot.config.walk = 4.16 mock_pokemongo_bot.get_forts.return_value = ex_forts follow_cluster = FollowCluster(mock_pokemongo_bot, config) - assert follow_cluster.work() == [37.39718375014263, -5.9932912500000013] + + expected = (37.397183750142624, -5.9932912500000013) + result = follow_cluster.work() + self.assertAlmostEqual(expected[0], result[0], delta=0.000000000010000) + self.assertAlmostEqual(expected[1], result[1], delta=0.000000000010000) assert follow_cluster.is_at_destination == True assert follow_cluster.announced == False diff --git a/pokemongo_bot/walkers/polyline_walker.py b/pokemongo_bot/walkers/polyline_walker.py index 001b7c77cf..687371e866 100644 --- a/pokemongo_bot/walkers/polyline_walker.py +++ b/pokemongo_bot/walkers/polyline_walker.py @@ -1,6 +1,5 @@ # -*- coding: utf-8 -*- -from pokemongo_bot import logger from pokemongo_bot.human_behaviour import sleep from pokemongo_bot.step_walker import StepWalker from polyline_generator import Polyline @@ -12,7 +11,13 @@ def __init__(self, bot, speed, dest_lat, dest_lng): super(PolylineWalker, self).__init__(bot, speed, dest_lat, dest_lng) self.polyline_walker = Polyline((self.api._position_lat, self.api._position_lng), (self.destLat, self.destLng), self.speed) - logger.log('[#] {}'.format(self.polyline_walker.URL)) + self.bot.event_manager.emit( + 'polyline_request', + sender=self, + level='info', + formatted="{url}", + data={'url': self.polyline_walker.URL} + ) def step(self): cLat, cLng = self.api._position_lat, self.api._position_lng diff --git a/pokemongo_bot/websocket_remote_control.py b/pokemongo_bot/websocket_remote_control.py index cd8e04e0fe..c4e15362b6 100644 --- a/pokemongo_bot/websocket_remote_control.py +++ b/pokemongo_bot/websocket_remote_control.py @@ -10,7 +10,10 @@ def __init__(self, bot): self.host, port_str = self.bot.config.websocket_server_url.split(':') self.port = int(port_str) self.sio = SocketIO(self.host, self.port) - self.sio.on('bot:process_request', self.on_remote_command) + self.sio.on( + 'bot:process_request:{}'.format(self.bot.config.username), + self.on_remote_command + ) self.thread = threading.Thread(target=self.process_messages) def start(self): @@ -28,7 +31,8 @@ def on_remote_command(self, command): 'bot:send_reply', { 'response': '', - 'command': 'command_not_found' + 'command': 'command_not_found', + 'account': self.bot.config.username } ) return @@ -42,7 +46,8 @@ def get_player_info(self): self.sio.emit( 'bot:send_reply', { - 'response': player_info, - 'command': 'get_player_info' + 'result': player_info, + 'command': 'get_player_info', + 'account': self.bot.config.username } ) diff --git a/tests/__init__.py b/tests/__init__.py index 5318e2d482..c02aed60fc 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -1,6 +1,7 @@ # __init__.py from mock import MagicMock +from pokemongo_bot.event_manager import EventManager from pokemongo_bot.api_wrapper import ApiWrapper, ApiRequest from pokemongo_bot import PokemonGoBot @@ -13,8 +14,10 @@ def create_request(self, return_value='mock return'): class FakeBot(PokemonGoBot): def __init__(self): - self.config = MagicMock() + self.config = MagicMock(websocket_server_url=False, show_events=False) self.api = FakeApi() + self.event_manager = EventManager() + self._setup_event_system() def updateConfig(self, conf): self.config.__dict__.update(conf) diff --git a/ws_server.py b/ws_server.py new file mode 100755 index 0000000000..85d6bb3a01 --- /dev/null +++ b/ws_server.py @@ -0,0 +1,26 @@ +#!/usr/bin/env python +# -*- coding: utf-8 - + +import argparse + +from pokemongo_bot.socketio_server.runner import SocketIoRunner + + +if __name__ == '__main__': + parser = argparse.ArgumentParser() + parser.add_argument( + "--host", + help="Host for the websocket", + type=str, + default='localhost' + ) + parser.add_argument( + "--port", + help="Port for the websocket", + type=int, + default=4000 + ) + config = parser.parse_known_args()[0] + + s = SocketIoRunner("{}:{}".format(config.host, config.port)) + s._start_listening_blocking()