Intermittent Ball Device Issue - Need some ideas on how to proceed with my problem analysis

[Greg Sealby]

Hi all,

I'm having an intermittent issue where every now and then my game will not start after I complete a game and push the start button for the next game.  I've done some problem analysis and it seems that the balldevice_bd_plunger_ball_eject_success event fires for a second time for an unknown reason.  This seems to cause the game to get out of sync with the actual playfield ball count, although it does still finish the ball (and game in this case) when the "first" ball drains.  Weird.  Has anybody had any experience with this event firing and can point me in a direction (hopefully to some reconfig I can try) to help me solve this one.  I took an excerpt of the original MPF log to analyse, here's the details of my analysis so far:

Problem Identification

---------------------------------

After game is complete, the start button is inactive and will not restart a new game.  I can hear Ball Search activating coils.

Reason

------------

Two balls on playfield reported by MPF, only one was actually on playfield.  This means that when the game is ended the game thinks there is a ball stuck somewhere on the playfield.  Ball Search was initiatied during Attract Mode and therefore the Start button's event to request a game start gets rejected as a ball search is in progress.

Questions

----------------

Why does the game end the players turn(ball) on the first ball drain if it believes there are two balls on the playfield?

Log Analysis

-------------------

** BALL IS EJECTED FROM TROUGH ONTO PLUNGER LANE
Line 3665 of Sample-Log.txt:
 2020-02-01 17:22:08,559 : INFO : SwitchController : <<<<<<< 's_plunger_lane' active >>>>>>>


Line 3680 of Sample-Log.txt :
 2020-02-01 17:22:09,062 : 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}


** PLAYER PLUNGES BALL
Line 3735 and 3736 of Sample-Log.txt :
 2020-02-01 17:22:12,842 : INFO : SwitchController : <<<<<<< 's_plunger_lane' inactive >>>>>>>
 2020-02-01 17:22:12,842 : INFO : EventManager : Event: ======'s_plunger_lane_inactive'====== Args={}


** GAME DETECTS playfield-active EVENT AND POSTS PLUNGER EJECT SUCESS
Line 3836 of Sample-Log.txt :
 2020-02-01 17:22:14,505 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ball_eject_success'====== Args={'balls': 1, 'target': <playfield.playfield>}


** PLAYFIELD BALL DEVICE IS UPDATED
Line 3843 and 3844 of Sample-Log.txt :
 2020-02-01 17:22:14,521 : INFO : EventManager : Event: ======'balldevice_playfield_ball_enter'====== Args={'new_balls': 1, 'unclaimed_balls': 1, 'device': <playfield.playfield>}
 2020-02-01 17:22:14,521 : INFO : EventManager : Event: ======'playfield_ball_count_change'====== Args={'balls': 1, 'change': 1}


** THIS IS ALL AS EXPECTED


** THEN OUT OF NOWHERE THIS EVENT FIRES, THERE ARE NO TROUGH OR PLUNGER EVENTS IN BETWEEN THIS EVENT AND THE PREVIOUS EVENTS.
Line 3987 of Sample-Log.txt :
 2020-02-01 17:22:18,285 : INFO : EventManager : Event: ======'balldevice_bd_plunger_ball_eject_success'====== Args={'balls': 1, 'target': <playfield.playfield>}


** WHICH CHANGES THIS COUNTER AND THE GAME IS OUT OF SYNC NOW
Line 3994 of Sample-Log.txt :
 2020-02-01 17:22:18,296 : INFO : EventManager : Event: ======'playfield_ball_count_change'====== Args={'balls': 2, 'change': 1}


** BALL DRAINS, TROUGH HAS THE CORRECT NUMBER OF BALLS, PLAYFIELD COUNT STILL HAS 1 BALL ON PLAYFIELD, BALL ENDS
Lines 4527 to 4538 of Sample-Log.txt :
 2020-02-01 17:22:37,064 : INFO : SwitchController : <<<<<<< 's_trough4' active >>>>>>>
 2020-02-01 17:22:37,065 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_trough4'====== Args={'value': 2050, 'prev_value': 2049, 'change': 1}
 2020-02-01 17:22:37,566 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_count_changed'====== Args={'balls': 4}
 2020-02-01 17:22:37,566 : INFO : EventManager : Event: ======'balldevice_captured_from_playfield'====== Args={'balls': 1}
 2020-02-01 17:22:37,566 : INFO : EventManager : Event: ======'sw_playfield_active'====== Args={'balls': 1}
 2020-02-01 17:22:37,567 : INFO : EventManager : Event: ======'playfield_ball_count_change'====== Args={'balls': 1, 'change': -1}
 2020-02-01 17:22:37,568 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_enter'====== Args={'new_balls': 1, 'unclaimed_balls': 1, 'new_available_balls': 1, 'device': <ball_device.bd_trough>}
 2020-02-01 17:22:37,568 : INFO : EventManager : Event: ======'ball_drain'====== Args={'device': <ball_device.bd_trough>, 'balls': 1}
 2020-02-01 17:22:37,570 : INFO : EventManager : Event: ======'ball_will_end'====== Args={}
 2020-02-01 17:22:37,570 : INFO : EventManager : Event: ======'balldevice_balls_available'====== Args={}
 2020-02-01 17:22:37,570 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_entered'====== Args={'new_balls': 1, 'device': <ball_device.bd_trough>}
 2020-02-01 17:22:37,579 : INFO : EventManager : Event: ======'ball_ending'====== Args={}


