search

smarthomej / addons

SmartHome/J addons for openHAB
Eclipse Public License 2.0
59 stars 23 forks source link

Tuya devices go OFFLINE for 5 seconds and then come back ONLINE #369

Closed owl770 closed 1 year ago

owl770 commented 2 years ago

Hi. I am using version 3.2.12 of the SmartHome/J Tuya Binding and am seeing some weird behaviour on a fairly regular basis where tuya devices go OFFLINE and then about 5 seconds later they come back online. I have three examples available from three different tuyaDevices (MAC address portion 080c, aaa1 and 3b6d). The log entries (below) are merged OH3 events.log and openhab.log files and only contain log entries for the one device (I deleted the 'noise' around it).

080c and aaa1 are very similar whereby the binding pings the switch and then gets an IOException (Connection reset by peer). The tuyaDevice then goes OFFLINE. Sometime later, the udpListener rediscovers the switch OK and the switch goes back ONLINE. Of course there are many (external) reasons why we might receive the Connection reset by peer message, which is out of your control but is it possible to build more resilience into the binding to handle these temporary situations?

3b6d is different in that it didn't respond to pings 3 times in a row (reason is unknown) and the tuyaDevice is forced OFFLINE. About 5 seconds later, TuyaEncoder sends a DP_QUERY that gets responded to and the tuyaDevice goes back ONLINE. Please note that in this environment, internet access is turned off at 23:00 and gets turned back on at 07:00 the next morning, hence the messages about the tuyaProject getting a DNS timeout. Would it be possible to perhaps do the DP_QUERY after a ping timeout to see if that 'wakes it up' or could you increase the number of pings (or make it configurable per device) to make the binding more resilient (I doubt this is a good fix)?

Logs for 080c:

