investigate duplicate MQTT timer directives

[jflamy]

Also suspicious timing (second request causing timer to terminate prematurely?)

17:12:13.216 INFO  FOP A    current athlete = #14 Loughran I. attempt = 5, requested = 76, clock=60000 initialTime=60000 
17:12:25.755 INFO  FOP A    MQTT received owlcms/clock/A : start                               
17:12:25.755 INFO  FOP A    MQTT received owlcms/clock/A : start                               
17:12:25.755 INFO  FOP A    state CURRENT_ATHLETE_DISPLAYED, event received app.owlcms.fieldofplay.FOPEvent$TimeStarted@45bd57cb from pp.owlcms.monitors.MQTTMonitor$MQTTCallback.postFopTimeEvents(MQTTMonitor.java:267) 
17:12:25.755 INFO  FOP A    setting clock owner to 3.14_Loughran_Isabelle_id1803410766905700065_695522042 [(FieldOfPlay.java:2829)] 
17:12:25.755 DEBUG FOP A     + lastChallengedRecords []                                        
17:12:25.755 DEBUG FOP A    **** resetting all decisions on new clock                          
17:12:25.755 INFO  FOP A    entering TIME_RUNNING (FieldOfPlay.java:2844)                      
17:12:25.755 DEBUG FOP A    MQTT resetDecisions                                                
17:12:25.756 INFO  FOP A    running 1:00                                                       
17:12:25.756 INFO  FOP A    state TIME_RUNNING, event received app.owlcms.fieldofplay.FOPEvent$TimeStarted@2196fd54 from pp.owlcms.monitors.MQTTMonitor$MQTTCallback.postFopTimeEvents(MQTTMonitor.java:267) 
17:12:25.756 INFO  FOP A    running 1:00                                                       
17:12:34.215 INFO  FOP A    +++++ running final warning                                        
17:12:34.215 INFO  FOP A    Final Warning                                                      
17:12:34.215 DEBUG FOP A    MQTT timeRemaining 30

[jflamy]

@scottgonzalez

1. do you have a log file with the logging location at the end?
2. can you check if 30 seconds before the final warning there was a timer started. There seems to be debouncing missing, and if multiple timers are running they might not all be cancelled out (which is an hypothesis about how the final warning timer could be produced).

I will need to log the unique id of the timer tasks (System.identityHashCode()) so we can see they are created and killed correctly.