Rule failed: timeout in Time

hey since update 3.0.1 i have a fault and i don’t know what to do with.

the fault :

[ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID ‘Time-4’ failed: timeout in Time

the rule:

rule “tijd automatisatie regels 1min”

when

//Item DATE_Time received update

Time cron "1 * * 1/1 * ? *"

then

//Bureau stekker

if(Bureau1onoff.state == ON && (!Bureau1onoff.changedSince(now.minusMinutes(600)))){

    sendCommand(Bureau1onoff, OFF)

}

// Keuken switch

if(Keuken_Stekker_Switch.state == ON && Keuken_Stekker_Watts1.state <= 1 && (!Keuken_Stekker_Switch.changedSince(now.minusMinutes(5))) && 

    (Keuken_Stekker_Watts1.historicState(now.minusMinutes(2)).state) <= 0.3 ){

    sendCommand(Keuken_Stekker_Switch, OFF)

}

// Slaapkamer lader

if(MaLaGSM_Switch.state == ON && MaLaGSM_Power.state <= 1 && (!MaLaGSM_Switch.changedSince(now.minusMinutes(5))) && 

    (MaLaGSM_Power.historicState(now.minusMinutes(2)).state) <= 0.3 ){

    sendCommand(MaLaGSM_Switch, OFF)

}

//Wasmachine uit bij geen verandering

if(Wasmachine_Switch.state == ON && Wasmachine_Watts.state <= 6 && (!Wasmachine_Switch.changedSince(now.minusMinutes(6))) &&  

    (Wasmachine_Watts.historicState(now.minusMinutes(6)).state <= 6 )){

        sendCommand(Wasmachine_Switch, OFF)

}

//Droogkast uit bij geen verandering

if(Droogkast_Switch.state == ON && Droogkast_Watts.state <= 6 && (!Droogkast_Switch.changedSince(now.minusMinutes(6))) && 

    (Droogkast_Watts.historicState(now.minusMinutes(6)).state <= 6 )){

        sendCommand(Droogkast_Switch, OFF)

}

//Senseo uit bij geen verandering

if(Senseo_Switch.state == ON && Senseo_Watts.state <= 1 && (!Senseo_Switch.changedSince(now.minusMinutes(15))) && 

    (Senseo_Watts.historicState(now.minusMinutes(6)).state <= 1)){

        sendCommand(Senseo_Switch, OFF)

}

//Vaatwas uit bij geen verandering

if(Vaatwas_Switch.state == ON && Vaatwas_Watts.state <= 6 && (!Vaatwas_Switch.changedSince(now.minusMinutes(15))) && 

    (Vaatwas_Watts.historicState(now.minusMinutes(6)).state <= 6)){

        sendCommand(Vaatwas_Switch, OFF)

}



//Crosstrainer uit bij geen verandering

if(Crosstrainer_Switch.state == ON && Crosstrainer_Watts.state <= 6 && (!Crosstrainer_Switch.changedSince(now.minusMinutes(15))) && 

    (Crosstrainer_Watts.historicState(now.minusMinutes(6)).state <= 6)){

        sendCommand(Crosstrainer_Switch, OFF)

}

end

if i delete this !XXXX_Switch.changedSince(now.minusMinutes(15)) the fault goes away if i delete the exclamation mark the fault stays. So i know where the problem is but i don’t understand why it wasn’t a problem before but now it is.

Logging can do wonders. What is being returned by the persistence calls? Probably null. Have you changed or has anything changed in your persistence config?

i tried to log this, but I don’t now exactly how to log a timeout…

2021-03-17 22:05:12.203 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID ‘Time-4’ failed: timeout in Time

==> /var/log/openhab/events.log <==

2021-03-17 22:05:12.204 [TRACE] [openhab.event.RuleStatusInfoEvent ] - Received event of type ‘RuleStatusInfoEvent’ under the topic ‘openhab/rules/Time-4/state’ with payload: ‘{“status”:“IDLE”,“statusDetail”:“NONE”}’

2021-03-17 22:05:12.206 [INFO ] [openhab.event.RuleStatusInfoEvent ] - Time-4 updated: IDLE

And no nothing changed on the persistence side. All the other persistence rules are still working.

Forget the error for the moment.

As I said, what gets returned by the persistence calls?

logInfo("testing", "Bureau1onoff.changedSince = " + Bureau1onoff.changedSince(now.minusMinutes(600)))

I think we’re all learning about this apparently new feature.
The persistence calls seem the most likely culprit. That might be competition for resource on a very busy system.

Ok this is what i have

code :

{

logInfo(“testing”, “Bureau1onoff.changedSince = {}”, Bureau1onoff.state)//changedSince(now.minusMinutes(600)).state)

logInfo(“testing”, “Bureau1onoff.updatedSince = {}”, Bureau1onoff.updatedSince(now.minusMinutes(600)))

logInfo(“testing”, “Bureau1onoff.changedSince = {}”, Bureau1onoff.changedSince(now.minusMinutes(600)))

logInfo(“testing”, “Bureau1onoff.changedSince = {}”, Bureau1onoff.historicState(now.minusMinutes(600)))

}

return :

2021-03-18 13:22:00.623 [INFO ] [rg.openhab.core.model.script.testing] - Bureau1onoff.live.status = ON

2021-03-18 13:22:01.304 [INFO ] [rg.openhab.core.model.script.testing] - Bureau1onoff.updatedSince = true

with the other 2 (historic and changed) i get no result.

now i changed my code from

//Bureau stekker

if(Bureau1onoff.state == ON && (!Bureau1onoff.changedSince(now.minusMinutes(600)))){

    sendCommand(Bureau1onoff, OFF)

}

this to

//Bureau stekker

if(Bureau1onoff.state == ON && (!Bureau1onoff.updatedSince(now.minusMinutes(600)))){

    sendCommand(Bureau1onoff, OFF)

}

and the fault is gone. So i don’t think there is a problem with persistence calls or the system, because it there was there would also be problems with updatedSince if i’m correct.

next test:

logInfo(“testing”, “Senseo.changedSince = {}”, Senseo_Switch.changedSince(now.minusMinutes(2)))

log:

2021-03-18 14:09:41.200 [INFO ] [rg.openhab.core.model.script.testing] - Senseo.changedSince = false

that meens that there is something wrong with my mqtt item. I think?

item:

Switch Bureau1onoff “Bureau [%s]” (Alles_Uit, MWakker){channel=“mqtt:topic:Zigbee:stopcontact3onoff”, ga=“outlet”}

thing

Type switch : stopcontact3onoff “Stopcontact ON/OFF” [stateTopic=“zigbee2mqtt/0xd0cf5efffebd3ef7”, transformationPattern=“JSONPATH:$.state”, commandTopic=“zigbee2mqtt/0xd0cf5efffebd3ef7/set”, transformationPatternOut=“JS:setstate.js”]

What persistence service do you use? Influxdb is currently broken for switches.

Different persistence calls may take different times. We started off looking for timeouts.

There’s quite a time delay there, over half a second, but I don’t know where/when the first message comes from. Did it really take that long to do updatedince() on one Item?

What persistence service do you use? Influxdb is currently broken for switches.

Idd Influxdb, but why does one switch work and the other not? All my zwave switches are working but my mqtt not.

There’s quite a time delay there, over half a second, but I don’t know where/when the first message comes from. Did it really take that long to do updatedince() on one Item?

The first is just a status bit that come from openhab itself the other comes from influx on another system then openhab. So i think this is normal?

I couldn’t say. An Item is an Item, persistence does not know or care how you update Items or from what binding.

Aha, slowly info comes out.
You could add before and after logs to your rule to find out just how long it takes to process the queries so far as openHAB is concerned.

You should be getting something from the logs. Or you should be seeing an error.

Not necessarily. There could be some weird behavior in how the query is done to persistence that allows some calls to work but others not. For example, there was a bug in InfluxDB that caused averageSince to fail and always return null.

In this case changedSince needs to search through the DB from the date passed in and look at all the values to see if the Item changed in that time. updatedSince just needs to see if there is any record at all saved to the DB in that time period.

And, as rossko57 suggests, add logging to see how long these queries are taking. It might be there is some problem where certain types of queries take too long to return a result. If that’s the case, you need to look at your InfluxDB server and/or your network to see why it’s taking so long to reply.

ok next test

//Bureau stekker

rule "tijd automatisatie regels test 1min"

when
	//Item DATE_Time received update
	Time cron "0/20 * * 1/1 * ? *"
then
{
logInfo("testing", "Senseo.live.state = {}", Senseo_Switch.state)
logInfo("testing", "Senseo.changedSince = {}", Senseo_Switch.changedSince(now.minusMinutes(2)))
logInfo("testing", "Keuken.live.state = {}", Keuken_Stekker_Switch.state)
logInfo("testing", "Keuken.changedSince = {}", Keuken_Stekker_Switch.changedSince(now.minusMinutes(2)))
logInfo("testing", "Bureau1onoff.live.state = {}", Bureau1onoff.state)
logInfo("testing", "Bureau1onoff.updatedSince = {}", Bureau1onoff.updatedSince(now.minusMinutes(600)))
logInfo("testing", "Bureau1onoff.changedSince = {}", Bureau1onoff.changedSince(now.minusMinutes(2)))
logInfo("testing", "Keuken.live.state = {}", Keuken_Stekker_Switch.state)
logInfo("testing", "Keuken.changedSince = {}", Keuken_Stekker_Switch.changedSince(now.minusMinutes(2)))

}

end

result

2021-03-18 16:50:00.979 [INFO ] [rg.openhab.core.model.script.testing] - Senseo.live.state = OFF
2021-03-18 16:50:01.031 [INFO ] [rg.openhab.core.model.script.testing] - Senseo.changedSince = false

2021-03-18 16:50:01.035 [INFO ] [rg.openhab.core.model.script.testing] - Keuken.live.state = OFF
2021-03-18 16:50:01.085 [INFO ] [rg.openhab.core.model.script.testing] - Keuken.changedSince = false

2021-03-18 16:50:01.086 [INFO ] [rg.openhab.core.model.script.testing] - Bureau1onoff.live.state = OFF
2021-03-18 16:50:01.820 [INFO ] [rg.openhab.core.model.script.testing] - Bureau1onoff.updatedSince = true

then the fault

2021-03-18 16:50:11.849 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID ‘Test-5’ failed: timeout in Test

so the rule stops fails here :

logInfo(“testing”, “Bureau1onoff.changedSince = {}”, Bureau1onoff.changedSince(now.minusMinutes(2)))

and it is so with every switch that works with zigbee over mqtt.

As rossko57 said, that’s irrelevant. By the time you are working with Items what/if anything the Item is linked to is irrelevant. All Persistence sees is Items states with no difference in how those Items are changing state. The only think that might be a problem is if those Items have not actually changed over that time period or their states are not being saved correctly.

You are using InfluxDB and these are Switched. As rossko57 pointed out, there are problems using InfluxDB with Switches right now. So frankly, I don’t think we will be able to solve this for you until the InfluxDB add-on itself is fixed.

Maybe we’re misinterpreting this message.
We have previously seen rules fail just because they took too long, but the message was different -
[ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'CheckDevices' failed: Total timeout 10000 ms elapsed

Let’s speculate the unspecified “timeout” in your message comes from persistence service.

To begin with, your rule seems to do queries quite quickly.
But then it bogs down -

2021-03-18 16:50:01.086 [INFO ] [rg.openhab.core.model.script.testing] - Bureau1onoff.live.state = OFF
2021-03-18 16:50:01.820 [INFO ] [rg.openhab.core.model.script.testing] - Bureau1onoff.updatedSince = true

Most of a second. Maybe the timeout threshold is one second here.

[ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID ‘CheckDevices’ failed: Total timeout 10000 ms elapsed

this is exactly the time the timeout fault appears in my logs after the first log off my test.

if my there was something wrong with my influx server/database i would get more errors but it is only on 3 switches.

Please don’t withhold information. Give us all relevant logs.

If there wasn’t something wrong you wouldn’t be posting here.

If you knew what the problem was you wouldn’t be posting here, so don’t make assumptions about what is and is not working. Between the two of us, rossko57 and I have nearly two decades worth of experience using openHAB and helping people solve problems like these. Don’t “help” us by withholding information and assuming you know better.

I think rossko57 is on to something. It’s not those specific three switches that are the problem (because as far as InfluxDB and even the InfluxDB Binding in OH are concerned there is no difference in those Items, they are just Switch Items like any other, there isn’t any way for them to be different). It’s the fact that you have a bunch of calls to persistence in a row with mere milliseconds between calls. Something is getting bogged down and/or stuck and it’s taking more than ten seconds to return a result.

i have the loggings in a txt file
log.txt (29.9 KB)
these are the only ones i’m getting…
my rule
testrule.txt (971 Bytes)
items:
items.txt (1.3 KB)
things:
things.txt (2.0 KB)
transfrom (setstate.js file)
transform.txt (375 Bytes)
my system is openhab 3.0.1 on rpi 4 4GB ram ssd 256Gb 64bit version, my influxdb database is also 2.0.3 on a rpi 4 8GB ram. if you have questions shoot it is not my intention to withhold information.

this is what i see on my server

It’s possible the persistence data for one or more Items is messed up, and Influx or OH persistence chokes on it.
Re-arrange your rule to do the “bad” queries first, and see what timings you get.

1 Like

hope i did it wright

log:

log2.txt (23.8 KB)

rule:

rulechange.txt (1.1 KB)

next what i can to do is change the item name then?

That would determine or rule out the source of the problem being those Item’s being messed up in the database. Renaming them will create a new series in InfluxDB.

Also, it’ll be easier for us if you just post the code and logs like you did above using code fences. You are a very long way from the limit on a post size with these.

Given that the timeout occurs on that first line of the rule, as evidenced by the fact that none of the log statements appear in openhab.log I would try renaming the Items and see what happens.