search

online-go / gtp2ogs

GTP Wrapper to allow bots to interface with the Online-Go.com Server
MIT License
88 stars 29 forks source link

Bot loses by timeout #394

Closed Dorus closed 1 year ago

Dorus commented 1 year ago

My gtp2ogs (rc.4 tag + 1 commit) just let one of my bots time out. These are the logs:

https://online-go.com/game/53797945

May 19 16:56:52   Bot.ts:163           [bot  6:85032] Root    6410    49   1  99.56% 99.55% 99.55%  0.98%  4.67   0.16%  -0.0 1.00
May 19 16:56:52   Bot.ts:163           [bot  6:85032] Final agent lambda=0.00, mu=0.00, interval [0.0, 0.0].
May 19 16:56:52   Game.ts:325          [game 53797945] Releasing bot(s)
May 19 16:56:52   Game.ts:535          [game 53797945] Playing a12 { x: 0, y: 7, text: 'a12', resign: false, pass: false }
May 19 16:56:52   Bot.ts:163           [bot  6:85032] 4.1 average depth, 11 max depth
May 19 16:56:52   Bot.ts:163           [bot  6:85032] 2293 non leaf nodes, 2.79 average children
May 19 16:56:52   Bot.ts:163           [bot  6:85032] 6410 visits, 1133988 nodes, 6361 playouts, 1674 n/s
May 19 16:56:57   Game.ts:230          [game 53797945] Opponent played a13
May 19 16:56:57   Game.ts:402          [game 53797945] Acquiring main bot instance
May 19 16:56:57   Game.ts:412          [bot  6:85032] [game 53797945] Acquired bot instance
May 19 16:56:57   Game.ts:467          [bot  6:85032] Generating move for game 53797945
May 19 16:56:57   Game.ts:468          [game 53797945] genmove black
May 19 16:56:57   Bot.ts:163           [bot  6:85032] Thinking at most 36.5 seconds...
May 19 16:56:57   Bot.ts:163           [bot  6:85032] NN eval=0.997, tree eval=0.996; lambda=0.00, mu=0.00, interval [0.0 ; 0.0]
May 19 16:56:57   Bot.ts:163           [bot  6:85032] cpus=10
May 19 16:57:00   Bot.ts:163           [bot  6:85032] Playouts: 4487, Win: 99.46%, PV: C19 D16 M13 L13 O3

Notice the following disconnect and stopping bot:

