search

esphome / issues

Issue Tracker for ESPHome
https://esphome.io/
291 stars 34 forks source link

Tuya communication stuck at init_state 3 #3629

Open rickyelopez opened 1 year ago

rickyelopez commented 1 year ago

The problem

I have a WiFi Temperature and Humidity sensor (this one, the wifi version) with a Tuya MCU and a CB3S. I swapped out the CB3S for an ESP12-e and loaded ESPHome onto it, but the Tuya initialization gets stuck at init_state 3.

I've done more investigation based on the data on these pages: one, two, three.

Seems like everything is working as it should up until step 3, "Query working mode of the module". ESPHome sends 55:AA:00:02:00:00:01 as it should, but the MCU just echoes it back, which is not (as far as I can tell) one of the allowed responses. From the pages linked earlier, the MCU should only be able to respond with either 55 aa 03 02 00 00 04 (for "coordinated processing mode of the MCU and the module", whatever that means) or 55 aa 03 02 00 02 05 00 0b (for "self-processing mode of the module", again, whatever that means).

Am I missing something here? Is this actually allowed but it means something else?

After that, ESPHome sends a command which I can't find a reference for anywhere: 55:AA:00:03:00:01:03:06. Not sure what this means, but after that the MCU requests a functional test by responding with 55:AA:00:07:00:00:06, which ESPHome appears to just ignore since the next thing it sends is 55:AA:00:00:00:00:FF.

After that, ESPHome just goes back to sending 55:AA:00:00:00:00:FF over and over again, with no response until the MCU powers on again, at which point it responds with 55:AA:00:00:00:01:01:01. This pointed me to this page which refers to a bluetooth mode.

So it seems like on first startup it behaves in wifi mode as expected until ESPHome sends a command it doesn't recognize, but then the next time it powers on it tries to go into some kind of bluetooth mode?

One other thing that I noticed is that the version string decodes into {"p":"q29ebws5adwye1l8","v":"1.0.0"} which, importantly (I think?) is missing the m (mode) attribute. Could that be part of the problem?

Which version of ESPHome has the issue?

2022.6.2

What type of installation are you using?

Docker

Which version of Home Assistant has the issue?

No response

What platform are you using?

ESP8266

Board

ESP12-E

Component causing the issue

Tuya

Example YAML snippet

esphome:
  name: sensor-ambient1

esp8266:
  board: esp12e

logger:
  baud_rate: 0
  level: VERY_VERBOSE

api:
  encryption:
    key: "<key>"

ota:
  password: "<pw>"

wifi:
  ssid: "<ssid>"
  password: "<pw>"
  use_address: <ip>
  domain: <domain>
  fast_connect: on

  ap:
    ssid: "sensor-ambient1"
    password: "<pw>"

captive_portal:

status_led:
  pin:
    number: 2
    inverted: true

uart:
  rx_pin: GPIO3
  tx_pin: GPIO1
  baud_rate: 9600
  debug:

tuya:

Anything in the logs that might be useful for us?

