search

smarthomej / addons

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

Tuya 3.1 Dimmers Online but not responding to commands or updates #319

Closed BigGeorgeTx closed 2 years ago

BigGeorgeTx commented 2 years ago

I have two Tuya light dimmers. They are 3.1 firmware. They didn't come online initially, but when I manually entered the ip addresses they did. But they are not responsive to commands sent through the channels and generate errors when the devices are controlled through the Tuya SmartLife App.

openHAB 3.2 Release Version with 3.2.10 Smarthome/J Tuya Binding

Log Info Level 2022-02-17 16:01:06.491 [WARN ] [inding.tuya.internal.util.CryptoUtil] - Decryption of MQ failed: Input length not multiple of 16 bytes Log TRACE showing heartbeat communication: 2022-02-17 15:44:57.918 [INFO ] [a.internal.handler.TuyaDeviceHandler] - Configuring IP address 'DeviceInfo{ip='192.168.1.245', version='3.1'}' for thing 'tuya:tuyaDevice:42434288807d3a372fd5'. 2022-02-17 16:02:45.928 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Sending ping 2022-02-17 16:02:45.929 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending HEART_BEAT, payload {devId=42434288807d3a372fd5, uid=42434288807d3a372fd5, t=1645135365, dps=, gwId=42434288807d3a372fd5} 2022-02-17 16:02:45.930 [TRACE] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending encoded '000055AA0000006C000000090000007B7B226465764964223A223432343334323838383037643361333732666435222C22756964223A223432343334323838383037643361333732666435222C2274223A313634353133353336352C22647073223A22222C2267774964223A223432343334323838383037643361333732666435227D0BBF6FC50000AA55' 2022-02-17 16:02:45.939 [TRACE] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received encoded '000055AA00000000000000090000000C00000000B051AB030000AA55' 2022-02-17 16:02:45.940 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-17 16:02:45.941 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Received pong 2022-02-17 16:02:55.933 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Sending ping 2022-02-17 16:02:55.934 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending HEART_BEAT, payload {devId=42434288807d3a372fd5, uid=42434288807d3a372fd5, t=1645135375, dps=, gwId=42434288807d3a372fd5} 2022-02-17 16:02:55.935 [TRACE] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending encoded '000055AA0000006D000000090000007B7B226465764964223A223432343334323838383037643361333732666435222C22756964223A223432343334323838383037643361333732666435222C2274223A313634353133353337352C22647073223A22222C2267774964223A223432343334323838383037643361333732666435227DDE8011BE0000AA55' 2022-02-17 16:02:55.950 [TRACE] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received encoded '000055AA00000000000000090000000C00000000B051AB030000AA55' 2022-02-17 16:02:55.952 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-17 16:02:55.952 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Received pong 2022-02-17 16:03:05.938 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Sending ping 2022-02-17 16:03:05.940 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending HEART_BEAT, payload {devId=42434288807d3a372fd5, uid=42434288807d3a372fd5, t=1645135385, dps=, gwId=42434288807d3a372fd5} 2022-02-17 16:03:05.941 [TRACE] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending encoded '000055AA0000006E000000090000007B7B226465764964223A223432343334323838383037643361333732666435222C22756964223A223432343334323838383037643361333732666435222C2274223A313634353133353338352C22647073223A22222C2267774964223A223432343334323838383037643361333732666435227D9A5EB8BE0000AA55' 2022-02-17 16:03:05.948 [TRACE] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received encoded '000055AA00000000000000090000000C00000000B051AB030000AA55' 2022-02-17 16:03:05.950 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-17 16:03:05.951 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Received pong 2022-02-17 16:03:15.945 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Sending ping 2022-02-17 16:03:15.946 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending HEART_BEAT, payload {devId=42434288807d3a372fd5, uid=42434288807d3a372fd5, t=1645135395, dps=, gwId=42434288807d3a372fd5} 2022-02-17 16:03:15.946 [TRACE] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending encoded '000055AA0000006F000000090000007B7B226465764964223A223432343334323838383037643361333732666435222C22756964223A223432343334323838383037643361333732666435222C2274223A313634353133353339352C22647073223A22222C2267774964223A223432343334323838383037643361333732666435227D4F61C6C50000AA55' 2022-02-17 16:03:15.958 [TRACE] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received encoded '000055AA00000000000000090000000C00000000B051AB030000AA55' 2022-02-17 16:03:15.959 [DEBUG] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-17 16:03:15.960 [TRACE] [rnal.local.handlers.HeartbeatHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Received pong

Log TRACE level when changed on SmartLife 2022-02-17 16:06:19.990 [TRACE] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received encoded '000055AA00000000000000080000008B00000000332E31623162626331663736653237643162306A5074684C6356484F4963475A6A4B57784F52553567514863' 2022-02-17 16:06:19.991 [TRACE] [.internal.local.handlers.TuyaDecoder] - Did not receive enough bytes from '42434288807d3a372fd5', exiting early 2022-02-17 16:06:19.992 [TRACE] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received encoded '000055AA00000000000000080000008B00000000332E31623162626331663736653237643162306A5074684C6356484F4963475A6A4B57784F52553567514863776A745837616B376467376A7856647262585369492F65474C52586B3937624D6978487558496C525A536F41536754475251336B396B526A717A733979497258337A426674706B47663768614F6B6E6673593D3CF6B4D80000AA55' 2022-02-17 16:06:19.993 [WARN ] [inding.tuya.internal.util.CryptoUtil] - Decryption of MQ failed: Input length not multiple of 16 bytes

Configuration from UI Code

`UID: tuya:tuyaDevice:42434288807d3a372fd5 label: Media Lights (Tuya) thingTypeUID: tuya:tuyaDevice configuration: protocol: "3.1" productId: IaA6oFXfDu3tm1Pc deviceId: 42434288807d3a372fd5 ip: 192.168.1.245 localKey: f93875122317ca44 channels:

Disabled and reenabled the device

2022-02-17 16:09:12.869 [DEBUG] [al.local.handlers.TuyaMessageHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Connection terminated. 2022-02-17 16:09:14.166 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP, content='{"ip":"192.168.1.245","gwId":"42434288807d3a372fd5","active":2,"ability":0,"mode":0,"encrypt":true,"productKey":"IaA6oFXfDu3tm1Pc","version":"3.1"}'} 2022-02-17 16:09:16.794 [INFO ] [a.internal.handler.TuyaDeviceHandler] - Configuring IP address 'DeviceInfo{ip='192.168.1.245', version='3.1'}' for thing 'tuya:tuyaDevice:42434288807d3a372fd5'. 2022-02-17 16:09:16.805 [DEBUG] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending DP_QUERY, payload {devId=42434288807d3a372fd5, uid=42434288807d3a372fd5, t=1645135756, dps=null, gwId=42434288807d3a372fd5} 2022-02-17 16:09:16.806 [TRACE] [.internal.local.handlers.TuyaEncoder] - 42434288807d3a372fd5/192.168.1.245:6668: Sending encoded '000055AA000000010000000A0000007B7B226465764964223A223432343334323838383037643361333732666435222C22756964223A223432343334323838383037643361333732666435222C2274223A313634353133353735362C22647073223A7B7D2C2267774964223A223432343334323838383037643361333732666435227D9A7E37B70000AA55' 2022-02-17 16:09:16.806 [DEBUG] [al.local.handlers.TuyaMessageHandler] - 42434288807d3a372fd5/192.168.1.245:6668: Connection established.

J-N-K commented 2 years ago

I have updated the development version

BigGeorgeTx commented 2 years ago

Thanks. The development version loaded and the Things came online. But I am seeing this in the log: 2022-02-18 09:22:01.894 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} ==> /var/log/openhab/events.log <== 2022-02-18 09:22:02.101 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:52.683 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.246', deviceId='eb755c84e755bbd761ymwj', active=2, ability=0, mode=0, encrypt=true, productKey='keyyj3fy8x98arty', version='3.3'}'} 2022-02-18 09:22:02.103 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:53.203 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.226', deviceId='ebb442e79ea9c02fb35xs8', active=2, ability=0, mode=0, encrypt=true, productKey='keytg5kq8gvkv9dh', version='3.3'}'} 2022-02-18 09:22:02.104 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:53.697 [ERROR] [.internal.local.handlers.TuyaDecoder] - 36802558840d8e95ef5d/192.168.1.244:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.107 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:53.725 [ERROR] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a3734e6/192.168.1.229:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.109 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:53.896 [ERROR] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.111 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:53.960 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.180', deviceId='eb3c82adf880a32bbe5ivy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:02.113 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:54.053 [ERROR] [.internal.local.handlers.TuyaDecoder] - 601867532462ab3a32c4/192.168.1.228:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.116 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:54.058 [ERROR] [.internal.local.handlers.TuyaDecoder] - 21410372c44f33b896bf/192.168.1.227:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.119 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:54.934 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.236', deviceId='eb349b6012eb05c13103yh', active=2, ability=0, mode=0, encrypt=true, productKey='keydqydsydtu759x', version='3.3'}'} 2022-02-18 09:22:02.120 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:55.016 [ERROR] [.internal.local.handlers.TuyaDecoder] - eb349b6012eb05c13103yh/192.168.1.236:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.121 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newWarningEvent triggered 2022-02-18 09:21:55.233 [WARN ] [rnal.local.handlers.UserEventHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: class io.netty.handler.codec.DecoderException caught, closing the channel 2022-02-18 09:22:02.123 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:55.422 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.208', deviceId='eb04ec86abf62e08b1932f', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:02.125 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:55.436 [ERROR] [.internal.local.handlers.TuyaDecoder] - eb3c82adf880a32bbe5ivy/192.168.1.180:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.126 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:56.709 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:02.127 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:57.684 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.246', deviceId='eb755c84e755bbd761ymwj', active=2, ability=0, mode=0, encrypt=true, productKey='keyyj3fy8x98arty', version='3.3'}'} 2022-02-18 09:22:02.129 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:58.205 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.226', deviceId='ebb442e79ea9c02fb35xs8', active=2, ability=0, mode=0, encrypt=true, productKey='keytg5kq8gvkv9dh', version='3.3'}'} 2022-02-18 09:22:02.130 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:58.298 [ERROR] [.internal.local.handlers.TuyaDecoder] - ebb442e79ea9c02fb35xs8/192.168.1.226:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.131 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:58.910 [ERROR] [.internal.local.handlers.TuyaDecoder] - eb04ec86abf62e08b1932f/192.168.1.208:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:02.133 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:59.055 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.180', deviceId='eb3c82adf880a32bbe5ivy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:02.134 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:21:59.936 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.236', deviceId='eb349b6012eb05c13103yh', active=2, ability=0, mode=0, encrypt=true, productKey='keydqydsydtu759x', version='3.3'}'} 2022-02-18 09:22:02.136 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newWarningEvent triggered 2022-02-18 09:22:00.863 [WARN ] [rnal.local.handlers.UserEventHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: class io.netty.handler.codec.DecoderException caught, closing the channel 2022-02-18 09:22:02.137 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:22:00.984 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.208', deviceId='eb04ec86abf62e08b1932f', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:02.139 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newErrorEvent triggered 2022-02-18 09:22:01.894 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} ==> /var/log/openhab/openhab.log <== 2022-02-18 09:22:02.684 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.246', deviceId='eb755c84e755bbd761ymwj', active=2, ability=0, mode=0, encrypt=true, productKey='keyyj3fy8x98arty', version='3.3'}'} 2022-02-18 09:22:03.207 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.226', deviceId='ebb442e79ea9c02fb35xs8', active=2, ability=0, mode=0, encrypt=true, productKey='keytg5kq8gvkv9dh', version='3.3'}'} 2022-02-18 09:22:03.705 [ERROR] [.internal.local.handlers.TuyaDecoder] - 36802558840d8e95ef5d/192.168.1.244:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:03.730 [ERROR] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a3734e6/192.168.1.229:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:03.899 [ERROR] [.internal.local.handlers.TuyaDecoder] - 42434288807d3a372fd5/192.168.1.245:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:04.065 [ERROR] [.internal.local.handlers.TuyaDecoder] - 601867532462ab3a32c4/192.168.1.228:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:04.066 [ERROR] [.internal.local.handlers.TuyaDecoder] - 21410372c44f33b896bf/192.168.1.227:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:04.198 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.180', deviceId='eb3c82adf880a32bbe5ivy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:04.936 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.236', deviceId='eb349b6012eb05c13103yh', active=2, ability=0, mode=0, encrypt=true, productKey='keydqydsydtu759x', version='3.3'}'} 2022-02-18 09:22:05.051 [ERROR] [.internal.local.handlers.TuyaDecoder] - eb349b6012eb05c13103yh/192.168.1.236:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:05.466 [ERROR] [.internal.local.handlers.TuyaDecoder] - eb3c82adf880a32bbe5ivy/192.168.1.180:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:05.986 [WARN ] [rnal.local.handlers.UserEventHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: class io.netty.handler.codec.DecoderException caught, closing the channel io.netty.handler.codec.DecoderException: com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:477) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) ~[?:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.68.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.68.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.68.Final] at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [bundleFile:4.1.68.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.68.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.68.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.68.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [bundleFile:4.1.68.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.68.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.68.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [bundleFile:4.1.68.Final] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [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) [?:?] Caused by: com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:226) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:932) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:897) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:846) ~[?:?] at org.smarthomej.binding.tuya.internal.local.handlers.TuyaDecoder.decode(TuyaDecoder.java:153) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[?:?] ... 21 more Caused by: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:386) ~[?:?] at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:215) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:932) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:897) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:846) ~[?:?] at org.smarthomej.binding.tuya.internal.local.handlers.TuyaDecoder.decode(TuyaDecoder.java:153) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[?:?] ... 21 more ==> /var/log/openhab/events.log <== 2022-02-18 09:22:05.980 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy' changed from OFFLINE to ONLINE 2022-02-18 09:22:05.997 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy' changed from ONLINE to OFFLINE ==> /var/log/openhab/openhab.log <== 2022-02-18 09:22:06.651 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.208', deviceId='eb04ec86abf62e08b1932f', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:07.050 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:07.684 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.246', deviceId='eb755c84e755bbd761ymwj', active=2, ability=0, mode=0, encrypt=true, productKey='keyyj3fy8x98arty', version='3.3'}'} 2022-02-18 09:22:08.207 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.226', deviceId='ebb442e79ea9c02fb35xs8', active=2, ability=0, mode=0, encrypt=true, productKey='keytg5kq8gvkv9dh', version='3.3'}'} 2022-02-18 09:22:08.331 [ERROR] [.internal.local.handlers.TuyaDecoder] - ebb442e79ea9c02fb35xs8/192.168.1.226:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:08.948 [ERROR] [.internal.local.handlers.TuyaDecoder] - eb04ec86abf62e08b1932f/192.168.1.208:6668: Received MessageWrapper{commandType=HEART_BEAT, content=''} 2022-02-18 09:22:09.280 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.180', deviceId='eb3c82adf880a32bbe5ivy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-18 09:22:09.937 [ERROR] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.236', deviceId='eb349b6012eb05c13103yh', active=2, ability=0, mode=0, encrypt=true, productKey='keydqydsydtu759x', version='3.3'}'}

J-N-K commented 2 years ago

Oops. Forgot to reset the logger... This is a DEBUG message.

BigGeorgeTx commented 2 years ago

OK. I checked the functionality. On both of the Tuya dimmers, changes made through the Tuya SmartLife or Alexa Apps are promptly reflected in the openHAB items linked to the Tuya Thing's bound using the Tuya binding. But the devices do not respond to commands (change of power state or change in brightness) entered through the openHAB UI on the Items linked to the Tuya channels.

J-N-K commented 2 years ago

Looks like commands are still wrong. I‘ll try to check that.

BigGeorgeTx commented 2 years ago

Thanks. I tried to do a TRACE level log, but with all of the debugging logging, there was so much that it was hard to see anything.

The commands are working, at least on two 3.1 power plugs that I tested. But not on these two 3.1 dimmers. I will try to check other devices later.

On Sat, Feb 19, 2022 at 9:41 AM J-N-K @.***> wrote:

Looks like commands are still wrong. I‘ll try to check that.

— Reply to this email directly, view it on GitHub https://github.com/smarthomej/addons/issues/319#issuecomment-1046045587, or unsubscribe https://github.com/notifications/unsubscribe-auth/ADEQZL33BNZ7PWFRZLQQRVTU36223ANCNFSM5OWALE5A . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you authored the thread.Message ID: @.***>

-- George Hyde Mobile +1-281-620-3039

J-N-K commented 2 years ago

That‘s very interesting. My guess would have been that all commands fail.

BigGeorgeTx commented 2 years ago

I have about 10 devices, and I checked them all. All of the 3.3 devices behave as expected, and all of the 3.1 devices behave as described above (they follow changes made through the SmartLife or Alexa apps, but do not control the device).

Also, just FYI, I switched to OpenHAB 3.3M1 and the Tuya binding appears to work exactly the same as it did in 3.2.0. This is as you said it would be.

On Sun, Feb 20, 2022 at 8:17 AM J-N-K @.***> wrote:

That‘s very interesting. My guess would have been that all commands fail.

— Reply to this email directly, view it on GitHub https://github.com/smarthomej/addons/issues/319#issuecomment-1046247617, or unsubscribe https://github.com/notifications/unsubscribe-auth/ADEQZLYVYDXKQM64SY7OYKTU4DZYLANCNFSM5OWALE5A . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

You are receiving this because you authored the thread.Message ID: @.***>

-- George Hyde Mobile +1-281-620-3039

J-N-K commented 2 years ago

I have updated the develop version (to 3.2.12-SNAPSHOT) and fixed some issues. Can you try again if the commands now work?

BigGeorgeTx commented 2 years ago

I tried it and the commands are now working, at least on a couple of the devices that I tried. I will check the remainder when I have time later.

It may be related to logging for your developmental purposes, but I do see this in the log: 2022-02-21 14:55:34.705 [WARN ] [rnal.local.handlers.UserEventHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: class io.netty.handler.codec.DecoderException caught, closing the channel io.netty.handler.codec.DecoderException: com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:477) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) ~[?:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.72.Final] at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.72.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.72.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [bundleFile:4.1.72.Final] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [bundleFile:4.1.72.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722) [bundleFile:4.1.72.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) [bundleFile:4.1.72.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) [bundleFile:4.1.72.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) [bundleFile:4.1.72.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.72.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.72.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.72.Final] at java.lang.Thread.run(Thread.java:829) [?:?] Caused by: com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:226) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:932) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:897) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:846) ~[?:?] at org.smarthomej.binding.tuya.internal.local.handlers.TuyaDecoder.decode(TuyaDecoder.java:153) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[?:?] ... 21 more Caused by: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:386) ~[?:?] at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:215) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:932) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:897) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:846) ~[?:?] at org.smarthomej.binding.tuya.internal.local.handlers.TuyaDecoder.decode(TuyaDecoder.java:153) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[?:?] ... 21 more

J-N-K commented 2 years ago

No, that‘s not debugging log, that’s another bug. Is there any TRACE log above from the same device?

BigGeorgeTx commented 2 years ago

Sure. It is a device that shows as offline. I disabled the Thing and the error stopped in the log.

2022-02-21 16:44:29.884 [DEBUG] [.internal.local.handlers.TuyaEncoder] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Sending DP_QUERY, payload {devId=ebf3cb07f3574a9688z4oy, uid=ebf3cb07f3574a9688z4oy, t=1645483469, dps=null, gwId=ebf3cb07f3574a9688z4oy} 2022-02-21 16:44:29.886 [TRACE] [.internal.local.handlers.TuyaEncoder] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Sending encoded '000055AA000000010000000A00000088AEBA5950965BC2EC9CD11FC6CF23BEB05FBCEEDB42C2FAA132619EAD89ADFB20B66FB78D4BC68658C93254134121DE5EF089BDD224EC53F1E310524C3D84C82C0B2123721512BBEAB032CE50A3ED74E46B8956D6462832AE542980CAE47451ABDF1FC976AE8F9003D418274707BCF1E37DE334016CFAD800FC1D4F9292D87AA85C8FB21A0000AA55' 2022-02-21 16:44:29.889 [DEBUG] [al.local.handlers.TuyaMessageHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Connection established. 2022-02-21 16:44:29.896 [TRACE] [.internal.local.handlers.TuyaDecoder] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Received encoded '000055AA000000010000000A0000002C00000001F08A058CF5A015BFE0E127D4B796C9882D36BADE6DB6A71DBCCDB78A4BC51EDD5132B3260000AA55' 2022-02-21 16:44:29.898 [TRACE] [.internal.local.handlers.TuyaDecoder] - ebf3cb07f3574a9688z4oy//192.168.1.148:6668: Decoded raw payload: json obj data unvalid 2022-02-21 16:44:29.901 [WARN ] [rnal.local.handlers.UserEventHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: class io.netty.handler.codec.DecoderException caught, closing the channel io.netty.handler.codec.DecoderException: com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:477) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) ~[?:?] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.72.Final] at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) [bundleFile:4.1.72.Final] at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) [bundleFile:4.1.72.Final] at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.72.Final] at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [bundleFile:4.1.72.Final] at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [bundleFile:4.1.72.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722) [bundleFile:4.1.72.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) [bundleFile:4.1.72.Final] at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) [bundleFile:4.1.72.Final] at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) [bundleFile:4.1.72.Final] at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) [bundleFile:4.1.72.Final] at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.72.Final] at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.72.Final] at java.lang.Thread.run(Thread.java:829) [?:?] Caused by: com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:226) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:932) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:897) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:846) ~[?:?] at org.smarthomej.binding.tuya.internal.local.handlers.TuyaDecoder.decode(TuyaDecoder.java:153) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[?:?] ... 21 more Caused by: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 1 column 1 path $ at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:386) ~[?:?] at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:215) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:932) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:897) ~[?:?] at com.google.gson.Gson.fromJson(Gson.java:846) ~[?:?] at org.smarthomej.binding.tuya.internal.local.handlers.TuyaDecoder.decode(TuyaDecoder.java:153) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507) ~[?:?] at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446) ~[?:?] ... 21 more 2022-02-21 16:44:29.910 [DEBUG] [al.local.handlers.TuyaMessageHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Connection terminated.

BigGeorgeTx commented 2 years ago

A little more on the device generating the error. I confirmed that it is plugged in and works in Smartlife and Alexa.

I noticed that the error message stopped after I manually entered the IP address, but the device still shows as being offline. Here is a TRACE log of the device being disabled and then enabled. It comes online for an instant that drops offline.

2022-02-21 18:57:48.203 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:57:53.434 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:57:53.435 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:57:58.631 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:57:58.632 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:03.211 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy' changed from OFFLINE to UNINITIALIZED 2022-02-21 18:58:03.228 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy' changed from UNINITIALIZED to UNINITIALIZED (DISABLED) 2022-02-21 18:58:03.824 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:03.824 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:09.000 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:09.001 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:13.970 [INFO ] [a.internal.handler.TuyaDeviceHandler] - Configuring IP address 'DeviceInfo{ip='192.168.1.148', version='3.3'}' for thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy'. 2022-02-21 18:58:14.055 [DEBUG] [.internal.local.handlers.TuyaEncoder] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Sending DP_QUERY, payload {devId=ebf3cb07f3574a9688z4oy, uid=ebf3cb07f3574a9688z4oy, t=1645491494, dps=null, gwId=ebf3cb07f3574a9688z4oy} 2022-02-21 18:58:14.056 [TRACE] [.internal.local.handlers.TuyaEncoder] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Sending encoded '000055AA000000010000000A00000088AEBA5950965BC2EC9CD11FC6CF23BEB05FBCEEDB42C2FAA132619EAD89ADFB20B66FB78D4BC68658C93254134121DE5EF089BDD224EC53F1E310524C3D84C82C77F9272CF4C2E16CEA61344C94FEDB9B6B8956D6462832AE542980CAE47451ABDF1FC976AE8F9003D418274707BCF1E37DE334016CFAD800FC1D4F9292D87AA89802EB3F0000AA55' 2022-02-21 18:58:14.057 [DEBUG] [al.local.handlers.TuyaMessageHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Connection established. 2022-02-21 18:58:14.063 [TRACE] [.internal.local.handlers.TuyaDecoder] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Received encoded '000055AA000000010000000A0000002C00000001F08A058CF5A015BFE0E127D4B796C9882D36BADE6DB6A71DBCCDB78A4BC51EDD5132B3260000AA55' 2022-02-21 18:58:14.065 [TRACE] [.internal.local.handlers.TuyaDecoder] - ebf3cb07f3574a9688z4oy//192.168.1.148:6668: Decoded raw payload: json obj data unvalid 2022-02-21 18:58:14.066 [WARN ] [rnal.local.handlers.UserEventHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: class io.netty.handler.codec.DecoderException caught, closing the channel 2022-02-21 18:58:14.077 [DEBUG] [al.local.handlers.TuyaMessageHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: Connection terminated. 2022-02-21 18:58:14.297 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:14.298 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:13.961 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy' changed from UNINITIALIZED (DISABLED) to INITIALIZING 2022-02-21 18:58:13.973 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy' changed from INITIALIZING to UNKNOWN 2022-02-21 18:58:14.061 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy' changed from UNKNOWN to ONLINE 2022-02-21 18:58:14.080 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'tuya:tuyaDevice:ebf3cb07f3574a9688z4oy' changed from ONLINE to OFFLINE 2022-02-21 18:58:15.451 [INFO ] [openhab.event.ChannelTriggeredEvent ] - logreader:reader:LogReaderOpenHABCloudConnectStatus:newWarningEvent triggered 2022-02-21 18:58:14.066 [WARN ] [rnal.local.handlers.UserEventHandler] - ebf3cb07f3574a9688z4oy/192.168.1.148:6668: class io.netty.handler.codec.DecoderException caught, closing the channel 2022-02-21 18:58:19.556 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:19.557 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:24.857 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:24.858 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:30.218 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:30.219 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:35.522 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:35.523 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:40.786 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:40.787 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:45.967 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:45.968 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:51.150 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:51.151 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:58:56.330 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:58:56.331 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:59:01.504 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:59:01.505 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'} 2022-02-21 18:59:06.682 [TRACE] [.internal.local.handlers.TuyaDecoder] - udpListener/: Decoded raw payload: {"ip":"192.168.1.148","gwId":"ebf3cb07f3574a9688z4oy","active":2,"ablilty":0,"encrypt":true,"productKey":"keygg897krt5kk4t","version":"3.3"} 2022-02-21 18:59:06.683 [DEBUG] [.internal.local.handlers.TuyaDecoder] - udpListener: Received MessageWrapper{commandType=UDP_NEW, content='DiscoveryMessage{ip='192.168.1.148', deviceId='ebf3cb07f3574a9688z4oy', active=2, ability=0, mode=0, encrypt=true, productKey='keygg897krt5kk4t', version='3.3'}'}

BigGeorgeTx commented 2 years ago

And the Thing configuration

`UID: tuya:tuyaDevice:ebf3cb07f3574a9688z4oy label: " Master Lamp Socket (Tuya)" thingTypeUID: tuya:tuyaDevice configuration: protocol: "3.3" productId: octeoqhuayzof69q deviceId: ebf3cb07f3574a9688z4oy ip: 192.168.1.148 localKey: d65e228c1c14a7e4 channels:

J-N-K commented 2 years ago

@BigGeorgeTx I think I also found the third bug here. Can you try the updated develop version and show what happens when you disable/enable the thing?

BigGeorgeTx commented 2 years ago

The good news is that the device is now online. I looked in the SmartLife App and saw there was a firmware update available. After I updated to 1.0.8, it came online. I'll try the new binding anyway, but I'm afraid I spoiled the experiment by changing another variable.

Also, after the firmware and binding update, I removed the IP address I had added manually to get it online, and it works fine without the IP address being specified in the configuration.

When I first installed the new Tuya binding, all of the devices came online but the Tuya Cloud project showed as unavailable. Also, it may just be coincidence, but at the same time the Amazon Account bridge stopped working. I restarted openHAB (systemctl restart openhab), and when it started back up, both the Tuya Cloud project and the Amazon Account Things came online and everything appears to be working. I will continue to play with it and report any unusual behavior.