2022-06-13 18:12:15.829 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 81446666c82b96cb080c/192.168.68.209:6668: Sending ping
2022-06-13 18:12:15.836 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 81446666c82b96cb080c/192.168.68.209:6668: Sending HEART_BEAT, payload {devId=81446666c82b96cb080c, uid=81446666c82b96cb080c, t=1655107935, dps=, gwId=81446666c82b96cb080c}
2022-06-13 18:12:15.845 [TRACE] [.internal.local.handlers.TuyaEncoder] - 81446666c82b96cb080c/192.168.68.209:6668: Sending encoded '000055AA000009240000000900000097332E33000000000000000000000000C2E4303EAFD84A796058A40DF75E31B4A55D1C0E407F4AACD9FCA5B9159667A5ECD81CD6694428364C51A0F277BAACDB5FDDA4A6A1FADDB578CF6027AB008D56757B80F37FB78ABA9D3A33680E116CBBA471D5E42173B1F8F9F4BB768383507B2C3CEB147DD5F0CF1BC0B4557A142543B766B4167AF8FF37AF42B05E45731F9439D3DEE80000AA55'
2022-06-13 18:12:15.890 [DEBUG] [rnal.local.handlers.UserEventHandler] - 81446666c82b96cb080c/192.168.68.209:6668: IOException caught, closing channel.
java.io.IOException: Connection reset by peer
    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:276) ~[?:?]
    at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
    at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:356) ~[?:?]
    at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253) ~[bundleFile:4.1.68.Final]
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[bundleFile:4.1.68.Final]
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350) ~[bundleFile:4.1.68.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [bundleFile:4.1.68.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.68.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.68.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.68.Final]
    at java.lang.Thread.run(Thread.java:829) [?:?]
2022-06-13 18:12:15.954 [DEBUG] [rnal.local.handlers.UserEventHandler] - IOException caught: 
java.io.IOException: Connection reset by peer
    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:276) ~[?:?]
    at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
    at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:356) ~[?:?]
    at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253) ~[bundleFile:4.1.68.Final]
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[bundleFile:4.1.68.Final]
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350) ~[bundleFile:4.1.68.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [bundleFile:4.1.68.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.68.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.68.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.68.Final]
    at java.lang.Thread.run(Thread.java:829) [?:?]
2022-06-13 18:12:15.977 [DEBUG] [al.local.handlers.TuyaMessageHandler] - 81446666c82b96cb080c/192.168.68.209:6668: Connection terminated.
2022-06-13 18:12:15.993 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:81446666c82b96cb080c' changed from ONLINE to OFFLINE
2022-06-13 18:12:17.262 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener: Received encoded '000055AA0000000000000013000000AC0000000028E0EF5F9D80C57C0585650A73708E393F482F4CBAD30A52DFA86C922660CF6347A2A10D40D28636C5D340A8EF2BD6912512E862E01AC3999903215AFCC5909E5C907565B323A346D0DE78C22F1FDABA1AE7C613C2CAE004E54A474561367714379E7D68A02456269F4616388E2AA04E5992EF40D1A7D97E76DA0C11B61B42A8720C9D70C37F0D4EC55DF6E7FE51F084384363DCD0F0705AE4CAC595BBF49625CC8C57E10000AA55'
2022-06-13 18:12:17.286 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.68.209","gwId":"81446666c82b96cb080c","active":2,"ability":0,"mode":0,"encrypt":true,"productKey":"xxxxxx","version":"3.3"}
2022-06-13 18:12:17.307 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener/: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.68.209', deviceId='81446666c82b96cb080c', active=2, ability=0, mode=0, encrypt=true, productKey='xxxxxx', version='3.3'}'}
2022-06-13 18:12:21.074 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 81446666c82b96cb080c/192.168.68.209:6668: Sending DP_QUERY, payload {devId=81446666c82b96cb080c, uid=81446666c82b96cb080c, t=1655107941, dps=null, gwId=81446666c82b96cb080c}
2022-06-13 18:12:21.099 [TRACE] [.internal.local.handlers.TuyaEncoder] - 81446666c82b96cb080c/192.168.68.209:6668: Sending encoded '000055AA000000010000000A00000088C2E4303EAFD84A796058A40DF75E31B4A55D1C0E407F4AACD9FCA5B9159667A5ECD81CD6694428364C51A0F277BAACDB5FDDA4A6A1FADDB578CF6027AB008D5660F1790C48BF950A80C0722C3D66F891F5DD5C3F6F043E034B318350AB41FF442C3CEB147DD5F0CF1BC0B4557A142543B766B4167AF8FF37AF42B05E45731F946FC668C40000AA55'
2022-06-13 18:12:21.107 [DEBUG] [al.local.handlers.TuyaMessageHandler] - 81446666c82b96cb080c/192.168.68.209:6668: Connection established.
2022-06-13 18:12:21.126 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:81446666c82b96cb080c' changed from OFFLINE to ONLINE
2022-06-13 18:12:21.142 [TRACE] [.internal.local.handlers.TuyaDecoder] - 81446666c82b96cb080c/192.168.68.209:6668: Received encoded '000055AA000000010000000A0000004C00000000C2E4303EAFD84A796058A40DF75E31B4A55D1C0E407F4AACD9FCA5B9159667A51E558AACB9EEE033A92A644114A08C583C0731E4AAC3B19CF5DECF4ED075D7D0B6CACA750000AA55'
2022-06-13 18:12:21.158 [TRACE] [.internal.local.handlers.TuyaDecoder] - 81446666c82b96cb080c//192.168.68.209:6668: Decoded raw payload: {"devId":"81446666c82b96cb080c","dps":{"1":true,"9":0}}
2022-06-13 18:12:21.174 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 81446666c82b96cb080c//192.168.68.209:6668: Received MessageWrapper{commandType=DP_QUERY, content='{1=true, 9=0.0}'}
2022-06-13 18:12:21.181 [TRACE] [a.internal.handler.TuyaDeviceHandler] - 'tuya:tuyaDevice:81446666c82b96cb080c' received status message '{1=true, 9=0.0}'

Logs for aaa1:

2022-06-14 03:51:13.801 [TRACE] [.internal.local.handlers.TuyaDecoder] - 461808082cf432abaaa1/192.168.68.206:6668: Received encoded '000055AA00000000000000090000000C00000000B051AB030000AA55'
2022-06-14 03:51:13.815 [TRACE] [.internal.local.handlers.TuyaDecoder] - 461808082cf432abaaa1//192.168.68.206:6668: Decoded raw payload: 
2022-06-14 03:51:13.834 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 461808082cf432abaaa1//192.168.68.206:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''}
2022-06-14 03:51:13.848 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 461808082cf432abaaa1/192.168.68.206:6668: Received pong
2022-06-14 03:51:23.785 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 461808082cf432abaaa1/192.168.68.206:6668: Sending ping
2022-06-14 03:51:23.803 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 461808082cf432abaaa1/192.168.68.206:6668: Sending HEART_BEAT, payload {devId=461808082cf432abaaa1, uid=461808082cf432abaaa1, t=1655142683, dps=, gwId=461808082cf432abaaa1}
2022-06-14 03:51:23.820 [TRACE] [.internal.local.handlers.TuyaEncoder] - 461808082cf432abaaa1/192.168.68.206:6668: Sending encoded '000055AA000016950000000900000097332E33000000000000000000000000264287A56ECD3326694EFE326CFBFDB58F710E6C76495BE0862C66A9D5F991FDA2C7E30C1281583CBE8119C84348575D267EC2E75906DAB4B35E292BEDB5D5C96A565660A3030ADF31A445DC723BE145E9AED7AD9D5C84DBAA6328CC78A63CA64E497EEEB7FF4BFE89579CBD14FCDA035DD6A2839DA6960F83C2AD20A07952F87A0C83A90000AA55'
2022-06-14 03:51:23.857 [DEBUG] [rnal.local.handlers.UserEventHandler] - 461808082cf432abaaa1/192.168.68.206:6668: IOException caught, closing channel.
java.io.IOException: Connection reset by peer
    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:276) ~[?:?]
    at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
    at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:356) ~[?:?]
    at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253) ~[bundleFile:4.1.68.Final]
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[bundleFile:4.1.68.Final]
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350) ~[bundleFile:4.1.68.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [bundleFile:4.1.68.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.68.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.68.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.68.Final]
    at java.lang.Thread.run(Thread.java:829) [?:?]
2022-06-14 03:51:24.028 [DEBUG] [rnal.local.handlers.UserEventHandler] - IOException caught: 
java.io.IOException: Connection reset by peer
    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:276) ~[?:?]
    at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
    at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
    at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:356) ~[?:?]
    at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253) ~[bundleFile:4.1.68.Final]
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[bundleFile:4.1.68.Final]
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350) ~[bundleFile:4.1.68.Final]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) [bundleFile:4.1.68.Final]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) [bundleFile:4.1.68.Final]
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.68.Final]
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.68.Final]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.68.Final]
    at java.lang.Thread.run(Thread.java:829) [?:?]