** ATTRACT MODE HAS STARTED, NORMALLY IN ATTRACT MODE IT POSTS "collecting_balls_completed" BUT THIS DOES NO COMPLETE AND BALL SEARCH STARTS ABOUT 1.3 SECS LATER
Line 4815 of Sample-Log.txt :
 2020-02-01 15:32:40,716 : INFO : EventManager : Event: ======'collecting_balls'====== Args={}
Line 4832 of Sample-Log.txt :
 2020-02-01 17:22:54,695 : INFO : EventManager : Event: ======'ball_search_started'====== Args={}


** START BUTTONS REQUEST TO START A GAME IS REJECTED DUE TO BALL SEARCH RUNNING
Lines 4838 to 4842 of Sample-Log.txt :
 2020-02-01 17:22:54,863 : INFO : SwitchController : <<<<<<< 's_start_button' active >>>>>>>
 2020-02-01 17:22:54,863 : INFO : EventManager : Event: ======'s_start_button_active'====== Args={}
 2020-02-01 17:22:54,984 : INFO : SwitchController : <<<<<<< 's_start_button' inactive >>>>>>>
 2020-02-01 17:22:54,984 : INFO : EventManager : Event: ======'request_to_start_game'====== Args={}
 2020-02-01 17:22:54,985 : INFO : EventManager : Event: ======'ball_search_prevents_game_start'====== Args={}

[jabdoa]

Hi Greg,

I tried to create a testcase to replicate this but failed. I probably got some differences in my config (i.e. timings). I got a couple more question for you:

1. Does this happen all the time? How often does it happen?

2. Is there any supporting evidence when this happens? Only on a second game? Is there some queue event ongoing or something delaying the eject? Diverters?

3. Which MPF version are you using?

I though about how we could create a reproduction example for this together. The best I could come up was to extend our doctests (which are selfcontained tests which you can run with "mpf test <your_testfile>"; add "-v" to see log output) to support real games. Can you install MPF dev (at least 0.54.0-dev.3) and try to break the following example?

##! no_simulation
##! no_fake_game
#config_version=5
playfields:
  playfield:
    default_source_device: bd_plunger
    tags: default

coils:
  c_trough_eject:
    number:
  c_autolauncher:
    number:

switches:
  s_trough_switch1:
    number:
  s_trough_switch2:
    number:
  s_trough_switch3:
    number:
  s_trough_jam:
    number:
  s_ball_switch_plunger_lane:
    number:
  s_playfield:
    number:
    tags: playfield_active

ball_devices:
  bd_trough:
    eject_coil: c_trough_eject
    ball_switches: s_trough_switch1, s_trough_switch2, s_trough_switch3, s_trough_jam
    jam_switch: s_trough_jam
    eject_targets: bd_plunger
    eject_timeouts: 3s
    tags: trough, drain, home
    debug: true
  bd_plunger:
    eject_coil: c_autolauncher
    ball_switches: s_ball_switch_plunger_lane
    mechanical_eject: true
    eject_targets: playfield
    eject_timeouts: 4s
    debug: true


##! test
#! # add balls to trough
#! hit_switch s_trough_switch1
#! hit_switch s_trough_switch2
#! hit_switch s_trough_switch3
#! # let balls settle
#! advance_time_and_run 2
#! start_game
#! advance_time_and_run .2
#! release_switch s_trough_switch1
#! advance_time_and_run 2
#! hit_switch s_ball_switch_plunger_lane
#! advance_time_and_run 3
#! release_switch s_ball_switch_plunger_lane
#! advance_time_and_run 3
#! hit_and_release_switch s_playfield
#! advance_time_and_run 10
#! # try to break that next assertion
#! assert_balls_on_playfield 1

If you need more assertions they can be found here: https://github.com/missionpinball/mpf/blob/dev/mpf/tests/MpfDocTestCase.py#L189. Let me know if you found something or need any more help.

Jan

[Greg Sealby]

Hi Jan,

Thanks for trying and for putting this option together.  To answer your questions:

1. No, it is very rare.  We played the game for about 3 hours before this issue occurred.
2. Queue events was the first thing that I looked for as that has been a cause in the past.
3. I am running on v0.53.1

Other supporting evidence/facts from my log:

• This occurred on ball 3
• The playfield_ball_count_change event at the end of ball 2 set the counter to 0 as expected as the ball drained.
• During ball 2, the game does run through a mode that has a queue event to hold the ball for 3 seconds.  However, I can see the "release" event come though and the playfield_ball_count_change event updates the counter as expected.
• The ball does drain during the above mode on ball 2.
• On ball 1, the ball save kicks in on an outlane switch hit, which creates a similar scenario where playfield_ball_count_change believes there are two balls on the playfield.  It then updates within 250ms back to 1 ball.  I believe this is correct behaviour, as this is an early ball save event and there was 2 balls on the playfield temporarily.
• There are no ball save events on ball 3 prior to the unexpected balldevice_bd_plunger_ball_eject_success event.  After the initial plunge on the ball 3, the ball hits a rollover, a spinner, a drop target and a standup - then the unexpected balldevice_bd_plunger_ball_eject_success occurs.

I am also unable to reproduce this issue so far.  Thanks for the simple game structure, I'll put together an environment with the latest dev and try it out on a test machine.

I also don't have debug on for the plunger ball device at the moment, and file_log is on basic.  I'm going to increase logging on this device using these two options, do you think that will provide any information on what triggered the event?

[jabdoa]

dev.3 should also give you a bit more log output from your ball devices by default. So even without debug we should be able to spot the source as there are seven or eight ways for a confirm to be generated.

Jan