Strange behaviour of a new rule

[JohnnyX (John)]

Dear all

today I created a new rule: if a physical KNX button near to the kitchen is pushed in my office (Licht_DG_Zi3_D) the ceiling light starts blinking (and also blinking the ceiling light in the kitchen (Licht_EG_Essen_17) as confirmation that the rule is currently running).

Basically the rule is working fine, but:

• I can use this rule only once, sometimes twice; if used more often in the log file the correct (Licht_EG_Kueche_CtE) items receives a command but the rule is not executed anymore (nothing happens)

• as soon as I use any other item, both via browser/app and physical switch, the correct item gets the desired command - but everytime twice, see here:

  2015-11-26 14:16:24.476 [INFO ] [runtime.busevents ] - Licht_DG_Zi3_D received command OFF
  2015-11-26 14:16:24.616 [INFO ] [runtime.busevents ] - Licht_DG_Zi3_D received command OFF

• after a restart of the OH server the rule is working fine again, all items get only one command but as soon as the rule is executed the “game” starts again

What is going with my rule?

item
Switch Licht_EG_Kueche_CtE "Küche - Call to Eat" (gLights, gEG_Kueche, gSzenen) {knx="<2/1/106"}

rule

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*
//import org.openhab.model.script.actions.Timer
import java.lang.Math
import java.util.concurrent.locks.ReentrantLock
import org.openhab.core.library.types.DecimalType

var Timer timer = null

rule "Blinklicht"
	when 
		Item Licht_EG_Kueche_CtE received command ON
	then
		if(timer!=null) 
			{
			timer.cancel()
			}
		if(timer==null) 
			{
			timer = createTimer(now.plusSeconds(3)) [|
				if (Licht_DG_Zi3_D.state == ON || Licht_EG_Essen_17.state == ON )
					{
					Licht_DG_Zi3_D.sendCommand(OFF)
					Licht_EG_Essen_17.sendCommand(OFF)
					}
				else
					{
					Licht_DG_Zi3_D.sendCommand(ON)
					Licht_EG_Essen_17.sendCommand(ON)
					}
				if (Licht_EG_Kueche_CtE.state == ON) 
					{
					timer.reschedule(now.plusSeconds(3))
					}
				]
			} 
		else 
			{
			timer.reschedule(now.plusSeconds(3))
			}
end

Thanks & Regards
John

[JohnnyX (John)]

I’m still struggeling with that strange rule behaviour.

Since I’m no developer/java expert can anyone please check whether my rule is correct from “coding perspective”?

Thanks & Regards
John

[kyb (blank)]

I’ve had undesireable issues with timers as well and have changed them according to this thread:
Replace the keyword null with 0 (as in number zero)
Optional: don’t reschedule, just cancel and recreate the timer.

Maybe these changes can solve your problem as well.

[JohnnyX (John)]

Thx @kyb, will give it a try and post my results.

[rlkoshak (Rich Koshak)]

If you don’t have anything to set Licht_EG_Kueche_CtE back to OFF (which I didn’t see in my quick perusal of the code) the rule will only execute the first time it is turned to ON and then not again I believe.

You can try changing your trigger to received command or received update and checking its state in your rule. Or you can have some other rule or timer set it back to false.

[JohnnyX (John)]

@rlkoshak

set Licht_EG_Kueche_CtE back to OFF

Thanks for the hint, I just implemented a button to switch it off.

[JohnnyX (John)]

Now, I’m totally lost. I’m struggling for 5 days with that rule. With reschedule I get it running at least one time (item is blinking) but that rule still works only once (beside an ON for Licht_EG_Kueche_CtE nothing else happens). If I replace reschedule with timer = createTimer(now.plusSeconds(3)) the desired blink-item Licht_DG_Zi3_D gets the command “ON” 3 times but nothing is blinking and no further log entries are displayed. I think I’ve consideres all hints in that post but something is obviously still wrong. Can anybody pls help me and check where my mistake is?

