ESPHome log window intermittent weirdness

Happy to report a PR, but before I do I thought Id check w/ the community first.

Not sure when it started but the log file window in ESPhome now only updates every 45 seconds on average versus what it used to show was in real-time events as they rolled in. Normally, this would just be an annoyance, but for sensors that only update every minute or so they do not show anything in the log. In other words there has to be a full 45 seconds of log activity before anything is shown in the log. So for a once a minute sensor, there would need to be 45 entries before you see it.

The log connection initiates immediately with the ESP home API but the above is illustrative of what happenswith the log. From what I can tell it happens over the air and also via the USB connection.

Is anyone else experiencing this issue? It seems to be fairly recent as it worked normally approximately about a month or so ago when I was developing new air sensor.

My environment:
Home Assistant 0.117.5
supervisor 2020.11.0
installation_type Home Assistant Supervised
esphome-1.15.0.dev0 AND 1.16.0-dev

I have 4 various ESPs (8266, Node MCU, D1 mini PRO) and same issue on all.

**Its happening on all of these platforms which use esphome-1.15.0.dev0 or 1.16.0-dev
standalone Raspberry Pi4 Raspbian
RPi w/ Ubuntu 20.4
standalone Intel NUC w/ Ubuntu 20.4

Given this, I dont think this is related to Home Assistant in any way.**

I get this up on connection at xx:00:00:

INFO Reading configuration /config/esphome/sensornode_airquality.yaml...
INFO Starting log output from 192.168.1.215 using esphome API
INFO Connecting to 192.168.1.215:6053 (192.168.1.215)
INFO Successfully connected to 192.168.1.215

Then nothing for 24 seconds, then:

