So, look in events.log.
Is the PIR Item changing when you expect it?
If it is, is it triggering the “timer” rule? That includes a logInfo you should see in openhab.log, and some logInfo progress reports about timer status.
If that rule is running, back to events.log - is the Sonoff4ch_2Channel5 command sent after expiry time?
If it is, is it triggering the matching “toggle” rule? You can’t tell - adding a logInfo here too would be useful, until it’s sorted out. It’s a simple enough rule you probably won’t need anything else.
Having said all that, it’s teaching a man to fish, blah.
The quicker fix is to make sure that the Item referenced in the toggle rule trigger is the same one referenced in the if() statement - look closely.
Thanks, I am only thinking this through as i am not at home (but have remote access!) so will have a good look tonight again. Thanks for the tips, I will keep you posted…
OK its not over yet! Something really weird is now happening with my timer rule. Its as though var Timer is not null at the start of the rule. When I first did the rule the timer would start and end perfectly but since I tried to cure the dreaded Alexa ON/OFF fault it has stopped working.
So this is my Openhab log:
2018-12-11 19:45:11.940 [vent.ItemStateChangedEvent] - D1mini_pir1 changed from OFF to ON
==> /var/log/openhab2/openhab.log <==
2018-12-11 19:45:11.944 [INFO ] [.eclipse.smarthome.model.script.PIR1] - RECEIVED UPDATE ON
2018-12-11 19:45:11.959 [INFO ] [.eclipse.smarthome.model.script.PIR1] - Timer Rescheduled
==> /var/log/openhab2/events.log <==
2018-12-11 19:45:14.731 [vent.ItemStateChangedEvent] - D1mini_pir1 changed from ON to OFF
This is my light toggle with a LogInfo in, which never triggers… But if I manually switch through my sitemap it triggers ok.
rule "Sonoff4ch_2Channel5 Toggle"
when
Item Sonoff4ch_2Channel5 received command
then
logInfo("Sonoff4ch_2Channel5","Toggle rule triggered")
if (receivedCommand != Sonoff4ch_2Channel5.state) {
// only if new request does not match actual current state
// then we need to toggle the relay state
if (Sonoff_relay5.state == OFF) {
Sonoff_relay5.sendCommand(ON)
} else {
Sonoff_relay5.sendCommand(OFF)
}
} // else already in
end
Its like the null in the IF statement is not null…but it all seems ok to me Do I need to clear the varible somehow? but surely the var Timer occupancyTimer = null does that at the start of the rule…
I can see the D1mini_pir1 changing in the event log but no Sonoff4ch_2Channel5 because the timer appears to be stuck in a constant re-shedule loop…
Another strange thing I have spotted in the openhab.log is this lot:
2018-12-11 19:32:54.854 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'control lights toggling.rules'
2018-12-11 19:33:52.920 [INFO ] [ome.model.script.Sonoff4ch_2Channel5] - Toggle rule triggered
2018-12-11 19:34:58.849 [INFO ] [.eclipse.smarthome.model.script.PIR1] - RECEIVED UPDATE ON
2018-12-11 19:34:58.863 [INFO ] [.eclipse.smarthome.model.script.PIR1] - Timer Rescheduled
2018-12-11 19:35:49.682 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 9522648 failed: null
2018-12-11 19:38:03.596 [WARN ] [io.openhabcloud.internal.CloudClient] - Jetty request 9522965 failed: null
2018-12-11 19:43:52.726 [INFO ] [.eclipse.smarthome.model.script.PIR1] - RECEIVED UPDATE ON
2018-12-11 19:43:52.739 [INFO ] [.eclipse.smarthome.model.script.PIR1] - Timer Rescheduled
2018-12-11 19:44:42.834 [INFO ] [.eclipse.smarthome.model.script.PIR1] - RECEIVED UPDATE ON
2018-12-11 19:44:42.849 [INFO ] [.eclipse.smarthome.model.script.PIR1] - Timer Rescheduled
2018-12-11 19:45:11.944 [INFO ] [.eclipse.smarthome.model.script.PIR1] - RECEIVED UPDATE ON
2018-12-11 19:45:11.959 [INFO ] [.eclipse.smarthome.model.script.PIR1] - Timer Rescheduled
2018-12-11 19:51:18.137 [ERROR] [lfe.hap.impl.http.impl.BinaryHandler] - Exception in binary handler
java.io.IOException: Connection timed out
at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) [?:?]
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) [?:?]
at sun.nio.ch.IOUtil.read(IOUtil.java:192) [?:?]
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) [?:?]
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447) [226:org.openhab.io.homekit:2.3.0]
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354) [226:org.openhab.io.homekit:2.3.0]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112) [226:org.openhab.io.homekit:2.3.0]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137) [226:org.openhab.io.homekit:2.3.0]
at java.lang.Thread.run(Thread.java:748) [?:?]
2018-12-11 19:51:18.145 [ERROR] [.hap.impl.http.impl.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Connection timed out
at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) [?:?]
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) [?:?]
at sun.nio.ch.IOUtil.read(IOUtil.java:192) [?:?]
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) [?:?]
at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447) [226:org.openhab.io.homekit:2.3.0]
at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382) [226:org.openhab.io.homekit:2.3.0]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354) [226:org.openhab.io.homekit:2.3.0]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112) [226:org.openhab.io.homekit:2.3.0]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137) [226:org.openhab.io.homekit:2.3.0]
at java.lang.Thread.run(Thread.java:748) [?:?]
I uninstalled the Homekit binding that appeared to be causing a lot of errors, I dont use Siri much anyway.
Also uninstalled a weather underground binding that I was playing with a while ago
then rebooted the Pi and hey presto things seem to work…
Would anyone like to speculate as to what on earth was going on???