2022-06-14 03:51:24.072 [DEBUG] [al.local.handlers.TuyaMessageHandler] - 461808082cf432abaaa1/192.168.68.206:6668: Connection terminated.
2022-06-14 03:51:24.099 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:461808082cf432abaaa1' changed from ONLINE to OFFLINE
2022-06-14 03:51:24.155 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener: Received encoded '000055AA0000000000000013000000AC0000000028E0EF5F9D80C57C0585650A73708E3930C7B5BF9822B13CA5AD9007F1A15DD25E8AE953FF7B208CD35FE74A477EB930EB190277F1F46FDDC96AFC89078A21115C907565B323A346D0DE78C22F1FDABA1AE7C613C2CAE004E54A474561367714379E7D68A02456269F4616388E2AA04EED4F41051F2D1C3282428A95C385E18BB57D836F8F87BBDB03D8DA8652786327384363DCD0F0705AE4CAC595BBF4962583C5A3480000AA55'
2022-06-14 03:51:24.175 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.68.206","gwId":"461808082cf432abaaa1","active":2,"ability":0,"mode":0,"encrypt":true,"productKey":"xxxxxx","version":"3.3"}
2022-06-14 03:51:24.200 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener/: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.68.206', deviceId='461808082cf432abaaa1', active=2, ability=0, mode=0, encrypt=true, productKey='xxxxxx', version='3.3'}'}
2022-06-14 03:51:29.065 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener: Received encoded '000055AA0000000000000013000000AC0000000028E0EF5F9D80C57C0585650A73708E3930C7B5BF9822B13CA5AD9007F1A15DD25E8AE953FF7B208CD35FE74A477EB930EB190277F1F46FDDC96AFC89078A21115C907565B323A346D0DE78C22F1FDABA1AE7C613C2CAE004E54A474561367714379E7D68A02456269F4616388E2AA04EED4F41051F2D1C3282428A95C385E18BB57D836F8F87BBDB03D8DA8652786327384363DCD0F0705AE4CAC595BBF4962583C5A3480000AA55'
2022-06-14 03:51:29.074 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.68.206","gwId":"461808082cf432abaaa1","active":2,"ability":0,"mode":0,"encrypt":true,"productKey":"xxxxxx","version":"3.3"}
2022-06-14 03:51:29.082 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener/: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.68.206', deviceId='461808082cf432abaaa1', active=2, ability=0, mode=0, encrypt=true, productKey='xxxxxx', version='3.3'}'}
2022-06-14 03:51:29.273 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 461808082cf432abaaa1/192.168.68.206:6668: Sending DP_QUERY, payload {devId=461808082cf432abaaa1, uid=461808082cf432abaaa1, t=1655142689, dps=null, gwId=461808082cf432abaaa1}
2022-06-14 03:51:29.295 [TRACE] [.internal.local.handlers.TuyaEncoder] - 461808082cf432abaaa1/192.168.68.206:6668: Sending encoded '000055AA000000010000000A00000088264287A56ECD3326694EFE326CFBFDB58F710E6C76495BE0862C66A9D5F991FDA2C7E30C1281583CBE8119C84348575D267EC2E75906DAB4B35E292BEDB5D5C9697D61F886316862BE0605D6E6A00D665FB5367296DB57B1157954C0F95A3A074E497EEEB7FF4BFE89579CBD14FCDA035DD6A2839DA6960F83C2AD20A07952F8B800A44C0000AA55'
2022-06-14 03:51:29.303 [DEBUG] [al.local.handlers.TuyaMessageHandler] - 461808082cf432abaaa1/192.168.68.206:6668: Connection established.
2022-06-14 03:51:29.325 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:461808082cf432abaaa1' changed from OFFLINE to ONLINE
2022-06-14 03:51:29.344 [TRACE] [.internal.local.handlers.TuyaDecoder] - 461808082cf432abaaa1/192.168.68.206:6668: Received encoded '000055AA000000010000000A0000004C00000000264287A56ECD3326694EFE326CFBFDB58F710E6C76495BE0862C66A9D5F991FD919AFA778911208840A6646EE8F601297D00029BC471947FA4BA450F37EC4CF141ECEB370000AA55'
2022-06-14 03:51:29.352 [TRACE] [.internal.local.handlers.TuyaDecoder] - 461808082cf432abaaa1//192.168.68.206:6668: Decoded raw payload: {"devId":"461808082cf432abaaa1","dps":{"1":false,"9":0}}
2022-06-14 03:51:29.365 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 461808082cf432abaaa1//192.168.68.206:6668: Received MessageWrapper{commandType=DP_QUERY, content='{1=false, 9=0.0}'}
2022-06-14 03:51:29.372 [TRACE] [a.internal.handler.TuyaDeviceHandler] - 'tuya:tuyaDevice:461808082cf432abaaa1' received status message '{1=false, 9=0.0}'

Logs for 3b6d:

