lubeda / EspHoMaTriXv2

A simple DIY status display with a 8x32 RGB LED matrix, implemented with esphome.io and Home Assistant.
MIT License
276 stars 25 forks source link

[BUG] LOG storm after deleted screen (empty queue) #152

Closed chertvl closed 10 months ago

chertvl commented 10 months ago

Bug report

Describe the bug

For example, I have only one clock screen with lifetime 1440, screentime 10. I called Alert Screen service with some parameters. After Alert is showed it must auto-deleted from queue, and after auto-delete screen I have very huge log storm with strange symbols for 3-4 seconds (many times per second). Somewhy my clock screen dissapears from queue and its empty now, on_empty_queue is trying to add a clock screen again but cant do it few seconds.

On Ulanzi display I see last frame of screen wich must be deleted, it freeze for 1-2 sec, then screen and logs both back to normal.

Additional information

Configuration

  on_start_running:
    then:
      lambda: |-
        id(rgb8x32)->icon_clock("blank|day#1", 1440, 10, true);
        id(rgb8x32)->set_infotext_color(150, 150, 150, 150, 150, 150, true, 0); 
        id(rgb8x32)->set_weekday_color(150, 150, 150);

  on_empty_queue:
    then:
      lambda: |-
        id(rgb8x32)->icon_clock("blank|day#1", 1440, 10, true);

Logs

[20:01:12][D][EHMTXv2:790]: oldest queue element is: 0/1
[20:01:12][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:12][D][EHMTXv2:1018]: on_next_screen trigger

[20:01:22][D][EHMTXv2:790]: oldest queue element is: 0/1
[20:01:22][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:22][D][EHMTXv2:1018]: on_next_screen trigger

[20:01:32][D][EHMTXv2:790]: oldest queue element is: 0/1
[20:01:32][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:32][D][EHMTXv2:1018]: on_next_screen trigger

[20:01:34][D][EHMTXv2:465]: icon: spotify found id: 29
[20:01:34][D][EHMTXv2:1699]: free_screen: found by endtime 1
[20:01:34][D][EHMTXv2:1025]: calc_scroll_time: mode: 16 text: "Song name - Artist name" pixels 96 calculated: 3.8 defined: 1 max_steps: 120
[20:01:34][D][EHMTXv2:1251]: alert screen icon: 29 iconname: spotify text: Song name - Artist name screen_time: 1
[20:01:34][D][EHMTXv2:128]: queue: icon: "spotify" for: 3.8 sec
[20:01:34][D][EHMTXv2:750]: force_screen: found position: 1
[20:01:34][W][EHMTXv2:754]: force_screen: icon spotify in mode 16
[20:01:34][D][EHMTXv2:790]: oldest queue element is: 1/2
[20:01:34][D][EHMTXv2:128]: queue: icon: "spotify" for: 3.8 sec
[20:01:34][D][EHMTXv2:1018]: on_next_screen trigger
[20:01:38][D][EHMTXv2:851]: remove expired queue element: slot 1: mode: 16 icon_name: spotify text: Song name - Artist name

[20:01:38][D][EHMTXv2:092]: empty slot
[20:01:38][D][EHMTXv2:1028]: on_empty_queue trigger
[20:01:38][D][EHMTXv2:1725]: find screen: found by mode 0 icon l$\xfb?
[20:01:38][D][EHMTXv2:1387]: icon clock icon: 91 iconname: blank|day#1 lifetime: 1440 screen_time: 10
[20:01:38][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:38][D][EHMTXv2:700]: info text color left: r: 150 g: 150 b: 150 right: r: 150 g: 150 b: 150 y_offset 0
[20:01:38][D][EHMTXv2:132]: default weekday color: 150 g: 150 b: 150

[20:01:38][D][EHMTXv2:092]: empty slot
[20:01:38][D][EHMTXv2:1028]: on_empty_queue trigger
[20:01:38][D][EHMTXv2:1725]: find screen: found by mode 0 icon l$\xfb?
[20:01:38][D][EHMTXv2:1387]: icon clock icon: 91 iconname: blank|day#1 lifetime: 1440 screen_time: 10
[20:01:38][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:38][D][EHMTXv2:700]: info text color left: r: 150 g: 150 b: 150 right: r: 150 g: 150 b: 150 y_offset 0
[20:01:38][D][EHMTXv2:132]: default weekday color: 150 g: 150 b: 150

[20:01:38][D][EHMTXv2:092]: empty slot
[20:01:38][D][EHMTXv2:1028]: on_empty_queue trigger
[20:01:38][D][EHMTXv2:1725]: find screen: found by mode 0 icon l$\xfb?
[20:01:38][D][EHMTXv2:1387]: icon clock icon: 91 iconname: blank|day#1 lifetime: 1440 screen_time: 10
[20:01:38][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:38][D][EHMTXv2:700]: info text color left: r: 150 g: 150 b: 150 right: r: 150 g: 150 b: 150 y_offset 0
[20:01:38][D][EHMTXv2:132]: default weekday color: 150 g: 150 b: 150

[20:01:38][D][EHMTXv2:092]: empty slot
[20:01:38][D][EHMTXv2:1028]: on_empty_queue trigger
[20:01:38][D][EHMTXv2:1725]: find screen: found by mode 0 icon l$\xfb?
[20:01:38][D][EHMTXv2:1387]: icon clock icon: 91 iconname: blank|day#1 lifetime: 1440 screen_time: 10
[20:01:38][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:38][D][EHMTXv2:700]: info text color left: r: 150 g: 150 b: 150 right: r: 150 g: 150 b: 150 y_offset 0
[20:01:38][D][EHMTXv2:132]: default weekday color: 150 g: 150 b: 150

