Trezorro commented 3 years ago

We are running into a nasty issue after updating our (pipenv) virtual environment from Rlbot 1.48 to the newest release (1.54).

Context

For testing purposes, we use

from rlbot import runner
runner.main()

as well as some custom functionality build around it.

Our bot is a PythonHivemind (launched as a helper process).
This issue does not occur when launching our code via the GUI.
We do not have support_early_start enabled.

The Issue

Since the update, the packet that is passed to self.initialize_hive(packet) during bot startup is no longer valid. For instance, it has values:

num_boost:0
num_cars:0
num_teams:0
num_tiles:0

...instead of the expected values as read from the MatchConfig.
This call results in incorrect initialization of our bot and finally in fatal errors during calls to get_output()

We have attempted to debug the SetupManager/PythonHivemind/GameInterface, but it's hard.

The only workaround that we have found so far is:

check in initialize_hive "if packet.num_cars == 0: then skip initialize_hive's functionality".
During calls to get_outputs, return {index: PlayerInput() for index in self.drone_indices} until the input packet in the get_outputs call is finally a valid one (packet.num_cars != 0)
Then we retry a call to self.initialize_hive(packet).

Notes

This seems to be a bug somewhere in the game interface. We have also noticed, since the RLBot update, this change in the implementation of PythonHivemind. This bit of code is new:

# Line 67:
# Wait for legitimate field info
        while True:
            self.game_interface.update_field_info_packet(self._field_info)
            if self._field_info.num_goals > 0:
                break
            time.sleep(0.2)

Deleting this part doesn't solve our issue (as expected), but maybe this was an attempt to prevent it?

Conclusion

It definitely doesn't seem like intended behaviour. Why would you have to tell the game interface what your bot wants to do before the game's match is even properly populated?

ViliamVadocz commented 3 years ago

Thanks for the issue. This is a known bug in the framework and is affecting all bots, hivemind bots just don't recover. If you want to make a pull request with your workaround I would be willing to look at it. Sorry about the inconvenience!

Trezorro commented 3 years ago

I'll give that a go when I start working on this task again. Might take a week though :)

tarehart commented 3 years ago

I'm currently working on some changes to how matches are started, I can probably just fix this along the way.

tarehart commented 3 years ago

I'm having trouble reproducing this issue. Would you mind providing the log? Mine looks like this:

C:\Users\tareh\AppData\Local\Programs\Python\Python37\python.exe C:\Users\tareh\AppData\Local\JetBrains\Toolbox\apps\IDEA-U\ch-0\203.7148.57.plugins\python\helpers\pydev\pydevd.py --multiproc --qt-support=auto --client 127.0.0.1 --port 51815 --file C:/Users/tareh/code/RLBot/runner.py
Connected to pydev debugger (build 203.7148.57)
starting
           ______ _     ______       _
     10100 | ___ \ |    | ___ \     | |   00101
    110011 | |_/ / |    | |_/ / ___ | |_  110011
  00110110 |    /| |    | ___ \/ _ \| __| 01101100
    010010 | |\ \| |____| |_/ / (_) | |_  010010
     10010 \_| \_\_____/\____/ \___/ \__| 01001
Version 1.54.0
    Adding a version of the socket management util that uses asyncio.

