Help requested debugging my code

ESPHome
1

I am working on an ESP32-S3 devkit board for a greenhouse, so I want to use deep sleep and tried merging bits of @Mahko_Mahko’s code … and things got rather weird. Almost all the log messages disappeared, except for a few about seep sleep starting and starting being successful, and a whole pile of ones about JSON.

So I have gone back and reduced the number of sensors and comments in my code to make it easier to debug, added some debugging logger.log actions, used the built-in LED to indicate program status, cleaned the build files, and physically powered off my ESP32 before loading the program below … but issues now are:

  1. actions in the on_boot do not appear to have been actioned
  2. my logger.log actions (starting ####) are not showing in the log
  3. Are the lines “Attempting to allocate 512 bytes for JSON serialization” expected from verbose logging, or do they indicate a problem. I note that flash usage has jumped from around 18% to 71%.
  4. why the delays from 20:23 to 20:32, 20:32 to 20:34, 20:34 to 20:39 ? It looks as though ESPHome is deliberately spacing its processing out to fill the update_interval.
#
# To control the greenhouse I have an ESP32-S3-DevKitC-1 (v1) board 
#
# THIS FILE SERIOUSLY CUT DOWN FOR EASE OF DEBUGGING !!!

substitutions:
  devicename:     "greenhouse"
  deviceIP:       "97"                     # last octet of the IP Address
  wifi_ssid:      !secret upstairs_ssid     ### which wi-fi to connect to
  wifi_password:  !secret upstairs_password 
  update_interval_network: "30 min"       # How often to measure and report network values
  update_interval_sensor:  "15 min"       # How often to measure and report other values
  sleep_run_duration:   "5 min"       # how long to run (be awake)
  sleep_duration: $update_interval_sensor      # how long to sleep for

packages:
  wi-fi: !include _common_wifi.yaml

# Enable logging
logger:
  level: VERBOSE            # DEBUG

esphome:
  name: $devicename
  platformio_options:
    board_build.flash_mode: dio 
  on_boot: 
    - priority: -100           # everything has been set up
      then:
      # enable all the peripheral sensors
        - logger.log: "##### on_boot started" 
        - light.turn_on:
            id: rgb_led
            red: 0%
            blue: 50%
            green: 50%
            brightness: 20%
        - logger.log: "....Starting sensor updates"

preferences:
  flash_write_interval: 60min

esp32:
  board: adafruit_feather_esp32s3     # esp32-s3-devkitc-1
  variant: esp32s3
  flash_size: 16mb
  framework:
    type: arduino

psram:                        # but PSRAM is NOT being accepted !
  mode: octal
  speed: 80MHz

#
# The RGB LED is built into the board
#
light:
  - platform: esp32_rmt_led_strip
    name: $devicename RGB LED
    id: rgb_led
    rgb_order: GRB
    pin: GPIO48
    num_leds: 1
    rmt_channel: 0
    chipset: ws2812


#   hardware configuration
i2c:
  - id: bus_a
    sda: GPIO1
    scl: GPIO2
    scan: true
    frequency: 400kHz


###################################################################
#                                                                 #
#   Place the ESP32 in Deep Sleep between sensor readings         #
#                                                                 #
###################################################################
#deep_sleep: 
# #Auto deep sleep shouldn't actually get used if data updates are happening properly (should sleep sooner).
# #But if something is wrong with data updates this will kick-in to protect battery discharge.
#  id: deep_sleep_1
#  run_duration:   $sleep_run_duration    # how long to run (be awake)
#  sleep_duration: $sleep_duration        # how long to sleep for

# wake up if it starts raining while asleep 
#  wakeup_pin: GPIO21            # wake up if a rain gauge pulse is detected
#  wakeup_pin_mode: KEEP_AWAKE   # stay awake if rain is happening when otherise would sleep


switch:

  - platform: gpio
    id: relay_solar
    name: $devicename Solar Power relay
    pin: GPIO9
    restore_mode: ALWAYS_ON   # Solar Power on when waking from sleep.

  # Control peripheral power (on solar power manager)
  #       DFRobot solar power manager can turn on/off the 5V header pins,
  #       making them ideal for powering sensors from
  - platform: gpio
    id: peripheral_power
    name: $devicename peripheral power
    pin: GPIO47
    restore_mode: ALWAYS_ON #Power on when waking from sleep.


sensor:

#  # DHT22 is also available
  - platform: dht
    model: DHT22
    pin: GPIO5
    temperature:
      name: $devicename DHT22 Temperature
    humidity:
      name: $devicename DHT22 Humidity
    update_interval: $update_interval_sensor

  # lux sensor to detect sun or storm, day or night
  - platform: bh1750
    name: $devicename BH1750 Illuminance
    address: 0x23
    update_interval: $update_interval_sensor


  #         Power Module sensors                        # 
 
  # MAX1704x is specifically for Li-ON battery                
  # My board is a MAX14048, but seems functionally a MAX17043 
  #    (adafruit driver available) but with a few extra unimplemented features
  - platform: max17043
    id: i2c_max17048
    battery_level:
      name: "Max17048 Battery level"
    battery_voltage:
      name: "MAX17048 Battery Voltage"
      id: batt_voltage
      on_value_range:
        - above: 4.1      # battery fully charged
          then:
            - logger.log: "##### battery is full charge 4.1v"
            - switch.turn_off: relay_solar        #- switch.turn_off: solarPanel
        - below: 3.3      # battery is running low
          then:
            - logger.log: "##### battery is LOW charge 3.3v" 
            # raise an alarm / notification / email
            - switch.turn_off: peripheral_power   # turn off all the sensors until power is restored
    update_interval: $update_interval_sensor

resulted in:

Linking .pioenvs/greenhouse/firmware.elf
RAM:   [==        ]  15.1% (used 49576 bytes from 327680 bytes)
Flash: [=======   ]  70.9% (used 1022829 bytes from 1441792 bytes)
Building .pioenvs/greenhouse/firmware.bin
Creating esp32s3 image...
Successfully created esp32s3 image.
esp32_create_combined_bin([".pioenvs/greenhouse/firmware.bin"], [".pioenvs/greenhouse/firmware.elf"])
Wrote 0x109cf0 bytes to file /data/build/greenhouse/.pioenvs/greenhouse/firmware.factory.bin, ready to flash to offset 0x0
esp32_copy_ota_bin([".pioenvs/greenhouse/firmware.bin"], [".pioenvs/greenhouse/firmware.elf"])
========================= [SUCCESS] Took 57.89 seconds =========================
INFO Successfully compiled program.
INFO Connecting to 192.168.1.97 port 3232...
INFO Connected to 192.168.1.97
INFO Uploading /data/build/greenhouse/.pioenvs/greenhouse/firmware.bin (1023216 bytes)
Uploading: [============================================================] 100% Done...

INFO Upload took 10.74 seconds, waiting for result...
INFO OTA successful
INFO Successfully uploaded program.
INFO Starting log output from 192.168.1.97 using esphome API
INFO Successfully connected to greenhouse @ 192.168.1.97 in 3.124s
INFO Successful handshake with greenhouse @ 192.168.1.97 in 0.091s
[20:22:41][I][app:100]: ESPHome version 2024.12.4 compiled on Feb  2 2025, 20:22:03
[20:22:41][C][wifi:600]: WiFi:
[20:22:41][C][wifi:428]:   Local MAC: 98:3D:AE:EB:24:F4
[20:22:41][C][wifi:433]:   SSID: [redacted]
[20:22:41][C][wifi:436]:   IP Address: 192.168.1.97
[20:22:41][C][wifi:440]:   BSSID: [redacted]
[20:22:41][C][wifi:441]:   Hostname: 'greenhouse'
[20:22:41][C][wifi:443]:   Signal strength: -66 dB ▂▄▆█
[20:22:41][C][wifi:447]:   Channel: 13
[20:22:41][C][wifi:448]:   Subnet: 255.255.255.0
[20:22:41][C][wifi:449]:   Gateway: 192.168.1.1
[20:22:41][C][wifi:450]:   DNS1: 0.0.0.0
[20:22:41][C][wifi:451]:   DNS2: 0.0.0.0
[20:22:41][C][logger:185]: Logger:
[20:22:41][C][logger:186]:   Level: VERBOSE
[20:22:41][C][logger:188]:   Log Baud Rate: 115200
[20:22:41][C][logger:189]:   Hardware UART: USB_CDC
[20:22:41][C][i2c.arduino:071]: I2C Bus:
[20:22:41][C][i2c.arduino:072]:   SDA Pin: GPIO1
[20:22:41][C][i2c.arduino:073]:   SCL Pin: GPIO2
[20:22:41][C][i2c.arduino:074]:   Frequency: 400000 Hz
[20:22:41][C][i2c.arduino:086]:   Recovery: bus successfully recovered
[20:22:41][I][i2c.arduino:096]: Results from i2c bus scan:
[20:22:41][I][i2c.arduino:102]: Found i2c device at address 0x23
[20:22:41][I][i2c.arduino:102]: Found i2c device at address 0x36
[20:22:41][I][i2c.arduino:102]: Found i2c device at address 0x40
[20:22:42][I][i2c.arduino:102]: Found i2c device at address 0x45
[20:22:42][I][i2c.arduino:102]: Found i2c device at address 0x48
[20:22:42][C][template.text_sensor:020]: Template Sensor 'greenhouse Uptime Human Readable'
[20:22:42][C][template.text_sensor:020]:   Icon: 'mdi:clock-start'
[20:22:42][C][esp32_rmt_led_strip:187]: ESP32 RMT LED Strip:
[20:22:42][C][esp32_rmt_led_strip:188]:   Pin: 48
[20:22:42][C][esp32_rmt_led_strip:189]:   Channel: 0
[20:22:42][C][esp32_rmt_led_strip:214]:   RGB Order: GRB
[20:22:42][C][esp32_rmt_led_strip:215]:   Max refresh rate: 0
[20:22:42][C][esp32_rmt_led_strip:216]:   Number of LEDs: 1
[20:22:42][C][switch.gpio:068]: GPIO Switch 'greenhouse Solar Power relay'
[20:22:42][C][switch.gpio:091]:   Restore Mode: always ON
[20:22:42][C][switch.gpio:031]:   Pin: GPIO9
[20:22:42][C][switch.gpio:068]: GPIO Switch 'greenhouse peripheral power'
[20:22:42][C][switch.gpio:091]:   Restore Mode: always ON
[20:22:42][C][switch.gpio:031]:   Pin: GPIO47
[20:22:42][C][uptime.sensor:033]: Uptime Sensor 'greenhouse Uptime'
[20:22:42][C][uptime.sensor:033]:   Device Class: 'duration'
[20:22:42][C][uptime.sensor:033]:   State Class: 'total_increasing'
[20:22:42][C][uptime.sensor:033]:   Unit of Measurement: 's'
[20:22:42][C][uptime.sensor:033]:   Accuracy Decimals: 0
[20:22:42][C][uptime.sensor:033]:   Icon: 'mdi:timer-outline'
[20:22:42][V][uptime.sensor:033]:   Unique ID: '983daeeb24f4-uptime'
[20:22:42][C][uptime.sensor:034]:   Type: Seconds
[20:22:42][C][light:092]: Light 'greenhouse RGB LED'
[20:22:42][C][light:094]:   Default Transition Length: 1.0s
[20:22:42][C][light:095]:   Gamma Correct: 2.80
[20:22:42][C][dht:017]: DHT:
[20:22:42][C][dht:018]:   Pin: GPIO5
[20:22:42][C][dht:024]:   Model: DHT22 (or equivalent)
[20:22:42][C][dht:027]:   Update Interval: 900.0s
[20:22:42][C][dht:029]:   Temperature 'greenhouse DHT22 Temperature'
[20:22:42][C][dht:029]:     Device Class: 'temperature'
[20:22:42][C][dht:029]:     State Class: 'measurement'
[20:22:42][C][dht:029]:     Unit of Measurement: '°C'
[20:22:42][C][dht:029]:     Accuracy Decimals: 1
[20:22:42][C][dht:030]:   Humidity 'greenhouse DHT22 Humidity'
[20:22:42][C][dht:030]:     Device Class: 'humidity'
[20:22:42][C][dht:030]:     State Class: 'measurement'
[20:22:42][C][dht:030]:     Unit of Measurement: '%'
[20:22:42][C][dht:030]:     Accuracy Decimals: 0
[20:22:42][C][bh1750.sensor:118]: BH1750 'greenhouse BH1750 Illuminance'
[20:22:42][C][bh1750.sensor:118]:   Device Class: 'illuminance'
[20:22:42][C][bh1750.sensor:118]:   State Class: 'measurement'
[20:22:42][C][bh1750.sensor:118]:   Unit of Measurement: 'lx'
[20:22:42][C][bh1750.sensor:118]:   Accuracy Decimals: 1
[20:22:42][C][bh1750.sensor:119]:   Address: 0x23
[20:22:42][C][bh1750.sensor:124]:   Update Interval: 900.0s
[20:22:42][C][max17043:076]: MAX17043:
[20:22:42][C][max17043:077]:   Address: 0x36
[20:22:42][C][max17043:081]:   Update Interval: 900.0s
[20:22:42][C][max17043:082]:   Battery Voltage 'MAX17048 Battery Voltage'
[20:22:42][C][max17043:082]:     Device Class: 'voltage'
[20:22:42][C][max17043:082]:     State Class: 'measurement'
[20:22:42][C][max17043:082]:     Unit of Measurement: 'V'
[20:22:42][C][max17043:082]:     Accuracy Decimals: 3
[20:22:42][C][max17043:083]:   Battery Level 'Max17048 Battery level'
[20:22:42][C][max17043:083]:     Device Class: 'battery'
[20:22:42][C][max17043:083]:     State Class: 'measurement'
[20:22:42][C][max17043:083]:     Unit of Measurement: '%'
[20:22:42][C][max17043:083]:     Accuracy Decimals: 3
[20:22:42][C][version.text_sensor:021]: Version Text Sensor 'greenhouse ESPHome Version'
[20:22:42][C][version.text_sensor:021]:   Icon: 'mdi:new-box'
[20:22:42][V][version.text_sensor:021]:   Unique ID: '983daeeb24f4-version'
[20:22:42][C][wifi_info:014]: WifiInfo Mac Address 'greenhouse Wifi MAC Address'
[20:22:42][V][wifi_info:014]:   Unique ID: '983daeeb24f4-wifiinfo-macadr'
[20:22:42][C][psram:020]: PSRAM:
[20:22:42][C][psram:021]:   Available: NO
[20:22:42][C][captive_portal:089]: Captive Portal:
[20:22:42][C][web_server:153]: Web Server:
[20:22:42][C][web_server:154]:   Address: 192.168.1.97:80
[20:22:42][C][sntp:042]: SNTP Time:
[20:22:42][C][sntp:045]:   Server 0: '0.pool.ntp.org'
[20:22:42][C][sntp:045]:   Server 1: '1.pool.ntp.org'
[20:22:42][C][sntp:045]:   Server 2: '2.pool.ntp.org'
[20:22:42][C][mdns:116]: mDNS:
[20:22:42][C][mdns:117]:   Hostname: greenhouse
[20:22:42][V][mdns:118]:   Services:
[20:22:42][V][mdns:120]:   - _esphomelib, _tcp, 6053
[20:22:42][V][mdns:122]:     TXT: version = 2024.12.4
[20:22:42][V][mdns:122]:     TXT: mac = 983daeeb24f4
[20:22:42][V][mdns:122]:     TXT: platform = ESP32
[20:22:42][V][mdns:122]:     TXT: board = adafruit_feather_esp32s3
[20:22:42][V][mdns:122]:     TXT: network = wifi
[20:22:42][V][mdns:122]:     TXT: api_encryption = Noise_NNpsk0_25519_ChaChaPoly_SHA256
[20:22:42][V][mdns:120]:   - _http, _tcp, 80
[20:22:42][C][esphome.ota:073]: Over-The-Air updates:
[20:22:42][C][esphome.ota:074]:   Address: 192.168.1.97:3232
[20:22:42][C][esphome.ota:075]:   Version: 2
[20:22:42][C][safe_mode:018]: Safe Mode:
[20:22:42][C][safe_mode:020]:   Boot considered successful after 60 seconds
[20:22:42][C][safe_mode:021]:   Invoke after 10 boot attempts
[20:22:42][C][safe_mode:023]:   Remain in safe mode for 300 seconds
[20:22:42][C][api:140]: API Server:
[20:22:42][C][api:141]:   Address: 192.168.1.97:6053
[20:22:42][C][api:143]:   Using noise encryption: YES
[20:22:42][D][api:103]: Accepted 192.168.1.98
[20:22:42][C][wifi_signal.sensor:010]: WiFi Signal 'greenhouse Wifi signal'
[20:22:42][C][wifi_signal.sensor:010]:   Device Class: 'signal_strength'
[20:22:42][C][wifi_signal.sensor:010]:   State Class: 'measurement'
[20:22:42][C][wifi_signal.sensor:010]:   Unit of Measurement: 'dBm'
[20:22:42][C][wifi_signal.sensor:010]:   Accuracy Decimals: 0
[20:22:42][V][wifi_signal.sensor:010]:   Unique ID: '983daeeb24f4-wifisignal'
[20:22:42][V][api.connection:1428]: Hello from client: 'Home Assistant 2025.1.3' | 192.168.1.98 | API Version 1.10
[20:22:42][C][wifi_info:012]: WifiInfo SSID 'greenhouse Wifi connected to SSID'
[20:22:42][V][wifi_info:012]:   Unique ID: '983daeeb24f4-wifiinfo-ssid'
[20:22:42][D][api.connection:1446]: Home Assistant 2025.1.3 (192.168.1.98): Connected successfully
[20:22:42][C][wifi_info:010]: WifiInfo IPAddress 'greenhouse Wifi IP Address'
[20:22:42][V][wifi_info:010]:   Unique ID: '983daeeb24f4-wifiinfo-ip'
[20:23:38][I][safe_mode:041]: Boot seems successful; resetting boot loop counter
[20:23:38][D][esp32.preferences:114]: Saving 3 preferences to flash...
[20:23:38][V][esp32.preferences:126]: sync: key: 233825507, len: 4
[20:23:38][V][esp32.preferences:163]: nvs_get_blob('3978338398'): ESP_ERR_NVS_NOT_FOUND - the key might not be set yet
[20:23:38][V][esp32.preferences:126]: sync: key: 3978338398, len: 7
[20:23:38][V][esp32.preferences:137]: NVS data not changed skipping 2523860430  len=1
[20:23:38][D][esp32.preferences:143]: Saving 3 preferences to flash: 1 cached, 2 written, 0 failed
[20:23:52][V][json:038][async_tcp]: Attempting to allocate 512 bytes for JSON serialization
[20:23:52][V][json:058][async_tcp]: Size after shrink 92 bytes
[20:23:52][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:23:52][V][json:058]: Size after shrink 236 bytes
[20:23:53][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:23:53][V][json:058]: Size after shrink 156 bytes
[20:23:53][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:23:53][V][json:058]: Size after shrink 164 bytes
[20:23:53][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:23:53][V][json:058]: Size after shrink 164 bytes

At this point the LED is blue, and there is a pause in the log.
I then noticed that the [View] page’s log shows some different messages … though I assume the entries at 20:22 are before the new firmware booted.

Time	level	Tag	Message
20:22:37	[I]	[app:132]	Rebooting safely...
20:22:37	[D]	[esp32.preferences:114]	Saving 1 preferences to flash...
20:22:37	[V]	[esp32.preferences:137]	NVS data not changed skipping 233825507  len=4
20:22:37	[D]	[esp32.preferences:143]	Saving 1 preferences to flash: 1 cached, 0 written, 0 failed
20:22:37	[D]	[main:988]	#### Turning off peripheral power...
20:22:37	[D]	[light:036]	'greenhouse RGB LED' Setting:
20:22:37	[D]	[light:047]	  State: OFF
20:22:37	[D]	[light:085]	  Transition length: 1.0s
20:22:37	[V]	[json:038]	Attempting to allocate 512 bytes for JSON serialization
20:22:37	[V]	[json:058]	Size after shrink 176 bytes
20:22:37	[D]	[main:974]	##### on_shutdown started
20:22:37	[D]	[light:036]	'greenhouse RGB LED' Setting:
20:22:37	[D]	[light:047]	  State: ON
20:22:37	[D]	[light:051]	  Brightness: 20%
20:22:37	[D]	[light:059]	  Red: 100%, Green: 0%, Blue: 0%
20:22:37	[D]	[light:085]	  Transition length: 1.0s
20:22:37	[V]	[json:038]	Attempting to allocate 512 bytes for JSON serialization
20:22:37	[V]	[json:058]	Size after shrink 176 bytes
20:23:52	[V]	[json:038]e[1;31m[async_tcp]e[0;37m	Attempting to allocate 512 bytes for JSON serialization
20:23:52	[V]	[json:058]e[1;31m[async_tcp]e[0;37m	Size after shrink 92 bytes

at 20:32 both logs resumed

[20:32:51][D][dht:048]: Got Temperature=29.6°C Humidity=59.1%
[20:32:51][V][sensor:043]: 'greenhouse DHT22 Temperature': Received new state 29.600000
[20:32:51][D][sensor:094]: 'greenhouse DHT22 Temperature': Sending state 29.60000 °C with 1 decimals of accuracy
[20:32:51][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:32:51][V][json:058]: Size after shrink 96 bytes
[20:32:51][V][sensor:043]: 'greenhouse DHT22 Humidity': Received new state 59.100002
[20:32:51][D][sensor:094]: 'greenhouse DHT22 Humidity': Sending state 59.10000 % with 0 decimals of accuracy
[20:32:51][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:32:51][V][json:058]: Size after shrink 88 bytes
[20:32:51][W][component:237]: Component dht.sensor took a long time for an operation (98 ms).
[20:32:51][W][component:238]: Components should block for at most 30 ms.

[20:34:18][V][sensor:043]: 'MAX17048 Battery Voltage': Received new state 3.892500
[20:34:18][D][sensor:094]: 'MAX17048 Battery Voltage': Sending state 3.89250 V with 3 decimals of accuracy
[20:34:18][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:34:18][V][json:058]: Size after shrink 88 bytes
[20:34:18][V][sensor:043]: 'Max17048 Battery level': Received new state 66.000000
[20:34:18][D][sensor:094]: 'Max17048 Battery level': Sending state 66.00000 % with 3 decimals of accuracy
[20:34:18][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:34:18][V][json:058]: Size after shrink 88 bytes
[20:34:18][W][component:237]: Component max17043.sensor took a long time for an operation (96 ms).
[20:34:18][W][component:238]: Components should block for at most 30 ms.
[20:34:19][V][bh1750.sensor:151]: L result: 7.419355 -> Calculated mode=2, mtreg=254
[20:34:19][D][bh1750.sensor:159]: 'greenhouse BH1750 Illuminance': Got illuminance=6.5lx
[20:34:19][V][sensor:043]: 'greenhouse BH1750 Illuminance': Received new state 6.451771
[20:34:19][D][sensor:094]: 'greenhouse BH1750 Illuminance': Sending state 6.45177 lx with 1 decimals of accuracy
[20:34:19][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[20:34:19][V][json:058]: Size after shrink 92 bytes
[20:34:19][W][component:237]: Component bh1750.sensor took a long time for an operation (56 ms).
[20:34:19][W][component:238]: Components should block for at most 30 ms.
2

I noticed that out of a 30 minute update_interval, the updates took 13 minutes (back with all the sensors before trimming the code), then nothing happened for 17 minutes. It seemed sensible to try deep sleep with 15 minute run_duration and 30 minute sleep_duration.

Assuming that ESPHome is spacing out the updates to fill the time available, could I get ESPHome to hurry its processing by giving 10 or even 5 minutes for the run_duration ? And this is where the log messages disappeared, though the “Attempting to allocate 512 bytes for JSON serialisation” messages suggest that maybe the data is being sent to HA.

And what is the relationship with update_interval ? I only want one update performed each wake period, so should update_interval be set the same as sleep_duration ?

Un-commenting the deep_sleep: section

deep_sleep: 
  id: deep_sleep_1
  run_duration:   "10 min"                    # how long to run (be awake)
  sleep_duration: $update_interval_sensor     # how long to sleep for

and adding to esphome: block

  on_shutdown:        #Includes deep sleep
    - priority: 900   # before everything else
      then:
        - logger.log: "##### on_shutdown started" 
# for testing, set the LED blue during shutdown
        - light.turn_on:
            id: rgb_led
            red: 100%
            blue: 0%
            green: 0%
            brightness: 20%
    - priority: -100    # after everything else
      then:
        - logger.log: "#### Turning off peripheral power..."
        - light.turn_off:
            id: rgb_led
        - delay: 5s
        - logger.log: "##### on_shutdown finished"

results in

Compiling .pioenvs/greenhouse/src/main.cpp.o
Linking .pioenvs/greenhouse/firmware.elf
RAM:   [==        ]  15.2% (used 49752 bytes from 327680 bytes)
Flash: [=======   ]  71.6% (used 1032417 bytes from 1441792 bytes)
Building .pioenvs/greenhouse/firmware.bin
Creating esp32s3 image...
Successfully created esp32s3 image.
esp32_create_combined_bin([".pioenvs/greenhouse/firmware.bin"], [".pioenvs/greenhouse/firmware.elf"])
Wrote 0x10c290 bytes to file /data/build/greenhouse/.pioenvs/greenhouse/firmware.factory.bin, ready to flash to offset 0x0
esp32_copy_ota_bin([".pioenvs/greenhouse/firmware.bin"], [".pioenvs/greenhouse/firmware.elf"])
========================= [SUCCESS] Took 34.90 seconds =========================
INFO Successfully compiled program.
INFO Connecting to 192.168.1.97 port 3232...
INFO Connected to 192.168.1.97
INFO Uploading /data/build/greenhouse/.pioenvs/greenhouse/firmware.bin (1032848 bytes)
Uploading: [============================================================] 100% Done...

INFO Upload took 11.55 seconds, waiting for result...
INFO OTA successful
INFO Successfully uploaded program.
INFO Starting log output from 192.168.1.97 using esphome API
INFO Successfully connected to greenhouse @ 192.168.1.97 in 3.122s
INFO Successful handshake with greenhouse @ 192.168.1.97 in 0.114s
[21:13:38][I][app:100]: ESPHome version 2024.12.4 compiled on Feb  2 2025, 21:13:11
[21:13:38][C][wifi:600]: WiFi:
[21:13:38][C][wifi:428]:   Local MAC: 98:3D:AE:EB:24:F4
[21:13:38][C][wifi:433]:   SSID: [redacted]
[21:13:38][C][wifi:436]:   IP Address: 192.168.1.97
[21:13:38][C][wifi:440]:   BSSID: [redacted]
[21:13:38][C][wifi:441]:   Hostname: 'greenhouse'
[21:13:38][C][wifi:443]:   Signal strength: -72 dB ▂▄▆█
[21:13:38][C][wifi:447]:   Channel: 13
[21:13:38][C][wifi:448]:   Subnet: 255.255.255.0
[21:13:38][C][wifi:449]:   Gateway: 192.168.1.1
[21:13:38][C][wifi:450]:   DNS1: 0.0.0.0
[21:13:38][C][wifi:451]:   DNS2: 0.0.0.0
[21:13:38][C][logger:185]: Logger:
[21:13:38][C][logger:186]:   Level: VERBOSE
[21:13:38][C][logger:188]:   Log Baud Rate: 115200
[21:13:38][C][logger:189]:   Hardware UART: USB_CDC
[21:13:38][C][i2c.arduino:071]: I2C Bus:
[21:13:38][C][i2c.arduino:072]:   SDA Pin: GPIO1
[21:13:38][C][i2c.arduino:073]:   SCL Pin: GPIO2
[21:13:38][C][i2c.arduino:074]:   Frequency: 400000 Hz
[21:13:38][C][i2c.arduino:086]:   Recovery: bus successfully recovered
[21:13:38][I][i2c.arduino:096]: Results from i2c bus scan:
[21:13:38][I][i2c.arduino:102]: Found i2c device at address 0x23
[21:13:38][I][i2c.arduino:102]: Found i2c device at address 0x36
[21:13:38][I][i2c.arduino:102]: Found i2c device at address 0x40
[21:13:38][I][i2c.arduino:102]: Found i2c device at address 0x45
[21:13:38][I][i2c.arduino:102]: Found i2c device at address 0x48
[21:13:38][C][template.text_sensor:020]: Template Sensor 'greenhouse Uptime Human Readable'
[21:13:38][C][template.text_sensor:020]:   Icon: 'mdi:clock-start'
[21:13:38][C][esp32_rmt_led_strip:187]: ESP32 RMT LED Strip:
[21:13:38][C][esp32_rmt_led_strip:188]:   Pin: 48
[21:13:38][C][esp32_rmt_led_strip:189]:   Channel: 0
[21:13:38][C][esp32_rmt_led_strip:214]:   RGB Order: GRB
[21:13:38][C][esp32_rmt_led_strip:215]:   Max refresh rate: 0
[21:13:38][C][esp32_rmt_led_strip:216]:   Number of LEDs: 1
[21:13:38][C][switch.gpio:068]: GPIO Switch 'greenhouse Solar Power relay'
[21:13:38][C][switch.gpio:091]:   Restore Mode: always ON
[21:13:38][C][switch.gpio:031]:   Pin: GPIO9
[21:13:38][C][switch.gpio:068]: GPIO Switch 'greenhouse peripheral power'
[21:13:38][C][switch.gpio:091]:   Restore Mode: always ON
[21:13:38][C][switch.gpio:031]:   Pin: GPIO47
[21:13:38][C][uptime.sensor:033]: Uptime Sensor 'greenhouse Uptime'
[21:13:38][C][uptime.sensor:033]:   Device Class: 'duration'
[21:13:38][C][uptime.sensor:033]:   State Class: 'total_increasing'
[21:13:38][C][uptime.sensor:033]:   Unit of Measurement: 's'
[21:13:38][C][uptime.sensor:033]:   Accuracy Decimals: 0
[21:13:38][C][uptime.sensor:033]:   Icon: 'mdi:timer-outline'
[21:13:38][V][uptime.sensor:033]:   Unique ID: '983daeeb24f4-uptime'
[21:13:38][C][uptime.sensor:034]:   Type: Seconds
[21:13:38][C][light:092]: Light 'greenhouse RGB LED'
[21:13:38][C][light:094]:   Default Transition Length: 1.0s
[21:13:38][C][light:095]:   Gamma Correct: 2.80
[21:13:38][C][dht:017]: DHT:
[21:13:38][C][dht:018]:   Pin: GPIO5
[21:13:38][C][dht:024]:   Model: DHT22 (or equivalent)
[21:13:38][C][dht:027]:   Update Interval: 900.0s
[21:13:38][C][dht:029]:   Temperature 'greenhouse DHT22 Temperature'
[21:13:38][C][dht:029]:     Device Class: 'temperature'
[21:13:38][C][dht:029]:     State Class: 'measurement'
[21:13:38][C][dht:029]:     Unit of Measurement: '°C'
[21:13:38][C][dht:029]:     Accuracy Decimals: 1
[21:13:38][C][dht:030]:   Humidity 'greenhouse DHT22 Humidity'
[21:13:38][C][dht:030]:     Device Class: 'humidity'
[21:13:38][C][dht:030]:     State Class: 'measurement'
[21:13:38][C][dht:030]:     Unit of Measurement: '%'
[21:13:38][C][dht:030]:     Accuracy Decimals: 0
[21:13:38][C][bh1750.sensor:118]: BH1750 'greenhouse BH1750 Illuminance'
[21:13:38][C][bh1750.sensor:118]:   Device Class: 'illuminance'
[21:13:38][C][bh1750.sensor:118]:   State Class: 'measurement'
[21:13:38][C][bh1750.sensor:118]:   Unit of Measurement: 'lx'
[21:13:38][C][bh1750.sensor:118]:   Accuracy Decimals: 1
[21:13:38][C][bh1750.sensor:119]:   Address: 0x23
[21:13:38][C][bh1750.sensor:124]:   Update Interval: 900.0s
[21:13:38][C][max17043:076]: MAX17043:
[21:13:38][C][max17043:077]:   Address: 0x36
[21:13:38][C][max17043:081]:   Update Interval: 900.0s
[21:13:38][C][max17043:082]:   Battery Voltage 'MAX17048 Battery Voltage'
[21:13:38][C][max17043:082]:     Device Class: 'voltage'
[21:13:38][C][max17043:082]:     State Class: 'measurement'
[21:13:38][C][max17043:082]:     Unit of Measurement: 'V'
[21:13:38][C][max17043:082]:     Accuracy Decimals: 3
[21:13:38][C][max17043:083]:   Battery Level 'Max17048 Battery level'
[21:13:38][C][max17043:083]:     Device Class: 'battery'
[21:13:38][C][max17043:083]:     State Class: 'measurement'
[21:13:38][C][max17043:083]:     Unit of Measurement: '%'
[21:13:38][C][max17043:083]:     Accuracy Decimals: 3
[21:13:39][C][version.text_sensor:021]: Version Text Sensor 'greenhouse ESPHome Version'
[21:13:39][C][version.text_sensor:021]:   Icon: 'mdi:new-box'
[21:13:39][V][version.text_sensor:021]:   Unique ID: '983daeeb24f4-version'
[21:13:39][C][wifi_info:014]: WifiInfo Mac Address 'greenhouse Wifi MAC Address'
[21:13:39][V][wifi_info:014]:   Unique ID: '983daeeb24f4-wifiinfo-macadr'
[21:13:39][C][psram:020]: PSRAM:
[21:13:39][C][psram:021]:   Available: NO
[21:13:39][C][captive_portal:089]: Captive Portal:
[21:13:39][C][web_server:153]: Web Server:
[21:13:39][C][web_server:154]:   Address: 192.168.1.97:80
[21:13:39][C][sntp:042]: SNTP Time:
[21:13:39][C][sntp:045]:   Server 0: '0.pool.ntp.org'
[21:13:39][C][sntp:045]:   Server 1: '1.pool.ntp.org'
[21:13:39][C][api:140]: API Server:
[21:13:39][C][wifi_info:010]: WifiInfo IPAddress 'greenhouse Wifi IP Address'
[21:13:39][V][wifi_info:010]:   Unique ID: '983daeeb24f4-wifiinfo-ip'
[21:13:39][C][deep_sleep:026]: Setting up Deep Sleep...
[21:13:39][C][deep_sleep:029]:   Sleep Duration: 900000 ms
[21:13:39][C][deep_sleep:032]:   Run Duration: 600000 ms
[21:13:39][D][api:103]: Accepted 192.168.1.98
[21:13:39][D][api:103]: Accepted 192.168.1.98
[21:13:39][W][component:237]: Component api took a long time for an operation (106 ms).
[21:13:39][W][component:238]: Components should block for at most 30 ms.
[21:13:39][V][api.connection:1428]: Hello from client: 'ESPHome Logs 2024.12.4' | 192.168.1.98 | API Version 1.10
[21:13:39][D][api.connection:1446]: ESPHome Logs 2024.12.4 (192.168.1.98): Connected successfully
[21:13:40][V][api.connection:1428]: Hello from client: 'Home Assistant 2025.1.3' | 192.168.1.98 | API Version 1.10
[21:13:40][D][api.connection:1446]: Home Assistant 2025.1.3 (192.168.1.98): Connected successfully
[21:14:34][I][safe_mode:041]: Boot seems successful; resetting boot loop counter
[21:14:34][D][esp32.preferences:114]: Saving 3 preferences to flash...
[21:14:34][V][esp32.preferences:126]: sync: key: 233825507, len: 4
[21:14:34][V][esp32.preferences:163]: nvs_get_blob('746206550'): ESP_ERR_NVS_NOT_FOUND - the key might not be set yet
[21:14:34][V][esp32.preferences:126]: sync: key: 746206550, len: 7
[21:14:34][V][esp32.preferences:137]: NVS data not changed skipping 2523860430  len=1
[21:14:34][D][esp32.preferences:143]: Saving 3 preferences to flash: 1 cached, 2 written, 0 failed
[21:14:34][W][component:237]: Component safe_mode took a long time for an operation (77 ms).
[21:14:34][W][component:238]: Components should block for at most 30 ms.
[21:14:49][V][json:038][async_tcp]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058][async_tcp]: Size after shrink 92 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 236 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 156 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 164 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 164 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 156 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 160 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 156 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 156 bytes
[21:14:49][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:49][V][json:058]: Size after shrink 152 bytes
[21:14:50][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:50][V][json:058]: Size after shrink 148 bytes
[21:14:50][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:50][V][json:058]: Size after shrink 180 bytes
[21:14:50][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:50][V][json:058]: Size after shrink 152 bytes
[21:14:50][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:50][V][json:058]: Size after shrink 156 bytes
[21:14:50][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:50][V][json:058]: Size after shrink 152 bytes
[21:14:50][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:14:50][V][json:058]: Size after shrink 160 bytes
[21:23:15][D][dht:048]: Got Temperature=29.9°C Humidity=56.9%
[21:23:15][V][sensor:043]: 'greenhouse DHT22 Temperature': Received new state 29.900000
[21:23:15][D][sensor:094]: 'greenhouse DHT22 Temperature': Sending state 29.90000 °C with 1 decimals of accuracy
[21:23:15][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:23:15][V][json:058]: Size after shrink 96 bytes
[21:23:15][V][sensor:043]: 'greenhouse DHT22 Humidity': Received new state 56.900002
[21:23:15][D][sensor:094]: 'greenhouse DHT22 Humidity': Sending state 56.90000 % with 0 decimals of accuracy
[21:23:15][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:23:15][V][json:058]: Size after shrink 88 bytes
[21:23:15][W][component:237]: Component dht.sensor took a long time for an operation (144 ms).
[21:23:15][W][component:238]: Components should block for at most 30 ms.
[21:23:37][I][deep_sleep:060]: Beginning Deep Sleep
[21:23:37][I][deep_sleep:062]: Sleeping for 900000000us
[21:23:37][D][esp32.preferences:114]: Saving 1 preferences to flash...
[21:23:37][V][esp32.preferences:137]: NVS data not changed skipping 233825507  len=4
[21:23:37][D][esp32.preferences:143]: Saving 1 preferences to flash: 1 cached, 0 written, 0 failed
[21:23:37][D][main:867]: #### Turning off peripheral power...
[21:23:37][D][light:036]: 'greenhouse RGB LED' Setting:
[21:23:37][D][light:047]:   State: OFF
[21:23:37][D][light:085]:   Transition length: 1.0s
[21:23:37][V][json:038]: Attempting to allocate 512 bytes for JSON serialization
[21:23:38][V][json:058]: Size after shrink 156 bytes
INFO Processing expected disconnect from ESPHome API for greenhouse @ 192.168.1.97
WARNING Disconnected from API
WARNING Can't connect to ESPHome API for greenhouse @ 192.168.1.97: Error connecting to [AddrInfo(family=<AddressFamily.AF_INET: 2>, type=<SocketKind.SOCK_STREAM: 1>, proto=6, sockaddr=IPv4Sockaddr(address='192.168.1.97', port=6053))]: [Errno 113] Connect call failed ('192.168.1.97', 6053) (SocketAPIError)
INFO Trying to connect to greenhouse @ 192.168.1.97 in the background
INFO Successfully connected to greenhouse @ 192.168.1.97 in 0.017s
INFO Successful handshake with greenhouse @ 192.168.1.97 in 0.167s
[21:39:20][I][safe_mode:041]: Boot seems successful; resetting boot loop counter
[21:39:20][D][esp32.preferences:114]: Saving 2 preferences to flash...
[21:39:20][V][esp32.preferences:126]: sync: key: 233825507, len: 4
[21:39:20][V][esp32.preferences:137]: NVS data not changed skipping 2523860430  len=1
[21:39:20][D][esp32.preferences:143]: Saving 2 preferences to flash: 1 cached, 1 written, 0 failed
[21:39:20][W][component:237]: Component safe_mode took a long time for an operation (111 ms).
[21:39:20][W][component:238]: Components should block for at most 30 ms.
[21:41:36][W][api.connection:105]: ESPHome Logs 2024.12.4 (192.168.1.98): Connection closed
[21:41:36][V][api:116]: Removing connection to ESPHome Logs 2024.12.4
[21:45:40][D][light:036]: 'greenhouse RGB LED' Setting:
[21:45:40][D][light:047]:   State: OFF
[21:45:40][D][light:085]:   Transition length: 1.0s
[21:45:55][D][switch:016]: 'greenhouse Solar Power relay' Turning OFF.
[21:45:55][D][switch:055]: 'greenhouse Solar Power relay': Sending state OFF
[21:46:45][V][bh1750.sensor:151]: L result: 7.419355 -> Calculated mode=2, mtreg=254
[21:46:46][D][bh1750.sensor:159]: 'greenhouse BH1750 Illuminance': Got illuminance=6.8lx
[21:46:46][V][sensor:043]: 'greenhouse BH1750 Illuminance': Received new state 6.791338
[21:46:46][D][sensor:094]: 'greenhouse BH1750 Illuminance': Sending state 6.79134 lx with 1 decimals of accuracy
[21:47:10][D][dht:048]: Got Temperature=30.3°C Humidity=56.0%
[21:47:10][V][sensor:043]: 'greenhouse DHT22 Temperature': Received new state 30.300001
[21:47:10][D][sensor:094]: 'greenhouse DHT22 Temperature': Sending state 30.30000 °C with 1 decimals of accuracy
[21:47:10][V][sensor:043]: 'greenhouse DHT22 Humidity': Received new state 56.000000
[21:47:10][D][sensor:094]: 'greenhouse DHT22 Humidity': Sending state 56.00000 % with 0 decimals of accuracy
[21:48:21][I][deep_sleep:060]: Beginning Deep Sleep
[21:48:21][I][deep_sleep:062]: Sleeping for 900000000us
[21:48:21][D][esp32.preferences:114]: Saving 1 preferences to flash...
[21:48:21][V][esp32.preferences:137]: NVS data not changed skipping 233825507  len=4
[21:48:21][D][esp32.preferences:143]: Saving 1 preferences to flash: 1 cached, 0 written, 0 failed
[21:48:21][D][main:867]: #### Turning off peripheral power...
[21:48:21][D][light:036]: 'greenhouse RGB LED' Setting:
[21:48:21][D][light:085]:   Transition length: 1.0s
INFO Processing expected disconnect from ESPHome API for greenhouse @ 192.168.1.97
WARNING Disconnected from API
WARNING Can't connect to ESPHome API for greenhouse @ 192.168.1.97: Error connecting to [AddrInfo(family=<AddressFamily.AF_INET: 2>, type=<SocketKind.SOCK_STREAM: 1>, proto=6, sockaddr=IPv4Sockaddr(address='192.168.1.97', port=6053))]: [Errno 113] Connect call failed ('192.168.1.97', 6053) (SocketAPIError)
INFO Trying to connect to greenhouse @ 192.168.1.97 in the background

At 21:37 i noticed the ESP32 board’s leds flicker for reboot, but nothing in the log for over a minute.

Note the gap from 21:14 to 21:23, and on my Home Assistant page it looks as though the DHT22 was the only value which was updated.

I will leave this running overnight and see if it reduces the battery consumption.

3

Did you try esp-idf? I believe it’s recommended for your board.

4

Good news is that yes, the battery consumption overnight does seem lower despite the boards LED being left on by the on_shutdown automation.

And in 26 awake periods overnight, 6 showed no sensors were reported to HA, and only twice were all 3 reported. In trying to make sense of it I have logged the relevant times:

image
image545×510 29.3 KB

I note that:

  1. in all cases there is a noticable delay after waking before any sensor is reported.
  2. The DHT22 sensor is wired directly to the ESP32’s GPIO pin, whereas both other sensors are connected via i2c

I am most concerned that all sensors use the same update_interval, yet they appear to be updated at random.

Thanks @Mahko_Mahko I have changed the platform and will test some more.

5

Try getting rid of this and set up a static ip address using manual_ip:. Also set fast_connect: true.

6

Not sure why you would assume that my _common_wifi.yaml doesn’t include these – it does. Or are you saying that !include or packages: is not compatible with deep sleep ?

In fact that include did generate errors - but it was the lambda function code (to display uptime in human readable format) not compatible with the esp-idf platform.

7

I assumed (since you named the file “my_common_wifi” that this meant they were settings common to all your devices, which would preclude you including a manual IP address…

I see however you have a device_ip: substitution, which now makes sense :smiley: