Mode does not stop at ball end

[Pinball People]

Hey! 

I've got a Superjets mode that is supposed to end when a timer runs out or the ball ends:

#config_version=5

mode:

    start_events: mode_superjets_lit_stopped

    stop_events: timer_superjets_timer_down_complete #, ball_ending

    stop_on_ball_end: true

    priority: 120

timers:

    superjets_timer_down:

        debug: True

        bcp: True

        start_value: 20

        end_value: 0

        direction: down

        tick_interval: 1s

        start_running: yes

        control_events:

            - event: ball_ending

              action: stop

I've even added a stop the the timer on ball end and explicitly set "stop on ball end" true. Even with "ball_ending" as a stop event, the mode will only be "stopping", but never actually stop.

019-10-10 20:43:04,665 : INFO : EventManager : Event: ======'ball_ending'====== Args={}

2019-10-10 20:43:04,666 : INFO : EventManager : Event: ======'mode_global_will_stop'====== Args={}

2019-10-10 20:43:04,667 : INFO : EventManager : Event: ======'mode_global_stopping'====== Args={}

2019-10-10 20:43:04,667 : INFO : Timer.superjets_timer_down : Stopping Timer

2019-10-10 20:43:04,667 : INFO : EventManager : Event: ======'timer_superjets_timer_down_stopped'====== Args={'ticks': 17, 'ticks_remaining': 17}

2019-10-10 20:43:04,668 : INFO : EventManager : Event: ======'mode_superjets_will_stop'====== Args={}

2019-10-10 20:43:04,668 : INFO : EventManager : Event: ======'mode_superjets_stopping'====== Args={}

2019-10-10 20:43:04,669 : INFO : EventManager : Event: ======'mode_base_will_stop'====== Args={}

2019-10-10 20:43:04,669 : INFO : EventManager : Event: ======'mode_base_stopping'====== Args={}

2019-10-10 20:43:04,670 : INFO : Mode.base : Stopped.

2019-10-10 20:43:04,671 : INFO : EventManager : Event: ======'mode_base_stopped'====== Args={}

2019-10-10 20:43:04,671 : INFO : EventManager : Event: ======'clear'====== Args={'key': 'base'}

2019-10-10 20:43:04,674 : INFO : Mode.global : Stopped.

2019-10-10 20:43:04,675 : INFO : EventManager : Event: ======'mode_global_stopped'====== Args={}

2019-10-10 20:43:04,675 : INFO : EventManager : Event: ======'clear'====== Args={'key': 'global'}

2019-10-10 20:43:04,678 : INFO : EventManager : Event: ======'balldevice_bd_drain_ball_eject_attempt'====== Args={'balls': 1, 'target': <ball_device.bd_trough>, 'source': <ball_device.bd_drain>, 'mechanical_eject': False, 'num_attempts': 0}

2019-10-10 20:43:04,679 : INFO : ball_device.bd_drain : Ejecting ball to <ball_device.bd_trough>

2019-10-10 20:43:04,679 : INFO : EventManager : Event: ======'balldevice_bd_drain_ejecting_ball'====== Args={'balls': 1, 'target': <ball_device.bd_trough>, 'source': <ball_device.bd_drain>, 'mechanical_eject': False, 'num_attempts': 0}

2019-10-10 20:43:04,679 : INFO : coil.c_drain_eject : Pulsing Driver for 8ms (1.0 pulse_power)

2019-10-10 20:43:04,680 : INFO : SwitchController : <<<<<<< 's_drain' inactive >>>>>>>

2019-10-10 20:43:04,784 : INFO : SwitchController : <<<<<<< 's_trough1' active >>>>>>>

2019-10-10 20:43:04,788 : INFO : EventManager : Event: ======'machine_var_audits_switches_s_trough1'====== Args={'value': 131, 'prev_value': 130, 'change': 1}

2019-10-10 20:43:05,286 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_count_changed'====== Args={'balls': 3}

2019-10-10 20:43:05,286 : INFO : EventManager : Event: ======'balldevice_bd_trough_ball_enter'====== Args={'new_balls': 1, 'unclaimed_balls': 0, 'device': <ball_device.bd_trough>}

2019-10-10 20:43:05,287 : INFO : EventManager : Event: ======'ball_drain'====== Args={'device': <ball_device.bd_trough>, 'balls': 0}

2019-10-10 20:43:05,287 : INFO : EventManager : Event: ======'balldevice_bd_drain_ball_eject_success'====== Args={'balls': 1, 'target': <ball_device.bd_trough>}

2019-10-10 20:43:05,288 : INFO : EventManager : Event: ======'balldevice_bd_drain_ball_count_changed'====== Args={'balls': 0}

The ball drains, is actively put into the trough and that's it. The next ball never starts.

Running 0.5x here.

What's wrong?

Thanks,

Sebastian

[Anthony van Winkle]

Hey Sebastian-

Is that a hash mark before the comma on your stop_events? That will comment out the ball_ending event, so it's not getting listened to there. 

There could also be a race condition because ball_ending is a very late event. I'd suggest using ball_will_end as the stop event for modes, as that ensures all of those handlers will be processed before the ball is actually ended.

[jabdoa]

It is actually weird that mode_superjets_stopped is never posted in that log. It should be. Which MPF version are you using? I there anything blocking mode_superjets_stopping? Any custom code in your machine? I will try to reproduce this over the weekend.

Jan

[Pinball People]

Hi Anthony,

yes, "ball ending" was commented out from an earlier try. But using "ball_will_end" as a stop event actually works. Oh those MPF nuances :)

Thanks a lot!

Sebastian

[jabdoa]

I tried to reproduce your problem. Unfortunately, with that example it neither happens on 0.52 nor on dev. Which version are you using?

Jan

[Cole M]

I had something like this happen to me about nine months ago.  I never could pin it down.  I removed all but the bare bones of the mode and still the mode was not stopping properly. On a guess that it had something to do with a corrupt yaml file, I rewrote the mode verbatim in a newly created file and the problem went away.  I never did figure out what caused it, maybe a typo? Or maybe something was hidden in the file that was confusing the framework.  I know this sounds ridiculous.

[Pinball People]

I'm running MPF v0.52.0-dev.0

[jabdoa]

@Coleman if you get to something similar again please zip up the machine and send it to me.

@Sebastian: Looks like a very early (actually the first) dev version of 0.52. So essentially you are on 0.51 + early (usually breaking) changes of 0.52. I suggest you update to latest 0.52 stable version.

Jan