search

esphome / issues

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

2023.7.0 broke a ventilation component I use #4715

Open spudje opened 1 year ago

spudje commented 1 year ago

The problem

Since updating from 2023.6.5 to 2023.7.0 a custom component I got from here https://gathering.tweakers.net/forum/list_messages/1728169/0 (and tweaked a bit) stopped working. I didn't change anything on the ventilation custom component code and verified that it is 100% caused by upgrading to 2023.7.0, since I went hence and forth between versions a couple of times and it was always only on 2023.6.5 it worked.

This uses an ESP32 combined with an nrf905 RF antenna.

Since the upgrade I only get timeouts. Even when I increase multiple timeout values in the config.

Comparing the ESPhome 2023.6.5 & 2023.7.0 code by hand I think the most probable cause is either:

Custom component code can be downloaded here: https://wetransfer.com/downloads/14dfd15b9f46396614c80a16d77b291220230719192018/f8f9b830c6df18d1bc8392ca6a5d222020230719192112/4f2a46

Which version of ESPHome has the issue?

2023.7.0

What type of installation are you using?

Home Assistant Add-on

Which version of Home Assistant has the issue?

2023.7.2

What platform are you using?

ESP32

Board

esp32doit-devkit-v1

Component causing the issue

Not sure but guessing SPI or Scheduler

Example YAML snippet

substitutions:
  devicename: ventilatie
  upper_devicename: Ventilatie

esphome:
  name: ventilatie
  comment: Fan controller

esp32:
  board: esp32doit-devkit-v1
  framework:
    type: arduino

# Enable logging
logger:
  level: DEBUG

# Enable Home Assistant API
api:
  # password: !secret esphome_ventilatie_api_password
  encryption:
    key: !secret esphome_ventilatie_api_encryption_key

  services:
    - service: set_speed
      variables:
        run_speed: int
        run_time: int
      then:
        - lambda: |-
            zehnder_fan->setSpeed(run_speed, run_time);  

ota:
  password: !secret esphome_ventilatie_ota_password

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password

  # manual_ip:
  #   static_ip: !secret wifi_ip_utility_bridge
  #   gateway: !secret wifi_gateway
  #   subnet: !secret wifi_subnet
  #   dns1: !secret wifi_gateway

  # Enable fallback hotspot (captive portal) in case wifi connection fails
  ap:
    ssid: "utility-bridge Fallback"
    password: !secret esphome_utility_bridge_ap_password

captive_portal:

time:
  - platform: homeassistant
    id: homeassistant_time
    timezone: Europe/Amsterdam

button:
  - platform: restart
    id: ${devicename}_esphome_restart
    name: ${upper_devicename} herstart

  # - platform: factory_reset
  #   name: Restart with Factory Default Settings

  # - platform: template
  #   id: ${devicename}_stand_1
  #   name: ${upper_devicename} Stand 1
  #   on_press:
  #     then:
  #       lambda: |-
  #         zehnder_fan->setSpeed(1,0);

  # - platform: template
  #   id: ${devicename}_stand_2
  #   name: ${upper_devicename} Stand 2
  #   on_press:
  #     then:
  #       lambda: |-
  #         zehnder_fan->setSpeed(2,0);

  # - platform: template
  #   id: ${devicename}_stand_3
  #   name: ${upper_devicename} Stand 3
  #   on_press:
  #     then:
  #       lambda: |-
  #         zehnder_fan->setSpeed(3,0);

  # - platform: template
  #   id: ${devicename}_stand_4
  #   name: ${upper_devicename} Stand 4
  #   on_press:
  #     then:
  #       lambda: |-
  #         zehnder_fan->setSpeed(4,0);          

  # - platform: template
  #   id: ${devicename}_esphome_dump_config
  #   name: ${upper_devicename} Dump config
  #   entity_category: config
  #   on_press:
  #     then:
  #       lambda: |-
  #         id(zehnder_fan).dump_config();

  # - platform: template
  #   id: ${devicename}_esphome_setup
  #   name: ${upper_devicename} Setup
  #   entity_category: config
  #   on_press:
  #     then:
  #       lambda: |-
  #         id(zehnder_fan).setup();     

# Load external components
external_components:
  - source:
      type: local
      path: custom_components

# SPI
spi:
  clk_pin: GPIO14
  mosi_pin: GPIO13
  miso_pin: GPIO12

# nRF905 config
nrf905:
  id: "nrf905_rf"
  # cs_pin: GPIO23
  cs_pin: GPIO15
  cd_pin: GPIO33
  ce_pin: GPIO27
  pwr_pin: GPIO26
  txen_pin: GPIO25
  # We don't need AM and DR at the moment as they are read from the inernal registers
  am_pin: GPIO32
  dr_pin: GPIO35

