investigate duplicate MQTT timer directives
Closed this issue · 1 comments
jflamy commented
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 commented
- do you have a log file with the logging location at the end?
- 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.