Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bot very slow with "enable_social:true" #5216

Closed
dragonalvaro opened this issue Sep 5, 2016 · 8 comments
Closed

Bot very slow with "enable_social:true" #5216

dragonalvaro opened this issue Sep 5, 2016 · 8 comments
Labels
Help to Test Needs More Information

Comments

@dragonalvaro
Copy link

dragonalvaro commented Sep 5, 2016 •
edited
Loading

Just clone the bot again since weeks. When I started it takes like hours to start doing something. I ran the script at 14:39 and it is 15:51 and just showed "Starting bot" message.

It's a desktop computer with i7 Skylake, 16 Gb ram and business bandwith. PokeMap runs fine in the same machine.

Take a look at the log time entries

2016-09-05 14:39:30,167 [ cli] [INFO] PokemonGO Bot v1.0
2016-09-05 14:39:30,171 [ cli] [INFO] commit: ca94424
2016-09-05 14:39:30,173 [ cli] [INFO] Configuration initialized
2016-09-05 14:39:30,173 [pokemongo_bot.health_record.bot_event] [INFO] Health check is enabled. For more information:
2016-09-05 14:39:30,173 [pokemongo_bot.health_record.bot_event] [INFO] https://github.com/PokemonGoF/PokemonGo-Bot/tree/dev#analytics
2016-09-05 14:39:30,177 [requests.packages.urllib3.connectionpool] [INFO] Starting new HTTP connection (1): www.google-analytics.com
(3170) wsgi starting up on http://127.0.0.1:4000
2016-09-05 14:39:30,267 [requests.packages.urllib3.connectionpool] [INFO] Starting new HTTP connection (1): 127.0.0.1
[2016-09-05 14:39:30] [SleepSchedule] [INFO] [next_sleep] Next sleep at 18:15:28, for a duration of 2:32:10
[2016-09-05 14:41:37] [PokemonGoBot] [INFO] [set_start_location] Setting start location.
[2016-09-05 14:43:44] [PokemonGoBot] [INFO] [x] Coordinates found in passed in location, not geocoding.
[2016-09-05 14:43:44] [PokemonGoBot] [INFO] [location_found] Location found: 42.578389, -10.616962 (46.558389, -3.616962, 8.0)
[2016-09-05 14:45:52] [PokemonGoBot] [INFO] [position_update] Now at (42.578389, -10.66962, 8.0)
[2016-09-05 14:52:13] [PokemonGoBot] [INFO] [login_started] Login procedure started.
[2016-09-05 14:54:22] [PokemonGoBot] [INFO] [login_successful] Login successful.
[2016-09-05 14:56:30] [PokemonGoBot] [INFO] Found encrypt.so! Platform: linux2 encrypt.so directory: /home/alvaro/Pokemon/PokemonGo-Bot
[2016-09-05 14:56:30] [PokemonGoBot] [INFO]
[2016-09-05 15:45:17] [PokemonGoBot] [INFO] [x] Error while opening cached forts: [Errno 2] No such file or directory: u'/home/alvaro/Pokemon/PokemonGo-Bot/pokemongo_bot/../data/recent-forts-dragonalvaro11.json'
[2016-09-05 15:47:25] [PokemonGoBot] [INFO] No inventory file /home/alvaro/Pokemon/PokemonGo-Bot/pokemongo_bot/../web/inventory-dragonalvaro11.json found. Creating a new one
[2016-09-05 15:47:25] [PokemonGoBot] [INFO] Level: 1 (Next Level: 400 XP) (Total: 600 XP)
[2016-09-05 15:47:25] [PokemonGoBot] [INFO] Pokemon Captured: 1 | Pokestops Visited: 0
[2016-09-05 15:47:26] [PokemonGoBot] [INFO]
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] --- trainername ---
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] Pokemon Bag: 1/250
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] Items: 54/350
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] Stardust: 100 | Pokecoins: 0
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] PokeBalls: 50 | GreatBalls: 0 | UltraBalls: 0 | MasterBalls: 0
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] RazzBerries: 0 | BlukBerries: 0 | NanabBerries: 0
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] LuckyEgg: 0 | Incubator: 0 | TroyDisk: 0
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] Potion: 0 | SuperPotion: 0 | HyperPotion: 0 | MaxPotion: 0
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] Incense: 2 | IncenseSpicy: 0 | IncenseCool: 0
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] Revive: 0 | MaxRevive: 0
[2016-09-05 15:47:26] [PokemonGoBot] [INFO]
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] Pokemon:
[2016-09-05 15:47:26] [PokemonGoBot] [INFO] #4 Charmander: (CP 12, IV 0.67)
[2016-09-05 15:47:26] [PokemonGoBot] [INFO]
[2016-09-05 15:47:26] [RandomAlivePause] [INFO] [next_random_alive_pause] Next random alive pause at 16:50:13, for a duration of 0:07:22
[2016-09-05 15:49:34] [RandomPause] [INFO] [next_random_pause] Next random pause at 17:45:55, for a duration of 0:05:47
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Applying catch_log
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] - applying step 0
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Marking catch_log applied
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Applying evolve_log
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] - applying step 0
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Marking evolve_log applied
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Applying pokestop_log
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] - applying step 0
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Marking pokestop_log applied
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Applying softban_log
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] - applying step 0
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Marking softban_log applied
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Applying transfer_log
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] - applying step 0
[2016-09-05 15:51:41] [yoyo.migrations] [INFO] Marking transfer_log applied
[2016-09-05 15:51:42] [RecycleItems] [INFO] [next_force_recycle] Next forced item recycle at 15:53:25
[2016-09-05 15:53:51] [pokemongo_bot.health_record.bot_event] [INFO] Health check is enabled. For more information:
[2016-09-05 15:53:51] [pokemongo_bot.health_record.bot_event] [INFO] https://github.com/PokemonGoF/PokemonGo-Bot/tree/dev#analytics
[2016-09-05 15:53:51] [PokemonGoBot] [INFO] [bot_start] Starting bot...
@db-coder
Copy link

