esphome / issues

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

[http_request] ESP32 reboots after few http requests #5951

Closed XavierBerger closed 3 weeks ago

XavierBerger commented 3 weeks ago

The problem

TLDR: My code is working on 2024.5.5 and is crashing on 2024.6.1 after about 1.5min - http_request suspected to be the root cause.


I have a project using http_request and parsing json :

The code I used in my yaml to parse the json is coming from the official documentation.

As the size of json I read is about 1600 bytes, I did update max_response_buffer_size.
The documentation of max_response_buffer_size let think that integer value is in kB : "Default 1kB"
It looks like, in reality, the unit is bytes.
I then set max_response_buffer_size to 4096 (I tried with 2048, issue is the same).

When I activate the http requests, after about a minute and half, my ESP is no more responding : No logs (even in debug), sensors unavailable in Web interface.
After investigation, I understood that the ESP32 has rebooted.

I'm suspecting http_request because, if I do not activate the http requests, my ESP is responding (logs and sensors are updates). As soon as I start the http request, my ESP stop responding after about a minute and half.

The latest log I can see is always coming from http_request as for example: 10:58:26 [D] [http_request.arduino:119] Content-Length: 1598

Which version of ESPHome has the issue?

2024.6.1

What type of installation are you using?

Home Assistant Add-on

and

esphome from pip

Which version of Home Assistant has the issue?

2024.6.4

What platform are you using?

ESP32-Arduino

Board

ESP32-dev board - Wroom-32U

Component causing the issue

http_request

Example YAML snippet

# ----------------------------------------------------------------------------------------------------
# Sensor updated every second to give feedback in Home Assistant
# ----------------------------------------------------------------------------------------------------

sensor:
  # Sensor showing the actual power consumption
  - id: real_power
    platform: template
    name: "Real Power"
    device_class: "power"
    unit_of_measurement: "W"
    update_interval: 1s

# ----------------------------------------------------------------------------------------------------
# Use http request component
# ----------------------------------------------------------------------------------------------------

http_request:
  id: http_request_data
  useragent: esphome/device
  timeout: 10s
  verify_ssl: False

# ----------------------------------------------------------------------------------------------------
# Define scripts for power collection
# ----------------------------------------------------------------------------------------------------

script:
  # Fronius script gather power reports from inverter and update globals (real_power)
  # Information are provided as json. Power exchanged with the grid is names PowerReal_P_Sum
  # When this value is positive, energy is taken from the grid.
  # When this value is negative, energy is pushed to the grid.
  - id: power_meter_source
    mode: single
    then:
      - if:
          condition:
            wifi.connected:
          then:
            - http_request.get:
                url: http://${power_meter_ip_address}/solar_api/v1/GetMeterRealtimeData.cgi
                capture_response: true
                max_response_buffer_size: 4096
                on_response:
                  then:
                    - lambda: |-
                        json::parse_json(body, [](JsonObject root) -> bool {
                          id(real_power).publish_state(root["Body"]["Data"]["0"]["PowerReal_P_Sum"].as< float >());
                          return true;
                        });

time:
  - platform: sntp
    on_time:
      - seconds: /1
        then:
          - if:
              condition:
                - lambda: return id(power_meter_activated) != 0;
              then:
                - script.execute: power_meter_source

Anything in the logs that might be useful for us?

[11:42:04][D][light:036]: 'dimmer_controller' Setting:
[11:42:04][D][light:051]:   Brightness: 100%
[11:42:04][D][light:036]: 'green_led' Setting:
[11:42:05][D][light:036]: 'yellow_led' Setting:
[11:42:05][D][http_request.arduino:119]: Content-Length: 1600
WARNING solarrouter @ 192.168.1.27: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for solarrouter @ 192.168.1.27
WARNING Disconnected from API
INFO Successfully connected to solarrouter @ 192.168.1.27 in 0.011s
INFO Successful handshake with solarrouter @ 192.168.1.27 in 0.100s
[11:42:30][D][light:036]: 'yellow_led' Setting:
[11:42:30][D][light:047]:   State: OFF
[11:42:30][D][light:036]: 'yellow_led' Setting:
[11:42:30][D][light:047]:   State: ON
[11:42:35][D][light:036]: 'yellow_led' Setting:

