Pokemon FRLG Magikarp shiny hunting issue #1124
Description
I was trying to hunt for a shiny Magikarp, but the program behaved incorrectly. I recorded the process here: recoding
Below is the log. It looks like that after pressing B to reject naming the Magikarp, the program never pressed BUTTON_PLUS.
2026-03-09 00:54:51.960159 - [Program]: Starting program...
2026-03-09 00:54:51.960162 - [Program]: Program State: RUNNING
2026-03-09 00:54:51.960292 - [Program]: Loading historical stats...
2026-03-09 00:54:51.960432 - [Global]: Setting sleep state to: No Sleep
2026-03-09 00:54:51.960450 - [Program]: Starting Program: PokemonFRLG:GiftReset
2026-03-09 00:54:51.962400 - [Console 0]: ConvertFrame: Count = 2, Mean = 2.211ms, Stddev = 1.67584ms, Min = 1.026ms, Max = 3.396ms
2026-03-09 00:54:51.962417 - [Console 0]: Going to home to check for black border.
2026-03-09 00:54:51.962421 - [Console 0]: Going Home...
2026-03-09 00:54:51.962595 - [Console 0]: issue_buttons(): HOME, delay = 160ms, hold = 160ms, cooldown = 0ms
2026-03-09 00:54:51.963130 - [Console 0]: wait_for_all()
2026-03-09 00:54:51.963139 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:52.685666 - [Console 0]: Setting console type to: Switch 1 + OLED
2026-03-09 00:54:52.685762 - [Console 0]: HomeMenuWatcher: Count = 11, Mean = 0.203636 ms, Stddev = 0.149495 ms, Min = 0.043 ms, Max = 0.492 ms
2026-03-09 00:54:52.685796 - [Console 0]: Home detected.
2026-03-09 00:54:52.693630 - [Console 0]: wait_for_all()
2026-03-09 00:54:52.693645 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:52.904734 - [Console 0]: HomeMenuWatcher: Count = 5, Mean = 0.41 ms, Stddev = 0.114695 ms, Min = 0.222 ms, Max = 0.503 ms
2026-03-09 00:54:52.904776 - [Console 0]: Home detected.
2026-03-09 00:54:52.904780 - [Console 0]: wait_for_all()
2026-03-09 00:54:52.904785 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:52.910159 - [Console 0]: Returning to game.
2026-03-09 00:54:52.910377 - [Console 0]: issue_buttons(): HOME, delay = 160ms, hold = 80ms, cooldown = 0ms
2026-03-09 00:54:52.910388 - [Console 0]: wait_for_all()
2026-03-09 00:54:52.910392 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:54.091565 - [Console 0]: UpdateMenuWatcher: Count = 19, Mean = 0.0276316 ms, Stddev = 0.0271625 ms, Min = 0.007 ms, Max = 0.125 ms
2026-03-09 00:54:54.093065 - [Console 0]: wait_for_all()
2026-03-09 00:54:54.093082 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:54.093086 - [Console 0]: Entered game.
2026-03-09 00:54:54.093089 - [Program]: Obtaining Pokemon.
2026-03-09 00:54:54.093435 - [Console 0]: issue_buttons(): A, delay = 960ms, hold = 320ms, cooldown = 0ms
2026-03-09 00:54:54.093612 - [Console 0]: issue_nop(): duration = 2000ms
2026-03-09 00:54:54.093619 - [Console 0]: wait_for_all()
2026-03-09 00:54:54.093624 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:55.606083 - [Console 0]: Sending: (0x4b) PABB_MSG_REQUEST_STOP: seqnum = 1275
2026-03-09 00:54:55.606235 - [Console 0]: Clearing all active commands... (Commands: 1)
2026-03-09 00:54:55.606305 - [Console 0]: AdvanceWhiteDialogWatcher: Count = 31, Mean = 0.518645 ms, Stddev = 0.124826 ms, Min = 0.356 ms, Max = 0.816 ms
2026-03-09 00:54:55.606324 - [Console 0]: wait_for_all()
2026-03-09 00:54:55.606339 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:55.652892 - [Program]: Initial A press completed.
2026-03-09 00:54:55.652910 - [Console 0]: wait_for_all()
2026-03-09 00:54:55.652915 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:55.920434 - [Console 0]: SelectionDialogWatcher: Count = 5, Mean = 0.0446 ms, Stddev = 0.0127004 ms, Min = 0.029 ms, Max = 0.06 ms
2026-03-09 00:54:55.920455 - [Console 0]: AdvanceWhiteDialogWatcher: Count = 6, Mean = 0.573833 ms, Stddev = 0.13743 ms, Min = 0.418 ms, Max = 0.804 ms
2026-03-09 00:54:56.431531 - [Program]: Detected Advance Dialog. Pressing B.
2026-03-09 00:54:56.431783 - [Console 0]: issue_buttons(): B, delay = 960ms, hold = 320ms, cooldown = 0ms
2026-03-09 00:54:56.431793 - [Console 0]: wait_for_all()
2026-03-09 00:54:56.431797 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:58.012512 - [Console 0]: SelectionDialogWatcher: Count = 11, Mean = 0.0388182 ms, Stddev = 0.0159551 ms, Min = 0.022 ms, Max = 0.073 ms
2026-03-09 00:54:58.012555 - [Console 0]: AdvanceWhiteDialogWatcher: Count = 12, Mean = 0.590917 ms, Stddev = 0.181235 ms, Min = 0.407 ms, Max = 0.988 ms
2026-03-09 00:54:58.515623 - [Program]: Detected Advance Dialog. Pressing B.
2026-03-09 00:54:58.515963 - [Console 0]: issue_buttons(): B, delay = 960ms, hold = 320ms, cooldown = 0ms
2026-03-09 00:54:58.515975 - [Console 0]: wait_for_all()
2026-03-09 00:54:58.515980 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:54:59.840462 - [Console 0]: SelectionDialogWatcher: Count = 7, Mean = 0.0357143 ms, Stddev = 0.0108737 ms, Min = 0.025 ms, Max = 0.054 ms
2026-03-09 00:54:59.840518 - [Console 0]: AdvanceWhiteDialogWatcher: Count = 7, Mean = 0.586429 ms, Stddev = 0.113405 ms, Min = 0.44 ms, Max = 0.788 ms
2026-03-09 00:55:00.354961 - [Program]: Detected Selection Dialog. Pressing A.
2026-03-09 00:55:00.355043 - [Program]: First selection box detected. YES to starter.
2026-03-09 00:55:00.355245 - [Console 0]: issue_buttons(): A, delay = 960ms, hold = 320ms, cooldown = 0ms
2026-03-09 00:55:00.355777 - [Console 0]: issue_buttons(): B, delay = 960ms, hold = 320ms, cooldown = 0ms
2026-03-09 00:55:00.356026 - [Console 0]: issue_nop(): duration = 500ms
2026-03-09 00:55:00.356031 - [Console 0]: wait_for_all()
2026-03-09 00:55:00.356035 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:55:02.788863 - [Console 0]: issue_buttons(): B, delay = 960ms, hold = 320ms, cooldown = 0ms
2026-03-09 00:55:02.788883 - [Console 0]: wait_for_all()
2026-03-09 00:55:02.788887 - [Console 0]: Waiting for all requests to finish...
2026-03-09 00:55:02.804691 - [Console 0]: Receive: (0x24) PABB_MSG_INFO_I32_LABEL: Report Failed: Cooldown: 14750
2026-03-09 00:55:02.804706 - [Console 0]: Receive: (0x24) PABB_MSG_INFO_I32_LABEL: Reported Delayed: 472
2026-03-09 00:55:03.756646 - [Console 0]: ConvertFrame: Count = 97, Mean = 3.43759ms, Stddev = 2.85424ms, Min = 0.868ms, Max = 9.88ms
2026-03-09 00:55:13.758181 - [Console 0]: SelectionDialogWatcher: Count = 199, Mean = 0.00481407 ms, Stddev = 0.00241431 ms, Min = 0.003 ms, Max = 0.023 ms
2026-03-09 00:55:13.758786 - [Console 0]: AdvanceWhiteDialogWatcher: Count = 199, Mean = 0.567945 ms, Stddev = 0.154724 ms, Min = 0.353 ms, Max = 1.34 ms
2026-03-09 00:55:13.759399 - [Console 0]: ConvertFrame: Count = 200, Mean = 2.66926ms, Stddev = 2.23184ms, Min = 0.905ms, Max = 11.649ms
2026-03-09 00:55:14.273646 - [Program]: Current Stats: Resets: 0 - Shinies: 0 - Errors: 1
2026-03-09 00:55:14.274916 - [Console 0]: OperationFailedException: obtain_starter(): No recognized state after 10 seconds.
2026-03-09 00:55:14.274982 - [Console 0]: Sending: (0x4b) PABB_MSG_REQUEST_STOP: seqnum = 1344
2026-03-09 00:55:14.275041 - [Console 0]: Clearing all active commands... (Commands: 0)
2026-03-09 00:55:14.275073 - [Program]: Program stopped with an exception!
2026-03-09 00:55:14.275327 - [Program]: Compiling Error Report...