# The FAN controller
fan:
  - platform: zehnder
    id: zehnder_fan
    name: "Ventilation"
    nrf905: nrf905_rf
    update_interval: "30s"

# define PIN_LED  2
# define PIN_AM   -1    // nRF905 AM pin (Address Match) : value is -1 (not connected)
# define PIN_CD   -1    // nRF905 CD pin (Carrier detect) : value is -1 (not connected)
# define PIN_CE   D2    // nRF905 CS pin (Enable pin)
# define PIN_DR   D1    // nRF905 DR pin (Data Ready)
# define PIN_PWR  D3    // nRF905 PWR pin (Power mode pin)
# define PIN_TXEN D0    // nRF905 TX_EN pin (Transmit enable pin)
# define PIN_MOSI D7    // nRF905 SPI MOSI pin (GPIO13)
# define PIN_MISO D6    // nRF905 SPI MISO pin (GPIO12)
# define PIN_SPICLK D5  // nRF905 SPI clock pin GPIO14)
# define PIN_SPICS D8   // nRF905 SPI CS pin (GPIO15)

Anything in the logs that might be useful for us?

--- Log of correctly (still with some timeouts) working 2023.6.5 version---

INFO ESPHome 2023.6.5
INFO Reading configuration /config/esphome/ventilatie.yaml...
WARNING GPIO12 is a Strapping PIN and should be avoided.
Attaching external pullup/down resistors to strapping pins can cause unexpected failures.
See https://esphome.io/guides/faq.html#why-am-i-getting-a-warning-about-strapping-pins
WARNING GPIO15 is a Strapping PIN and should be avoided.
Attaching external pullup/down resistors to strapping pins can cause unexpected failures.
See https://esphome.io/guides/faq.html#why-am-i-getting-a-warning-about-strapping-pins
INFO Starting log output from ventilatie.local using esphome API
INFO Successfully connected to ventilatie.local
[20:48:40][I][app:102]: ESPHome version 2023.6.5 compiled on Jul 19 2023, 18:24:00
[20:48:40][C][wifi:543]: WiFi:
[20:48:40][C][wifi:379]:   Local MAC: 84:CC:A8:48:89:14
[20:48:40][C][wifi:380]:   SSID: 'IoTFi'[redacted]
[20:48:40][C][wifi:381]:   IP Address: <redacted>
[20:48:40][C][wifi:383]:   BSSID: E2:63:DA:16:2D:78[redacted]
[20:48:40][C][wifi:384]:   Hostname: 'ventilatie'
[20:48:40][C][wifi:386]:   Signal strength: -50 dB ▂▄▆█
[20:48:40][C][wifi:390]:   Channel: 1
[20:48:40][C][wifi:391]:   Subnet: 255.255.255.0
[20:48:40][C][wifi:392]:   Gateway: <redacted>
[20:48:40][C][wifi:393]:   DNS1: <redacted>
[20:48:40][C][wifi:394]:   DNS2: 0.0.0.0
[20:48:40][C][logger:301]: Logger:
[20:48:40][C][logger:302]:   Level: DEBUG
[20:48:40][C][logger:303]:   Log Baud Rate: 115200
[20:48:40][C][logger:305]:   Hardware UART: UART0
[20:48:40][C][spi:125]: SPI bus:
[20:48:40][C][spi:126]:   CLK Pin: GPIO14
[20:48:40][C][spi:127]:   MISO Pin: GPIO12
[20:48:40][C][spi:128]:   MOSI Pin: GPIO13
[20:48:40][C][spi:130]:   Using HW SPI: YES
[20:48:40][C][homeassistant.time:010]: Home Assistant Time:
[20:48:40][C][homeassistant.time:011]:   Timezone: 'CET-1CEST,M3.5.0,M10.5.0/3'
[20:48:40][C][restart.button:017]: Restart Button 'Ventilatie herstart'
[20:48:40][C][zehnder:154]: Zehnder Fan config:
[20:48:40][C][zehnder:155]:   Polling interval   30000
[20:48:40][C][zehnder:156]:   Fan networkId      0xC11852FC
[20:48:40][C][zehnder:157]:   Fan my device type 0x03
[20:48:40][C][zehnder:158]:   Fan my device id   0x7F
[20:48:40][C][zehnder:159]:   Fan main_unit type 0x01
[20:48:40][C][zehnder:160]:   Fan main unit id   0xD2
[20:48:40][C][captive_portal:088]: Captive Portal:
[20:48:40][C][mdns:112]: mDNS:
[20:48:40][C][mdns:113]:   Hostname: ventilatie
[20:48:40][C][ota:093]: Over-The-Air Updates:
[20:48:40][C][ota:094]:   Address: ventilatie.local:3232
[20:48:40][C][ota:097]:   Using Password.
[20:48:40][C][api:138]: API Server:
[20:48:40][C][api:139]:   Address: ventilatie.local:6053
[20:48:40][C][api:141]:   Using noise encryption: YES
[20:48:40][C][nRF905:074]: Config:
[20:48:40][C][nRF905:076]:   CS Pin:GPIO15
[20:48:40][C][nRF905:078]:   AM Pin:GPIO32
[20:48:40][C][nRF905:081]:   DR Pin:GPIO35
[20:48:40][C][nRF905:084]:   CD Pin:GPIO33
[20:48:40][C][nRF905:086]:   CE Pin:GPIO27
[20:48:40][C][nRF905:087]:   PWR Pin:GPIO26
[20:48:40][C][nRF905:088]:   TXEN Pin:GPIO25
[20:48:50][D][zehnder:489]: Query device
[20:48:50][D][zehnder:654]: Start TX
[20:48:50][D][zehnder:136]: Tx Ready
[20:48:51][D][zehnder:666]: Receive timeout
[20:48:51][D][zehnder:670]: No data received, retry again (left: 9)
[20:48:51][D][zehnder:654]: Start TX
[20:48:51][D][zehnder:136]: Tx Ready
[20:48:51][D][zehnder:234]: Current state: 0x06
[20:48:51][D][zehnder:373]: Received fan settings; speed: 0x01 voltage: 10 timer: 0
[20:48:51][D][fan:092]: 'Ventilation' - Sending state:
[20:48:51][D][fan:093]:   State: ON
[20:48:51][D][fan:095]:   Speed: 1
[20:49:20][D][zehnder:489]: Query device
[20:49:20][D][zehnder:654]: Start TX
[20:49:20][D][zehnder:136]: Tx Ready
[20:49:20][D][zehnder:234]: Current state: 0x06
[20:49:20][D][zehnder:373]: Received fan settings; speed: 0x01 voltage: 10 timer: 0
[20:49:20][D][fan:092]: 'Ventilation' - Sending state:
[20:49:20][D][fan:093]:   State: ON
[20:49:20][D][fan:095]:   Speed: 1
[20:49:50][D][zehnder:489]: Query device
[20:49:50][D][zehnder:654]: Start TX
[20:49:50][D][zehnder:136]: Tx Ready
[20:49:51][D][zehnder:666]: Receive timeout
[20:49:51][D][zehnder:670]: No data received, retry again (left: 9)
[20:49:51][D][zehnder:654]: Start TX
[20:49:51][D][zehnder:136]: Tx Ready
[20:49:52][D][zehnder:666]: Receive timeout
[20:49:52][D][zehnder:670]: No data received, retry again (left: 8)
[20:49:52][D][zehnder:654]: Start TX
[20:49:52][D][zehnder:136]: Tx Ready
[20:49:52][D][zehnder:234]: Current state: 0x06
[20:49:52][D][zehnder:373]: Received fan settings; speed: 0x01 voltage: 10 timer: 0
[20:49:52][D][fan:092]: 'Ventilation' - Sending state:
[20:49:52][D][fan:093]:   State: ON
[20:49:52][D][fan:095]:   Speed: 1
[20:50:20][D][zehnder:489]: Query device
[20:50:20][D][zehnder:654]: Start TX
[20:50:20][D][zehnder:136]: Tx Ready
[20:50:21][D][zehnder:666]: Receive timeout
[20:50:21][D][zehnder:670]: No data received, retry again (left: 9)
[20:50:21][D][zehnder:654]: Start TX
[20:50:21][D][zehnder:136]: Tx Ready
[20:50:22][D][zehnder:666]: Receive timeout
[20:50:22][D][zehnder:670]: No data received, retry again (left: 8)
[20:50:22][D][zehnder:654]: Start TX
[20:50:22][D][zehnder:136]: Tx Ready
[20:50:23][D][zehnder:666]: Receive timeout
[20:50:23][D][zehnder:670]: No data received, retry again (left: 7)
[20:50:23][D][zehnder:654]: Start TX
[20:50:23][D][zehnder:136]: Tx Ready
[20:50:24][D][zehnder:666]: Receive timeout
[20:50:24][D][zehnder:670]: No data received, retry again (left: 6)
[20:50:24][D][zehnder:654]: Start TX
[20:50:24][D][zehnder:136]: Tx Ready
[20:50:24][D][zehnder:234]: Current state: 0x06
[20:50:24][D][zehnder:373]: Received fan settings; speed: 0x01 voltage: 10 timer: 0
[20:50:24][D][fan:092]: 'Ventilation' - Sending state:
[20:50:24][D][fan:093]:   State: ON
[20:50:24][D][fan:095]:   Speed: 1
[20:50:25][D][zehnder:234]: Current state: 0x05
[20:50:25][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x07 from ID 0xD2 type 0x01
[20:50:25][D][zehnder:234]: Current state: 0x05
[20:50:25][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x07 from ID 0xD2 type 0x01
[20:50:50][D][zehnder:489]: Query device
[20:50:50][D][zehnder:654]: Start TX
[20:50:50][D][zehnder:136]: Tx Ready
[20:50:51][D][zehnder:666]: Receive timeout
[20:50:51][D][zehnder:670]: No data received, retry again (left: 9)
[20:50:51][D][zehnder:654]: Start TX
[20:50:51][D][zehnder:136]: Tx Ready
[20:50:52][D][zehnder:666]: Receive timeout
[20:50:52][D][zehnder:670]: No data received, retry again (left: 8)
[20:50:52][D][zehnder:654]: Start TX
[20:50:52][D][zehnder:136]: Tx Ready
[20:50:52][D][zehnder:234]: Current state: 0x06
[20:50:52][D][zehnder:373]: Received fan settings; speed: 0x01 voltage: 10 timer: 0
[20:50:52][D][fan:092]: 'Ventilation' - Sending state:
[20:50:52][D][fan:093]:   State: ON
[20:50:52][D][fan:095]:   Speed: 1
[20:50:53][D][zehnder:234]: Current state: 0x05
[20:50:53][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x07 from ID 0xD2 type 0x01
[20:51:06][D][nRF905:124]: Addr match
[20:51:06][D][nRF905:130]: Rx Invalid
[20:51:06][D][zehnder:234]: Current state: 0x05
[20:51:06][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x02 from ID 0x3C type 0x0B
[20:51:06][D][zehnder:234]: Current state: 0x05
[20:51:06][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x02 from ID 0x3C type 0x0B
[20:51:07][D][zehnder:234]: Current state: 0x05
[20:51:07][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x07 from ID 0xD2 type 0x01
[20:51:07][D][zehnder:234]: Current state: 0x05
[20:51:07][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x07 from ID 0xD2 type 0x01
[20:51:20][D][zehnder:489]: Query device
[20:51:20][D][zehnder:654]: Start TX
[20:51:20][D][zehnder:136]: Tx Ready
[20:51:21][D][zehnder:666]: Receive timeout
[20:51:21][D][zehnder:670]: No data received, retry again (left: 9)
[20:51:21][D][zehnder:654]: Start TX
[20:51:21][D][zehnder:136]: Tx Ready
[20:51:22][D][zehnder:666]: Receive timeout
[20:51:22][D][zehnder:670]: No data received, retry again (left: 8)
[20:51:22][D][zehnder:654]: Start TX
[20:51:22][D][zehnder:136]: Tx Ready
[20:51:22][D][zehnder:234]: Current state: 0x06
[20:51:22][D][zehnder:373]: Received fan settings; speed: 0x01 voltage: 10 timer: 0
[20:51:22][D][fan:092]: 'Ventilation' - Sending state:
[20:51:22][D][fan:093]:   State: ON
[20:51:22][D][fan:095]:   Speed: 1
[20:51:23][D][zehnder:234]: Current state: 0x05
[20:51:23][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x07 from ID 0xD2 type 0x01
[20:51:23][D][zehnder:234]: Current state: 0x05
[20:51:23][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x07 from ID 0xD2 type 0x01
[20:51:50][D][zehnder:489]: Query device
[20:51:50][D][zehnder:654]: Start TX
[20:51:50][D][zehnder:136]: Tx Ready
[20:51:51][D][zehnder:666]: Receive timeout
[20:51:51][D][zehnder:670]: No data received, retry again (left: 9)
[20:51:51][D][zehnder:654]: Start TX
[20:51:51][D][zehnder:136]: Tx Ready
[20:51:52][D][zehnder:666]: Receive timeout
[20:51:52][D][zehnder:670]: No data received, retry again (left: 8)
[20:51:52][D][zehnder:654]: Start TX
[20:51:52][D][zehnder:136]: Tx Ready

-------------------------------------------

--- Log of not working 2023.7.0 version ---

INFO ESPHome 2023.7.0
INFO Reading configuration /config/esphome/ventilatie.yaml...
WARNING GPIO12 is a Strapping PIN and should be avoided.
Attaching external pullup/down resistors to strapping pins can cause unexpected failures.
See https://esphome.io/guides/faq.html#why-am-i-getting-a-warning-about-strapping-pins
WARNING GPIO15 is a Strapping PIN and should be avoided.
Attaching external pullup/down resistors to strapping pins can cause unexpected failures.
See https://esphome.io/guides/faq.html#why-am-i-getting-a-warning-about-strapping-pins
INFO Generating C++ source...
INFO Compiling app...
Processing ventilatie (board: esp32doit-devkit-v1; framework: arduino; platform: platformio/espressif32@5.3.0)
--------------------------------------------------------------------------------
HARDWARE: ESP32 240MHz, 320KB RAM, 4MB Flash
 - toolchain-xtensa-esp32 @ 8.4.0+2021r2-patch5
Dependency Graph
|-- AsyncTCP-esphome @ 1.2.2
|-- WiFi @ 2.0.0
|-- FS @ 2.0.0
|-- Update @ 2.0.0
|-- ESPAsyncWebServer-esphome @ 2.1.0
|-- DNSServer @ 2.0.0
|-- ESPmDNS @ 2.0.0
|-- noise-c @ 0.1.4
|-- SPI @ 2.0.0
Compiling /data/ventilatie/.pioenvs/ventilatie/src/main.cpp.o
Linking /data/ventilatie/.pioenvs/ventilatie/firmware.elf
RAM:   [=         ]  12.7% (used 41656 bytes from 327680 bytes)
Flash: [=====     ]  53.2% (used 976957 bytes from 1835008 bytes)
Building /data/ventilatie/.pioenvs/ventilatie/firmware.bin
Creating esp32 image...
Successfully created esp32 image.
esp32_create_combined_bin(["/data/ventilatie/.pioenvs/ventilatie/firmware.bin"], ["/data/ventilatie/.pioenvs/ventilatie/firmware.elf"])
Wrote 0xffed0 bytes to file /data/ventilatie/.pioenvs/ventilatie/firmware-factory.bin, ready to flash to offset 0x0
========================= [SUCCESS] Took 32.54 seconds =========================
INFO Successfully compiled program.
INFO Resolving IP address of ventilatie.local
INFO  -> <redacted>
INFO Uploading /data/ventilatie/.pioenvs/ventilatie/firmware.bin (982736 bytes)
Uploading: [============================================================] 100% Done...

INFO Waiting for result...
INFO OTA successful
INFO Successfully uploaded program.
INFO Starting log output from ventilatie.local using esphome API
INFO Successfully connected to ventilatie.local
[16:36:30][I][app:102]: ESPHome version 2023.7.0 compiled on Jul 19 2023, 16:35:41
[16:36:30][C][wifi:543]: WiFi:
[16:36:30][C][wifi:379]:   Local MAC: 84:CC:A8:48:89:14
[16:36:30][C][wifi:380]:   SSID: 'IoTFi'[redacted]
[16:36:30][C][wifi:381]:   IP Address: <redacted>
[16:36:30][C][wifi:383]:   BSSID: E2:63:DA:16:2D:78[redacted]
[16:36:30][C][wifi:384]:   Hostname: 'ventilatie'
[16:36:30][C][wifi:386]:   Signal strength: -50 dB ▂▄▆█
[16:36:30][V][wifi:388]:   Priority: 0.0
[16:36:30][C][wifi:390]:   Channel: 1
[16:36:30][C][wifi:391]:   Subnet: 255.255.255.0
[16:36:30][C][wifi:392]:   Gateway: <redacted>
[16:36:30][C][wifi:393]:   DNS1: <redacted>
[16:36:30][C][wifi:394]:   DNS2: 0.0.0.0
[16:36:30][C][logger:301]: Logger:
[16:36:30][C][logger:302]:   Level: VERY_VERBOSE
[16:36:30][C][logger:303]:   Log Baud Rate: 115200
[16:36:30][C][logger:305]:   Hardware UART: UART0
[16:36:30][C][spi:125]: SPI bus:
[16:36:30][C][spi:126]:   CLK Pin: GPIO14
[16:36:30][C][spi:127]:   MISO Pin: GPIO12
[16:36:30][C][spi:128]:   MOSI Pin: GPIO13
[16:36:30][C][spi:130]:   Using HW SPI: YES
[16:36:30][C][homeassistant.time:010]: Home Assistant Time:
[16:36:30][C][homeassistant.time:011]:   Timezone: 'CET-1CEST,M3.5.0,M10.5.0/3'
[16:36:30][C][restart.button:017]: Restart Button 'Ventilatie herstart'
[16:36:30][C][zehnder:154]: Zehnder Fan config:
[16:36:30][C][zehnder:155]:   Polling interval   30000
[16:36:30][C][zehnder:156]:   Fan networkId      0xC11852FC
[16:36:30][C][zehnder:157]:   Fan my device type 0x03
[16:36:30][C][zehnder:158]:   Fan my device id   0x7F
[16:36:30][C][zehnder:159]:   Fan main_unit type 0x01
[16:36:30][C][zehnder:160]:   Fan main unit id   0xD2
[16:36:30][C][captive_portal:088]: Captive Portal:
[16:36:30][C][mdns:112]: mDNS:
[16:36:30][C][mdns:113]:   Hostname: ventilatie
[16:36:30][V][mdns:114]:   Services:
[16:36:30][V][mdns:116]:   - _esphomelib, _tcp, 6053
[16:36:30][V][mdns:118]:     TXT: version = 2023.7.0
[16:36:30][V][mdns:118]:     TXT: mac = 84cca8488914
[16:36:30][V][mdns:118]:     TXT: platform = ESP32
[16:36:30][V][mdns:118]:     TXT: board = esp32doit-devkit-v1
[16:36:30][V][mdns:118]:     TXT: network = wifi
[16:36:30][V][mdns:118]:     TXT: api_encryption = Noise_NNpsk0_25519_ChaChaPoly_SHA256
[16:36:30][C][ota:093]: Over-The-Air Updates:
[16:36:30][C][ota:094]:   Address: ventilatie.local:3232
[16:36:30][C][ota:097]:   Using Password.
[16:36:30][C][api:138]: API Server:
[16:36:30][C][api:139]:   Address: ventilatie.local:6053
[16:36:30][C][api:141]:   Using noise encryption: YES
[16:36:30][C][nRF905:074]: Config:
[16:36:30][C][nRF905:076]:   CS Pin:GPIO15
[16:36:30][C][nRF905:078]:   AM Pin:GPIO32
[16:36:30][C][nRF905:081]:   DR Pin:GPIO35
[16:36:30][C][nRF905:084]:   CD Pin:GPIO33
[16:36:30][C][nRF905:086]:   CE Pin:GPIO27
[16:36:30][C][nRF905:087]:   PWR Pin:GPIO26
[16:36:30][C][nRF905:088]:   TXEN Pin:GPIO25
[16:36:33][D][zehnder:177]: Discovery
[16:36:34][D][zehnder:185]: Config data valid, start polling
[16:36:34][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:36:34][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:36:34][V][nRF905:246]: Write config OK
[16:36:34][D][nRF905:264]: Set TX Address: 0xC11852FC
[16:36:34][D][zehnder:489]: Query device
[16:36:34][V][zehnder:607]: In startTransmit
[16:36:34][V][nRF905:356]: Read config (command to be sent) data: 0x01 0xD2 0x03 0x7F 0xFA 0x10 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
[16:36:34][W][component:204]: Component zehnder.fan took a long time for an operation (0.07 s).
[16:36:34][W][component:205]: Components should block for at most 20-30ms.
[16:36:34][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:36:34][D][zehnder:654]: Start TX
[16:36:34][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:36:34][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:36:34][V][nRF905:246]: Write config OK
[16:36:34][V][nRF905:098]: State change: 0x00 -> 0x20
[16:36:34][D][zehnder:136]: Tx Ready
[16:36:34][V][nRF905:098]: State change: 0x20 -> 0x00
[16:36:34][V][nRF905:098]: State change: 0x00 -> 0xA0
[16:36:34][V][nRF905:104]: RX Complete: 0x03 0x7F 0x01 0xD2 0xFA 0x07 0x04 0x01 0x0A 0x00 0x06 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
[16:36:34][V][zehnder:148]: Received frame
[16:36:34][V][zehnder:233]: In rfHandleReceived
[16:36:34][D][zehnder:234]: Current state: 0x06
[16:36:34][V][zehnder:359]: In rfHandleReceived --> StateWaitQueryResponse
[16:36:34][D][zehnder:373]: Received fan settings; speed: 0x01 voltage: 10 timer: 0
[16:36:34][V][zehnder:633]: rfComplete
[16:36:34][D][fan:092]: 'Ventilation' - Sending state:
[16:36:34][D][fan:093]:   State: ON
[16:36:34][D][fan:095]:   Speed: 1
[16:36:34][VV][api.service:104]: send_fan_state_response: FanStateResponse {
  key: 3172605362
  state: YES
  oscillating: NO
  speed: FAN_SPEED_LOW
  direction: FAN_DIRECTION_FORWARD
  speed_level: 1
}
[16:36:34][W][component:204]: Component nrf905 took a long time for an operation (0.08 s).
[16:36:34][W][component:205]: Components should block for at most 20-30ms.
[16:36:34][V][nRF905:098]: State change: 0xA0 -> 0x00
[16:36:34][V][nRF905:098]: State change: 0x00 -> 0x80
[16:36:34][D][nRF905:124]: Addr match
[16:36:34][V][nRF905:098]: State change: 0x80 -> 0xA0
[16:36:34][V][nRF905:104]: RX Complete: 0x03 0x7F 0x01 0xD2 0x4B 0x07 0x04 0x01 0x0A 0x00 0x06 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
[16:36:34][V][zehnder:148]: Received frame
[16:36:34][V][zehnder:233]: In rfHandleReceived
[16:36:34][D][zehnder:234]: Current state: 0x05
[16:36:34][D][zehnder:461]: Received frame from unknown device in unknown state; type 0x07 from ID 0xD2 type 0x01
[16:36:48][VV][api.service:540]: on_ping_request: PingRequest {}
[16:36:48][VV][api.service:043]: send_ping_response: PingResponse {}
[16:36:50][VV][api.service:540]: on_ping_request: PingRequest {}
[16:36:50][VV][api.service:043]: send_ping_response: PingResponse {}
[16:37:03][VV][scheduler:226]: Running interval '' with interval=60000 last_execution=4294951780 (now=44491)
[16:37:04][D][zehnder:489]: Query device
[16:37:04][V][zehnder:607]: In startTransmit
[16:37:04][V][nRF905:356]: Read config (command to be sent) data: 0x01 0xD2 0x03 0x7F 0xFA 0x10 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
[16:37:04][V][nRF905:098]: State change: 0xA0 -> 0x00
[16:37:04][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:04][D][zehnder:654]: Start TX
[16:37:04][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:04][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:04][V][nRF905:246]: Write config OK
[16:37:04][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:04][D][zehnder:136]: Tx Ready
[16:37:04][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:05][D][zehnder:666]: Receive timeout
[16:37:05][D][zehnder:670]: No data received, retry again (left: 9)
[16:37:05][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:05][D][zehnder:654]: Start TX
[16:37:05][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:05][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:05][V][nRF905:246]: Write config OK
[16:37:05][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:05][D][zehnder:136]: Tx Ready
[16:37:05][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:06][D][zehnder:666]: Receive timeout
[16:37:06][D][zehnder:670]: No data received, retry again (left: 8)
[16:37:06][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:06][D][zehnder:654]: Start TX
[16:37:06][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:06][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:06][V][nRF905:246]: Write config OK
[16:37:06][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:06][D][zehnder:136]: Tx Ready
[16:37:06][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:06][V][nRF905:098]: State change: 0x00 -> 0x80
[16:37:06][D][nRF905:124]: Addr match
[16:37:06][V][nRF905:098]: State change: 0x80 -> 0x00
[16:37:06][D][nRF905:130]: Rx Invalid
[16:37:06][V][nRF905:098]: State change: 0x00 -> 0xA0
[16:37:07][V][nRF905:104]: RX Complete: 0x01 0x00 0x0B 0x3C 0x62 0x02 0x01 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
[16:37:07][V][zehnder:148]: Received frame
[16:37:07][V][zehnder:233]: In rfHandleReceived
[16:37:07][D][zehnder:234]: Current state: 0x06
[16:37:07][V][zehnder:359]: In rfHandleReceived --> StateWaitQueryResponse
[16:37:07][D][zehnder:391]: Received frame from unknown device; type 0x02 from ID 0x3C type 0x0B
[16:37:07][W][component:204]: Component nrf905 took a long time for an operation (0.05 s).
[16:37:07][W][component:205]: Components should block for at most 20-30ms.
[16:37:07][D][zehnder:666]: Receive timeout
[16:37:07][D][zehnder:670]: No data received, retry again (left: 7)
[16:37:07][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:07][D][zehnder:654]: Start TX
[16:37:07][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:07][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:07][V][nRF905:246]: Write config OK
[16:37:07][V][nRF905:098]: State change: 0xA0 -> 0x00
[16:37:07][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:07][D][zehnder:136]: Tx Ready
[16:37:07][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:08][D][zehnder:666]: Receive timeout
[16:37:08][D][zehnder:670]: No data received, retry again (left: 6)
[16:37:08][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:08][D][zehnder:654]: Start TX
[16:37:08][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:08][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:08][V][nRF905:246]: Write config OK
[16:37:08][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:08][D][zehnder:136]: Tx Ready
[16:37:08][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:08][VV][api.service:540]: on_ping_request: PingRequest {}
[16:37:08][VV][api.service:043]: send_ping_response: PingResponse {}
[16:37:09][D][zehnder:666]: Receive timeout
[16:37:09][D][zehnder:670]: No data received, retry again (left: 5)
[16:37:09][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:09][D][zehnder:654]: Start TX
[16:37:09][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:09][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:09][V][nRF905:246]: Write config OK
[16:37:09][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:09][D][zehnder:136]: Tx Ready
[16:37:09][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:10][VV][api.service:540]: on_ping_request: PingRequest {}
[16:37:10][VV][api.service:043]: send_ping_response: PingResponse {}
[16:37:10][D][zehnder:666]: Receive timeout
[16:37:10][D][zehnder:670]: No data received, retry again (left: 4)
[16:37:10][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:10][D][zehnder:654]: Start TX
[16:37:10][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:10][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:10][V][nRF905:246]: Write config OK
[16:37:10][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:10][D][zehnder:136]: Tx Ready
[16:37:10][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:11][D][zehnder:666]: Receive timeout
[16:37:11][D][zehnder:670]: No data received, retry again (left: 3)
[16:37:11][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:11][D][zehnder:654]: Start TX
[16:37:11][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:11][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:11][V][nRF905:246]: Write config OK
[16:37:11][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:11][D][zehnder:136]: Tx Ready
[16:37:11][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:12][D][zehnder:666]: Receive timeout
[16:37:12][D][zehnder:670]: No data received, retry again (left: 2)
[16:37:12][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:12][D][zehnder:654]: Start TX
[16:37:12][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:13][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:13][V][nRF905:246]: Write config OK
[16:37:13][W][component:204]: Component zehnder.fan took a long time for an operation (0.05 s).
[16:37:13][W][component:205]: Components should block for at most 20-30ms.
[16:37:13][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:13][D][zehnder:136]: Tx Ready
[16:37:13][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:14][D][zehnder:666]: Receive timeout
[16:37:14][D][zehnder:670]: No data received, retry again (left: 1)
[16:37:14][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:14][D][zehnder:654]: Start TX
[16:37:14][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:14][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:14][V][nRF905:246]: Write config OK
[16:37:14][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:14][D][zehnder:136]: Tx Ready
[16:37:14][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:15][D][zehnder:666]: Receive timeout
[16:37:15][D][zehnder:670]: No data received, retry again (left: 0)
[16:37:15][V][zehnder:653]: In rfHandler --> RfStateWaitAirwayFree airway not busy
[16:37:15][D][zehnder:654]: Start TX
[16:37:15][V][nRF905:528]: Config:
  Channel 117 Band 868 MHz -> 868200000
  Rx Power normal
  Tx Retransmit Off
  Rx Address (4) 0xC11852FC
  Rx Payload width 16
  Tx Address (4)
  Tx Payload width 16
  Clk Out 500000
  XTAL Freq 16000000
  CRC On -> 16
  TX Power 10 dBm
[16:37:15][V][nRF905:227]: Write config data: 0x75 0x0E 0x44 0x10 0x10 0xFC 0x52 0x18 0xC1 0xDB
[16:37:15][V][nRF905:246]: Write config OK
[16:37:15][V][nRF905:098]: State change: 0x00 -> 0x20
[16:37:15][D][zehnder:136]: Tx Ready
[16:37:15][V][nRF905:098]: State change: 0x20 -> 0x00
[16:37:16][D][zehnder:666]: Receive timeout
[16:37:16][D][zehnder:677]: No messages received, giving up now...
[16:37:16][W][zehnder:506]: Query Timeout

Additional information

No response

ssieb commented 1 year ago

External components not working is not an esphome issue unless you can reduce it to a bug in esphome code. We can't even see what your code is.

spudje commented 1 year ago

Nothing changed in the external component. It stopped working as soon as I upgraded to 2023.7.0. The code (not mine) is in the wetransfer link. I think my issue might be related to issues like https://github.com/esphome/issues/issues/4717, https://github.com/esphome/issues/issues/4714 & https://github.com/esphome/issues/issues/4716

ssieb commented 1 year ago

It has nothing to do with those. That message was just changed to a different logging level so that it's visible now. https://github.com/esphome/issues/issues/4717 Regardless of whether anything changed in the external component, things might have changed internally in esphome. It's up to whoever created the component to determine if the problem is in the component or esphome.

spudje commented 10 months ago

I'm still struggling with this (Now trying with 2023.10.3). Every ESPHome release after 2023.6 breaks this custom component. I have the idea it has something to do with performance and timeouts being too tight. Did 2023.7 introduce functionality that increases load/resources impact? I still feel it's related to below linked issue.

ssieb commented 10 months ago

It is absolutely not related to that issue. Have you talked to the person who made the component?

golles commented 1 week ago

Is this the component you're using? https://github.com/Sanderhuisman/ESPHome-Zehnder-RF (I've got the same problem, don't want to download from wetransfer...)