May 19 16:57:01   GobanSocket.ts:217   GobanSocket closed with code 1006: Abnormal Closure
May 19 16:57:01   main.ts:143          Disconnected from server
May 19 16:57:01   main.ts:213          Disconnecting from game  53797945
May 19 16:57:01   Game.ts:325          [game 53797945] Releasing bot(s)
May 19 16:57:01   Game.ts:647          [game 53797945] Disconnecting from game.
May 19 16:57:01   GobanSocket.ts:289   GobanSocket reconnecting in 50ms
May 19 16:57:01   Bot.ts:741           [bot  6:85032] Stopping bot
May 19 16:57:01   GobanSocket.ts:176   GobanSocket connected to wss://online-go.com
May 19 16:57:01   socket.ts:16         Connected to https://online-go.com in 23177322ms
May 19 16:57:01   main.ts:124          Bot is username:  20bTurboLz-Elf-v1
May 19 16:57:01   main.ts:125          Bot is user id:  625990
May 19 16:57:01   main.ts:202          Connecting to game  53797945
May 19 16:57:01   Game.ts:69           [game 53797945] Connecting to game.
May 19 16:57:01   Game.ts:131          [game 53797945] gamedata       B toposlogos88  [19x19]    
May 19 16:57:01   Game.ts:402          [game 53797945] Acquiring main bot instance
May 19 16:57:01   Bot.ts:125           [bot 8] Starting  D:\lz\sai-0.18.2-gpu\sai.exe --gtp -w Elfv1.gz --noponder -v 6400 -r 1.5 --precision half --lagbuffer 100 --restrict_tt --dumbpass
May 19 16:57:01   Game.ts:131          [game 53797945] gamedata       B toposlogos88  [19x19]    
May 19 16:57:01   Game.ts:402          [game 53797945] Acquiring main bot instance
May 19 16:57:01   Game.ts:412          [bot  8:83028] [game 53797945] Acquired bot instance
May 19 16:57:01   Game.ts:412          [bot  8:83028] [game 53797945] Acquired bot instance
May 19 16:57:01   Bot.ts:163           [bot  8:83028] Using OpenCL batch size of 5
May 19 16:57:01   Bot.ts:163           [bot  8:83028] Using 10 thread(s).
May 19 16:57:01   Bot.ts:163           [bot  8:83028] RNG seed: 446072008316534503
May 19 16:57:01   Bot.ts:163           [bot  8:83028] BLAS Core: built-in Eigen 3.3.7 library.
May 19 16:57:03   Bot.ts:163           [bot  8:83028] Version 2 weights file (ELF).
May 19 16:57:03   Bot.ts:163           [bot  8:83028] Detecting residual layers... v2
May 19 16:57:03   Bot.ts:163           [bot  8:83028] 18 input planes, 8 input moves
May 19 16:57:06   Bot.ts:749           [bot  6:85032] Bot exited with code 0
May 19 16:57:07   Bot.ts:163           [bot  8:83028] 224 channels... 20 blocks
May 19 16:57:07   Bot.ts:163           [bot  8:83028] 2 policy outputs. Single value head: 1 outputs, 256 channels.
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Initializing OpenCL (half precision).
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Detected 1 OpenCL platforms.
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Platform version: OpenCL 3.0 CUDA 12.1.112
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Platform profile: FULL_PROFILE
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Platform name:    NVIDIA CUDA
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Platform vendor:  NVIDIA Corporation
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Device ID:     0
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Device name:   NVIDIA GeForce RTX 2080
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Device type:   GPU
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Device vendor: NVIDIA Corporation
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Device driver: 531.79
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Device speed:  1860 MHz
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Device cores:  46 CU
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Device score:  1130
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Selected platform: NVIDIA CUDA
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Selected device: NVIDIA GeForce RTX 2080
May 19 16:57:07   Bot.ts:163           [bot  8:83028] with OpenCL 3.0 capability.
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Half precision compute support: No.
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Tensor Core support: Yes.
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Loaded existing SGEMM tuning.
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Wavefront/Warp size: 32
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Max workgroup size: 1024
May 19 16:57:07   Bot.ts:163           [bot  8:83028] Max workgroup dimensions: 1024 1024 64
May 19 16:57:08   Bot.ts:163           [bot  8:83028] Setting max tree size to 4136 MiB and cache size to 459 MiB.
May 19 16:57:08   Bot.ts:163           [bot  8:83028] Warning: komi set to 7.5 because network does not allow variable komi.
May 19 16:57:08   Bot.ts:163           [bot  8:83028] Agent parameters (lambda, mu):
May 19 16:57:08   Bot.ts:163           [bot  8:83028] CPU,   ahead (0.50, 0.05), behind (0.30, 0.03)
May 19 16:57:08   Bot.ts:163           [bot  8:83028] human, ahead (0.00, 0.00), behind (0.00, 0.00)
May 19 16:57:08   pools.ts:203         Bot "D:\lz\sai-0.18.2-gpu\sai.exe --gtp -w Elfv1.gz --noponder -v 6400 -r 1.5 --precision half --lagbuffer 100 --restrict_tt --dumbpass" started with PID 83028. Ready in 6164ms.
May 19 16:57:08   Bot.ts:163           [bot  8:83028] Agent parameters (lambda, mu):
May 19 16:57:08   Bot.ts:163           [bot  8:83028] CPU,   ahead (0.50, 0.05), behind (0.30, 0.03)
May 19 16:57:08   Bot.ts:163           [bot  8:83028] human, ahead (0.00, 0.00), behind (0.00, 0.00)
May 19 16:57:08   Bot.ts:163           [bot  8:83028] Agent parameters (lambda, mu):
May 19 16:57:08   Bot.ts:163           [bot  8:83028] CPU,   ahead (0.50, 0.05), behind (0.30, 0.03)
May 19 16:57:08   Bot.ts:163           [bot  8:83028] human, ahead (0.00, 0.00), behind (0.00, 0.00)

Then, illegal move:

May 19 16:57:08   Bot.ts:207           [bot  8:83028] ? illegal move
May 19 16:57:08   Bot.ts:210           [bot  8:83028] 