Trouble? Ask on Discord at https://discord.gg/5cNbXgG or report an issue at https://github.com/RLBot/RLBot/issues
Launching RLBot binary with args ['C:\\Users\\tareh\\code\\RLBot\\src\\main\\python\\rlbot\\dll\\RLBot.exe', '23233', '127.0.0.1', '0']
2021-02-08 21:22:13,417 INFO:rlbot[    setup_manager.py:371 - ensure_rlbot_gateway_started() ] Python started RLBot.exe with process id 16664 and port 23233
Setting up soccer geometry for ball prediction...
Ball Prediction Service Started
RLBot.exe trying to connect to Rocket League on port 23233...
RLBot.exe Connected successfully to port 23233 !
front end listening for connections
RLBot.exe has begun listening for local socket clients on port 23234.
Game spawn detected at payload count 1
Zeroing numCars because we just got a fresh game spawn.
Clearing actor_id mappings!
Setting up soccer geometry for ball prediction...
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest, actor id 38, command id 0
Got message with unknown command id 0. Assuming it's a human and allocating index 0!
Associating player id 38 with player index 0!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (2), actor id 39, command id 0
Got message with unknown command id 0. Assuming it's a human and allocating index 1!
Associating player id 39 with player index 1!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (3), actor id 40, command id 0
Got message with unknown command id 0. Assuming it's a human and allocating index 2!
Associating player id 40 with player index 2!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (4), actor id 41, command id 0
Got message with unknown command id 0. Assuming it's a human and allocating index 3!
Associating player id 41 with player index 3!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (5), actor id 42, command id 0
Got message with unknown command id 0. Assuming it's a human and allocating index 4!
Associating player id 42 with player index 4!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (6), actor id 43, command id 0
Got message with unknown command id 0. Assuming it's a human and allocating index 5!
Associating player id 43 with player index 5!
Field spawn messages at payload count 1
2021-02-08 21:22:13,832 INFO:rlbot[    setup_manager.py:203 -      connect_to_game() ] Loading interface...
2021-02-08 21:22:14,035 INFO:rlbot[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-08 21:22:14,035 INFO:rlbot[   game_interface.py:307 -       load_interface() ] About to call StartTcp
9144 - C:\Users\tareh\AppData\Local\Programs\Python\Python37\python.exe DLL client connected!
9144 - C:\Users\tareh\AppData\Local\Programs\Python\Python37\python.exe Sending ready message...
front end server accepted new bot connection
ready to accept the next connection...
2021-02-08 21:22:15,036 INFO:rlbot[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-08 21:22:15,049 INFO:rlbot[    setup_manager.py:488 - launch_bot_process_helper() ] Successfully started 0 bot processes
2021-02-08 21:22:15,150 INFO:rlbot[    setup_manager.py:524 -          start_match() ] Python attempting to start match.
2021-02-08 21:22:15,150 INFO:rlbot[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-08 21:22:15,150 INFO:rlbot[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-08 21:22:15,150 INFO:rlbot[   game_interface.py:264 - wait_until_valid_packet() ] Waiting for valid packet...
Handling match start message which originated locally and which will apply locally. 
Starting match with command open music_p?game=TAGame.GameInfo_Soccar_TA?Playtest?GameTags=PlayerCount8,5Minutes,OneSecondsRespawn
Spawning bot 0 on team 0 with primary color rgb(61, 10, 204). Is rlbot? 1 
Spawning bot 1 on team 1 with primary color rgb(252, 124, 12). Is rlbot? 1 
Spawning bot 2 on team 0 with primary color rgb(61, 10, 204). Is rlbot? 1 
Spawning bot 3 on team 1 with primary color rgb(252, 124, 12). Is rlbot? 1 
Spawning bot 4 on team 0 with primary color rgb(61, 10, 204). Is rlbot? 1 
Spawning bot 5 on team 1 with primary color rgb(252, 124, 12). Is rlbot? 1 
Game spawn detected at payload count 187
Zeroing numCars because we just got a fresh game spawn.
Clearing actor_id mappings!
Setting up soccer geometry for ball prediction...
Field spawn messages at payload count 187
We have a player spawn message ready to go, sending!
We had player spawn messages queued up when arriving at a pause menu, sent!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest, actor id 38, command id 2
Associating player id 38 with player index 0!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (2), actor id 39, command id 3
Associating player id 39 with player index 1!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (3), actor id 40, command id 4
Associating player id 40 with player index 2!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (4), actor id 41, command id 5
Associating player id 41 with player index 3!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (5), actor id 42, command id 6
Associating player id 42 with player index 4!
Detected player spawn. Current network role: 0
Got player spawn message for HivemindTest (6), actor id 43, command id 7
Associating player id 43 with player index 5!
2021-02-08 21:22:16,658 INFO:rlbot[   game_interface.py:283 - wait_until_valid_packet() ] Packets are looking good, all spawn ids accounted for!
2021-02-08 21:22:16,658 INFO:rlbot[    setup_manager.py:527 -          start_match() ] Match has started
2021-02-08 21:22:16,662 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 0 was sent with spawn id 87654264, will search in the packet.
2021-02-08 21:22:16,662 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 0
2021-02-08 21:22:17,853 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 1 was sent with spawn id 620372539, will search in the packet.
2021-02-08 21:22:17,854 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 1
2021-02-08 21:22:19,022 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 2 was sent with spawn id 448654787, will search in the packet.
2021-02-08 21:22:19,022 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 2
2021-02-08 21:22:20,192 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 3 was sent with spawn id 210337761, will search in the packet.
2021-02-08 21:22:20,192 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 3
2021-02-08 21:22:21,352 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 4 was sent with spawn id 89042159, will search in the packet.
2021-02-08 21:22:21,353 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 4
2021-02-08 21:22:22,519 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 5 was sent with spawn id 68411623, will search in the packet.
2021-02-08 21:22:22,519 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 5
2021-02-08 21:22:23,679 INFO:rlbot[    setup_manager.py:488 - launch_bot_process_helper() ] Successfully started 6 bot processes
2021-02-08 21:22:23,679 INFO:rlbot[    setup_manager.py:533 -        infinite_loop() ] Press 'r' to reload all agents, or 'q' to exit
2021-02-08 21:22:23,688 INFO:rlbot[process_configuration.py:60 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 11404
2021-02-08 21:22:24,515 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 11404
2021-02-08 21:22:24,518 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 1112
2021-02-08 21:22:24,522 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 25820
2021-02-08 21:22:24,525 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 11404
2021-02-08 21:22:24,529 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 1112
2021-02-08 21:22:24,533 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 25820
2021-02-08 21:22:24,537 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 11404
2021-02-08 21:22:24,540 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 1112
2021-02-08 21:22:24,544 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 24996
2021-02-08 21:22:24,548 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 25820
2021-02-08 21:22:24,551 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 11404
2021-02-08 21:22:24,555 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 1112
2021-02-08 21:22:24,558 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 24996
2021-02-08 21:22:24,562 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 25820
2021-02-08 21:22:24,565 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 11404
2021-02-08 21:22:24,569 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 1112
2021-02-08 21:22:24,573 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 24996
2021-02-08 21:22:24,938 INFO:HivemindTest Hivemind[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-08 21:22:24,938 INFO:HivemindTest Hivemind[   game_interface.py:307 -       load_interface() ] About to call StartTcp
10864 - C:\Users\tareh\AppData\Local\Programs\Python\Python37\python.exe DLL client connected!
10864 - C:\Users\tareh\AppData\Local\Programs\Python\Python37\python.exe Sending ready message...
front end server accepted new bot connection
ready to accept the next connection...
2021-02-08 21:22:25,779 INFO:HivemindTest Hivemind[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-08 21:22:25,779 INFO:HivemindTest Hivemind[   game_interface.py:307 -       load_interface() ] About to call StartTcp
14172 - C:\Users\tareh\AppData\Local\Programs\Python\Python37\python.exe DLL client connected!
14172 - C:\Users\tareh\AppData\Local\Programs\Python\Python37\python.exe Sending ready message...
front end server accepted new bot connection
ready to accept the next connection...
2021-02-08 21:22:25,939 INFO:HivemindTest Hivemind[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-08 21:22:25,939 INFO:HivemindTest Hivemind[  python_hivemind.py:75 -                start() ] Collecting drones; give me a moment.
2021-02-08 21:22:25,940 INFO:HivemindTest Hivemind[  python_hivemind.py:77 -                start() ] Ready to go!
2021-02-08 21:22:25,940 INFO:HivemindTest Hivemind[             hive.py:12 -      initialize_hive() ] Initialised with 6 cars on pitch and 3 on team!
2021-02-08 21:22:26,780 INFO:HivemindTest Hivemind[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-08 21:22:26,780 INFO:HivemindTest Hivemind[  python_hivemind.py:75 -                start() ] Collecting drones; give me a moment.
2021-02-08 21:22:26,780 INFO:HivemindTest Hivemind[  python_hivemind.py:77 -                start() ] Ready to go!
2021-02-08 21:22:26,780 INFO:HivemindTest Hivemind[             hive.py:12 -      initialize_hive() ] Initialised with 6 cars on pitch and 3 on team!

Darxeal commented 3 years ago

I'm not sure if it's the cause of @Trezorro's issues as well, but for me (and other people) this issue happens only when you pause the game at the start of the match. Maybe they also paused the game without realizing it's the problem. Anyway, here's my log with Bumblebee when I pause the game at the start:

[{'name': 'Botimus Prime', 'team': 0, 'type': 'rlbot', 'skill': 1, 'path': 'C:\\Users\\Jirka\\Documents\\Projekty\\RLBot\\My bots\\Botimus&Bumblebee\\botimus.cfg'}, {'name': 'Bumblebee', 'team': 1, 'type': 'rlbot', 'skill': 1, 'path': 'C:\\Users\\Jirka\\Documents\\Projekty\\RLBot\\My bots\\Botimus&Bumblebee\\bumblebee.cfg'}]
{'map': 'NeoTokyo', 'game_mode': 'Soccer', 'skip_replays': False, 'instant_start': False, 'enable_lockstep': False, 'match_behavior': 'Restart If Different', 'mutators': {'ball_bounciness': 'Default', 'ball_max_speed': 'Default', 'ball_size': 'Default', 'ball_type': 'Default', 'ball_weight': 'Default', 'boost_amount': 'Unlimited', 'boost_strength': '1x', 'demolish': 'Default', 'game_speed': 'Default', 'gravity': 'Default', 'match_length': 'Unlimited', 'max_score': 'Unlimited', 'overtime': 'Unlimited', 'respawn_time': '3 Seconds', 'rumble': 'None', 'series_length': 'Unlimited'}, 'randomizeMap': True, 'enable_rendering': True, 'enable_state_setting': True, 'auto_save_replay': True, 'scripts': []}

           ______ _     ______       _
     10100 | ___ \ |    | ___ \     | |   00101
    110011 | |_/ / |    | |_/ / ___ | |_  110011
  00110110 |    /| |    | ___ \/ _ \| __| 01101100
    010010 | |\ \| |____| |_/ / (_) | |_  010010
     10010 \_| \_\_____/\____/ \___/ \__| 01001

Version 1.54.0

    Adding a version of the socket management util that uses asyncio.

Trouble? Ask on Discord at https://discord.gg/5cNbXgG or report an issue at https://github.com/RLBot/RLBot/issues

Launching RLBot binary with args ['C:\\Users\\Jirka\\AppData\\Local\\RLBotGUIX\\venv\\lib\\site-packages\\rlbot\\dll\\RLBot.exe', '23233', '127.0.0.1', '0']
2021-02-09 11:57:03,393 INFO:rlbot[    setup_manager.py:371 - ensure_rlbot_gateway_started() ] Python started RLBot.exe with process id 18196 and port 23233
Setting up soccer geometry for ball prediction...
Ball Prediction Service Started
RLBot.exe trying to connect to Rocket League on port 23233...
2021-02-09 11:57:03,799 INFO:rlbot[    setup_manager.py:247 - launch_rocket_league() ] Launching Rocket League with: ['c:\\program files (x86)\\steam\\steam.exe', '-applaunch', '252950', '-rlbot', 'RLBot_ControllerURL=127.0.0.1:23233', 'RLBot_PacketSendRate=240', '-nomovie']
2021-02-09 11:57:03,810 INFO:rlbot[    setup_manager.py:203 -      connect_to_game() ] Loading interface...
2021-02-09 11:57:04,018 INFO:rlbot[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-09 11:57:04,018 INFO:rlbot[   game_interface.py:307 -       load_interface() ] About to call StartTcp
RLBot.exe Connected successfully to port 23233 !
front end listening for connections
RLBot.exe has begun listening for local socket clients on port 23234.
15008 - C:\Users\Jirka\AppData\Local\RLBotGUIX\Python37\python.exe DLL client connected!
front end server accepted new bot connection
15008 - C:\Users\Jirka\AppData\Local\RLBotGUIX\Python37\python.exe ready to accept the next connection...
Sending ready message...
2021-02-09 11:57:23,030 INFO:rlbot[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-09 11:57:23,067 INFO:rlbot[    setup_manager.py:488 - launch_bot_process_helper() ] Successfully started 0 bot processes
2021-02-09 11:57:23,168 INFO:rlbot[    setup_manager.py:524 -          start_match() ] Python attempting to start match.
2021-02-09 11:57:23,168 INFO:rlbot[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-09 11:57:23,170 INFO:rlbot[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-09 11:57:23,171 INFO:rlbot[   game_interface.py:264 - wait_until_valid_packet() ] Waiting for valid packet...
Handling match start message which originated locally and which will apply locally.
Starting match with command open NeoTokyo_Standard_P?game=TAGame.GameInfo_Soccar_TA?Playtest?GameTags=PlayerCount8,UnlimitedTime,UnlimitedBooster
Spawning bot 0 on team 0 with primary color rgb(12, 184, 252). Is rlbot? 1
Spawning bot 1 on team 1 with primary color rgb(252, 200, 12). Is rlbot? 1
Game spawn detected at payload count 1
Zeroing numCars because we just got a fresh game spawn.
Clearing actor_id mappings!
Setting up soccer geometry for ball prediction...
Field spawn messages at payload count 1
We have a player spawn message ready to go, sending!
We had player spawn messages queued up when arriving at a pause menu, sent!
Detected player spawn. Current network role: 0
Got player spawn message for Botimus Prime, actor id 38, command id 2
Associating player id 38 with player index 0!
2021-02-09 11:57:28,474 INFO:rlbot[   game_interface.py:292 - wait_until_valid_packet() ] Scooting bots out of the way to allow more to spawn!
Detected player spawn. Current network role: 0
Got player spawn message for Bumblebee, actor id 39, command id 3
Associating player id 39 with player index 1!
2021-02-09 11:57:28,574 INFO:rlbot[   game_interface.py:292 - wait_until_valid_packet() ] Scooting bots out of the way to allow more to spawn!
2021-02-09 11:57:28,689 INFO:rlbot[   game_interface.py:283 - wait_until_valid_packet() ] Packets are looking good, all spawn ids accounted for!
2021-02-09 11:57:28,689 INFO:rlbot[    setup_manager.py:527 -          start_match() ] Match has started
2021-02-09 11:57:28,726 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 0 was sent with spawn id 1511450718, will search in the packet.
2021-02-09 11:57:28,726 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 0
2021-02-09 11:57:28,815 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 1 was sent with spawn id 141757514, will search in the packet.
2021-02-09 11:57:28,815 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 1
2021-02-09 11:57:28,907 INFO:rlbot[    setup_manager.py:488 - launch_bot_process_helper() ] Successfully started 2 bot processes
Initializing rlutilities...
00007FFA63240000
2021-02-09 11:57:30,146 INFO: bot0[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-09 11:57:30,146 INFO: bot0[   game_interface.py:307 -       load_interface() ] About to call StartTcp
front end server accepted new bot connection
ready to accept the next connection...
18772 - C:\Users\Jirka\AppData\Local\RLBotGUIX\Python37\python.exe DLL client connected!
18772 - C:\Users\Jirka\AppData\Local\RLBotGUIX\Python37\python.exe Sending ready message...
Initializing rlutilities...
00007FFA63240000
2021-02-09 11:57:30,616 INFO:Beehive[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-09 11:57:30,616 INFO:Beehive[   game_interface.py:307 -       load_interface() ] About to call StartTcp
front end server accepted new bot connection
ready to accept the next connection...
1572 - C:\Users\Jirka\AppData\Local\RLBotGUIX\Python37\python.exe DLL client connected!
1572 - C:\Users\Jirka\AppData\Local\RLBotGUIX\Python37\python.exe Sending ready message...
2021-02-09 11:57:31,151 INFO: bot0[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
setting mode: soccar
2021-02-09 11:57:31,625 INFO:Beehive[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-09 11:57:31,625 INFO:Beehive[  python_hivemind.py:75 -                start() ] Collecting drones; give me a moment.
2021-02-09 11:57:31,627 INFO:Beehive[  python_hivemind.py:77 -                start() ] Ready to go!
2021-02-09 11:57:31,650 INFO:Beehive[         hivemind.py:33 -      initialize_hive() ] packet.num_cars: 0
setting mode: soccar
2021-02-09 11:57:31,657 INFO:Beehive[         hivemind.py:45 -      initialize_hive() ] Beehive initialized

tarehart commented 3 years ago

Thanks Darxeal, that helps a lot!

Trezorro commented 3 years ago

Hi @tarehart . No problem. My problem does look a bit different though. Rocketleague is started from scratch in this case, but it happens regardless of whether it is already running.


(rocketnoodles) D:\Code\serpentine\rocketnoodles> d: && cd d:\Code\serpentine\rocketnoodles && cmd /C "C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\Scripts\python.exe c:\Users\miltre\.vscode\extensions\ms-python.python-2021.1.502429796\pythonFiles\lib\python\debugpy\launcher 64319 -- -m run main "
starting

           ______ _     ______       _
     10100 | ___ \ |    | ___ \     | |   00101
    110011 | |_/ / |    | |_/ / ___ | |_  110011
  00110110 |    /| |    | ___ \/ _ \| __| 01101100
    010010 | |\ \| |____| |_/ / (_) | |_  010010
     10010 \_| \_\_____/\____/ \___/ \__| 01001

Version 1.54.0

    Adding a version of the socket management util that uses asyncio.

Trouble? Ask on Discord at https://discord.gg/5cNbXgG or report an issue at https://github.com/RLBot/RLBot/issues

Launching RLBot binary with args ['C:\\Users\\miltre\\.virtualenvs\\rocketnoodles-MTVV8oK0\\Lib\\site-packages\\rlbot\\dll\\RLBot.exe', '23233', '127.0.0.1', '0']
2021-02-10 18:48:41,724 INFO:rlbot[    setup_manager.py:371 - ensure_rlbot_gateway_started() ] Python started RLBot.exe with process id 26028 and port 23233
Setting up soccer geometry for ball prediction...
Ball Prediction Service Started
RLBot.exe trying to connect to Rocket League on port 23233...
2021-02-10 18:48:42,275 INFO:rlbot[      epic_launch.py:20 - launch_with_epic_simple() ] Launching Rocket League with: ['D:\\Personal\\Epic Library\\rocketleague\\Binaries\\Win64\\RocketLeague.exe', '-rlbot', 'RLBot_ControllerURL=127.0.0.1:23233', 'RLBot_PacketSendRate=240', '-nomovie']
2021-02-10 18:48:42,291 INFO:rlbot[    setup_manager.py:203 -      connect_to_game() ] Loading interface...
2021-02-10 18:48:42,499 INFO:rlbot[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-10 18:48:42,500 INFO:rlbot[   game_interface.py:307 -       load_interface() ] About to call StartTcp
RLBot.exe Connected successfully to port 23233 !
front end listening for connections
RLBot.exe has begun listening for local socket clients on port 23234.
2front end server accepted new bot connection
248ready to accept the next connection...
0 - C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\Scripts\python.exe DLL client connected!
22480 - C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\Scripts\python.exe Sending ready message...
2021-02-10 18:48:58,541 INFO:rlbot[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-10 18:48:58,578 INFO:rlbot[    setup_manager.py:488 - launch_bot_process_helper() ] Successfully started 0 bot processes
2021-02-10 18:48:58,681 INFO:rlbot[    setup_manager.py:524 -          start_match() ] Python attempting to start match.
2021-02-10 18:48:58,681 INFO:rlbot[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-10 18:48:58,682 INFO:rlbot[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!      
2021-02-10 18:48:58,683 INFO:rlbot[   game_interface.py:264 - wait_until_valid_packet() ] Waiting for valid packet...
Handling match start message which originated locally and which will apply locally.
Starting match with command open farm_p?game=TAGame.GameInfo_Soccar_TA?Playtest?GameTags=PlayerCount8,5Minutes
Spawning bot 0 on team 0 with primary color rgb(46, 127, 6). Is rlbot? 1
Spawning bot 1 on team 1 with primary color rgb(127, 90, 57). Is rlbot? 1
Spawning bot 2 on team 0 with primary color rgb(46, 127, 6). Is rlbot? 1
Spawning bot 3 on team 1 with primary color rgb(127, 90, 57). Is rlbot? 1
Spawning bot 4 on team 0 with primary color rgb(46, 127, 6). Is rlbot? 1
Spawning bot 5 on team 1 with primary color rgb(127, 90, 57). Is rlbot? 1
Game spawn detected at payload count 1
Zeroing numCars because we just got a fresh game spawn.
Clearing actor_id mappings!
Setting up soccer geometry for ball prediction...
Field spawn messages at payload count 1
We have a player spawn message ready to go, sending!
We had player spawn messages queued up when arriving at a pause menu, sent!
Detected player spawn. Current network role: 0
Got player spawn message for RocketNoodlesDev, actor id 38, command id 2
Associating player id 38 with player index 0!
Detected player spawn. Current network role: 0
Got player spawn message for RocketNoodlesDev (2), actor id 39, command id 3
Associating player id 39 with player index 1!
Detected player spawn. Current network role: 0
Got player spawn message for RocketNoodlesDev (3), actor id 40, command id 4
Associating player id 40 with player index 2!
Detected player spawn. Current network role: 0
Got player spawn message for RocketNoodlesDev (4), actor id 41, command id 5
Associating player id 41 with player index 3!
Detected player spawn. Current network role: 0
Got player spawn message for RocketNoodlesDev (5), actor id 42, command id 6
Associating player id 42 with player index 4!
Detected player spawn. Current network role: 0
Got player spawn message for RocketNoodlesDev (6), actor id 43, command id 7
Associating player id 43 with player index 5!
2021-02-10 18:49:01,300 INFO:rlbot[   game_interface.py:283 - wait_until_valid_packet() ] Packets are looking good, all spawn ids accounted for!
2021-02-10 18:49:01,300 INFO:rlbot[    setup_manager.py:527 -          start_match() ] Match has started
2021-02-10 18:49:01,314 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 0 was sent with spawn id 989512261, will search in the packet.
2021-02-10 18:49:01,315 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 0
2021-02-10 18:49:02,770 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 1 was sent with spawn id 2126687745, will search in the packet.
2021-02-10 18:49:02,770 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 1
2021-02-10 18:49:04,722 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 2 was sent with spawn id 1043506061, will search in the packet.
2021-02-10 18:49:04,723 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 2
2021-02-10 18:49:07,739 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 3 was sent with spawn id 265515281, will search in the packet.
2021-02-10 18:49:07,740 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 3
2021-02-10 18:49:10,710 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 4 was sent with spawn id 1518551386, will search in the packet.
2021-02-10 18:49:10,711 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 4
Task was destroyed but it is pending!
task: <Task pending name='Task-3' coro=<IocpProactor.accept.<locals>.accept_coro() running at C:\Users\miltre\Miniconda3\envs\py38\lib\asyncio\windows_events.py:562> wait_for=<_OverlappedFuture cancelled>>
Task was destroyed but it is pending!
task: <Task pending name='Task-4' coro=<IocpProactor.accept.<locals>.accept_coro() running at C:\Users\miltre\Miniconda3\envs\py38\lib\asyncio\windows_events.py:562> wait_for=<_OverlappedFuture cancelled>>
2021-02-10 18:49:12,839 INFO:rlbot[    setup_manager.py:440 - launch_bot_process_helper() ] Player in slot 5 was sent with spawn id 1069801264, will search in the packet.
2021-02-10 18:49:12,839 INFO:rlbot[    setup_manager.py:444 - launch_bot_process_helper() ] Looks good, considering participant index to be 5
2021-02-10 18:49:14,733 INFO:rlbot[    setup_manager.py:488 - launch_bot_process_helper() ] Successfully started 6 bot processes
2021-02-10 18:49:14,734 INFO:rlbot[    setup_manager.py:533 -        infinite_loop() ] Press 'r' to reload all agents, or 'q' to exit
2021-02-10 18:49:14,770 INFO:rlbot[process_configuration.py:60 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 28472
2021-02-10 18:49:14,824 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 28472
2021-02-10 18:49:14,865 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 3660
2021-02-10 18:49:14,877 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 28472
2021-02-10 18:49:14,886 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 24036
2021-02-10 18:49:14,892 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 3660
2021-02-10 18:49:14,901 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 28472
2021-02-10 18:49:14,909 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 24036
2021-02-10 18:49:14,917 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 3660
2021-02-10 18:49:14,927 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 28472
2021-02-10 18:49:14,935 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 24036
2021-02-10 18:49:14,941 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 3660
2021-02-10 18:49:17,056 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 28472
2021-02-10 18:49:17,061 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 24036
2021-02-10 18:49:17,067 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 22204
2021-02-10 18:49:17,074 INFO:rlbot[process_configuration.py:48 -  configure_processes() ] psutil.NoSuchProcess no process found with pid 3660
Logging enabled
2021-02-10 18:49:18,618 INFO:NoodleHive[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-10 18:49:18,620 INFO:NoodleHive[   game_interface.py:307 -       load_interface() ] About to call StartTcp
front end server accepted new bot connection
ready to accept the next connection...
2572 - C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\Scripts\python.exe DLL client connected!
2572 - C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\Scripts\python.exe Sending ready message...
Logging enabled
2021-02-10 18:49:19,107 INFO:NoodleHive[   game_interface.py:241 -    wait_until_loaded() ] DLL is initialized!
2021-02-10 18:49:19,119 INFO:NoodleHive[   game_interface.py:307 -       load_interface() ] About to call StartTcp
front end server accepted new bot connection
ready to accept the next connection...
22632 - C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\Scripts\python.exe DLL client connected!
22632 - C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\Scripts\python.exe Sending ready message...
2021-02-10 18:49:19,623 INFO:NoodleHive[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-10 18:49:19,624 INFO:NoodleHive[  python_hivemind.py:75 -                start() ] Collecting drones; give me a moment.
2021-02-10 18:49:19,626 INFO:NoodleHive[  python_hivemind.py:77 -                start() ] Ready to go!
Process Process-8:
Traceback (most recent call last):
  File "C:\Users\miltre\Miniconda3\envs\py38\lib\multiprocessing\process.py", line 315, in _bootstrap
    self.run()
  File "C:\Users\miltre\Miniconda3\envs\py38\lib\multiprocessing\process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\lib\site-packages\rlbot\botmanager\helper_process_manager.py", line 68, in run_helper_process
    helper.start()
  File "C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\lib\site-packages\rlbot\agents\hivemind\python_hivemind.py", line 80, in start
    self.__game_loop()
  File "C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\lib\site-packages\rlbot\agents\hivemind\python_hivemind.py", line 106, in __game_loop
    self.initialize_hive(packet)
  File "d:\code\serpentine\rocketnoodles\src\main.py", line 83, in initialize_hive
    self.coach = globals()[self.config['strategy']['coach']]()
  File "D:\Code\serpentine\rocketnoodles\src\strategy\coaches\triple_rotations.py", line 33, in __init__
    self.current = Kickoff()
  File "D:\Code\serpentine\rocketnoodles\src\strategy\captains\kickoff.py", line 22, in __init__
    drones_dist_to_ball_list = [(drone, drone.car.dist_to_ball) for drone in shared.drones]
  File "D:\Code\serpentine\rocketnoodles\src\strategy\captains\kickoff.py", line 22, in <listcomp>
    drones_dist_to_ball_list = [(drone, drone.car.dist_to_ball) for drone in shared.drones]
  File "D:\Code\serpentine\rocketnoodles\src\strategy\drone_team.py", line 132, in car
    return self._world.cars[self.index]
IndexError: list index out of range
2021-02-10 18:49:20,137 INFO:NoodleHive[   game_interface.py:254 - wait_until_ready_to_communicate() ] DLL is ready for comms!
2021-02-10 18:49:20,138 INFO:NoodleHive[  python_hivemind.py:75 -                start() ] Collecting drones; give me a moment.
2021-02-10 18:49:20,140 INFO:NoodleHive[  python_hivemind.py:77 -                start() ] Ready to go!
Process Process-7:
Traceback (most recent call last):
  File "C:\Users\miltre\Miniconda3\envs\py38\lib\multiprocessing\process.py", line 315, in _bootstrap
    self.run()
  File "C:\Users\miltre\Miniconda3\envs\py38\lib\multiprocessing\process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\lib\site-packages\rlbot\botmanager\helper_process_manager.py", line 68, in run_helper_process
    helper.start()
  File "C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\lib\site-packages\rlbot\agents\hivemind\python_hivemind.py", line 80, in start
    self.__game_loop()
  File "C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\lib\site-packages\rlbot\agents\hivemind\python_hivemind.py", line 106, in __game_loop
    self.initialize_hive(packet)
  File "d:\code\serpentine\rocketnoodles\src\main.py", line 83, in initialize_hive
    self.coach = globals()[self.config['strategy']['coach']]()
  File "D:\Code\serpentine\rocketnoodles\src\strategy\coaches\triple_rotations.py", line 33, in __init__
    self.current = Kickoff()
  File "D:\Code\serpentine\rocketnoodles\src\strategy\captains\kickoff.py", line 22, in __init__
    drones_dist_to_ball_list = [(drone, drone.car.dist_to_ball) for drone in shared.drones]
  File "D:\Code\serpentine\rocketnoodles\src\strategy\captains\kickoff.py", line 22, in <listcomp>
    drones_dist_to_ball_list = [(drone, drone.car.dist_to_ball) for drone in shared.drones]
  File "D:\Code\serpentine\rocketnoodles\src\strategy\drone_team.py", line 132, in car
    return self._world.cars[self.index]
IndexError: list index out of range
uninitialized_bot error reading header: An existing connection was forcibly closed by the remote host
uninitialized_bot error reading header: An existing connection was forcibly closed by the remote host

tarehart commented 3 years ago

I believe this is now fixed in version 1.55.1!

Trezorro commented 3 years ago

@tarehart Amazing. I just tested it and it does indeed seem to be fixed.

Thank you so much for the quick response!

Out of curiosity. Is this diff what fixed it? https://github.com/RLBot/RLBot/commit/1e91e093e4cf16a9a0fde06aa5ea5817190437d8#diff-db137ba3cca830667746e3303c8b2d3270ab86d297efc5397a9317af1df45b70

If I may ask, there have popped up some new things that might be related and be troublesome:

I am now seeing something new in the terminal log. A big waterfall of lines saying:

Not sending message to Rocket League because that would bring the bytes sent since last receive to 68734, and the limit is 65535 bytes.
Not sending message to Rocket League because that would bring the bytes sent since last receive to 68734, and the limit is 65535 bytes.
Failed to send render removal to Rocket League!
Not sending message to Rocket League because that would bring the bytes sent since last receive to 68860, and the limit is 65535 bytes.
Not sending message to Rocket League because that would bring the bytes sent since last receive to 68860, and the limit is 65535 bytes.
Failed to send render removal to Rocket League!
Not sending message to Rocket League because that would bring the bytes sent since last receive to 82144, and the limit is 65535 bytes.
...

and so on.

Is this related? Might have to do with lockstep being on, in combination with things like the pause menu / replays.

Another new bug, though this might be intentional:

I encountered it after calling...

setup_manager.load_config()
setup_manager.connect_to_game()
setup_manager.launch_early_start_bot_processes()
setup_manager.start_match()
setup_manager.launch_bot_processes()

Then calling setup_manager.game_interface.update_player_input(PlayerInput(), 0)

Yields this exception:

File "D:\Code\serpentine\rocketnoodles\src\evaluation\rlbot_runner.py", line 58, in run
    setup_manager.game_interface.update_player_input(PlayerInput(), idx)
  File "C:\Users\miltre\.virtualenvs\rocketnoodles-MTVV8oK0\lib\site-packages\rlbot\utils\structures\game_interface.py", line 207, in update_player_input
    rlbot_status = self.game.UpdatePlayerInput(player_input, index)
AttributeError: 'NoneType' object has no attribute 'UpdatePlayerInput'
uninitialized_bot error reading header: An existing connection was forcibly closed by the remote host
uninitialized_bot error reading header: An existing connection was forcibly closed by the remote host
Task was destroyed but it is pending!
task: <Task pending name='Task-3' coro=<IocpProactor.accept.<locals>.accept_coro() running at C:\Users\miltre\Miniconda3\envs\py38\lib\asyncio\windows_events.py:562> wait_for=<_OverlappedFuture cancelled>>
Task was destroyed but it is pending!
task: <Task pending name='Task-4' coro=<IocpProactor.accept.<locals>.accept_coro() running at C:\Users\miltre\Miniconda3\envs\py38\lib\asyncio\windows_events.py:562> wait_for=<_OverlappedFuture cancelled>>

This call was left over from the workaround, but it does seem weird that it fails. Why is there no longer an initialized game attribute there?

ViliamVadocz commented 3 years ago

Not sending message to Rocket League because that would bring the bytes sent since last receive to 82144, and the limit is 65535 bytes.

This error probably has to do with rendering. You should split up your rendering into groups to avoid this. https://github.com/RLBot/RLBot/wiki/Rendering#rendering-a-large-amount

tarehart commented 3 years ago

Not sending message to Rocket League because that would bring the bytes sent since last receive to 68734, and the limit is 65535 bytes. With increasing values generally means we're getting no data from Rocket League but bots are still sending a bunch of inputs. If it's only happening temporarily like during match start, it's probably harmless, but still something I should look into.

'NoneType' object has no attribute 'UpdatePlayerInput' should now be fixed.

Regarding what fixed the original bug, you are correct that https://github.com/RLBot/RLBot/commit/1e91e093e4cf16a9a0fde06aa5ea5817190437d8#diff-db137ba3cca830667746e3303c8b2d3270ab86d297efc5397a9317af1df45b70 is the essential part in that diff. There was also a change behind the scenes to send a packet to clients of RLBot.exe immediately when they connect.

ViliamVadocz commented 3 years ago

Is this safe to close?

tarehart commented 3 years ago

Seems like there are a few lingering questions, but I'll go ahead and close. Trezorro, feel free to reopen and/or open a new issue if you're getting blocked by errors!

RLBot / RLBot

PythonHivemind.initialize_hive(packet) called with invalid GameTickPacket (after updating from RLBot 1.48 to 1.54) #543

Context

The Issue

Notes

Conclusion