Strange behaviour with a function that uses timers inside

I have a very strange behavious with a function and timers inside of it.

I try to implement a generic function for random timers related to items. If the timer end, the function send a given state to the related item.

I will use this for a random behaviour of my house for rollershutter down and other things.

I put a lot of debug code to see what is going on.

var HashMap<String, Timer> tRandomTimers = newHashMap()

// this function is used to wait for a random interval and then set the item to a state
// GenericItem = item
// Hashmap of the Timer
// Numberitem with the maximum of delay
// new state after interval is reached
val Functions$Function4<GenericItem, HashMap<String, Timer>, NumberItem, State, Boolean> startRandomTimerWithAction= [ relatedItem, tRandomTimers, nuRandomTimerTime, newitemstate  |
    var int randomTime

    logInfo("TIMERCHECK", "randomTimer relatedItem:       " + relatedItem.name)
    //logInfo("TIMERCHECK", "randomTimer nuRandomTimerTime: " + nuRandomTimer.state)

    // ensure that random value is greater then 0
    if((nuRandomTimer.state as DecimalType).intValue == 0)
        randomTime = 2        
    else
        randomTime = (new java.util.Random).nextInt((nuRandomTimer.state as DecimalType).intValue) + 2
    if(tRandomTimers.get(relatedItem.name) === null)
    {
        logInfo("TIMERCHECK", "randomTimer CreateTimer:       " + relatedItem.name + " - " + randomTime)
        tRandomTimers.put(relatedItem.name, createTimer(now.plusSeconds(randomTime))
        [|
            logInfo("TIMERCHECK", "randomTimer TimerEnded:        " + relatedItem.name)
            relatedItem.sendCommand(newitemstate.toString)
            tRandomTimers.remove(relatedItem.name)
            logInfo("TIMERCHECK", "randomTimer tRandomTimers:     " + tRandomTimers)
            logInfo("TIMERCHECK", "randomTimer ###############################")            
        ])
    }
    else
    {
        logInfo("TIMERCHECK", "randomTimer reschedule: " + relatedItem.name + " - " + randomTime)
        tRandomTimers.get(relatedItem.name).reschedule(now.plusSeconds(randomTime))
    }

    logInfo("TIMERCHECK", "randomTimer tRandomTimers:     " + tRandomTimers)
    logInfo("TIMERCHECK", "randomTimer ###############################")
    true
]

I can start this function with this command:

startRandomTimerWithAction.apply(swRandomTimer01, tRandomTimers, nuRandomTimer, OFF)

Now to my problem:
If two timers are filled with similar values, it sometimes happen, that some of the timer do not end. Timer is in the HashMap but does not end. It looks like the timer is never created. Is this a problem with ThreadSave of functions?

My code to test this:

        startRandomTimerWithAction.apply(swRandomTimer01, tRandomTimers, nuRandomTimer, OFF)
        startRandomTimerWithAction.apply(swRandomTimer02, tRandomTimers, nuRandomTimer, OFF)
        startRandomTimerWithAction.apply(swRandomTimer03, tRandomTimers, nuRandomTimer, OFF)
        startRandomTimerWithAction.apply(swRandomTimer04, tRandomTimers, nuRandomTimer, OFF)

output:

2018-02-21 09:36:42.049 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer relatedItem:       swRandomTimer01
2018-02-21 09:36:42.049 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer CreateTimer:       swRandomTimer01 - 2
2018-02-21 09:36:42.049 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer tRandomTimers:     {swRandomTimer01=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@8c1fef}
2018-02-21 09:36:42.049 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer ###############################
2018-02-21 09:36:42.049 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer relatedItem:       swRandomTimer02
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer CreateTimer:       swRandomTimer02 - 2
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer tRandomTimers:     {swRandomTimer02=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@b381e6, swRandomTimer01=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@8c1fef}
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer ###############################
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer relatedItem:       swRandomTimer03
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer CreateTimer:       swRandomTimer03 - 2
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer tRandomTimers:     {swRandomTimer02=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@b381e6, swRandomTimer03=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1b115d4, swRandomTimer01=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@8c1fef}
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer ###############################
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer relatedItem:       swRandomTimer04
2018-02-21 09:36:42.065 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer CreateTimer:       swRandomTimer04 - 2
2018-02-21 09:36:42.080 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer tRandomTimers:     {swRandomTimer04=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1f3c362, swRandomTimer02=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@b381e6, swRandomTimer03=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1b115d4, swRandomTimer01=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@8c1fef}
2018-02-21 09:36:42.080 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer ###############################
2018-02-21 09:36:44.049 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer TimerEnded:        swRandomTimer01
2018-02-21 09:36:44.049 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer tRandomTimers:     {swRandomTimer04=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1f3c362, swRandomTimer02=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@b381e6, swRandomTimer03=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1b115d4}
2018-02-21 09:36:44.049 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer ###############################
2018-02-21 09:36:44.081 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer TimerEnded:        swRandomTimer04
2018-02-21 09:36:44.081 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer tRandomTimers:     {swRandomTimer02=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@b381e6, swRandomTimer03=org.eclipse.smarthome.model.script.internal.actions.TimerImpl@1b115d4}
2018-02-21 09:36:44.081 [INFO ] [se.smarthome.model.script.TIMERCHECK] - randomTimer ###############################