Thank you for your help.

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*
import org.openhab.model.script.actions.Timer
import java.lang.Math
import java.util.concurrent.locks.ReentrantLock
import org.openhab.core.library.types.DecimalType

var Timer timer = 0

rule "Blinklicht"
	when 
		Item Licht_EG_Kueche_CtE received command ON
	then
		if(timer!=0)
			{
			timer.cancel()
			}

		else if(timer==0) 
			{
			timer = createTimer(now.plusSeconds(3)) 
				[|
				if (Licht_DG_Zi3_D.state == ON)
					{
					Licht_DG_Zi3_D.sendCommand(OFF)
					}
				else
					{
					Licht_DG_Zi3_D.sendCommand(ON)
					}
				if (Licht_EG_Kueche_CtE.state == ON) 
					{
//					timer.reschedule(now.plusSeconds(3))
					timer.cancel
					timer = createTimer(now.plusSeconds(3)) 
						[|
							Licht_DG_Zi3_D.sendCommand(ON)
						]	
					}
				]	
			}
			 
		else  
			{
//				timer.reschedule(now.plusSeconds(3))
				timer.cancel
				timer = createTimer(now.plusSeconds(3)) 
				[|
					Licht_DG_Zi3_D.sendCommand(ON)
				]
			}

		if(receivedCommand==OFF) 
		{
		if(timer!=null) 
			{
			timer.cancel
			timer = 0
			}
		}	

end

[rlkoshak (Rich Koshak)]

Lets see if I understand what you are trying to do.

You want Licht_EG_Kueche_CtE to blink three times at three second intervals (3 seconds on, 3 seconds off, etc) three times when it receives the ON command. Correct?

This is how I would do that:

First of all, it is better to use null instead of 0 in the rule’s language. This helps prevent the engine from trying to cast something to a Number when you really don’t want it to be one. It also makes the code easier to read as your intent is more clear.

var Timer timer = null
var blinkCount = 0