Additional information

I recompile the v1.1.0 of my project with ESPHome 2.5.5 (pip) and everything is working well.

Here is the diff between the version which is working and the version which is crashing:

diff --git a/solar_router/power_meter_fronius.yaml b/solar_router/power_meter_fronius.yaml
index af3aa4e..0c6fad8 100644
--- a/solar_router/power_meter_fronius.yaml
+++ b/solar_router/power_meter_fronius.yaml
@@ -19,6 +19,7 @@ http_request:
   id: http_request_data
   useragent: esphome/device
   timeout: 10s
+  verify_ssl: False

 # ----------------------------------------------------------------------------------------------------
 # Define scripts for power collection
@@ -38,14 +39,14 @@ script:
           then:
             - http_request.get:
                 url: http://${power_meter_ip_address}/solar_api/v1/GetMeterRealtimeData.cgi
-                headers:
-                  Content-Type: application/json
-                verify_ssl: False
+                capture_response: true
+                max_response_buffer_size: 4096
                 on_response:
                   then:
                     - lambda: |-
-                        json::parse_json(id(http_request_data).get_string(), [](JsonObject data) {
-                          id(real_power).publish_state(data["Body"]["Data"]["0"]["PowerReal_P_Sum"].as< float >());
+                        json::parse_json(body, [](JsonObject root) -> bool {
+                          id(real_power).publish_state(root["Body"]["Data"]["0"]["PowerReal_P_Sum"].as< float >());
+                          return true;
                         });

 time:
XavierBerger commented 3 weeks ago

When I run the same code on ESP8285, I have other logs that may help in troubleshooting.

I did install this program with Home Assistant Addon.

Configuration:

# ----------------------------------------------------------------------------------------------------
# ESPHome configuration - This part depends on your hardware target
# ----------------------------------------------------------------------------------------------------

esphome:
  name: "esp8285"
  friendly_name: ESP8285

esp8266:
  board: esp01_1m
  framework:
    version: 3.0.2

# Enable logging
logger:
  baud_rate: 115200
  level: INFO
  logs:
    component: ERROR

# Enable Home Assistant API
api:

# Enable over-the-air updates
ota:
  - platform: esphome

# WiFi connection
wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password

# Activate web interface
web_server:
  port: 80

# ----------------------------------------------------------------------------------------------------
# Customisation
# ----------------------------------------------------------------------------------------------------

substitutions:
  # Power meter source -----------------------------------------------------------
  # Define ip address of Fronius inverter
  power_meter_ip_address: "192.168.1.21"

  # LEDs -------------------------------------------------------------------------
  # Yellow LED is reflecting power meter
  yellow_led_pin: GPIO1

globals:
  - id: power_meter_activated
    type: int
    initial_value: "1"

packages:
  power_meter:
    url: https://github.com/XavierBerger/Solar-Router-for-ESPHome/
    file: solar_router/power_meter_fronius.yaml
    ref: v1.1.1

http_request:
  esp8266_disable_ssl_support: True

The logs:

19:57:54][I][logger:034]: Log initialized
[19:57:54][I][app:029]: Running through setup()...
[19:58:00][I][wifi:539]: - 'Livebox-6D70' (38:A6:59:45:6D:78) ▂▄▆█
[19:58:00][I][wifi:312]: WiFi Connecting to 'Livebox-6D70'...
[19:58:02][I][wifi:616]: WiFi Connected!
[19:58:02][I][app:062]: setup() finished successfully!
[19:58:02][I][app:100]: ESPHome version 2024.6.1 compiled on Jun 24 2024, 19:57:13
[19:58:02]
[19:58:02]--------------- CUT HERE FOR EXCEPTION DECODER ---------------
[19:58:02]
[19:58:02]Exception (9):
WARNING Exception type: LoadStoreAlignmentCause: Load or store to an unaligned address
[19:58:02]epc1=0x4022798a epc2=0x00000000 epc3=0x00000000 excvaddr=0x041405de depc=0x00000000
WARNING Decoded 0x4022798a: HTTPClient::connected()
[19:58:02]
[19:58:02]>>>stack>>>
WARNING Found stack trace! Trying to decode it
[19:58:02]
[19:58:02]ctx: cont
[19:58:02]sp: 3ffffbb0 end: 3fffffd0 offset: 0190
[19:58:02]3ffffd40:  3fff2ffc 3ffffeb4 00000000 40206a23  
WARNING Decoded 0x40206a23: esphome::http_request::HttpRequestArduino::start(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::list<esphome::http_request::Header, std::allocator<esphome::http_request::Header> >)
[19:58:02]3ffffd50:  00000000 00002171 d53f7ced 0026ab9e  
[19:58:02]3ffffd60:  000020a0 00000414 3fff2ffc 4021e7d5  
WARNING Decoded 0x4021e7d5: HTTPClient::getStreamPtr()
[19:58:02]3ffffd70:  3fff2fe0 0000064e 3fff14b4 402066a0  
WARNING Decoded 0x402066a0: esphome::http_request::HttpContainerArduino::read(unsigned char*, unsigned int)
[19:58:02]3ffffd80:  00000000 00000000 3fff2524 40100d5e  
WARNING Decoded 0x40100d5e: free
[19:58:02]3ffffd90:  3fff335c 00000200 3fff14b4 3fff13fc  
[19:58:02]3ffffda0:  00001000 0000064e 00000020 3fff335c  
[19:58:02]3ffffdb0:  00000000 0000064e 3fff14b4 40213bbe  
WARNING Decoded 0x40213bbe: esphome::http_request::HttpRequestSendAction<>::play()
[19:58:02]3ffffdc0:  3ffffdc8 00000000 00015100 00000000  
[19:58:02]3ffffdd0:  6679b3aa 00000000 3ffffde0 00000003 <
[19:58:02]3ffffde0:  00544547 00000000 00000000 4022184e  
WARNING Decoded 0x4022184e: String::changeBuffer(unsigned int)
[19:58:02]3ffffdf0:  3fff2524 00000039 00000039 00000100  
[19:58:02]3ffffe00:  00000000 00000000 3ffffe08 3ffffe08  
[19:58:02]3ffffe10:  00000000 d9d50000 0000d9d5 00000000  
[19:58:02]3ffffe20:  0000a8c0 333cd9d5 00000022 008083dc  
[19:58:02]3ffffe30:  3ffffe60 3fff1894 3ffffe40 00000000 <
[19:58:02]3ffffe40:  85bc0e00 00061ba6 000f4240 3ffe83c4  
[19:58:02]3ffffe50:  3ffffe58 00000000 3ffe8300 4022fa12  
WARNING Decoded 0x4022fa12: _getenv_r at /workdir/repo/newlib/newlib/libc/stdlib/getenv_r.c:126
[19:58:02]3ffffe60:  00000000 4022a3d5 3ffffe68 3ffffe68  
WARNING Decoded 0x4022a3d5: gmtime_r at /workdir/repo/newlib/newlib/libc/time/gmtime_r.c:59
[19:58:02]3ffffe70:  00000000 f4240000 00000000 4022d805  
WARNING Decoded 0x4022d805: _tzset_unlocked_r at /workdir/repo/newlib/newlib/libc/time/tzset_r.c:25
[19:58:02]3ffffe80:  00004d0b 000007e8 3ffe8368 3ffe8398  
[19:58:02]3ffffe90:  00000000 00000018 00000018 3ffe83c0  
[19:58:02]3ffffea0:  4025e05a 3fff0f04 00000002 00000001  
WARNING Decoded 0x4025e05a: wifi_get_opmode
[19:58:02]3ffffeb0:  4025f24b 3fff2fe0 3fff2fd4 00000005  
WARNING Decoded 0x4025f24b: wifi_station_get_connect_status
[19:58:02]3ffffec0:  40206774 4020ea44 00000200 000007e8  
WARNING Decoded 0x40206774: esphome::http_request::HttpRequestArduino::start(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::__cxx11::list<esphome::http_request::Header, std::allocator<esphome::http_request::Header> >)
WARNING Decoded 0x4020ea44: esphome::wifi::WiFiComponent::wifi_sta_connect_status_()
[19:58:02]3ffffed0:  3ffe8368 40262900 3fff1974 3fff170c  
WARNING Decoded 0x40262900: chip_v6_unset_chanfreq
[19:58:02]3ffffee0:  3fff2d28 00000002 3fff14b4 4021236c  
WARNING Decoded 0x4021236c: esphome::Action<>::play_complex()
[19:58:02]3ffffef0:  00000000 00000002 3fff17dc 4021236c  
WARNING Decoded 0x4021236c: esphome::Action<>::play_complex()
[19:58:02]3fffff00:  3fff2d28 00000002 3fff170c 4020a7d5  
WARNING Decoded 0x4020a7d5: esphome::time::CronTrigger::loop()
[19:58:02]3fffff10:  3fffdad0 3ffef8e4 3ffef8e4 40211a5b  
WARNING Decoded 0x40211a5b: esphome::Scheduler::call()
[19:58:02]3fffff20:  4025e05a 3fff0f04 00002108 00000001  
WARNING Decoded 0x4025e05a: wifi_get_opmode
[19:58:02]3fffff30:  6679b301 00000000 02133a02 00b00018  
[19:58:02]3fffff40:  07e80006 00000001 6679b3aa 00000000  
[19:58:02]3fffff50:  02133a02 00b00018 07e80006 00000001  
[19:58:02]3fffff60:  6679b3aa 00000000 3fffff80 40210860  
WARNING Decoded 0x40210860: esphome::WarnIfComponentBlockingGuard::WarnIfComponentBlockingGuard(esphome::Component*)
[19:58:02]3fffff70:  3fff2d28 00000002 3ffef8e4 4020f012  
WARNING Decoded 0x4020f012: esphome::Application::loop()
[19:58:02]3fffff80:  00002108 3fff170c 3fff1900 3ffefce0  
[19:58:02]3fffff90:  3fff2d44 3fff1358 3ffef918 3ffefce0  
[19:58:02]3fffffa0:  3fffdad0 00000000 3ffefccc 3ffefce0  
[19:58:02]3fffffb0:  3fffdad0 00000000 3ffefccc 40222bd4  
WARNING Decoded 0x40222bd4: loop_wrapper() at core_esp8266_main.cpp
[19:58:02]3fffffc0:  feefeffe feefeffe 3ffe8660 40100459  
WARNING Decoded 0x40100459: cont_wrapper
[19:58:02]<<<stack<<<
[19:58:02]
[19:58:02]--------------- CUT HERE FOR EXCEPTION DECODER ---------------
[19:58:02]
[19:58:02] ets Jan  8 2013,rst cause:1, boot mode:(3,7)
[19:58:02]
[19:58:02]load 0x4010f000, len 3460, room 16 
[19:58:02]tail 4
[19:58:02]chksum 0xcc
[19:58:02]load 0x3fff20b8, len 40, room 4 
[19:58:02]tail 4
[19:58:02]chksum 0xc9
[19:58:02]csum 0xc9
[19:58:02]v0006da80
[19:58:02]~ld
XavierBerger commented 3 weeks ago

Issue is fixed for ESP32-dev board - Wroom-32U board.

On ESP8285 the warning about http_request.arduino velocity is continuously poping but has no impact on overall performances.

Issue is closed.