You can see, all 4 timers are filled with 2 sec. But only two of the (01 and 04) will really end. The two others exist in the Hashmap again but will never end.

Can someone give me a hint what is wrong?

I have a workaround but not sure why this is working. I think the whole problem is related to the rule execusion time speed?

        startRandomTimerWithAction.apply(swRandomTimer01, tRandomTimers, nuRandomTimer, OFF)
        Thread::sleep(500)
        startRandomTimerWithAction.apply(swRandomTimer02, tRandomTimers, nuRandomTimer, OFF)
        Thread::sleep(500)
        startRandomTimerWithAction.apply(swRandomTimer03, tRandomTimers, nuRandomTimer, OFF)
        Thread::sleep(500)
        startRandomTimerWithAction.apply(swRandomTimer04, tRandomTimers, nuRandomTimer, OFF)

I’ve seen something similar in a private thread with @bob_dickenson. The working theory is that the lambda is represented by a single object and that object is not thread safe. This means that if you call it twice too close to gether in time the two calls can inerfear with eachother.

It works with your Thread::sleeps because you are sleeping long enough for each call to the lambda to complete before the next call is made.

You can make it thread safe by using a ReentrantLock so no two instances of the lambda would be executing at the same time.

I tried to use ReentrantLock but it is similar. Sometimes all timers are started and ended and sometimes only some of them. I try to change it to a procedure as you mentioned here.

And I try to find simple code to force the error. In my case it looks like all timers are created, because they are all in the HashMap but not startet correct. And because of this do not end.

But if I understand the other post correct, functions are not thread save at all. So it cannot fixed becasue timers are ansynchon with call of function.

And another thought. ReentrantLock should work at the first start of the function and should create only one timer and if this ends (and the ReentrantLock is unlocked) create the next one, but this does not happen, some timers are started in parallel but all are created in HashMap.

I will post code tomorrow, maybe there is a error in my code.

I come back to this topic.

I made some tests with ReentrantLock but I cannot get it to work.

If I use:

val Functions$Function5<GenericItem, HashMap<String, Timer>, NumberItem, ReentrantLock, String, Boolean> startRandomTimerWithAction= [ relatedItem, tRandomTimers, nuRandomTimerTime, tRandomTimersLockInternal, newitemstate |
    
    tRandomTimersLockInternal.lock()
    try
    {
        // ensure that random value is greater then 0
        var int randomTime
        if((nuRandomTimerTime.state as DecimalType).intValue == 0)
            randomTime = 2        
        else
            randomTime = (new java.util.Random).nextInt((nuRandomTimerTime.state as DecimalType).intValue) + 2
        if(tRandomTimers.get(relatedItem.name) === null || tRandomTimers.get(relatedItem.name).hasTerminated())
        {
            logInfo("TIMERCHECK", "RandomTimer for Item " + relatedItem.name + " started with " + randomTime + " sec.")
            tRandomTimers.put(relatedItem.name, createTimer(now.plusSeconds(randomTime))
            [|
                logInfo("TIMERCHECK", "RandomTimer for Item " + relatedItem.name + " reached end. Action " + newitemstate.toString + " executed.")
                relatedItem.sendCommand(newitemstate)
                tRandomTimers.remove(relatedItem.name)
            ])
        }
    }
        
    finally
    {
        logInfo("ReentrantLock","randomTimer tRandomTimersLock.unlock(): " + relatedItem.name)
        tRandomTimersLockInternal.unlock()
    }    
    true
]

The lock will be unlock after the try is finished, not when the timer is finished

If I use:

