Clarification on new release logic

kobus-v-schoor · May 12, 2023, 8:32pm

Hey, thanks for the new release! I just went through its diff and want to clarify some of the changes. Unfortunately I don’t yet have a bot with which to test the properly so I might have this all wrong

I see in 2023-Cy-Fi/CyFiEngine.cs at ebf159cb845114037f5cfb8a3e0205e532c47129 · EntelectChallenge/2023-Cy-Fi · GitHub that when a player advances a level, all the other bots have their points incremented by 5 * collected (L228). Additionally, the bot that advanced a level has its score incremented twice (first time, second time) (although I guess this would be a nop since collected would be set to 0?). Finally in EndGame the players are ranked according to score. Does this work out to first at level 4 == winner?

Next, in 2023-Cy-Fi/CyFiEngine.cs at ebf159cb845114037f5cfb8a3e0205e532c47129 · EntelectChallenge/2023-Cy-Fi · GitHub it looks like the command queue is cleared on each tick, but as only three commands are processed per tick (still not sure why? is it meant to be an extra game mechanic?) it means that the last command will be cleared before being processed in the next tick, or am I missing something?

EDIT: super stoked that a logger was added - just a heads up of something a bit bizarre, looks like the logger’s generated json is missing a ] at the end of the file.

~/repos/ec/logs $ jq . 23-05-12-T2058logging.json
parse error: Unfinished JSON term at EOF at line 1, column 824037
~/repos/ec/logs $ echo "]" >> 23-05-12-T2058logging.json 
~/repos/ec/logs $ jq . 23-05-12-T2058logging.json | tail
        },
        "CurrentLevel": 0,
        "Id": "130ceb9e-2db2-4d47-bbd0-00dd7c585011",
        "NickName": "BestNicknameEver",
        "ConnectionId": "AL67bnohFlBto3bGe2dN2w",
        "TotalPoints": 0
      }
    ]
  }
]

EDIT 2: I’m starting to suspect that the missing ] is because I’m cancelling the game early, and would’ve been added if the game as been completed so please ignore if that’s the case

EDIT 3: Looks like the logger is producing mangled json sometimes An excerpt from my logs:

...","TotalPoints":0}]}[{"Tick":0,"Levels":...