[20:01:38][D][EHMTXv2:092]: empty slot
[20:01:38][D][EHMTXv2:1028]: on_empty_queue trigger

.........  ~1000 strings more .........

[20:01:42][D][EHMTXv2:092]: empty slot
[20:01:42][D][EHMTXv2:1028]: on_empty_queue trigger
[20:01:42][D][EHMTXv2:1725]: find screen: found by mode 0 icon l$\xfb?
[20:01:42][D][EHMTXv2:1387]: icon clock icon: 91 iconname: blank|day#1 lifetime: 1440 screen_time: 10
[20:01:42][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:42][D][EHMTXv2:700]: info text color left: r: 150 g: 150 b: 150 right: r: 150 g: 150 b: 150 y_offset 0
[20:01:42][D][EHMTXv2:132]: default weekday color: 150 g: 150 b: 150

[20:01:42][D][EHMTXv2:092]: empty slot
[20:01:42][D][EHMTXv2:1028]: on_empty_queue trigger
[20:01:42][D][EHMTXv2:1725]: find screen: found by mode 0 icon l$\xfb?
[20:01:42][D][EHMTXv2:1387]: icon clock icon: 91 iconname: blank|day#1 lifetime: 1440 screen_time: 10
[20:01:42][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:42][D][EHMTXv2:700]: info text color left: r: 150 g: 150 b: 150 right: r: 150 g: 150 b: 150 y_offset 0
[20:01:42][D][EHMTXv2:132]: default weekday color: 150 g: 150 b: 150

[20:01:42][D][EHMTXv2:790]: oldest queue element is: 0/1
[20:01:42][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:42][D][EHMTXv2:1018]: on_next_screen trigger

[20:01:52][D][EHMTXv2:790]: oldest queue element is: 0/1
[20:01:52][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:52][D][EHMTXv2:1018]: on_next_screen trigger

[20:02:02][D][EHMTXv2:790]: oldest queue element is: 0/1
[20:02:02][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:02:02][D][EHMTXv2:1018]: on_next_screen trigger
andrewjswan commented 10 months ago

Doesn't find the clock screen when the alert screen has been removed. https://github.com/lubeda/EspHoMaTriXv2/blob/2023.9.1/components/ehmtxv2/EHMTX.cpp#L798 The reason is:

this->queue[this->screen_pointer]->last_time = ts + this->queue[this->screen_pointer]->screen_time_;

Showed the clock screen in 20:01:32:

[20:01:32][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:32][D][EHMTXv2:1018]: on_next_screen trigger

this->queue[this->screen_pointer]->last_time = 20:01:42; Showed an alert screen and deleted it in 20:01:38:

[20:01:38][D][EHMTXv2:851]: remove expired queue element: slot 1: mode: 16 icon_name: spotify text: Song name - Artist name

And we didn’t find the clock screen because the condition is not met:

if ((this->queue[i]->endtime > this->get_tick()) && (this->queue[i]->last_time < last_time))

Ie:

There are constant skipping cycles until the above condition is met (in 20:01:42), and then we start showing the screens:

[20:01:42][D][EHMTXv2:790]: oldest queue element is: 0/1
[20:01:42][D][EHMTXv2:122]: queue: icon clock: "day#1" for: 10.0 sec
[20:01:42][D][EHMTXv2:1018]: on_next_screen trigger

I propose a solution: If we haven’t found any old screens, but our queue is not empty, return the first one from the queue to display. https://github.com/lubeda/EspHoMaTriXv2/blob/2023.9.1/components/ehmtxv2/EHMTX.cpp#L804-L807 Change to:

    uint8_t queue_count = this->queue_count();
    if (hit != MAXQUEUE)
    {
      ESP_LOGD(TAG, "oldest queue element is: %d/%d", hit, queue_count);
    }
    else if (queue_count > 0)
    {
      hit = 0;
      ESP_LOGD(TAG, "oldest queue element is first: %d/%d", hit, queue_count);
    }
andrewjswan commented 10 months ago

Or the solution is even simpler, we simply indicate the fact that the screen is displayed. https://github.com/lubeda/EspHoMaTriXv2/blob/2023.9.1/components/ehmtxv2/EHMTX.cpp#L1006 Change to:

 this->queue[this->screen_pointer]->last_time = ts;
andrewjswan commented 10 months ago

I have transferred the https://github.com/lubeda/EspHoMaTriXv2/pull/153 to a draft for now, if the https://github.com/lubeda/EspHoMaTriXv2/pull/154 does not help or produces unwanted artifacts, then we will try it.

andrewjswan commented 10 months ago

@chertvl Can you check: first: https://github.com/andrewjswan/EspHoMaTriXv2/tree/2023.9.1-152-last_time_-_actual_time if not help, then: https://github.com/andrewjswan/EspHoMaTriXv2/tree/2023.9.1-152-find_oldest_queue_element_fix

chertvl commented 10 months ago

2023.9.1-152-lasttime-_actual_time 2023.9.1-152-find_oldest_queue_element_fix

Both looks good! I cant catch log issues anymore. Thanks! Which one is better and optimal? ;P

andrewjswan commented 10 months ago

@lubeda Both changes work equally well, whichever one you like better and whichever one fits more into the concept, that PR and merge, the second one will be closed then.

PS: Read below

andrewjswan commented 10 months ago

Although you can infuse these two changes, it will certainly not be worse, and reliability will add ....

chertvl commented 10 months ago

Fixd by https://github.com/lubeda/EspHoMaTriXv2/pull/153 https://github.com/lubeda/EspHoMaTriXv2/pull/154

Thanks, guys!