val Functions$Function5<GenericItem, HashMap<String, Timer>, NumberItem, ReentrantLock, String, Boolean> startRandomTimerWithAction= [ relatedItem, tRandomTimers, nuRandomTimerTime, tRandomTimersLockInternal, newitemstate |
    
    tRandomTimersLockInternal.lock()
    try
    {
        // ensure that random value is greater then 0
        var int randomTime
        if((nuRandomTimerTime.state as DecimalType).intValue == 0)
            randomTime = 2        
        else
            randomTime = (new java.util.Random).nextInt((nuRandomTimerTime.state as DecimalType).intValue) + 2
        if(tRandomTimers.get(relatedItem.name) === null || tRandomTimers.get(relatedItem.name).hasTerminated())
        {
            logInfo("TIMERCHECK", "RandomTimer for Item " + relatedItem.name + " started with " + randomTime + " sec.")
            tRandomTimers.put(relatedItem.name, createTimer(now.plusSeconds(randomTime))
            [|
                logInfo("TIMERCHECK", "RandomTimer for Item " + relatedItem.name + " reached end. Action " + newitemstate.toString + " executed.")
                relatedItem.sendCommand(newitemstate)
                tRandomTimers.remove(relatedItem.name)

                logInfo("ReentrantLock","randomTimer tRandomTimersLock.unlock(): " + relatedItem.name)
                tRandomTimersLockInternal.unlock()                
            ])
        }
    }
        
    finally
    {
        //logInfo("ReentrantLock","randomTimer tRandomTimersLock.unlock(): " + relatedItem.name)
        //tRandomTimersLockInternal.unlock()
    }    
    true
]

It throws an error

2018-02-24 12:28:08.233 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.2018-02-24T12:28:08.217+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <XFeatureCallImplCustom>.sendCommand(<XFeatureCallImplCustom>)
  <XFeatureCallImplCustom>.remove(<XMemberFeatureCallImplCustom>)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <XFeatureCallImplCustom>.unlock()
} ] threw an unhandled Exception:
java.lang.IllegalMonitorStateException: null
        at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:151) [?:?]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1261) [?:?]
        at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:457) [?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1085) [164:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1060) [164:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1046) [164:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:991) [164:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:141) [145:org.eclipse.smarthome.model.script:0.10.0.b1]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:763) [164:org.eclipse.xtext.xbase:2.12.0.v

But I think both, even if it will work will not fix it.

I need that every function runs in parallel to each other. The problem is, that they are not thread save. If two timers are end at the same time, only on of them will execute the command for timer end. The other do nothing,

I will try to switch to procedure now.

I’ve tested it with procedure too. Same issue.

It looks like the timer cannot run in parallel. Only the first timer wins and the other which run on the same time loose.

Different timer ending times - good:

2018-02-24 12:50:26.264 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer01 started with 10 sec.
2018-02-24 12:50:26.264 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer02 started with 29 sec.
2018-02-24 12:50:26.280 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer03 started with 13 sec.
2018-02-24 12:50:26.280 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer04 started with 14 sec.
2018-02-24 12:50:26.280 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item rsRandomTimer05 started with 18 sec.
2018-02-24 12:50:36.265 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer01 reached end. Action OFF executed.
2018-02-24 12:50:39.281 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer03 reached end. Action OFF executed.
2018-02-24 12:50:40.281 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer04 reached end. Action OFF executed.
2018-02-24 12:50:44.280 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item rsRandomTimer05 reached end. Action 100 executed.
2018-02-24 12:50:55.265 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer02 reached end. Action OFF executed.

Same time timer ending times - Bad:

2018-02-24 12:51:20.280 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer01 started with 2 sec.
2018-02-24 12:51:20.280 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer02 started with 2 sec.
2018-02-24 12:51:20.280 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer03 started with 2 sec.
2018-02-24 12:51:20.280 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer04 started with 2 sec.
2018-02-24 12:51:20.296 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item rsRandomTimer05 started with 2 sec.
2018-02-24 12:51:22.296 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item rsRandomTimer05 reached end. Action 100 executed.
2018-02-24 12:51:22.296 [INFO ] [se.smarthome.model.script.TIMERCHECK] - RandomTimer for Item swRandomTimer04 reached end. Action OFF executed.

So using timer inside of functions/procedure are not reliable

I come back with some new things.

It is not a problem of function/procedure. It is a problem of timers.

I will open a new post for this.

It looks like the problem is solved.

timer.cancel
timer = null

is needed as the first lines inside the timer.

            tRandomTimers.put(relatedItem.name, createTimer(now.plusSeconds(randomTime))
            [|
                tRandomTimers.get(relatedItem.name).cancel()
                tRandomTimers.put(relatedItem.name, null)
                logInfo("TIMERCHECK", "RandomTimer for Item " + relatedItem.name + " reached end. Action " + newitemstate.toString + " executed.")
                relatedItem.sendCommand(newitemstate)
                tRandomTimers.remove(relatedItem.name)

                logInfo("ReentrantLock","randomTimer tRandomTimersLock.unlock(): " + relatedItem.name)
                tRandomTimersLockInternal.unlock()                
            ])

1 Like

That is there correct behavior. You don’t want to prevent other times from being created while you have a timer running, and if you did there other ways to implement that.

You want the lock to just prevent two copies of the lambda from running at the same time. So locking it at the top of the lambda and unlocking it at the bottom is what you want.

Thread safe, by definition means that the lambda can only ever be run by one thread at a time.

This is an unrelated to the lambda problem discussed in this thread. This would be a problem with the Timers scheduler.

I see in the later posts you have already figured this out. Glad you got it to work.