May 19 16:57:08   Game.ts:325          [game 53797945] Releasing bot(s)
May 19 16:57:08 ! Game.ts:505          [game 53797945] Failed to start the bot, can not make a move, trying to restart
May 19 16:57:08 ! Game.ts:506          [game 53797945] illegal move
May 19 16:57:08 ! Game.ts:595          [game 53797945] illegal move
May 19 16:57:08   Game.ts:513          [game 53797945] Unable to react correctly - re-connect to trigger action based on game state.
May 19 16:57:08   Game.ts:467          [bot  8:83028] Generating move for game 53797945
May 19 16:57:08   Game.ts:468          [game 53797945] genmove black
May 19 16:57:08   Bot.ts:163           [bot  8:83028] CPU role fixed as Black.
May 19 16:57:08   Bot.ts:163           [bot  8:83028] Thinking at most 36.2 seconds...
May 19 16:57:08   Bot.ts:163           [bot  8:83028] NN eval=0.498, tree eval=0.996; lambda=0.00, mu=0.00, interval [0.0 ; 0.0]
May 19 16:57:08   Bot.ts:163           [bot  8:83028] cpus=10
May 19 16:57:08   Game.ts:117          [game 53797945] Killing bot because of gamedata change after bot was started
May 19 16:57:08   Game.ts:118          [game 53797945] Previously seen gamedata: {
  white_player_id: 1170685,
  black_player_id: 625990,
  group_ids: [],
  game_id: 53797945,
  game_name: '친선 대국',
  private: false,
  pause_on_weekends: false,
  players: {
    black: {
      username: '20bTurboLz-Elf-v1',
      rank: 36.51490964538372,
      professional: false,
      id: 625990
    },
    white: {
      username: 'toposlogos88',
      rank: 33.30041811697688,
      professional: false,
      id: 1170685
    }
  },
  ranked: true,
  disable_analysis: false,
  handicap: 0,
  komi: 7.5,
  width: 19,
  height: 19,
  rules: 'chinese',
  rengo: false,
  rengo_teams: { black: [], white: [] },
  rengo_casual_mode: false,
  time_control: {
    system: 'fischer',
    time_control: 'fischer',
    speed: 'live',
    pause_on_weekends: false,
    time_increment: 30,
    initial_time: 120,
    max_time: 300
  },
  meta_groups: [ 3211 ],
  phase: 'play',
  initial_player: 'black',
  moves: [
    [ 15, 3, 9035 ],

Omitting some game output

    [ 1, 1, 4422 ],
    [ 11, 12, 3866 ],
    [ 17, 16, 21988 ],
    ... 84 more items
  ],
  allow_self_capture: false,
  automatic_stone_removal: false,
  free_handicap_placement: true,
  aga_handicap_scoring: false,
  allow_ko: false,
  allow_superko: false,
  superko_algorithm: 'csk',
  player_pool: {
    '625990': {
      username: '20bTurboLz-Elf-v1',
      rank: 36.51490964538372,
      professional: false,
      id: 625990
    },
    '1170685': {
      username: 'toposlogos88',
      rank: 33.30041811697688,
      professional: false,
      id: 1170685
    }
  },
  score_territory: true,
  score_territory_in_seki: true,
  score_stones: true,
  score_handicap: true,
  score_prisoners: false,
  score_passes: true,
  white_must_pass_last: false,
  opponent_plays_first_after_resume: false,
  strict_seki_mode: false,
  initial_state: { black: '', white: '' },
  start_time: 1684507158,
  original_disable_analysis: false,
  state_version: 370,
  malkovich_present: true,
  latencies: { '625990': 102, '1170685': 199 },
  clock: {
    game_id: 53797945,
    current_player: 625990,
    black_player_id: 625990,
    white_player_id: 1170685,
    title: '친선 대국',
    last_move: 1684508217793,
    expiration: 1684508517793,
    black_time: { thinking_time: 300, skip_bonus: false },
    white_time: { thinking_time: 300, skip_bonus: false }
  }
}
May 19 16:57:08   Game.ts:119          [game 53797945] New gamedata: {
  white_player_id: 1170685,
  black_player_id: 625990,
  group_ids: [],
  game_id: 53797945,
  game_name: '친선 대국',
  private: false,
  pause_on_weekends: false,
  players: {
    black: {
      username: '20bTurboLz-Elf-v1',
      rank: 36.51490964538372,
      professional: false,
      id: 625990
    },
    white: {
      username: 'toposlogos88',
      rank: 33.30041811697688,
      professional: false,
      id: 1170685
    }
  },
  ranked: true,
  disable_analysis: false,
  handicap: 0,
  komi: 7.5,
  width: 19,
  height: 19,
  rules: 'chinese',
  rengo: false,
  rengo_teams: { black: [], white: [] },
  rengo_casual_mode: false,
  time_control: {
    system: 'fischer',
    time_control: 'fischer',
    speed: 'live',
    pause_on_weekends: false,
    time_increment: 30,
    initial_time: 120,
    max_time: 300
  },
  meta_groups: [ 3211 ],
  phase: 'play',
  initial_player: 'black',
  moves: [
    [ 15, 3, 9035 ],

Omitting some game output

    [ 1, 1, 4422 ],
    [ 11, 12, 3866 ],
    [ 17, 16, 21988 ],
    ... 84 more items
  ],
  allow_self_capture: false,
  automatic_stone_removal: false,
  free_handicap_placement: true,
  aga_handicap_scoring: false,
  allow_ko: false,
  allow_superko: false,
  superko_algorithm: 'csk',
  player_pool: {
    '625990': {
      username: '20bTurboLz-Elf-v1',
      rank: 36.51490964538372,
      professional: false,
      id: 625990
    },
    '1170685': {
      username: 'toposlogos88',
      rank: 33.30041811697688,
      professional: false,
      id: 1170685
    }
  },
  score_territory: true,
  score_territory_in_seki: true,
  score_stones: true,
  score_handicap: true,
  score_prisoners: false,
  score_passes: true,
  white_must_pass_last: false,
  opponent_plays_first_after_resume: false,
  strict_seki_mode: false,
  initial_state: { black: '', white: '' },
  start_time: 1684507158,
  original_disable_analysis: false,
  state_version: 370,
  malkovich_present: true,
  latencies: { '625990': 102, '1170685': 208 },
  clock: {
    game_id: 53797945,
    current_player: 625990,
    black_player_id: 625990,
    white_player_id: 1170685,
    title: '친선 대국',
    last_move: 1684508217793,
    expiration: 1684508517793,
    black_time: { thinking_time: 300, skip_bonus: false },
    white_time: { thinking_time: 300, skip_bonus: false }
  }
}
May 19 16:57:08   Game.ts:325          [game 53797945] Releasing bot(s)
May 19 16:57:08   Game.ts:131          [game 53797945] gamedata       B toposlogos88  [19x19]    
May 19 16:57:08   Game.ts:402          [game 53797945] Acquiring main bot instance
May 19 16:57:08   Game.ts:131          [game 53797945] gamedata       B toposlogos88  [19x19]    
May 19 16:57:08   Game.ts:402          [game 53797945] Acquiring main bot instance
May 19 16:57:08   Game.ts:412          [bot  8:83028] [game 53797945] Acquired bot instance
May 19 16:57:08   Game.ts:412          [bot  8:83028] [game 53797945] Acquired bot instance
May 19 16:57:08   Game.ts:467          [bot  8:83028] Generating move for game 53797945
May 19 16:57:08   Game.ts:468          [game 53797945] genmove black
May 19 16:57:08   Game.ts:467          [bot  8:83028] Generating move for game 53797945
May 19 16:57:08   Game.ts:468          [game 53797945] genmove black
May 19 16:57:10   Bot.ts:163           [bot  8:83028] Playouts: 4113, Win: 99.48%, PV: Q4 O3 C19 K3
May 19 16:57:11   Bot.ts:163           [bot  8:83028] move  visits reuse ppv winrate  agent   LCB   stdev policy fvisit alpkt w1st PV
May 19 16:57:11   PvOutputParser.ts:36 Detected engine: sai18
May 19 16:57:11   Bot.ts:163           [bot  8:83028] Q4     186     0  28  99.68% 99.68% 99.64%  0.14%  2.78%  2.90%  -0.0   5% Q4 O3 M13 L13 D16
May 19 16:57:11   Bot.ts:163           [bot  8:83028] P5      82     0  67  99.70% 99.70% 99.61%  0.18%  1.13%  1.28%  -0.0  12% P5 O3 M13 L13 D16
May 19 16:57:11   Bot.ts:163           [bot  8:83028] M12      89     0  67  99.69% 99.69% 99.60%  0.19%  1.14%  1.39%  -0.0  26% M12 M13 D16 D15 O3 O2
May 19 16:57:11   Bot.ts:163           [bot  8:83028] H10      75     0  82  99.67% 99.67% 99.57%  0.19%  0.94%  1.17%  -0.0  11% H10 Q4 P5 O3 M13