As you can see there is a comma missing between the "TotalPoints":0}]} and {"Tick":0, and there’s a [ instead

kobus-v-schoor · May 13, 2023, 3:58pm

Something else I’ve found, it looks like you can queue more than one command per tick. These logs were generated if my bot sent more than one command per tick, you can see that they both get processed (the send command log lines only get printed inside the main GameLoop function if the command is being processed):

2023-05-13T15:55:55.8283758+00:00 Information CyFi.CyFiEngine - Tick: 70 *************************************************
2023-05-13T15:55:55.8292468+00:00 Information CyFi.CyFiEngine - bot States: X 38, Y 20
2023-05-13T15:55:55.8298865+00:00 Information CyFi.CyFiEngine - Bot: 9e30fec5-016a-4fe4-8acf-0a82ee7bdfc6 send command UP
Current state of bot: CyFi.Physics.Movement.Falling
update input
2023-05-13T15:55:55.8300880+00:00 Information CyFi.CyFiEngine - Bot: 9e30fec5-016a-4fe4-8acf-0a82ee7bdfc6 send command DOWN
Current state of bot: CyFi.Physics.Movement.Falling

kobus-v-schoor · May 13, 2023, 4:43pm

Something else I’ve noticed, and I’m not sure if this is by design, but it looks like all the state updates are delayed by an extra 1 tick w.r.t the commands being sent because the engine publishes its states before it performs the state updates. It can be seen in the logs below:

Bot logs:
DEBU[0005] t[5]: {x:23 y:14}
DEBU[0005] t[5]: sending RIGHT
DEBU[0005] t[6]: {x:23 y:14}
DEBU[0005] t[6]: sending UP
DEBU[0005] t[7]: {x:23 y:14}
DEBU[0005] t[7]: sending LEFT
DEBU[0006] t[8]: {x:23 y:15}
DEBU[0006] t[8]: sending RIGHT
DEBU[0006] t[9]: {x:22 y:16}
DEBU[0006] t[9]: sending UP

Engine logs (cleaned up):
2023-05-13T16:25:57.6489227+00:00 Information CyFi.CyFiEngine - Tick: 6
2023-05-13T16:25:57.6495883+00:00 Information CyFi.CyFiEngine - bot States: X 23, Y 14
2023-05-13T16:25:57.6499809+00:00 Information CyFi.CyFiEngine - Bot: send command RIGHT
2023-05-13T16:25:57.9509711+00:00 Information CyFi.CyFiEngine - Tick: 7
2023-05-13T16:25:57.9518883+00:00 Information CyFi.CyFiEngine - bot States: X 23, Y 14
2023-05-13T16:25:57.9534453+00:00 Information CyFi.CyFiEngine - Bot: send command UP
2023-05-13T16:25:58.2477973+00:00 Information CyFi.CyFiEngine - Tick: 8
2023-05-13T16:25:58.2490422+00:00 Information CyFi.CyFiEngine - bot States: X 23, Y 15
2023-05-13T16:25:58.2497180+00:00 Information CyFi.CyFiEngine - Bot: send command LEFT
2023-05-13T16:25:58.5464311+00:00 Information CyFi.CyFiEngine - Tick: 9
2023-05-13T16:25:58.5538106+00:00 Information CyFi.CyFiEngine - bot States: X 22, Y 16
2023-05-13T16:25:58.5548065+00:00 Information CyFi.CyFiEngine - Bot:  send command RIGHT
2023-05-13T16:25:58.8507509+00:00 Information CyFi.CyFiEngine - Tick: 10
2023-05-13T16:25:58.8512566+00:00 Information CyFi.CyFiEngine - bot States: X 23, Y 17
2023-05-13T16:25:58.8518293+00:00 Information CyFi.CyFiEngine - Bot: send command UP

If you compare my bot’s received position/tick number, with when the commands are being processed you’ll see there’s an extra tick of delay:

During tick 6: Sends UP command
Start of tick 7: Engine publishes current state
Middle of tick 7: After publishing the state, the engine processes the queued UP command
Start of Tick 8: Tick 7’s state is published and the UP command’s effect can be observed in the state (Y increases)

If the state publishing routine gets moved to after the command processing loop it means we’ll get the state update after our previous action was executed, which makes it much easier to react to the engine’s updates (otherwise we’ll need to compensate for a delay). How I think it was intended to work:

During tick 6: Sends UP command
Start of tick 7: the engine processes the queued UP command
Middle of tick 7: The engine publishes the newly updated state (in which the bot’s Y has already increased)

EDIT: PR opened

kobus-v-schoor · May 13, 2023, 10:03pm

Sorry for all the posts, I figured it might be easier to read instead of one massive post. It looks like if you fall on a collectible it triggers a collision causing you to stop on top of the collectable. See attached video to see what I mean (note the state in the top left corner)

kobus-v-schoor · May 14, 2023, 4:53pm

It also looks like the first action after a state change to “idle” doesn’t get processed (you can also see that transitioning from jumping → idle → falling causes an extra jump before the falling starts). Two examples (one after a jump, one after falling):

In this case, the RIGHT command on tick 3 is ignored):

In this case, the LEFT command on tick 19 is ignored:

kobus-v-schoor · May 19, 2023, 6:44pm

@Jenique I’ve opened a PR in an attempt to fix a “momentum” issue that I found, whereby a player keeps on moving left or right, even if they’ve stopped sending the command, while falling or jumping. I’m not too sure about the fix but it might be a start: Fixed momentum issue where bot would keep going in previous X direction after transitioning from jumping/falling by kobus-v-schoor · Pull Request #3 · EntelectChallenge/2023-Cy-Fi · GitHub

Jenique · May 20, 2023, 7:45am

Thanks Kobus

I’ll have a look at everything and respond to all your comments on Sunday.

We are planning a release within the weekend we will try to address all of you concerns

kobus-v-schoor · May 27, 2023, 5:14pm

Hey @Jenique , I’ve been able to confirm the bug that I suspected here (I can DM you a recording if needed):

I’ve built an engine where I removed the limit of 3 commands per tick and that resolves the issue

kobus-v-schoor · May 27, 2023, 9:56pm

@Jenique Something else, it looks like when you advance a level, your bot’s current state (and delta) is carried over with the advancement. This can lead to a weird situation where you spawn in such a position that your bot cannot land/navigate onto the next level’s starting platform. For instance, in the video below, my bot goes into the falling state - this then gets carried over after the bot advances to the next level, after which it falls right past the starting platform

kobus-v-schoor · May 28, 2023, 9:17am

Just to be clear on this one, what happens is that the last bot to publish a command gets consistently ignored, leading to it being stuck (in my case, the player got stuck for something like 10+ ticks). This can unfairly disadvantage players using a slower language (especially Python), the last player to get the state update i.e. player 4 (what happened in my case), or players who might have a strategy that just takes some more time to execute.

ted · June 18, 2023, 3:03pm

My take is that the solution to this issue is in two areas.

HasBotMoved(BotCommand command) I would change that to return CommandQueue.Any(x => x.BotId == command.BotId);
Since command queue increasing due to non processing of the 4th bot’s command. I would also change here: get the top first 3 commands to dequeue 4 commands.

styphoiz · June 19, 2023, 10:56am

I was under the impression that the command will go through on the tick from the Readme, am I incorrect in this understanding?

kobus-v-schoor · June 19, 2023, 11:08am

Yeah in the latest release it works like this:

First 3 commands received by the engine are processed like usual
The last command received is ignored (for the current tick), and queued only to be processed on the next tick.

When I initially raised the issue the command queue was cleared on each tick, so 1 bot’s command was essentially discarded every tick (and not re-queued). This has since been fixed.