2022-06-14 00:13:35.232 [TRACE] [.internal.local.handlers.TuyaDecoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Received encoded '000055AA00000000000000090000000C00000000B051AB030000AA55'
2022-06-14 00:13:35.245 [TRACE] [.internal.local.handlers.TuyaDecoder] - 48324655dc4f22a73b6d//192.168.68.205:6668: Decoded raw payload: 
2022-06-14 00:13:35.262 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 48324655dc4f22a73b6d//192.168.68.205:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''}
2022-06-14 00:13:35.276 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 48324655dc4f22a73b6d/192.168.68.205:6668: Received pong
2022-06-14 00:13:45.143 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending ping
2022-06-14 00:13:45.156 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending HEART_BEAT, payload {devId=48324655dc4f22a73b6d, uid=48324655dc4f22a73b6d, t=1655129625, dps=, gwId=48324655dc4f22a73b6d}
2022-06-14 00:13:45.178 [TRACE] [.internal.local.handlers.TuyaEncoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending encoded '000055AA000011980000000900000097332E330000000000000000000000003FDE8D467B04D25925B5C6F04BBAA0D1ADB39EB53DEF643EDA6BE571A1FFB38D331F61C799D489BD71DB2232E626490B79A5A7155DAC0220E7FC62FCBC6168F3FB83995CCBE8548B989BC8DD7D063E378CC3A6F2C97E7FC5D3B7DD002DFDC8B5D4BFAC2F2923294805D51373AA880BD88B8E7740EF798F27C63175A1FEFA12F2328B409B0000AA55'
2022-06-14 00:13:46.362 [TRACE] [ding.tuya.internal.cloud.TuyaOpenAPI] - Sending to 'https://openapi.tuyaeu.com/v1.0/iot-01/associated-users/actions/authorized-login': Method = {POST}, Headers = {Accept-Encoding: gzip, User-Agent: Jetty/9.4.43.v20210629, t: 1655129626357, Signature-Headers: client_id, sign_method: HMAC-SHA256, access_token: , sign: B4B3D5736B0DCE2F999A9560E1B5AA5804F23C917A24C4155162AD0666834FCD, client_id: xxxxxx, Content-Type: application/json}, Content = {{"username":"xxxxxx","password":"xxxxxx","country_code":61,"schema":"smartLife"}}
2022-06-14 00:13:55.207 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending ping
2022-06-14 00:13:55.225 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending HEART_BEAT, payload {devId=48324655dc4f22a73b6d, uid=48324655dc4f22a73b6d, t=1655129635, dps=, gwId=48324655dc4f22a73b6d}
2022-06-14 00:13:55.242 [TRACE] [.internal.local.handlers.TuyaEncoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending encoded '000055AA000011990000000900000097332E330000000000000000000000003FDE8D467B04D25925B5C6F04BBAA0D1ADB39EB53DEF643EDA6BE571A1FFB38D331F61C799D489BD71DB2232E626490B79A5A7155DAC0220E7FC62FCBC6168F358B1F24578BF3E6FA1B59A3CD021492D8CC3A6F2C97E7FC5D3B7DD002DFDC8B5D4BFAC2F2923294805D51373AA880BD88B8E7740EF798F27C63175A1FEFA12F26578F2640000AA55'
2022-06-14 00:14:01.372 [TRACE] [a.internal.cloud.TuyaContentListener] - Received from 'https://openapi.tuyaeu.com/v1.0/iot-01/associated-users/actions/authorized-login': Code = {0}, Headers = null, Content = {null}
2022-06-14 00:14:01.384 [DEBUG] [a.internal.cloud.TuyaContentListener] - Requesting 'https://openapi.tuyaeu.com/v1.0/iot-01/associated-users/actions/authorized-login' (method='POST', content='org.eclipse.jetty.client.util.StringContentProvider@44865b') failed: DNS timeout 15000 ms
2022-06-14 00:14:05.269 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending ping
2022-06-14 00:14:05.281 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending HEART_BEAT, payload {devId=48324655dc4f22a73b6d, uid=48324655dc4f22a73b6d, t=1655129645, dps=, gwId=48324655dc4f22a73b6d}
2022-06-14 00:14:05.310 [TRACE] [.internal.local.handlers.TuyaEncoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending encoded '000055AA0000119A0000000900000097332E330000000000000000000000003FDE8D467B04D25925B5C6F04BBAA0D1ADB39EB53DEF643EDA6BE571A1FFB38D331F61C799D489BD71DB2232E626490B79A5A7155DAC0220E7FC62FCBC6168F377B4E3E175BA72A44855B6FC026C5DBF8CC3A6F2C97E7FC5D3B7DD002DFDC8B5D4BFAC2F2923294805D51373AA880BD88B8E7740EF798F27C63175A1FEFA12F24A6000620000AA55'
2022-06-14 00:14:15.322 [WARN ] [rnal.local.handlers.HeartbeatHandler] - 48324655dc4f22a73b6d/192.168.68.205:6668: Missed more than 3 heartbeat responses. Connection seems to be dead.
2022-06-14 00:14:15.341 [DEBUG] [al.local.handlers.TuyaMessageHandler] - 48324655dc4f22a73b6d/192.168.68.205:6668: Connection terminated.
2022-06-14 00:14:15.370 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:48324655dc4f22a73b6d' changed from ONLINE to OFFLINE
2022-06-14 00:14:20.478 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending DP_QUERY, payload {devId=48324655dc4f22a73b6d, uid=48324655dc4f22a73b6d, t=1655129660, dps=null, gwId=48324655dc4f22a73b6d}
2022-06-14 00:14:20.524 [TRACE] [.internal.local.handlers.TuyaEncoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Sending encoded '000055AA000000010000000A000000883FDE8D467B04D25925B5C6F04BBAA0D1ADB39EB53DEF643EDA6BE571A1FFB38D331F61C799D489BD71DB2232E626490B79A5A7155DAC0220E7FC62FCBC6168F30B9F9CCFF3C029BCAC14AD7BF401412AE5634086F877ECFEFAE7303CBBC1EB11D4BFAC2F2923294805D51373AA880BD88B8E7740EF798F27C63175A1FEFA12F2F5C211D60000AA55'
2022-06-14 00:14:20.567 [DEBUG] [al.local.handlers.TuyaMessageHandler] - 48324655dc4f22a73b6d/192.168.68.205:6668: Connection established.
2022-06-14 00:14:20.608 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:48324655dc4f22a73b6d' changed from OFFLINE to ONLINE
2022-06-14 00:14:20.616 [TRACE] [.internal.local.handlers.TuyaDecoder] - 48324655dc4f22a73b6d/192.168.68.205:6668: Received encoded '000055AA000000010000000A0000004C000000003FDE8D467B04D25925B5C6F04BBAA0D1ADB39EB53DEF643EDA6BE571A1FFB38DC506AC86BCC473B7891BFB4F46C6C3B342E2055511965ACDB9481C5D78B41812462818E30000AA55'
2022-06-14 00:14:20.647 [TRACE] [.internal.local.handlers.TuyaDecoder] - 48324655dc4f22a73b6d//192.168.68.205:6668: Decoded raw payload: {"devId":"48324655dc4f22a73b6d","dps":{"1":false,"11":0}}
2022-06-14 00:14:20.667 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 48324655dc4f22a73b6d//192.168.68.205:6668: Received MessageWrapper{commandType=DP_QUERY, content='{1=false, 11=0.0}'}
2022-06-14 00:14:20.693 [TRACE] [a.internal.handler.TuyaDeviceHandler] - 'tuya:tuyaDevice:48324655dc4f22a73b6d' received status message '{1=false, 11=0.0}'

Thanks for any assistance you can provide.

J-N-K commented 2 years ago

I think raising the log level to INFO (which should be the default) is enough to prevent flooding your logs. IMO the binding is behaving correctly here: the connection is broken for at least three retries, i.e. at least 30s. If this is timespan is increased, you'll probably experience issues with proper response from the device.

owl770 commented 2 years ago

The log level was only at TRACE whilst I investigated why the switches were dropping OFFLINE intermittently. It is back at DEFAULT now. I agree that increasing the number of pings is probably a bad idea. I need to find out the root cause of why they are dropping off the network for > 30 seconds.

Regarding the other issue Connection reset by peer (perhaps I shouldn't have combined them in the one post) - given the device is re-discovered within 0.056 seconds (in this example), would it make sense for the binding to at least have one go at reconnecting before taking the device OFFLINE? Would that be possible and is it a good idea?

BigGeorgeTx commented 2 years ago

I’m seeing the same things with a Tuya device:

2022-07-24 14:47:23.152 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from OFFLINE to ONLINE 2022-07-24 14:47:23.161 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from ONLINE to OFFLINE 2022-07-24 14:47:28.173 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from OFFLINE to ONLINE 2022-07-24 14:47:28.181 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from ONLINE to OFFLINE 2022-07-24 14:47:30.596 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LocalTime_Date' changed from 2022-07-24T14:48:50.686-0500 to 2022-07-24T14:49:50.688-0500 2022-07-24 14:47:33.193 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from OFFLINE to ONLINE 2022-07-24 14:47:33.203 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from ONLINE to OFFLINE 2022-07-24 14:47:38.222 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from OFFLINE to ONLINE 2022-07-24 14:47:38.233 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from ONLINE to OFFLINE 2022-07-24 14:47:43.240 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from OFFLINE to ONLINE 2022-07-24 14:47:43.248 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from ONLINE to OFFLINE 2022-07-24 14:47:48.263 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from OFFLINE to ONLINE 2022-07-24 14:47:48.268 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from ONLINE to OFFLINE 2022-07-24 14:47:54.356 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from OFFLINE to ONLINE 2022-07-24 14:47:54.377 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:800061668caab5005de9' changed from ONLINE to OFFLINE

I have seen it with a different device from time to time.

owl770 commented 2 years ago

@BigGeorgeTx I saw something similar in #366. I worked around it by forcing the switch to have a fixed IP address in my router (the problem appeared when, for some reason, the switch changed its IP address). Might be worth a try.

stale[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.