Omitting some bot output

May 19 16:57:11   Bot.ts:163           [bot  8:83028] visits reuse  de winrate  agent parent  stdev p_loss  ineff alpkt beta
May 19 16:57:11   Bot.ts:163           [bot  8:83028] Root    6419     0   5  99.46% 99.47% 99.46%  1.93%  4.89   0.26%  -0.0 1.00
May 19 16:57:11   Bot.ts:163           [bot  8:83028] Final agent lambda=0.00, mu=0.00, interval [0.0, 0.0].
May 19 16:57:11   Bot.ts:163           [bot  8:83028] 3.9 average depth, 9 max depth
May 19 16:57:11   Bot.ts:163           [bot  8:83028] 2226 non leaf nodes, 2.88 average children
May 19 16:57:11   Game.ts:325          [game 53797945] Releasing bot(s)
May 19 16:57:11   Game.ts:535          [game 53797945] Playing q4 { x: 15, y: 15, text: 'q4', resign: false, pass: false }
May 19 16:57:11   Bot.ts:163           [bot  8:83028] 6419 visits, 1123699 nodes, 6417 playouts, 1650 n/s
May 19 16:57:11   Bot.ts:163           [bot  8:83028] Thinking at most 36.2 seconds...
May 19 16:57:11   Bot.ts:163           [bot  8:83028] NN eval=0.997, tree eval=0.998; lambda=0.00, mu=0.00, interval [0.0 ; 0.0]
May 19 16:57:11   Bot.ts:163           [bot  8:83028] cpus=10