[19:10:43][VV][scheduler:195]: Running interval 'heartbeat' with interval=15000 last_execution=7398 (now=22402)
[19:10:43][V][tuya:383]: Sending Tuya: CMD=0x00 VERSION=0 DATA=[] INIT_STATE=0
[19:10:43][D][uart_debug:114]: >>> 55:AA:00:00:00:00:FF
[19:10:43][V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[00] INIT_STATE=0
[19:10:43][V][tuya:148]: MCU Heartbeat (0x00)
[19:10:43][I][tuya:151]: MCU restarted
[19:10:43][V][tuya:383]: Sending Tuya: CMD=0x01 VERSION=0 DATA=[] INIT_STATE=1
[19:10:43][D][uart_debug:114]: <<< 55:AA:00:00:00:01:00:00
[19:10:43][D][uart_debug:114]: >>> 55:AA:00:01:00:00:00
[19:10:43][V][tuya:120]: Received Tuya: CMD=0x01 VERSION=0 DATA=[7B.22.70.22.3A.22.71.32.39.65.62.77.73.35.61.64.77.79.65.31.6C.38.22.2C.22.76.22.3A.22.31.2E.30.2E.30.22.7D (36)] INIT_STATE=1
[19:10:43][V][tuya:120]: Received Tuya: CMD=0x07 VERSION=0 DATA=[] INIT_STATE=2
[19:10:43][V][tuya:383]: Sending Tuya: CMD=0x02 VERSION=0 DATA=[] INIT_STATE=2
[19:10:43][D][uart_debug:114]: <<< 55:AA:00:01:00:24:7B:22:70:22:3A:22:71:32:39:65:62:77:73:35:61:64:77:79:65:31:6C:38:22:2C:22:76:22:3A:22:31:2E:30:2E:30:22:7D:50:55:AA:00:07:00:00:06
[19:10:43][D][uart_debug:114]: >>> 55:AA:00:02:00:00:01
[19:10:43][V][tuya:120]: Received Tuya: CMD=0x02 VERSION=0 DATA=[] INIT_STATE=2
[19:10:43][V][tuya:201]: Configured WIFI_STATE periodic send
[19:10:43][VV][scheduler:057]: set_interval(name='wifi', interval=1000, offset=79)
[19:10:43][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=21498 (now=22595)
[19:10:43][D][tuya:456]: Sending WiFi Status
[19:10:43][V][tuya:383]: Sending Tuya: CMD=0x03 VERSION=0 DATA=[03] INIT_STATE=3
[19:10:43][D][uart_debug:114]: <<< 55:AA:00:02:00:00:01
[19:10:44][D][uart_debug:114]: >>> 55:AA:00:03:00:01:03:06
[19:10:44][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=22498 (now=23503)
[19:10:45][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=23498 (now=24499)
[19:10:46][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=24498 (now=25504)
[19:10:47][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=25498 (now=26499)
[19:10:48][V][tuya:120]: Received Tuya: CMD=0x07 VERSION=0 DATA=[] INIT_STATE=3
[19:10:48][VV][api.service:373]: on_ping_request: PingRequest {}
[19:10:48][VV][api.service:043]: send_ping_response: PingResponse {}
[19:10:48][D][uart_debug:114]: <<< 55:AA:00:07:00:00:06
[19:10:48][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=26498 (now=27498)
[19:10:49][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=27498 (now=28498)
[19:10:50][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=28498 (now=29498)
[19:10:51][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=29498 (now=30498)
[19:10:51][VV][api.service:373]: on_ping_request: PingRequest {}
[19:10:51][VV][api.service:043]: send_ping_response: PingResponse {}
[19:10:52][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=30498 (now=31501)
[19:10:53][V][tuya:120]: Received Tuya: CMD=0x07 VERSION=0 DATA=[] INIT_STATE=3
[19:10:53][D][uart_debug:114]: <<< 55:AA:00:07:00:00:06
[19:10:53][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=31498 (now=32498)
[19:10:54][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=32498 (now=33501)
[19:10:55][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=33498 (now=34498)
[19:10:56][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=34498 (now=35505)
[19:10:57][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=35498 (now=36500)
[19:10:58][V][tuya:120]: Received Tuya: CMD=0x07 VERSION=0 DATA=[] INIT_STATE=3
[19:10:58][VV][scheduler:195]: Running interval 'heartbeat' with interval=15000 last_execution=22398 (now=37402)
[19:10:58][V][tuya:383]: Sending Tuya: CMD=0x00 VERSION=0 DATA=[] INIT_STATE=3
[19:10:58][D][uart_debug:114]: <<< 55:AA:00:07:00:00:06
[19:10:58][D][uart_debug:114]: >>> 55:AA:00:00:00:00:FF
[19:10:58][V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[01] INIT_STATE=3
[19:10:58][V][tuya:148]: MCU Heartbeat (0x01)
[19:10:58][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=36498 (now=37498)
[19:10:58][D][uart_debug:114]: <<< 55:AA:00:00:00:01:01:01
[19:10:59][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=37498 (now=38498)
[19:11:00][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=38498 (now=39498)
[19:11:01][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=39498 (now=40498)
[19:11:02][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=40498 (now=41498)
[19:11:03][VV][api.service:373]: on_ping_request: PingRequest {}
[19:11:03][VV][api.service:043]: send_ping_response: PingResponse {}
[19:11:03][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=41498 (now=42498)
[19:11:03][V][tuya:120]: Received Tuya: CMD=0x07 VERSION=0 DATA=[] INIT_STATE=3
[19:11:03][D][uart_debug:114]: <<< 55:AA:00:07:00:00:06
[19:11:04][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=42498 (now=43498)
[19:11:05][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=43498 (now=44498)
[19:11:06][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=44498 (now=45498)
[19:11:07][VV][api.service:373]: on_ping_request: PingRequest {}
[19:11:07][VV][api.service:043]: send_ping_response: PingResponse {}
[19:11:07][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=45498 (now=46502)
[19:11:08][VV][scheduler:195]: Running interval 'wifi' with interval=1000 last_execution=46498 (now=47502)
[19:11:09][V][tuya:120]: Received Tuya: CMD=0x07 VERSION=0 DATA=[] INIT_STATE=3
[19:11:09][D][uart_debug:114]: <<< 55:AA:00:07:00:00:06

Additional information

No response

rickyelopez commented 1 year ago

Bump. Anybody have any ideas about what's going on, or any suggestions for me to debug further?

ssieb commented 1 year ago

This appears to be the low-power protocol used for battery powered devices. It's different, one indication is that it stays in protocol 0 the whole time. That's the difference between the 55:AA:00:02:00:00:01 that it's sending compared to the 55 aa 03 02 00 00 04 (version 3) that you're expecting. I started working on this at one point, but didn't get it finished.

rickyelopez commented 1 year ago

Interesting, yeah that makes sense since this is a battery powered device, and I've definitely observed some other oddities coming from low-power modes. Is that work something that you could follow up on, or that you could point me to so that I can try to continue where you left off?

leoshusar commented 1 year ago

I have the same problem. I have curtain motor powered from mains but it looks like they put the protocol for battery powered devices in it. I can control it, but since ESPHome receives 55:AA:00:03:00:01:03:06 and doesn't know what to do with it, it's stuck on waiting for init therefore never runs TuyaCover::setup() with configuration.

I tried to debug it somehow; I tried to put some LOGV commands to tuya.cpp message handling and finally in the main loop:

void Tuya::loop() {
  while (this->available()) {
    uint8_t c;
    this->read_byte(&c);
    this->handle_char_(c);
    ESP_LOGV(TAG, "hit");
  }
  process_command_queue_();
}

and for some reason I didn't get any hit logs after receiving this particular message (message logged via uart_debug). But it worked for all other messages like config query and heartbeats, which is strange.

Maybe hardware debug would tell me more, unfortunately I don't have any way to try it now.

Evka2k commented 1 year ago

Same issue with BCM500DS-TYW Curtain Motor.

[V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[01] INIT_STATE=0
[V][tuya:148]: MCU Heartbeat (0x01)
[V][tuya:383]: Sending Tuya: CMD=0x01 VERSION=0 DATA=[] INIT_STATE=1
[C][tuya.cover:107]: Tuya Cover:
[C][tuya.cover:122]:    Position has datapoint ID 101
[V][tuya:120]: Received Tuya: CMD=0x01 VERSION=0 DATA=[58.53.37.36.42.59.35.51.31.75.4B.4F.36.67.6A.43.31.2E.30.2E.30 (21)] INIT_STATE=1
[V][tuya:383]: Sending Tuya: CMD=0x02 VERSION=0 DATA=[] INIT_STATE=2
[V][tuya:120]: Received Tuya: CMD=0x02 VERSION=0 DATA=[] INIT_STATE=2
[V][tuya:201]: Configured WIFI_STATE periodic send
[D][tuya:456]: Sending WiFi Status
[V][tuya:383]: Sending Tuya: CMD=0x03 VERSION=0 DATA=[03] INIT_STATE=3
[C][tuya:033]: Tuya:
[C][tuya:038]:   Configuration will be reported when setup is complete. Current init_state: 3
[C][tuya:041]:   If no further output is received, confirm that this is a supported Tuya device.
[V][tuya:383]: Sending Tuya: CMD=0x00 VERSION=0 DATA=[] INIT_STATE=3
[V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[01] INIT_STATE=3
[V][tuya:148]: MCU Heartbeat (0x01)
[V][tuya:383]: Sending Tuya: CMD=0x00 VERSION=0 DATA=[] INIT_STATE=3
[V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[01] INIT_STATE=3
[V][tuya:148]: MCU Heartbeat (0x01)
[V][tuya:383]: Sending Tuya: CMD=0x00 VERSION=0 DATA=[] INIT_STATE=3
[V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[01] INIT_STATE=3
[V][tuya:148]: MCU Heartbeat (0x01)
EvkaPC➜  ~ cat /tmp/blind.log | grep "tuya\|uart"
[C][uart.arduino_esp8266:059]: Setting up UART bus...
[V][tuya:383]: Sending Tuya: CMD=0x00 VERSION=0 DATA=[] INIT_STATE=0
[D][uart_debug:158]: >>> "U\xAA\x00\x00\x00\x00\xFF"
[V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[01] INIT_STATE=0
[V][tuya:148]: MCU Heartbeat (0x01)
[V][tuya:383]: Sending Tuya: CMD=0x01 VERSION=0 DATA=[] INIT_STATE=1
[D][uart_debug:158]: <<< "U\xAA\x00\x00\x00\x01\x01\x01"
[C][uart.arduino_esp8266:102]: UART Bus:
[C][uart.arduino_esp8266:103]:   TX Pin: GPIO15
[C][uart.arduino_esp8266:104]:   RX Pin: GPIO13
[C][uart.arduino_esp8266:106]:   RX Buffer Size: 256
[C][uart.arduino_esp8266:108]:   Baud Rate: 9600 baud
[C][uart.arduino_esp8266:109]:   Data Bits: 8
[C][uart.arduino_esp8266:110]:   Parity: NONE
[C][uart.arduino_esp8266:111]:   Stop bits: 1
[C][uart.arduino_esp8266:113]:   Using hardware serial interface.
[C][tuya.cover:107]: Tuya Cover:
[C][tuya.cover:122]:    Position has datapoint ID 101
[D][uart_debug:158]: >>> "U\xAA\x00\x01\x00\x00\x00"
[V][tuya:120]: Received Tuya: CMD=0x01 VERSION=0 DATA=[58.53.37.36.42.59.35.51.31.75.4B.4F.36.67.6A.43.31.2E.30.2E.30 (21)] INIT_STATE=1
[V][tuya:383]: Sending Tuya: CMD=0x02 VERSION=0 DATA=[] INIT_STATE=2
[D][uart_debug:158]: <<< "U\xAA\x00\x01\x00\x15XS76BY5Q1uKO6gjC1.0.0\xC5"
[D][uart_debug:158]: >>> "U\xAA\x00\x02\x00\x00\x01"
[V][tuya:120]: Received Tuya: CMD=0x02 VERSION=0 DATA=[] INIT_STATE=2
[V][tuya:201]: Configured WIFI_STATE periodic send
[D][tuya:456]: Sending WiFi Status
[V][tuya:383]: Sending Tuya: CMD=0x03 VERSION=0 DATA=[03] INIT_STATE=3
[D][uart_debug:158]: <<< "U\xAA\x00\x02\x00\x00\x01"
[C][tuya:033]: Tuya:
[C][tuya:038]:   Configuration will be reported when setup is complete. Current init_state: 3
[C][tuya:041]:   If no further output is received, confirm that this is a supported Tuya device.
[D][uart_debug:158]: >>> "U\xAA\x00\x03\x00\x01\x03\x06"
[V][tuya:383]: Sending Tuya: CMD=0x00 VERSION=0 DATA=[] INIT_STATE=3
[D][uart_debug:158]: >>> "U\xAA\x00\x00\x00\x00\xFF"
[V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[01] INIT_STATE=3
[V][tuya:148]: MCU Heartbeat (0x01)
[D][uart_debug:158]: <<< "U\xAA\x00\x00\x00\x01\x01\x01"
[V][tuya:383]: Sending Tuya: CMD=0x00 VERSION=0 DATA=[] INIT_STATE=3
[D][uart_debug:158]: >>> "U\xAA\x00\x00\x00\x00\xFF"
[V][tuya:120]: Received Tuya: CMD=0x00 VERSION=0 DATA=[01] INIT_STATE=3
[V][tuya:148]: MCU Heartbeat (0x01)
[D][uart_debug:158]: <<< "U\xAA\x00\x00\x00\x01\x01\x01"
github-k8n commented 11 months ago

Similar issue with BCM700D-TY01 curtain motor.

Previously I was connecting an esp in parallel to the existing chip (WBR1-IPEX) There, it seems the MCU was initialized correctly (afaik), at least the esp received and showed the datapoints correctly. (101 for position, 102 for control), even if the stop, up, down values are mixed up..

Once I removed the original chip and only kept the ESP however I do not receive anything from the MCU anymore, however I can still control it by sending values to the datapoints... Debugging shows me a similar issue to the issue above:

[15:48:59][D][uart_debug:114]: >>> 55:AA:00:00:00:00:FF [15:48:59][D][uart_debug:114]: <<< 55:AA:00:00:00:01:01:01

"Configuration will be reported when setup is complete. Current init_state: 3"

Any chance that this can get addressed at some point?