[06:24:02][I][app:105]: ESPHome version 1.16.0-dev compiled on Oct 28 2020, 12:55:37
[06:24:02][C][wifi:443]: WiFi:
[06:24:02][C][wifi:303]:   SSID: 'HOPI'[redacted]
[06:24:02][C][wifi:304]:   IP Address: 192.168.1.215
[06:24:02][C][wifi:306]:   BSSID: E2:63:DA:15:93:89[redacted]
[06:24:02][C][wifi:307]:   Hostname: 'sensornode_airquality'
[06:24:02][C][wifi:311]:   Signal strength: -65 dB ▂▄▆█
[06:24:02][C][wifi:315]:   Channel: 1
[06:24:02][C][wifi:316]:   Subnet: 255.255.255.0
[06:24:02][C][wifi:317]:   Gateway: 192.168.1.2
[06:24:02][C][wifi:318]:   DNS1: (IP unset)
[06:24:02][C][wifi:319]:   DNS2: (IP unset)
[06:24:02][C][i2c:028]: I2C Bus:
[06:24:02][C][i2c:029]:   SDA Pin: GPIO4
[06:24:02][C][i2c:030]:   SCL Pin: GPIO5
[06:24:02][C][i2c:031]:   Frequency: 50000 Hz
[06:24:02][I][i2c:033]: Scanning i2c bus for active devices...
[06:24:02][I][i2c:040]: Found i2c device at address 0x76
[06:24:02][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 5 µg/m^3
[06:24:02][D][sensor:092]: 'sensornode_airquality_pm_2_5': Sending state 3.28889 µg/m³ with 0 decimals of accuracy
[06:24:02][C][uart_esp8266:075]: UART Bus:
[06:24:02][C][uart_esp8266:077]:   TX Pin: GPIO1
[06:24:02][C][uart_esp8266:080]:   RX Pin: GPIO3
[06:24:02][C][uart_esp8266:081]:   RX Buffer Size: 256
[06:24:02][C][uart_esp8266:083]:   Baud Rate: 9600 baud
[06:24:02][C][uart_esp8266:084]:   Data Bits: 8
[06:24:02][C][uart_esp8266:085]:   Parity: NONE
[06:24:02][C][uart_esp8266:086]:   Stop bits: 1
[06:24:02][C][uart_esp8266:088]:   Using hardware serial interface.
[06:24:02][C][esp8266_pwm:022]: ESP8266 PWM:
[06:24:02][C][esp8266_pwm:023]:   Pin: GPIO14 (Mode: OUTPUT)
[06:24:02][C][esp8266_pwm:024]:   Frequency: 1000.0 Hz
[06:24:02][C][esp8266_pwm:022]: ESP8266 PWM:
[06:24:02][C][esp8266_pwm:023]:   Pin: GPIO12 (Mode: OUTPUT)
[06:24:02][C][esp8266_pwm:024]:   Frequency: 1000.0 Hz
[06:24:02][C][esp8266_pwm:022]: ESP8266 PWM:
[06:24:02][C][esp8266_pwm:023]:   Pin: GPIO13 (Mode: OUTPUT)
[06:24:02][C][esp8266_pwm:024]:   Frequency: 1000.0 Hz
[06:24:02][C][logger:185]: Logger:
[06:24:02][C][logger:186]:   Level: DEBUG
[06:24:02][C][logger:187]:   Log Baud Rate: 0
[06:24:02][C][logger:188]:   Hardware UART: UART0
[06:24:02][C][light:178]: Light 'sensornode_airquality_led'
[06:24:02][C][light:180]:   Default Transition Length: 1.0s
[06:24:02][C][light:181]:   Gamma Correct: 2.80
[06:24:02][C][bme280.sensor:142]: BME280:
[06:24:02][C][bme280.sensor:143]:   Address: 0x76
[06:24:02][C][bme280.sensor:155]:   IIR Filter: OFF
[06:24:02][C][bme280.sensor:156]:   Update Interval: 15.0s
[06:24:02][C][bme280.sensor:158]:   Temperature 'sensornode_airquality_temp'
[06:24:02][C][bme280.sensor:158]:     Unit of Measurement: '°C'
[06:24:02][C][bme280.sensor:158]:     Accuracy Decimals: 1
[06:24:02][C][bme280.sensor:158]:     Icon: 'mdi:thermometer'
[06:24:02][C][bme280.sensor:159]:     Oversampling: 16x
[06:24:02][C][bme280.sensor:160]:   Pressure 'sensornode_airquality_pressure'
[06:24:02][C][bme280.sensor:160]:     Unit of Measurement: 'hPa'
[06:24:02][C][bme280.sensor:160]:     Accuracy Decimals: 1
[06:24:02][C][bme280.sensor:160]:     Icon: 'mdi:gauge'
[06:24:02][C][bme280.sensor:161]:     Oversampling: 16x
[06:24:02][C][bme280.sensor:162]:   Humidity 'sensornode_airquality_humidity'
[06:24:02][C][bme280.sensor:162]:     Unit of Measurement: '%'
[06:24:02][C][bme280.sensor:162]:     Accuracy Decimals: 1
[06:24:02][C][bme280.sensor:162]:     Icon: 'mdi:water-percent'
[06:24:02][C][bme280.sensor:163]:     Oversampling: 16x
[06:24:02][C][pmsx003:165]: PMSX003:
[06:24:02][C][pmsx003:166]:   PM1.0 'sensornode_airquality_pm_1_0'
[06:24:02][C][pmsx003:166]:     Unit of Measurement: 'µg/m³'
[06:24:02][C][pmsx003:166]:     Accuracy Decimals: 0
[06:24:02][C][pmsx003:166]:     Icon: 'mdi:chemical-weapon'
[06:24:02][C][pmsx003:167]:   PM2.5 'sensornode_airquality_pm_2_5'
[06:24:02][C][pmsx003:167]:     Unit of Measurement: 'µg/m³'
[06:24:02][C][pmsx003:167]:     Accuracy Decimals: 0
[06:24:02][C][pmsx003:167]:     Icon: 'mdi:chemical-weapon'
[06:24:02][C][pmsx003:168]:   PM10.0 'sensornode_airquality_pm_10_0'
[06:24:02][C][pmsx003:168]:     Unit of Measurement: 'µg/m³'
[06:24:02][C][pmsx003:168]:     Accuracy Decimals: 0
[06:24:02][C][pmsx003:168]:     Icon: 'mdi:chemical-weapon'
[06:24:02][C][captive_portal:169]: Captive Portal:
[06:24:02][C][ota:029]: Over-The-Air Updates:
[06:24:02][C][ota:030]:   Address: 192.168.1.215:8266
[06:24:02][C][api:095]: API Server:
[06:24:02][C][api:096]:   Address: 192.168.1.215:6053
[06:24:03][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 5 µg/m^3
[06:24:03][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 5 µg/m^3
[06:24:04][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:05][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:06][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:07][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:08][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:09][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:10][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:10][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:11][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:12][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 5 µg/m^3, PM10.0 Concentration: 5 µg/m^3
[06:24:13][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 5 µg/m^3, PM10.0 Concentration: 5 µg/m^3
[06:24:14][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 5 µg/m^3, PM10.0 Concentration: 5 µg/m^3

last timestamp is [06:24:14] then the next log dumps come every 40-45 seconds.

[06:24:15][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:16][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:16][D][bme280.sensor:197]: Got temperature=27.8°C pressure=1005.2hPa humidity=18.7%
[06:24:16][D][sensor:092]: 'sensornode_airquality_temp': Sending state 27.84000 °C with 1 decimals of accuracy
[06:24:16][D][sensor:092]: 'sensornode_airquality_pressure': Sending state 1005.22620 hPa with 1 decimals of accuracy
[06:24:16][D][sensor:092]: 'sensornode_airquality_humidity': Sending state 18.69434 % with 1 decimals of accuracy
[06:24:16][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:17][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 5 µg/m^3, PM10.0 Concentration: 5 µg/m^3
[06:24:18][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 5 µg/m^3, PM10.0 Concentration: 5 µg/m^3
[06:24:19][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 5 µg/m^3, PM10.0 Concentration: 5 µg/m^3
[06:24:20][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:21][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:22][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:22][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:23][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:24][D][pmsx003:111]: Got PM1.0 Concentration: 3 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:25][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:26][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:27][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:28][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:29][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:29][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:30][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:31][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:31][D][bme280.sensor:197]: Got temperature=27.8°C pressure=1005.2hPa humidity=18.7%
[06:24:31][D][sensor:092]: 'sensornode_airquality_temp': Sending state 27.84000 °C with 1 decimals of accuracy
[06:24:31][D][sensor:092]: 'sensornode_airquality_pressure': Sending state 1005.22467 hPa with 1 decimals of accuracy
[06:24:31][D][sensor:092]: 'sensornode_airquality_humidity': Sending state 18.70605 % with 1 decimals of accuracy
[06:24:32][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:33][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:34][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:35][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:35][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:36][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:37][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:38][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:39][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:40][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:41][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:41][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:42][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:43][D][pmsx003:111]: Got PM1.0 Concentration: 1 µg/m^3, PM2.5 Concentration 1 µg/m^3, PM10.0 Concentration: 1 µg/m^3
[06:24:44][D][pmsx003:111]: Got PM1.0 Concentration: 1 µg/m^3, PM2.5 Concentration 1 µg/m^3, PM10.0 Concentration: 1 µg/m^3
[06:24:45][D][pmsx003:111]: Got PM1.0 Concentration: 1 µg/m^3, PM2.5 Concentration 1 µg/m^3, PM10.0 Concentration: 1 µg/m^3
[06:24:46][D][pmsx003:111]: Got PM1.0 Concentration: 1 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:46][D][bme280.sensor:197]: Got temperature=27.8°C pressure=1005.2hPa humidity=18.7%
[06:24:46][D][sensor:092]: 'sensornode_airquality_temp': Sending state 27.83000 °C with 1 decimals of accuracy
[06:24:46][D][sensor:092]: 'sensornode_airquality_pressure': Sending state 1005.18744 hPa with 1 decimals of accuracy
[06:24:46][D][sensor:092]: 'sensornode_airquality_humidity': Sending state 18.70605 % with 1 decimals of accuracy
[06:24:47][D][pmsx003:111]: Got PM1.0 Concentration: 1 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:48][D][pmsx003:111]: Got PM1.0 Concentration: 1 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:48][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:49][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:50][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 2 µg/m^3, PM10.0 Concentration: 2 µg/m^3
[06:24:51][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:52][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:53][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 3 µg/m^3, PM10.0 Concentration: 3 µg/m^3
[06:24:54][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3
[06:24:54][D][pmsx003:111]: Got PM1.0 Concentration: 2 µg/m^3, PM2.5 Concentration 4 µg/m^3, PM10.0 Concentration: 4 µg/m^3

Ok, happy to report that this is a known BUG in the dev version, 1.16.0-dev

I installed [ESPHome 1.14.5 ] and the log works normally.

for those looking how to install a different version, heres the proper formatting in the config section. don’t forget the “v”:

esphome_version: v1.15.3