Skip to content

Investigate flaky tests related to time and #3823

@extremeheat

Description

@extremeheat

We have 2 flaky tests affecting most versions indiscriminately. One, related to time:

Time:

    ✔ team
Resetting state
[19:14:31] [Server thread/INFO]: [flatbot: Set own game mode to Survival Mode]
[19:14:31] [Server thread/INFO]: [flatbot: Set own game mode to Creative Mode]
[19:14:31] [Server thread/INFO]: [flatbot: Gave 1 [Stone] to flatbot]
[19:14:31] [Server thread/INFO]: [flatbot: Removed 1 items from player flatbot]
/execute in overworld run teleport flatbot 0 4 0
[19:14:31] [Server thread/INFO]: [flatbot: Teleported flatbot to 0.500000, 4.000000, 0.500000]
[19:14:33] [Server thread/INFO]: [flatbot: Gave 1 [Stone] to flatbot]
[19:14:33] [Server thread/INFO]: [flatbot: Removed 1 items from player flatbot]
State reset
### Starting time
/time set 18000
[19:14:33] [Server thread/INFO]: <flatbot> ### Starting time
[19:14:33] [Server thread/INFO]: [flatbot: Set the time to 18000]
    1) time
...
  59 passing (4m)
  1 failing

  1) mineflayer_external 1.17.1v
       time:

      AssertionError [ERR_ASSERTION]: Expected time to be close to 18000, got 21957
      + expected - actual

      -false
      +true
      
      at /home/runner/work/mineflayer/mineflayer/test/externalTests/time.js:49:5

Another with the digger example:

    ✔ exampleBlockFinder (7503ms)
Resetting state
[12:54:24] [Server thread/INFO]: [flatbot: Set own game mode to Survival Mode]
[12:54:24] [Server thread/INFO]: [flatbot: Set own game mode to Creative Mode]
[12:54:24] [Server thread/INFO]: finder lost connection: Disconnected
[12:54:24] [Server thread/INFO]: finder left the game
[12:54:25] [Server thread/INFO]: [flatbot: Gave 1 [Stone] to flatbot]
[12:54:25] [Server thread/INFO]: [flatbot: Removed 1 items from player flatbot]
/execute in overworld run teleport flatbot 0 4 0
[12:54:25] [Server thread/INFO]: [flatbot: Teleported flatbot to 0.5, 4.0, 0.5]
[12:54:26] [Server thread/INFO]: [flatbot: Gave 1 [Stone] to flatbot]
[12:54:26] [Server thread/INFO]: [flatbot: Removed 1 items from player flatbot]
State reset
### Starting exampleDigger
[12:54:26] [Server thread/INFO]: <flatbot> ### Starting exampleDigger
[12:54:27] [Server thread/INFO]: digger[/127.0.0.1:54896] logged in with entity id 78 at (-148.5, 4.0, -57.5)
[12:54:27] [Server thread/INFO]: digger joined the game
[12:54:27] [Server thread/INFO]: [flatbot: Teleported digger to 50.5, 4.0, 0.5]
[12:54:32] [Server thread/INFO]: <flatbot> loaded
[12:54:42] [Server thread/INFO]: digger lost connection: Timed out
[12:54:42] [Server thread/INFO]: digger left the game
Error: Promise timed out.
    at /home/runner/work/mineflayer/mineflayer/lib/promise_utils.js:83:13
    at async Object.runExample (/home/runner/work/mineflayer/mineflayer/test/externalTests/plugins/testCommon.js:232:7)
    at async /home/runner/work/mineflayer/mineflayer/test/externalTests/exampleDigger.js:4:3
kill process 2334
Error: kill ESRCH
    at process.kill (node:internal/process/per_thread:281:13)
    at closeExample (/home/runner/work/mineflayer/mineflayer/test/externalTests/plugins/testCommon.js:218:17)
    at Object.runExample (/home/runner/work/mineflayer/mineflayer/test/externalTests/plugins/testCommon.js:235:14)
    at async /home/runner/work/mineflayer/mineflayer/test/externalTests/exampleDigger.js:4:3 {
  errno: -3,
  code: 'ESRCH',
  syscall: 'kill'
}
...
  59 passing (5m)
  1 failing

  1) mineflayer_external 1.15.2v
       exampleDigger:
     Error: Promise timed out.
      at /home/runner/work/mineflayer/mineflayer/lib/promise_utils.js:83:13
      at async Object.runExample (test/externalTests/plugins/testCommon.js:232:7)
      at async /home/runner/work/mineflayer/mineflayer/test/externalTests/exampleDigger.js:4:3

The issue on the second is that promises are being awaited and timing out without useful information. When we await a promise we should always register a timeout and if that timeout fails, have a useful log message determined by the caller (e.g., await resolve(promise, timeout, "Optional debugging message"))

For the first it's possibly just a race issue

Metadata

Metadata

Labels

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions