Trough switches not working in build

[arthurkehrwald]

The trough switches behave differently in builds vs development builds or the editor.
In the editor or in a development build, they work fine:
Screen Recording 2024-09-22 204032.webm
But in a non-development build, the second switch does not close again after ejecting a ball.
Screen Recording 2024-09-22 204201.webm
This causes MPF to think two balls have left the through and that there is still a ball on the playfield left when the one ball that ejected drains, breaking the game:

2024-09-22 20:41:05,069 : INFO : root : Loading config.
2024-09-22 20:41:05,078 : INFO : YamlMultifileConfigLoader : Machine config file #1: config.yaml
2024-09-22 20:41:05,078 : INFO : ConfigProcessor : Loading config from cache: C:\Users\arthu\AppData\Local\Temp\bd944a774611c15be3c40d59cbc2f7ac.mpf_cache
2024-09-22 20:41:05,145 : DEBUG : YamlMultifileConfigLoader : Loading mode attract from C:\Users\arthu\AppData\Local\Programs\Python\Python39\lib\site-packages\mpf\modes\attract\config\attract.yaml
2024-09-22 20:41:05,145 : INFO : ConfigProcessor : Loading config from cache: C:\Users\arthu\AppData\Local\Temp\fe7d5e4b8bf55d6b7133f9f98e72ca1c.mpf_cache
2024-09-22 20:41:05,145 : DEBUG : YamlMultifileConfigLoader : Loading mode game from C:\Users\arthu\AppData\Local\Programs\Python\Python39\lib\site-packages\mpf\modes\game\config\game.yaml
2024-09-22 20:41:05,146 : INFO : ConfigProcessor : Loading config from cache: C:\Users\arthu\AppData\Local\Temp\65bdddfbb73565ff4188fea38cd5c9d6.mpf_cache
2024-09-22 20:41:05,146 : INFO : Machine : Mission Pinball Framework Core Engine v0.57.2
2024-09-22 20:41:05,146 : INFO : Machine : Command line arguments: {'no_load_cache': False, 'create_config_cache': True, 'bcp': False, 'configfile': ['config.yaml'], 'force_assets_load': False, 'platform_integration_test': False, 'jsonlogging': False, 'logfile': 'logs\\2024-09-22-20-41-05-mpf-arthurs-laptop.log', 'pause': False, 'production': False, 'text_ui': True, 'loglevel': 10, 'consoleloglevel': 10, 'force_platform': None, 'syslog_address': None, 'mc_file_name': None, 'no_sound': False}
2024-09-22 20:41:05,146 : INFO : Machine : MPF path: C:\Users\arthu\AppData\Local\Programs\Python\Python39\lib\site-packages\mpf
2024-09-22 20:41:05,146 : INFO : Machine : Machine path: C:\Users\arthu\Downloads\FutureBoxPinballBuilds\240922-2023\FutureBoxPinball_Data\StreamingAssets\MachineFolder
2024-09-22 20:41:05,146 : INFO : Machine : Platform: win32
2024-09-22 20:41:05,146 : INFO : Machine : Python executable location: C:\Users\arthu\AppData\Local\Programs\Python\Python39\python.exe
2024-09-22 20:41:05,147 : INFO : Machine : Python version: 3.9.13 (64-bit)
2024-09-22 20:41:05,148 : DEBUG : asyncio : Using proactor: IocpProactor
2024-09-22 20:41:05,148 : INFO : Machine : Initializing MPF...
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,219 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D8495D040>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D84AA11E0>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D84AA12B0>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Blur: <asciimatics.widgets.layout.Layout object at 0x0000019D84A9BB20>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Blur: <mpf.core.text_ui.MpfLayout object at 0x0000019D84A947B0>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D84AA16C0>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D84AA15F0>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D84AA1790>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D84AA1520>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D84AA1450>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.widget : Widget blur: <asciimatics.widgets.label.Label object at 0x0000019D84AA1380>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Blur: <asciimatics.widgets.layout.Layout object at 0x0000019D84A9BBE0>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Focus: <asciimatics.widgets.layout.Layout object at 0x0000019D84A9BB20>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Focus: <mpf.core.text_ui.MpfLayout object at 0x0000019D84A947B0>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Focus: <asciimatics.widgets.layout.Layout object at 0x0000019D84A9BBE0>
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.frame : Cloning: Test
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,220 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,221 : DEBUG : asciimatics.widgets.layout : Updating: None
2024-09-22 20:41:05,302 : DEBUG : grpc._cython.cygrpc : Using AsyncIOEngine.POLLER as I/O engine
2024-09-22 20:41:05,306 : INFO : VPE Platform : Starting server on [::]:50051
2024-09-22 20:41:05,914 : INFO : VPE Platform : VPE connected
2024-09-22 20:41:05,914 : DEBUG : VPE Platform : Got response initial_switch_states {
  key: "0"
  value: false
}
initial_switch_states {
  key: "1"
  value: false
}
initial_switch_states {
  key: "2"
  value: true
}
initial_switch_states {
  key: "3"
  value: true
}
initial_switch_states {
  key: "4"
  value: true
}
initial_switch_states {
  key: "5"
  value: true
}
initial_switch_states {
  key: "6"
  value: false
}
initial_switch_states {
  key: "7"
  value: false
}
initial_switch_states {
  key: "8"
  value: false
}
initial_switch_states {
  key: "9"
  value: false
}

2024-09-22 20:41:05,916 : INFO : EventManager : Event: ======'machine_var_credits_string'====== Args={'value': 'FREE PLAY', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,957 : DEBUG : YAML File Interface : Loading file: C:\Users\arthu\Downloads\FutureBoxPinballBuilds\240922-2023\FutureBoxPinball_Data\StreamingAssets\MachineFolder\data/machine_vars.yaml
2024-09-22 20:41:05,960 : INFO : EventManager : Event: ======'machine_var_master_volume'====== Args={'value': 0.5, 'prev_value': None, 'change': True}
2024-09-22 20:41:05,960 : INFO : EventManager : Event: ======'machine_var_player1_score'====== Args={'value': 0, 'prev_value': None, 'change': True}
2024-09-22 20:41:05,960 : INFO : EventManager : Event: ======'machine_var_mpf_version'====== Args={'value': 'Mission Pinball Framework v0.57.2', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,960 : INFO : EventManager : Event: ======'machine_var_mpf_extended_version'====== Args={'value': 'Mission Pinball Framework v0.57.2, Config version:6, Show version: 6, BCP version:1.1', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,960 : INFO : EventManager : Event: ======'machine_var_python_version'====== Args={'value': '3.9.13', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,969 : INFO : EventManager : Event: ======'machine_var_platform'====== Args={'value': 'Windows-10-10.0.22631-SP0', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,970 : INFO : EventManager : Event: ======'machine_var_platform_system'====== Args={'value': 'Windows', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,970 : INFO : EventManager : Event: ======'machine_var_platform_release'====== Args={'value': '10', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,970 : INFO : EventManager : Event: ======'machine_var_platform_version'====== Args={'value': '10.0.22631', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,970 : INFO : EventManager : Event: ======'machine_var_platform_machine'====== Args={'value': 'AMD64', 'prev_value': None, 'change': True}
2024-09-22 20:41:05,970 : INFO : EventManager : Event: ======'init_phase_1'====== Args={}
2024-09-22 20:41:05,974 : DEBUG : ModeController : Loaded mode game
2024-09-22 20:41:05,977 : DEBUG : ModeController : Loaded mode attract
2024-09-22 20:41:05,979 : DEBUG : ball_device.bd_trough : Configuring device with settings: '{'ball_switches': 's_trough1, s_trough2, s_trough3, s_trough4', 'eject_coil': 'c_trough_eject', 'eject_coil_jam_pulse': '15ms', 'eject_targets': [<ball_device.bd_plunger>], 'tags': ['trough', 'home', 'drain'], 'eject_timeouts': [3000], 'debug': True, 'label': '%', 'console_log': 'full', 'file_log': 'full', 'entrance_events': {}, 'idle_missing_ball_timeout': 5.0, 'confirm_eject_type': 'target', 'captures_from': <playfield.playfield>, 'ball_missing_timeouts': [], 'ball_missing_target': <playfield.playfield>, 'confirm_eject_switch': None, 'confirm_eject_event': None, 'max_eject_attempts': 0, 'request_ball_events': {}, 'eject_events': {}, 'eject_all_events': {}, 'mechanical_eject': False, 'player_controlled_eject_event': None, 'ball_search_order': 200, 'auto_fire_on_unexpected_ball': True, 'target_on_unexpected_ball': None}'
2024-09-22 20:41:05,984 : INFO : EventManager : Event: ======'init_phase_2'====== Args={}
2024-09-22 20:41:05,984 : INFO : SwitchController : Found active switch: ('2', <mpf.platforms.visual_pinball_engine.visual_pinball_engine.VisualPinballEnginePlatform object at 0x0000019D848CBEE0>) <switch.s_trough1>
2024-09-22 20:41:05,984 : INFO : SwitchController : Found active switch: ('3', <mpf.platforms.visual_pinball_engine.visual_pinball_engine.VisualPinballEnginePlatform object at 0x0000019D848CBEE0>) <switch.s_trough2>
2024-09-22 20:41:05,984 : INFO : SwitchController : Found active switch: ('4', <mpf.platforms.visual_pinball_engine.visual_pinball_engine.VisualPinballEnginePlatform object at 0x0000019D848CBEE0>) <switch.s_trough3>
2024-09-22 20:41:05,984 : INFO : SwitchController : Found active switch: ('5', <mpf.platforms.visual_pinball_engine.visual_pinball_engine.VisualPinballEnginePlatform object at 0x0000019D848CBEE0>) <switch.s_trough4>
2024-09-22 20:41:05,985 : DEBUG : ball_device.bd_trough : SC: Counted 4 balls. Active switches: [<switch.s_trough3>, <switch.s_trough1>, <switch.s_trough2>, <switch.s_trough4>]. Old: None
2024-09-22 20:41:05,985 : DEBUG : ball_device.bd_trough : SC: New count 4 last: None
2024-09-22 20:41:05,985 : INFO : ball_device.bd_trough : BCH: Initial count: 4
2024-09-22 20:41:05,985 : INFO : ball_device.bd_trough : State: idle
2024-09-22 20:41:05,985 : DEBUG : ball_device.bd_trough : Waiting for eject request.
2024-09-22 20:41:05,985 : INFO : ball_device.bd_plunger : BCH: Initial count: 0
2024-09-22 20:41:05,986 : INFO : ball_device.bd_plunger : State: idle
2024-09-22 20:41:05,987 : DEBUG : YAML File Interface : Loading file: C:\Users\arthu\Downloads\FutureBoxPinballBuilds\240922-2023\FutureBoxPinball_Data\StreamingAssets\MachineFolder\data/audits.yaml
2024-09-22 20:41:06,007 : DEBUG : Machine : "info_lights:" section not found in machine configuration, so the InfoLights will not be used.
2024-09-22 20:41:06,008 : DEBUG : Machine : "switch_player:" section not found in machine configuration, so the SwitchPlayer will not be used.
2024-09-22 20:41:06,011 : DEBUG : Machine : "twitch_client:" section not found in machine configuration, so the TwitchBot will not be used.
2024-09-22 20:41:06,011 : DEBUG : Machine : "virtual_segment_display_connector:" section not found in machine configuration, so the VirtualSegmentDisplayConnector will not be used.
2024-09-22 20:41:06,011 : INFO : EventManager : Event: ======'init_phase_3'====== Args={}
2024-09-22 20:41:06,011 : DEBUG : ShowController : Loading show: flash
2024-09-22 20:41:06,011 : DEBUG : ShowController : Loading show: on
2024-09-22 20:41:06,011 : DEBUG : ShowController : Loading show: off
2024-09-22 20:41:06,012 : DEBUG : ShowController : Loading show: led_color
2024-09-22 20:41:06,012 : DEBUG : ShowController : Loading show: bl_color
2024-09-22 20:41:06,012 : DEBUG : ShowController : Loading show: flash_color
2024-09-22 20:41:06,012 : INFO : EventManager : Event: ======'init_phase_4'====== Args={}
2024-09-22 20:41:06,012 : DEBUG : ball_device.bd_trough : SC: Counted 4 balls. Active switches: [<switch.s_trough3>, <switch.s_trough1>, <switch.s_trough2>, <switch.s_trough4>]. Old: 4
2024-09-22 20:41:06,012 : INFO : BallController : Initial balls found: 4
2024-09-22 20:41:06,013 : INFO : EventManager : Event: ======'machine_var_audits_events_game_ended'====== Args={'value': 11, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,013 : INFO : EventManager : Event: ======'machine_var_audits_events_game_started'====== Args={'value': 28, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,013 : INFO : EventManager : Event: ======'machine_var_audits_missing_switches_s_launch_button'====== Args={'value': 2, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,013 : INFO : EventManager : Event: ======'machine_var_audits_missing_switches_s_left_flipper'====== Args={'value': 5, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,014 : INFO : EventManager : Event: ======'machine_var_audits_missing_switches_s_plunger_lane_exit'====== Args={'value': 3, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,014 : INFO : EventManager : Event: ======'machine_var_audits_missing_switches_s_right_flipper'====== Args={'value': 5, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,014 : INFO : EventManager : Event: ======'machine_var_audits_missing_switches_s_start'====== Args={'value': 6, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,014 : INFO : EventManager : Event: ======'machine_var_audits_missing_switches_s_trough2'====== Args={'value': 2, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,014 : INFO : EventManager : Event: ======'machine_var_audits_missing_switches_s_trough3'====== Args={'value': 2, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,014 : INFO : EventManager : Event: ======'machine_var_audits_missing_switches_s_trough4'====== Args={'value': 3, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,014 : INFO : EventManager : Event: ======'machine_var_audits_player_score'====== Args={'value': {'average': 0, 'top': [0, 0, 0, 0, 0, 0, 0, 0, 0, 0], 'total': 11}, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_launch_button'====== Args={'value': 90, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_left_flipper'====== Args={'value': 331, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_plunger_lane'====== Args={'value': 65, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_plunger_lane_exit'====== Args={'value': 20, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_right_flipper'====== Args={'value': 299, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_start'====== Args={'value': 9, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_trough1'====== Args={'value': 65, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_trough2'====== Args={'value': 63, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,015 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_trough3'====== Args={'value': 63, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,016 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_trough4'====== Args={'value': 48, 'prev_value': None, 'change': True}
2024-09-22 20:41:06,016 : INFO : EventManager : Event: ======'init_phase_5'====== Args={}
2024-09-22 20:41:06,016 : DEBUG : asciimatics.screen : Processing mouse: 48, 4
2024-09-22 20:41:06,016 : DEBUG : asciimatics.widgets.frame : New event: MouseEvent (48, 4) 0
2024-09-22 20:41:06,041 : INFO : EventManager : Event: ======'init_done'====== Args={}
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'machine_reset_phase_1'====== Args={}
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'machine_reset_phase_2'====== Args={}
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'machine_reset_phase_3'====== Args={}
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'reset_complete'====== Args={}
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'mode_attract_will_start'====== Args={}
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'mode_attract_starting'====== Args={}
2024-09-22 20:41:06,042 : INFO : Mode.attract : Started. Priority: 10
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'modes_active_modes_changed'====== Args={}
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'mode_attract_started'====== Args={}
2024-09-22 20:41:06,042 : INFO : EventManager : Event: ======'collecting_balls_complete'====== Args={}
2024-09-22 20:41:06,044 : DEBUG : asciimatics.screen : Processing mouse: 51, 1
2024-09-22 20:41:06,044 : DEBUG : asciimatics.widgets.frame : New event: MouseEvent (51, 1) 0
2024-09-22 20:41:06,057 : INFO : Machine : Starting the main run loop.
2024-09-22 20:41:06,222 : DEBUG : asciimatics.screen : Processing mouse: 55, 0
2024-09-22 20:41:06,222 : DEBUG : asciimatics.widgets.frame : New event: MouseEvent (55, 0) 0
2024-09-22 20:41:10,226 : DEBUG : asciimatics.screen : Processing mouse: 104, 19
2024-09-22 20:41:10,226 : DEBUG : asciimatics.widgets.frame : New event: MouseEvent (104, 19) 0
2024-09-22 20:41:11,235 : DEBUG : asciimatics.screen : Processing mouse: 119, 29
2024-09-22 20:41:11,236 : DEBUG : asciimatics.widgets.frame : New event: MouseEvent (119, 29) 0
2024-09-22 20:41:14,575 : DEBUG : VPE Platform : Got Switch Change: switch_number: "0"
switch_state: true

2024-09-22 20:41:14,575 : INFO : SwitchController : <<<<<<< 's_left_flipper' active >>>>>>>
2024-09-22 20:41:15,089 : DEBUG : VPE Platform : Got Switch Change: switch_number: "0"

2024-09-22 20:41:15,089 : INFO : SwitchController : <<<<<<< 's_left_flipper' inactive >>>>>>>
2024-09-22 20:41:40,189 : DEBUG : VPE Platform : Got Switch Change: switch_number: "8"
switch_state: true

2024-09-22 20:41:40,189 : INFO : SwitchController : <<<<<<< 's_start' active >>>>>>>
2024-09-22 20:41:41,182 : DEBUG : VPE Platform : Got Switch Change: switch_number: "8"

2024-09-22 20:41:41,182 : INFO : SwitchController : <<<<<<< 's_start' inactive >>>>>>>
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'request_to_start_game'====== Args={}
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'game_start'====== Args={'buttons': [], 'hold_time': 1.0}
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'mode_game_will_start'====== Args={'buttons': [], 'hold_time': 1.0}
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'mode_game_starting'====== Args={'buttons': [], 'hold_time': 1.0}
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'mode_attract_will_stop'====== Args={}
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'mode_attract_stopping'====== Args={}
2024-09-22 20:41:41,184 : INFO : Mode.attract : Stopped.
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'modes_active_modes_changed'====== Args={}
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'mode_attract_stopped'====== Args={}
2024-09-22 20:41:41,184 : INFO : EventManager : Event: ======'clear'====== Args={'key': 'attract'}
2024-09-22 20:41:41,186 : INFO : Mode.game : Started. Priority: 20
2024-09-22 20:41:41,186 : INFO : EventManager : Event: ======'modes_active_modes_changed'====== Args={}
2024-09-22 20:41:41,186 : INFO : EventManager : Event: ======'mode_game_started'====== Args={'buttons': [], 'hold_time': 1.0}
2024-09-22 20:41:41,192 : INFO : EventManager : Event: ======'game_will_start'====== Args={}
2024-09-22 20:41:41,192 : INFO : EventManager : Event: ======'game_starting'====== Args={'game': <Mode.game>}
2024-09-22 20:41:41,192 : DEBUG : Auditor : Enabling the Auditor
2024-09-22 20:41:41,192 : INFO : EventManager : Unordered handler for class <Auditor> on event game_ended with priority 1. Handlers: [RegisteredHandler(callback=<bound method Auditor.disable of <Auditor>>, priority=1, kwargs={}, key=UUID('2e3d4c82-2244-4d4e-a4f4-5d64ef32af01'), condition=None, blocking_facility=None), RegisteredHandler(callback=<bound method Auditor._save_audits of <Auditor>>, priority=1, kwargs={}, key=UUID('d310f41a-bfb7-48f6-a547-ea9973e07051'), condition=None, blocking_facility=None)]. The order of those handlers is not defined and they will be executed in random order. This might lead to race conditions and potential bugs.
2024-09-22 20:41:41,192 : INFO : EventManager : Event: ======'player_add_request'====== Args={}
2024-09-22 20:41:41,193 : INFO : EventManager : Event: ======'player_will_add'====== Args={'number': 1}
2024-09-22 20:41:41,193 : DEBUG : Player : Creating new player: Player 1. (player index '0')
2024-09-22 20:41:41,193 : DEBUG : Player : Setting 'score' to: 0, (prior: 0, change: 0)
2024-09-22 20:41:41,193 : INFO : EventManager : Event: ======'player_adding'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:41,193 : INFO : EventManager : Event: ======'player_added'====== Args={'player': <Player 1>, 'num': 1}
2024-09-22 20:41:41,193 : INFO : Mode.game : Player added successfully. Total players: 1
2024-09-22 20:41:41,193 : INFO : EventManager : Event: ======'player_index'====== Args={'value': 0, 'prev_value': 0, 'change': 0, 'player_num': 1}
2024-09-22 20:41:41,193 : INFO : EventManager : Event: ======'player_number'====== Args={'value': 1, 'prev_value': 1, 'change': 0, 'player_num': 1}
2024-09-22 20:41:41,193 : INFO : EventManager : Event: ======'player_score'====== Args={'value': 0, 'prev_value': 0, 'change': 0, 'player_num': 1}
2024-09-22 20:41:41,194 : INFO : EventManager : Event: ======'game_started'====== Args={}
2024-09-22 20:41:41,201 : INFO : EventManager : Event: ======'player_turn_will_start'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:41,202 : INFO : EventManager : Event: ======'player_turn_starting'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:41,202 : DEBUG : Player : Setting 'ball' to: 1, (prior: 0, change: 1)
2024-09-22 20:41:41,202 : INFO : EventManager : Event: ======'player_ball'====== Args={'value': 1, 'prev_value': 0, 'change': 1, 'player_num': 1}
2024-09-22 20:41:41,202 : INFO : EventManager : Event: ======'player_turn_started'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:41,203 : INFO : EventManager : Event: ======'ball_will_start'====== Args={'player': 1, 'ball': 1, 'balls_remaining': 2, 'is_extra_ball': False}
2024-09-22 20:41:41,205 : INFO : EventManager : Event: ======'ball_starting'====== Args={'player': 1, 'ball': 1, 'balls_remaining': 2, 'is_extra_ball': False}
2024-09-22 20:41:41,207 : INFO : EventManager : Event: ======'balls_in_play'====== Args={'balls': 1}
2024-09-22 20:41:41,207 : INFO : EventManager : Event: ======'ball_started'====== Args={'player': 1, 'ball': 1, 'balls_remaining': 2, 'is_extra_ball': False}
2024-09-22 20:41:41,208 : INFO : EventManager : Event: ======'single_player_ball_started'====== Args={}
2024-09-22 20:41:41,209 : INFO : EventManager : Event: ======'ball_start_target'====== Args={'target': 'playfield'}
2024-09-22 20:41:41,209 : INFO : ball_device.bd_plunger : Setting up player-controlled eject. Balls: 1, Target: <playfield.playfield>, player_controlled_eject_event: s_launch_button_active
2024-09-22 20:41:41,209 : DEBUG : ball_device.bd_trough : Adding eject chain
2024-09-22 20:41:41,209 : INFO : EventManager : Event: ======'balldevice_balls_available'====== Args={}
2024-09-22 20:41:41,209 : DEBUG : ball_device.bd_trough : Got eject request
2024-09-22 20:41:41,210 : DEBUG : ball_device.bd_trough : BCH: Counting. New count: 4 Old count: 4
2024-09-22 20:41:41,210 : INFO : ball_device.bd_trough : State: waiting_for_target_ready
2024-09-22 20:41:41,210 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_eject_attempt'====== Args={'balls': 1, 'target': <ball_device.bd_plunger>, 'source': <ball_device.bd_trough>, 'mechanical_eject': True, 'num_attempts': 0}
2024-09-22 20:41:41,210 : INFO : ball_device.bd_plunger : State: waiting_for_ball
2024-09-22 20:41:41,229 : INFO : ball_device.bd_trough : State: ejecting
2024-09-22 20:41:41,229 : INFO : ball_device.bd_trough : Ejecting ball to <ball_device.bd_plunger>
2024-09-22 20:41:41,229 : INFO : EventManager : Event: ======'balldevice_bd_trough_ejecting_ball'====== Args={'balls': 1, 'target': <ball_device.bd_plunger>, 'source': <ball_device.bd_trough>, 'mechanical_eject': True, 'num_attempts': 0}
2024-09-22 20:41:41,234 : DEBUG : ball_device.bd_trough : Entered eject mode.
2024-09-22 20:41:41,235 : INFO : ball_device.bd_trough : Wait for ball to leave device
2024-09-22 20:41:41,235 : INFO : coil.c_trough_eject : Pulsing Driver for 20ms (1.0 pulse_power)
2024-09-22 20:41:41,236 : DEBUG : ball_device.bd_trough : Firing eject coil. Current balls: 4.
2024-09-22 20:41:41,272 : DEBUG : VPE Platform : Got Switch Change: switch_number: "2"

2024-09-22 20:41:41,272 : INFO : SwitchController : <<<<<<< 's_trough1' inactive >>>>>>>
2024-09-22 20:41:41,276 : DEBUG : ball_device.bd_trough : SC: Ball left. Old count: 4
2024-09-22 20:41:41,277 : DEBUG : ball_device.bd_trough : Got ball left during eject
2024-09-22 20:41:41,277 : DEBUG : ball_device.bd_trough : SC: Switch 's_trough1' changed too recently. Aborting count!
2024-09-22 20:41:41,277 : INFO : ball_device.bd_trough : State: ball_left
2024-09-22 20:41:41,277 : INFO : ball_device.bd_trough : Ball left
2024-09-22 20:41:41,277 : INFO : ball_device.bd_trough : Wait for confirm with timeout 3.0
2024-09-22 20:41:41,405 : DEBUG : VPE Platform : Got Switch Change: switch_number: "3"

2024-09-22 20:41:41,406 : INFO : SwitchController : <<<<<<< 's_trough2' inactive >>>>>>>
2024-09-22 20:41:41,413 : DEBUG : VPE Platform : Got Switch Change: switch_number: "5"

2024-09-22 20:41:41,414 : INFO : SwitchController : <<<<<<< 's_trough4' inactive >>>>>>>
2024-09-22 20:41:41,471 : DEBUG : VPE Platform : Got Switch Change: switch_number: "6"
switch_state: true

2024-09-22 20:41:41,472 : INFO : SwitchController : <<<<<<< 's_plunger_lane' active >>>>>>>
2024-09-22 20:41:41,472 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_plunger_lane'====== Args={'value': 66, 'prev_value': 65, 'change': 1}
2024-09-22 20:41:41,555 : DEBUG : VPE Platform : Got Switch Change: switch_number: "2"
switch_state: true

2024-09-22 20:41:41,555 : INFO : SwitchController : <<<<<<< 's_trough1' active >>>>>>>
2024-09-22 20:41:41,555 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_trough1'====== Args={'value': 66, 'prev_value': 65, 'change': 1}
2024-09-22 20:41:41,560 : DEBUG : VPE Platform : Got Switch Change: switch_number: "4"
switch_state: true

2024-09-22 20:41:41,560 : WARNING : SwitchController : Received duplicate switch state 1 for switch s_trough3 from the platform interface. Log Code: Log-SwitchController-1 (https://missionpinball.org/logs)
2024-09-22 20:41:41,911 : DEBUG : ball_device.bd_trough : SC: Switch 's_trough1' changed too recently. Aborting count!
2024-09-22 20:41:41,974 : INFO : ball_device.bd_plunger : Received ball from <ball_device.bd_trough>
2024-09-22 20:41:41,974 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ball_enter'====== Args={'new_balls': 1, 'unclaimed_balls': 0, 'new_available_balls': 0, 'device': <ball_device.bd_plunger>}
2024-09-22 20:41:41,974 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ball_entered'====== Args={'new_balls': 0, 'device': <ball_device.bd_plunger>}
2024-09-22 20:41:41,974 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ball_count_changed'====== Args={'balls': 1}
2024-09-22 20:41:41,975 : INFO : ball_device.bd_trough : Got eject confirm
2024-09-22 20:41:41,975 : INFO : ball_device.bd_trough : Eject successful
2024-09-22 20:41:41,975 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_eject_success'====== Args={'balls': 1, 'target': <ball_device.bd_plunger>}
2024-09-22 20:41:41,975 : INFO : ball_device.bd_plunger : State: waiting_for_target_ready
2024-09-22 20:41:41,975 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ball_eject_attempt'====== Args={'balls': 1, 'target': <playfield.playfield>, 'source': <ball_device.bd_plunger>, 'mechanical_eject': True, 'num_attempts': 0}
2024-09-22 20:41:41,975 : DEBUG : ball_device.bd_trough : Exited eject mode. Eject success: True
2024-09-22 20:41:41,975 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_count_changed'====== Args={'balls': 3}
2024-09-22 20:41:41,975 : INFO : ball_device.bd_trough : State: idle
2024-09-22 20:41:41,975 : DEBUG : ball_device.bd_trough : Waiting for eject request.
2024-09-22 20:41:41,975 : INFO : ball_device.bd_plunger : State: ejecting
2024-09-22 20:41:41,975 : INFO : ball_device.bd_plunger : Ejecting ball to <playfield.playfield>
2024-09-22 20:41:41,976 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ejecting_ball'====== Args={'balls': 1, 'target': <playfield.playfield>, 'source': <ball_device.bd_plunger>, 'mechanical_eject': True, 'num_attempts': 0}
2024-09-22 20:41:41,976 : INFO : ball_device.bd_plunger : Wait for ball to leave device
2024-09-22 20:41:42,051 : DEBUG : ball_device.bd_trough : SC: Counted 2 balls. Active switches: [<switch.s_trough3>, <switch.s_trough1>]. Old: 3
2024-09-22 20:41:42,051 : DEBUG : ball_device.bd_trough : SC: New count 2 last: 3
2024-09-22 20:41:42,051 : DEBUG : ball_device.bd_trough : SC: Updating count to 2
2024-09-22 20:41:42,052 : DEBUG : ball_device.bd_trough : BCH: Counting. New count: 2 Old count: 3
2024-09-22 20:41:43,607 : DEBUG : VPE Platform : Got Switch Change: switch_number: "7"
switch_state: true

2024-09-22 20:41:43,608 : INFO : SwitchController : <<<<<<< 's_launch_button' active >>>>>>>
2024-09-22 20:41:43,608 : INFO : EventManager : Event: ======'s_launch_button_active'====== Args={}
2024-09-22 20:41:43,608 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_launch_button'====== Args={'value': 91, 'prev_value': 90, 'change': 1}
2024-09-22 20:41:43,613 : INFO : coil.c_plunger : Pulsing Driver for 20ms (1.0 pulse_power)
2024-09-22 20:41:43,642 : DEBUG : VPE Platform : Got Switch Change: switch_number: "6"

2024-09-22 20:41:43,643 : INFO : SwitchController : <<<<<<< 's_plunger_lane' inactive >>>>>>>
2024-09-22 20:41:43,646 : INFO : ball_device.bd_plunger : State: ball_left
2024-09-22 20:41:43,646 : INFO : ball_device.bd_plunger : Ball left
2024-09-22 20:41:43,646 : INFO : ball_device.bd_plunger : Wait for confirm with timeout 3.0
2024-09-22 20:41:43,689 : DEBUG : VPE Platform : Got Switch Change: switch_number: "7"

2024-09-22 20:41:43,689 : INFO : SwitchController : <<<<<<< 's_launch_button' inactive >>>>>>>
2024-09-22 20:41:46,644 : INFO : ball_device.bd_plunger : State: failed_confirm
2024-09-22 20:41:46,644 : INFO : ball_device.bd_plunger : Got timeout (3.0s) before confirm from <playfield.playfield>
2024-09-22 20:41:46,736 : INFO : ball_device.bd_plunger : Confirming eject because target is playfield and ball did not return.
2024-09-22 20:41:46,736 : INFO : ball_device.bd_plunger : Eject successful
2024-09-22 20:41:46,736 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ball_eject_success'====== Args={'balls': 1, 'target': <playfield.playfield>}
2024-09-22 20:41:46,737 : INFO : EventManager : Event: ======'balldevice_playfield_ball_enter'====== Args={'new_balls': 1, 'unclaimed_balls': 1, 'device': <playfield.playfield>}
2024-09-22 20:41:46,737 : INFO : EventManager : Event: ======'playfield_ball_count_change'====== Args={'balls': 1, 'change': 1}
2024-09-22 20:41:46,737 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ball_count_changed'====== Args={'balls': 0}
2024-09-22 20:41:46,737 : INFO : ball_device.bd_plunger : State: idle
2024-09-22 20:41:47,033 : DEBUG : ball_device.bd_trough : BCH: Lost 1 balls
2024-09-22 20:41:47,033 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_count_changed'====== Args={'balls': 2}
2024-09-22 20:41:47,033 : WARNING : ball_device.bd_trough : Ball disappeared while idle. This should not normally happen.
2024-09-22 20:41:47,033 : INFO : EventManager : Event: ======'balldevice_playfield_ball_enter'====== Args={'new_balls': 1, 'unclaimed_balls': 1, 'device': <playfield.playfield>}
2024-09-22 20:41:47,033 : INFO : EventManager : Event: ======'playfield_ball_count_change'====== Args={'balls': 2, 'change': 1}
2024-09-22 20:41:47,033 : INFO : ball_device.bd_trough : 1 ball(s) missing from device. Mechanical eject? False
2024-09-22 20:41:47,033 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_missing'====== Args={'balls': 1}
2024-09-22 20:41:47,034 : INFO : EventManager : Event: ======'balldevice_ball_missing'====== Args={'balls': 1, 'name': 'bd_trough'}
2024-09-22 20:41:47,034 : DEBUG : ball_device.bd_trough : BCH: Counting. New count: 2 Old count: 2
2024-09-22 20:41:47,035 : DEBUG : ball_device.bd_trough : BCH: Counting. New count: 2 Old count: 2
2024-09-22 20:41:47,640 : DEBUG : VPE Platform : Got Switch Change: switch_number: "5"
switch_state: true

2024-09-22 20:41:47,641 : INFO : SwitchController : <<<<<<< 's_trough4' active >>>>>>>
2024-09-22 20:41:47,641 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_trough4'====== Args={'value': 49, 'prev_value': 48, 'change': 1}
2024-09-22 20:41:48,138 : DEBUG : ball_device.bd_trough : SC: Counted 3 balls. Active switches: [<switch.s_trough3>, <switch.s_trough1>, <switch.s_trough4>]. Old: 2
2024-09-22 20:41:48,139 : DEBUG : ball_device.bd_trough : SC: New count 3 last: 2
2024-09-22 20:41:48,139 : DEBUG : ball_device.bd_trough : SC: Updating count to 3
2024-09-22 20:41:48,139 : DEBUG : ball_device.bd_trough : BCH: Counting. New count: 3 Old count: 2
2024-09-22 20:41:48,139 : DEBUG : ball_device.bd_trough : BCH: Found 1 new balls
2024-09-22 20:41:48,139 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_count_changed'====== Args={'balls': 3}
2024-09-22 20:41:48,139 : INFO : ball_device.bd_trough : Received unexpected ball
2024-09-22 20:41:48,139 : INFO : EventManager : Event: ======'balldevice_captured_from_playfield'====== Args={'balls': 1}
2024-09-22 20:41:48,139 : INFO : EventManager : Event: ======'sw_playfield_active'====== Args={'balls': 1}
2024-09-22 20:41:48,139 : INFO : EventManager : Event: ======'playfield_ball_count_change'====== Args={'balls': 1, 'change': -1}
2024-09-22 20:41:48,140 : DEBUG : ball_device.bd_trough : SC: Counted 3 balls. Active switches: [<switch.s_trough3>, <switch.s_trough1>, <switch.s_trough4>]. Old: 3
2024-09-22 20:41:48,140 : DEBUG : ball_device.bd_trough : Processing new ball
2024-09-22 20:41:48,140 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_enter'====== Args={'new_balls': 1, 'unclaimed_balls': 1, 'new_available_balls': 1, 'device': <ball_device.bd_trough>}
2024-09-22 20:41:48,140 : INFO : EventManager : Event: ======'ball_drain'====== Args={'device': <ball_device.bd_trough>, 'balls': 1}
2024-09-22 20:41:48,140 : INFO : EventManager : Event: ======'ball_will_end'====== Args={}
2024-09-22 20:41:48,140 : DEBUG : ball_device.bd_trough : Adding ball
2024-09-22 20:41:48,140 : INFO : EventManager : Event: ======'balldevice_balls_available'====== Args={}
2024-09-22 20:41:48,140 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_entered'====== Args={'new_balls': 1, 'device': <ball_device.bd_trough>}
2024-09-22 20:41:48,141 : INFO : EventManager : Event: ======'ball_ending'====== Args={}
2024-09-22 20:41:48,141 : INFO : EventManager : Event: ======'ball_ended'====== Args={}
2024-09-22 20:41:48,142 : INFO : EventManager : Event: ======'player_turn_will_end'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:48,145 : INFO : EventManager : Event: ======'player_turn_ending'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:48,145 : INFO : EventManager : Event: ======'player_turn_ended'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:48,146 : INFO : EventManager : Event: ======'player_turn_will_start'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:48,146 : INFO : EventManager : Event: ======'player_turn_starting'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:48,146 : DEBUG : Player : Setting 'ball' to: 2, (prior: 1, change: 1)
2024-09-22 20:41:48,146 : INFO : EventManager : Event: ======'player_ball'====== Args={'value': 2, 'prev_value': 1, 'change': 1, 'player_num': 1}
2024-09-22 20:41:48,146 : INFO : EventManager : Event: ======'player_turn_started'====== Args={'player': <Player 1>, 'number': 1}
2024-09-22 20:41:48,146 : INFO : EventManager : Event: ======'ball_will_start'====== Args={'player': 1, 'ball': 2, 'balls_remaining': 1, 'is_extra_ball': False}
2024-09-22 20:41:48,148 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:48,148 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:49,147 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:49,147 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:50,140 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:50,140 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:51,143 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:51,143 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:52,136 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:52,136 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:53,139 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:53,139 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:54,145 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:54,145 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:55,139 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:55,139 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:56,137 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:56,137 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:57,146 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:57,146 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:58,137 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:58,137 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:41:59,147 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:41:59,147 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:00,140 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:42:00,140 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:01,136 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:42:01,137 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:02,146 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:42:02,147 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:03,134 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:42:03,134 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:04,133 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:42:04,133 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:05,145 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:42:05,145 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:06,140 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:42:06,140 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:07,147 : INFO : BallController : Found 1 ball(s) on playfield.
2024-09-22 20:42:07,147 : WARNING : BallController : Playfields still contain balls. Waiting for those to drain.
2024-09-22 20:42:07,925 : INFO : Machine : Shutting down...
2024-09-22 20:42:07,925 : INFO : EventManager : Event: ======'shutdown'====== Args={}
2024-09-22 20:42:07,926 : DEBUG : ball_device.bd_trough : Stopping ball device
2024-09-22 20:42:07,926 : INFO : EventManager : Event: ======'mode_game_will_stop'====== Args={}
2024-09-22 20:42:07,926 : INFO : EventManager : Event: ======'mode_game_stopping'====== Args={}
2024-09-22 20:42:07,926 : INFO : Mode.game : Stopped.
2024-09-22 20:42:07,926 : INFO : EventManager : Event: ======'modes_active_modes_changed'====== Args={}
2024-09-22 20:42:07,927 : INFO : EventManager : Event: ======'mode_game_stopped'====== Args={}
2024-09-22 20:42:07,927 : INFO : EventManager : Event: ======'clear'====== Args={'key': 'game'}
2024-09-22 20:42:07,929 : DEBUG : grpc._cython.cygrpc : RPC cancelled for servicer method [/mpf.vpe.MpfHardwareService/Start]
2024-09-22 20:42:08,907 : INFO : root : MPF run loop ended.

This is impossible to debug because it only happens in non-development builds that do not support debugging. I'm stumped.