db-coder commented Sep 5, 2016

In config.json, try doing "enable_social": false

@dragonalvaro
Copy link
Author

Yep. That worked, thanks.
Whats wrong with that parameter?

@db-coder
Copy link

db-coder commented Sep 5, 2016

No clue, I just know that disabling it works.
Maybe, keep this issue open so that some dev can look into it.

@dragonalvaro dragonalvaro changed the title Bot so slow Bot very slow with "enable_social:true" Sep 5, 2016
@db-coder
Copy link

db-coder commented Sep 5, 2016

#4790 this has some more logs...

@Gobberwart
Copy link
Contributor

Gobberwart commented Sep 5, 2016 •
edited
Loading

@dragonalvaro Could you (or anyone else having this issue) please edit the file pokemongo_bot\event_handlers\social_handler.py and at line 11 change "DEBUG_ON = False" to "DEBUG_ON = True" then restart the bot and paste the results. You'll get a LOT of info unfortunately, but it might tell us what's happening during these big gaps.

@Gobberwart
Copy link
Contributor

Gobberwart commented Sep 5, 2016 •
edited
Loading

IMHO social_handler.py could use a complete rewrite. For example:

  • Why does a new MQTT object need to be instantiated, reconnect etc. every time it's called? Surely we should have a single object that connects once and then can be reused for future requests (reconnecting if it's ever necessary).
  • Why all those "if DEBUG_ON: print whatever" lines? Can't we use the global debug flag, and the logger?
  • If there are any errors that can't be overcome (eg. can't connect to broker.pikabot.org:1883), MQTT should stop trying, at least for a little while, instead of continually retrying the same request ad infinitum. Pretty sure that's the definition of insanity (repeating the same thing over and over, expecting different results).
  • Why does social_handler constantly retrieve pokemon data? Sounds like overkill to me given that a spawned pokemon generally has a TTL of at least a few minutes. Even when connection attempt succeeds, the bot is spending almost all its time handling mqttc requests.
  • MoveToMapPokemon requires enable_social:true to work properly, but that's unclear. If enable_social:false, continual cryptic error messages are shown eg. "[MoveToMapPokemon] [INFO] Failure! Could not update trainer location PokemonGo-Map: http://localhost:5000. Is it running?"

@dragonalvaro
Copy link
Author

@Gobberwart here is the trace

Maybe my network is blocking some connections

2016-09-06 09:11:57,166 [ cli] [INFO] PokemonGO Bot v1.0
2016-09-06 09:11:57,169 [ cli] [INFO] commit: f543e3d
2016-09-06 09:11:57,171 [ cli] [INFO] Configuration initialized
2016-09-06 09:11:57,171 [pokemongo_bot.health_record.bot_event] [INFO] Health check is enabled. For more information:
2016-09-06 09:11:57,171 [pokemongo_bot.health_record.bot_event] [INFO] https://github.com/PokemonGoF/PokemonGo-Bot/tree/dev#analytics
2016-09-06 09:11:57,174 [requests.packages.urllib3.connectionpool] [INFO] Starting new HTTP connection (1): www.google-analytics.com
(17751) wsgi starting up on http://127.0.0.1:4000
2016-09-06 09:11:57,234 [requests.packages.urllib3.connectionpool] [INFO] Starting new HTTP connection (1): 127.0.0.1
[2016-09-06 09:11:57] [SleepSchedule] [INFO] Next sleep at 11:58:48, for a duration of 5:20:46
need connect
connect again
[2016-09-06 09:14:04] [PokemonGoBot] [INFO] Setting start location.
need connect
connect again
[2016-09-06 09:16:12] [PokemonGoBot] [INFO] [x] Coordinates found in passed in location, not geocoding.
[2016-09-06 09:16:12] [PokemonGoBot] [INFO] Location found: 40.536210, -3.631569 (40.53621, -3.631569, 8.0)
need connect
connect again
[2016-09-06 09:18:19] [PokemonGoBot] [INFO] Now at (40.53621, -3.631569, 8.0)
need connect
connect again
need connect
connect again
need connect
connect again
[2016-09-06 09:24:41] [PokemonGoBot] [INFO] Login procedure started.
need connect
connect again
[2016-09-06 09:26:50] [PokemonGoBot] [INFO] Login successful.
need connect
connect again
[2016-09-06 09:28:57] [PokemonGoBot] [INFO] Found encrypt.so! Platform: linux2 encrypt.so directory: /home/alvaro/Pokemon/PokemonGo-Bot
[2016-09-06 09:28:57] [PokemonGoBot] [INFO]
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again
need connect
connect again

@Gobberwart
Copy link
Contributor

Sounds like it. It's trying to make a connection to broker.pikabort.org port 1883. If your network is blocking that, you won't be able to use social.

@Gobberwart Gobberwart mentioned this issue Sep 6, 2016
Merged
@k4n30 k4n30 closed this as completed Oct 5, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Help to Test Needs More Information
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@k4n30 @sohje @dragonalvaro @db-coder @Gobberwart