And then move_number is invalid:

May 19 16:57:12 ! Game.ts:214          Received move for 53797945 but move_number is invalid. 185 !== 186
May 19 16:57:14   Bot.ts:163           [bot  8:83028] Playouts: 3778, Win: 99.55%, PV: B10 B9 B8 D9 D8
May 19 16:57:18   Game.ts:230          [game 53797945] Opponent played k3
May 19 16:57:18   Game.ts:402          [game 53797945] Acquiring main bot instance
May 19 16:57:18 ! Game.ts:214          Received move for 53797945 but move_number is invalid. 186 !== 187
May 19 16:57:18   Game.ts:412          [bot  8:83028] [game 53797945] Acquired bot instance
May 19 16:57:18   Game.ts:467          [bot  8:83028] Generating move for game 53797945
May 19 16:57:18   Game.ts:468          [game 53797945] genmove black

And then some time later (between the log line above and below, no other mentions of game 53797945 or bot 83028 or bot 85032)

May 19 17:02:18   Game.ts:678          [game 53797945] Game over.   Result: W+Time  L
May 19 17:02:18   Game.ts:325          [game 53797945] Releasing bot(s)
May 19 17:02:18   Game.ts:697          [game 53797945] Starting disconnect Timeout in Game 53797945 gameOver()
May 19 17:02:18   Game.ts:678          [game 53797945] Game over.   Result: W+Time  L
May 19 17:02:18   Game.ts:325          [game 53797945] Releasing bot(s)
May 19 17:02:18   Game.ts:697          [game 53797945] Starting disconnect Timeout in Game 53797945 gameOver()
May 19 17:02:18   main.ts:173          game 53797945 is now finished
May 19 17:02:18   Bot.ts:741           [bot  8:83028] Stopping bot
May 19 17:02:19   main.ts:213          Disconnecting from game  53797945
May 19 17:02:19   Game.ts:325          [game 53797945] Releasing bot(s)
May 19 17:02:19   Game.ts:647          [game 53797945] Disconnecting from game.
May 19 17:02:19   main.ts:213          Disconnecting from game  53797945
May 19 17:02:23   Bot.ts:752           [bot  8:83028] Bot didn't exit after 5000ms with "quit" message, killing forcefully
anoek commented 1 year ago

This might be resolved by https://github.com/online-go/gtp2ogs/commit/1162d4ef7194739df6ee12fbf5d7bd949c524ac9

Dorus commented 1 year ago

I just had another timeout, but that was with gtp2ogs on 41fce37, one commit pre 1162d4e. I'll update and continue observing.

Timeout game: https://online-go.com/game/53973272 I can post logs if that's valuable

Dorus commented 1 year ago

Been observing my bots, no timeouts so far.

anoek commented 1 year ago

Thanks for the followup, closing as fixed