rule "Blinklicht"
    when
        Item Licht_EG_Kueche_CtE received command ON
    then
        // Cancel the current timers and start over if the timer isn't null
        if(timer == null) {
            timer.cancel
            blinkCount = 0
        }

        // Create timer
        timer = createTimer(now.plusSeconds(3), [|
            if(blinkCount <= 6) { // 3 ONs, 3 OFFs
                if(Licht_DG_Zi3_d.state == ON) {
                    Licht_DG_Zi3_d.sendCommand(OFF)
                    blinkCount = blinkCount + 1
                }
                else {
                    Lich_DG_Zi3_D.sendCommand(ON)
                }

                // Reschedule the timer
                timer.reschedule(now.plusSeconds(3))
            }
        ]
end

[JohnnyX (John)]

@rlkoshak

You want Licht_EG_Kueche_CtE to blink three times at three second intervals (3 seconds on, 3 seconds off, etc) three times when it receives the ON command. Correct?

No
In prosa: I’d like to have a switch (Licht_EG_Kueche_CtE) that, if switched on, starts the lights in the office (Licht_DG_Zi3_D) blinking. 3 seconds is just for testing, it can also be 2 or 4 or something else. It should blink as long as Licht_EG_Kueche_CtE is not switched off.
The mentioned “three times in the log file” is the current result that I see. With my code the items gets three times the “ON” but nothing else.

Regarding null vs. 0: I followed the recommendation from a previous post in this thread:

@kyb

Replace the keyword null with 0 (as in number zero)

Thank you for your help.

[rlkoshak (Rich Koshak)]

In that case I’d make the rules as follows:

var Timer timer = null

rule "Blinklicht ON"
when
    Item Licht_EG_Kueche_CtE received command ON
then
    // Cancel any current timers that might be hanging around
    if(timer != null || !timer.hasTerminated) {
        timer.cancel
    }

    timer = createTimer(now.plusSeconds(3), [| // you don't say where the blinking period comes from so that is left up to you
        if(Licht_DG_Zi3_d.state == ON) Licht_DG_Zi3_d.sendCommand(OFF)
        else Licht_DG_Zi3_d.sendCommand(ON)

        timer.resechedule(now.plusSeconds(3))
    ]
end

rule "Blinklicht OFF"
when
    Item Licht_EG_Kueche_CtE received command OFF
then
    if(timer != null) {
        timer.cancel
        Licht_DG_Zi3_d.sendCommand(OFF)
    }
end

[JohnnyX (John)]

Thank you @rlkoshak, I’ve tried your code but now I get a new error:

2015-11-30 20:00:34.857 [ERROR] [o.o.c.s.ScriptExecutionThread ] - Error during the execution of rule 'Blinklicht ON': cannot invoke method public abstract boolean org.openhab.model.script.actions.Timer.hasTerminated() on null

What does this mean? Do I have to import any further libraries? Currently I’m importing these here:

import org.openhab.core.library.types.*
import org.openhab.core.persistence.*
import org.openhab.model.script.actions.*
import org.openhab.model.script.actions.Timer
import java.lang.Math
import java.util.concurrent.locks.ReentrantLock
import org.openhab.core.library.types.DecimalType

How is that part to be understood:
!timer.hasTerminated)
What happens here with the exclamation mark?

[rlkoshak (Rich Koshak)]

That is odd. It shouldn’t have executed that part. The if statement means if timer isn’t null and timer.hasTerminated is false (i.e. the timer is still running) then cancel the timer. The if statement should have bailed out as soon as it saw that timer was null.

Change the if to:

if(timer != null)

At the end of “Blinklicht OFF” add:

    timer = null

@JohnnyX

What happens here with the exclamation mark?

The explanation mark is the negation operation. If timer.hasTerminated returns true the ! turns it false and visa versa. So by saying !timer.hasTerminated what I’m really saying is if the timer has not terminated, since hasTerminated returns true if the timer has expired.

[JohnnyX (John)]

Finally!!! It works Thank you @rlkoshak

One more question reg. (actually two questions) some side effects:
As you can see in my log the switched items receive every command twice. Why?

2015-12-01 11:06:22.298 [INFO ] [runtime.busevents] - Licht_EG_Kueche_CtE received command ON
2015-12-01 11:06:25.328 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command ON
2015-12-01 11:06:25.468 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command ON
2015-12-01 11:06:28.358 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command OFF
2015-12-01 11:06:28.513 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command OFF
2015-12-01 11:06:31.383 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command ON
2015-12-01 11:06:31.513 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command ON
2015-12-01 11:06:34.408 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command OFF
2015-12-01 11:06:34.563 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command OFF
2015-12-01 11:06:37.433 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command ON
2015-12-01 11:06:37.558 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command ON
2015-12-01 11:06:40.463 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command OFF
2015-12-01 11:06:40.633 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command OFF
2015-12-01 11:06:43.493 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command ON
2015-12-01 11:06:43.628 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command ON
2015-12-01 11:06:45.558 [INFO ] [runtime.busevents] - Licht_EG_Kueche_CtE received command OFF
2015-12-01 11:06:45.583 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command OFF
2015-12-01 11:06:45.738 [INFO ] [runtime.busevents] - Licht_DG_Zi3_D received command OFF

After I have activated Licht_EG_Kueche_CtE for the first time all manually switched items receive also every command twice. Why?

2015-12-01 11:08:11.363 [INFO ] [runtime.busevents] - Licht_DG_Zi3_W received command ON
2015-12-01 11:08:11.503 [INFO ] [runtime.busevents] - Licht_DG_Zi3_W received command ON
2015-12-01 11:08:12.883 [INFO ] [runtime.busevents] - Licht_DG_Zi3_W received command OFF
2015-12-01 11:08:13.013 [INFO ] [runtime.busevents] - Licht_DG_Zi3_W received command OFF
2015-12-01 11:08:29.004 [INFO ] [runtime.busevents] - Licht_DG_Zi2_D received command ON
2015-12-01 11:08:29.179 [INFO ] [runtime.busevents] - Licht_DG_Zi2_D received command ON
2015-12-01 11:08:29.944 [INFO ] [runtime.busevents] - Licht_DG_Zi2_D received command OFF
2015-12-01 11:08:30.109 [INFO ] [runtime.busevents] - Licht_DG_Zi2_D received command OFF
2015-12-01 11:08:40.989 [INFO ] [runtime.busevents] - Licht_DG_Bad received command ON
2015-12-01 11:08:41.119 [INFO ] [runtime.busevents] - Licht_DG_Bad received command ON
2015-12-01 11:08:42.309 [INFO ] [runtime.busevents] - Licht_DG_Bad received command OFF
2015-12-01 11:08:42.469 [INFO ] [runtime.busevents] - Licht_DG_Bad received command OFF

This behaviour is reproducible. After a restart of OH all switches receive only one command. As soon as I used this new rule all manually switched items receive every command twice.

Manually switched = either clicked in the browser on the switch or pushed a physical button on the wall.

[rlkoshak (Rich Koshak)]

You would need to add some logging to the rule and timer to see if you are accidentally creating two timers or something like that. Without experimenting with it I can’t tell you why you are getting two commands, but it is certainly because of something in the rule.

[JohnnyX (John)]

@rlkoshak

need to add some logging to the rule and timer

I guess you already expected my question How can I do that?

[rlkoshak (Rich Koshak)]

logInfo(“My Rules”, “log statement”)

In the log the “My Rules” part is used to identify where the logging statement came from.

By default the logs are saved to /etc/logs/openhab/openhab.log if you installed on Linux using apt-get.

[JohnnyX (John)]

First test result:

2015-12-01 17:48:47.196 [INFO ] [runtime.busevents             ] - Licht_EG_Kueche_CtE received command ON
2015-12-01 17:48:50.486 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:48:50.606 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:48:50.631 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:48:53.621 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:48:53.661 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:48:53.761 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:48:56.661 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:48:56.691 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:48:56.796 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:48:59.686 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:48:59.716 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:48:59.831 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:49:02.716 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:49:02.746 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:49:02.866 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:49:05.746 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:49:05.776 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:49:05.881 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:49:08.776 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:49:08.801 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:49:08.916 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:49:11.801 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:49:11.831 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:49:11.946 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:49:14.831 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:49:14.831 [INFO ] [runtime.busevents             ] - Licht_EG_Kueche_CtE received command OFF
2015-12-01 17:49:14.861 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:49:14.981 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 17:49:14.986 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 17:49:15.071 [INFO ] [.openhab.model.script.My Rules] - log statement
2015-12-01 17:49:15.116 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF

I checked the logfiles events.log and openhab.log but there are no further information. I guess I added your code at the wrong place:

var Timer timer = null

rule "Blinklicht ON"
when

Item Licht_EG_Kueche_CtE received command ON
then
if(timer != null)
{
timer.cancel
logInfo(“My Rules”, “log statement”)
}

timer = createTimer(now.plusSeconds(3))
[|
if(Licht_DG_Zi3_D.state == ON)
Licht_DG_Zi3_D.sendCommand(OFF)
else
Licht_DG_Zi3_D.sendCommand(ON)

timer.reschedule(now.plusSeconds(3))
logInfo("My Rules", "log statement")
]

end

rule "Blinklicht OFF"
when

Item Licht_EG_Kueche_CtE received command OFF
then
if(timer != null) {
timer.cancel
Licht_DG_Zi3_D.sendCommand(OFF)
timer = null
logInfo(“My Rules”, “log statement”)
}
end

[rlkoshak (Rich Koshak)]

@JohnnyX

I checked the logfiles events.log and openhab.log but there are no further information. I guess I added your code at the wrong place:

???

I see several of your log statements in the log you posted above. Every line that reads:

2015-12-01 17:48:53.661 [INFO ] [.openhab.model.script.My Rules] - log statement

in openhab.log comes from your log statement. Of course, you are supposed to actually put something meaningful in the “log statement” part and usually put the name of the rule in the “My Rules” part so you can tell exactly which lines have executed and when…

For example:

    if(timer != null) 
    {
        timer.cancel
        logInfo("Blinklicht ON", "Canceled timer")
    }

And

timer = createTimer(now.plusSeconds(3)) 
    [|
        if(Licht_DG_Zi3_D.state == ON) 
            Licht_DG_Zi3_D.sendCommand(OFF)
        else 
            Licht_DG_Zi3_D.sendCommand(ON)

        timer.reschedule(now.plusSeconds(3))
        logInfo("Blinklicht ON", "Timer executed, rescheduled")
    ]

[JohnnyX (John)]

@rlkoshak

Of course, you are supposed to actually put something meaningful in the “log statement” part and usually put the name of the rule in the “My Rules” part so you can tell exactly which lines have executed and when.

Sorry for being that stupid but for any reason I didn’t realize what you were trying to say me…
Anyway, now I changed the code according to your explanation and got the following results:

2015-12-01 19:28:15.982 [INFO ] [runtime.busevents             ] - Licht_EG_Kueche_CtE received command ON
2015-12-01 19:28:19.167 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, now execute if/else
2015-12-01 19:28:19.302 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 19:28:19.357 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, 'else' executed=sendCommand(ON)
2015-12-01 19:28:19.447 [INFO ] [hab.model.script.Blinklicht ON] - Timer executed, rescheduled
2015-12-01 19:28:19.472 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON

2015-12-01 19:28:22.417 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, now execute if/else
2015-12-01 19:28:22.472 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 19:28:22.502 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, 'else' executed=sendCommand(ON)
2015-12-01 19:28:22.502 [INFO ] [hab.model.script.Blinklicht ON] - Timer executed, rescheduled
2015-12-01 19:28:22.602 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF

2015-12-01 19:28:25.502 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, now execute if/else
2015-12-01 19:28:25.502 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 19:28:25.947 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, 'else' executed=sendCommand(ON)
2015-12-01 19:28:25.947 [INFO ] [hab.model.script.Blinklicht ON] - Timer executed, rescheduled
2015-12-01 19:28:26.082 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON

2015-12-01 19:28:28.947 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, now execute if/else
2015-12-01 19:28:28.952 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 19:28:28.977 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, 'else' executed=sendCommand(ON)
2015-12-01 19:28:28.982 [INFO ] [hab.model.script.Blinklicht ON] - Timer executed, rescheduled
2015-12-01 19:28:29.102 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF

2015-12-01 19:28:31.982 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, now execute if/else
2015-12-01 19:28:31.982 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 19:28:32.012 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, 'else' executed=sendCommand(ON)
2015-12-01 19:28:32.012 [INFO ] [hab.model.script.Blinklicht ON] - Timer executed, rescheduled
2015-12-01 19:28:32.132 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON

2015-12-01 19:28:35.012 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, now execute if/else
2015-12-01 19:28:35.017 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 19:28:35.052 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, 'else' executed=sendCommand(ON)
2015-12-01 19:28:35.052 [INFO ] [hab.model.script.Blinklicht ON] - Timer executed, rescheduled
2015-12-01 19:28:35.167 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF

2015-12-01 19:28:38.052 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, now execute if/else
2015-12-01 19:28:38.052 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 19:28:38.082 [INFO ] [hab.model.script.Blinklicht ON] - Timer created, 'else' executed=sendCommand(ON)
2015-12-01 19:28:38.087 [INFO ] [hab.model.script.Blinklicht ON] - Timer executed, rescheduled
2015-12-01 19:28:38.202 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON

2015-12-01 19:28:38.667 [INFO ] [runtime.busevents             ] - Licht_EG_Kueche_CtE received command OFF
2015-12-01 19:28:38.782 [INFO ] [.o.model.script.Blinklicht OFF] - timer was !=null, canceled timer
2015-12-01 19:28:38.837 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 19:28:38.892 [INFO ] [.o.model.script.Blinklicht OFF] - executed=sendCommand(OFF)
2015-12-01 19:28:38.942 [INFO ] [.o.model.script.Blinklicht OFF] - timer=null
2015-12-01 19:28:38.972 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF

Just for understanding reasons here again my adapted code with enhanced logging:

var Timer timer = null

rule "Blinklicht ON"
when
Item Licht_EG_Kueche_CtE received command ON
then
if(timer != null) 
    	{
timer.cancel
logInfo("Blinklicht ON", "timer was !=null, canceled timer")
}

timer = createTimer(now.plusSeconds(3))
	[|
	logInfo("Blinklicht ON", "Timer created, now execute if/else")
if(Licht_DG_Zi3_D.state == ON) 
	Licht_DG_Zi3_D.sendCommand(OFF)

else 
	Licht_DG_Zi3_D.sendCommand(ON)
		logInfo("Blinklicht ON", "Timer created, 'else' executed=sendCommand(ON)")
	
timer.reschedule(now.plusSeconds(3))
logInfo("Blinklicht ON", "Timer executed, rescheduled")
]

end

rule "Blinklicht OFF"
when
Item Licht_EG_Kueche_CtE received command OFF
then
if(timer != null) {
timer.cancel
logInfo("Blinklicht OFF", "timer was !=null, canceled timer")
Licht_DG_Zi3_D.sendCommand(OFF)
logInfo("Blinklicht OFF", "executed=sendCommand(OFF)")
timer = null
logInfo("Blinklicht OFF", "timer=null")
}
end

I just checked it again: as soon as the rule is executed my switches receive all commands twice:

2015-12-01 19:28:48.592 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 19:28:48.732 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command ON
2015-12-01 19:29:04.462 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 19:29:04.637 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_D received command OFF
2015-12-01 19:29:10.372 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_W received command ON
2015-12-01 19:29:10.532 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_W received command ON
2015-12-01 19:29:11.917 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_W received command OFF
2015-12-01 19:29:12.092 [INFO ] [runtime.busevents             ] - Licht_DG_Zi3_W received command OFF

Can you see in that information why all items get the commands twice? Can I provide any further information?

[rlkoshak (Rich Koshak)]

I think what is happening is that you send the command to the Switch which sends it to the device. When the device acts on the command it sends the status back to the binding so the Switch looks like it gets updated twice but what is actually happening is you are really getting a confirmation that the switch was turned on.

I don’t know for sure that is what is happening but I can say that, assuming the logging is in order the rule is not issuing the command twice.

Below is some commentary on your logging so in the future you can better use logging to debug your rules.

First of all, your “Timer created, now executing if/else” statement is misleading. When that log statement executes your timer is executing. It was actually created three seconds ago (at least). Any log statement that talks about creating a timer should be immediately before the call to createTimer.

You have added a log statement everywhere except the one place I would need to include or exclude some of the many things that could be happening. Add a log statement as the very first line of the rule so we can see how often the rule itself is called.

Then add a log statement immediately before the call to createTimer. that is where “Timer created…” log statement actually goes. If the rule is being called twice I need to know whether the timer is being created twice.

I don’t need “Timer created, ‘else’ executed” because I can see when the ON command is sent already.

When debugging with log statements you usually want to put a statement immediately before and/or immediately after important lines of code (e.g. the first or last thing your rule executes, immediately before creating a timer, the first line in a timer, etc). You want to do this because see the log statement tells you whether or not that part of the code is even executing and when you don’t see an expected log statement you know the code immediately before it caused an error.