KeyError in ui.log after client disconnected

[Thermaltech]

Description

Hey!
Not sure if this is a bug, or an issue with my code (see below), but it seems that when the ui.log element is used with the python logging module, the page / element throws an error under the following conditions:

1. max_lines is non-zero ( Not Equal to None )
2. page is changed to another page / closed
3. a time period elapses (I assume when nicegui is cleaning up the disconnected page / elements)

If I set max_lines to None (default), then no error occurs. as this seems to be related to the nicegui codebase in log.py, line 28/29 where the LogeElementhandler in my code is attempting to log an event / trim the list, but nicegui has already cleaned up and deleted the log element, hence the error.

        while self.max_lines is not None and len(self.default_slot.children) > self.max_lines:
            self.remove(0)

The Error:

--- Logging error ---
Traceback (most recent call last):
  File "/mnt/datastore/wm/ui_event_log.py", line 22, in emit
    self.element.push(msg)
  File "/usr/local/lib/python3.10/dist-packages/nicegui/elements/log.py", line 29, in push
    self.remove(0)
  File "/usr/local/lib/python3.10/dist-packages/nicegui/element.py", line 525, in remove
    self.client.remove_elements(elements)
  File "/usr/local/lib/python3.10/dist-packages/nicegui/client.py", line 304, in remove_elements
    del self.elements[element_id]
KeyError: 35

My Code:

import logging

from nicegui import ui, Tailwind
import modules.config_loader as cfg

import ui_header
import ui_footer
from time import strftime, localtime

logger = logging.getLogger('wm.ui.event_log')

class LogElementHandler(logging.Handler):
    """A logging handler that emits messages to a log element."""

    def __init__(self, element: ui.log, level: int = logging.NOTSET) -> None:
        self.element = element
        super().__init__(level)

    def emit(self, record: logging.LogRecord) -> None:
        try:
            msg = f'{strftime("%A, %B %d, %Y, %H:%M:%S", localtime(record.created))} - {record.levelname} - {record.name} - {record.message}'
            self.element.push(msg)
        except Exception:
            self.handleError(record)


@ui.page('/event_log')
def content():

    wm_config = cfg.configs['wm'].config

    # Page Configuration
    ui.page_title(f"{wm_config['SETTINGS']['TITLE']} - Event Log")
    ui_header.content()
    ui_footer.content()

    ui_logger = logging.getLogger('wm')

    with ui.card().classes('w-full'):
        # Title
        lbl_log = ui.label('Event Log')
        lbl_log.tailwind('font-bold')
        # Log viewer
        log = ui.log(max_lines = 20)
        log.tailwind('h-[500px]')
        # Add log event handler to the ui_logger
        ui_logger.addHandler(LogElementHandler(log))
        
        # Clear log button
        ui.button('CLEAR EVENT LOG', on_click=lambda : log.clear())

In any case, thanks so much for any help that can be provided. Cheers!

[falkoschindler]

Hi @Thermaltech, thanks for reaching out!

I'm struggling to reproduce the error. Your code is missing some imports like modules, ui_footer and ui_header. So I reduced it to this:

import logging
from time import localtime, strftime
from nicegui import ui

class LogElementHandler(logging.Handler):

    def __init__(self, element: ui.log, level: int = logging.NOTSET) -> None:
        self.element = element
        super().__init__(level)

    def emit(self, record: logging.LogRecord) -> None:
        try:
            msg = f'{strftime("%A, %B %d, %Y, %H:%M:%S", localtime(record.created))} - {record.levelname} - {record.name} - {record.message}'
            self.element.push(msg)
        except Exception:
            self.handleError(record)

@ui.page('/')
def page():
    ui_logger = logging.getLogger('wm')
    log = ui.log(max_lines=10)
    ui_logger.addHandler(LogElementHandler(log))
    ui.button('Clear', on_click=log.clear)

But I don't get any exception when closing the page. Maybe because there is no log happening?

[Thermaltech]

Falko,

Thanks for the quick reply. The ui_header and ui_footer didn't have anything to do with the problem at hand, so I didn't include them. Sorry if it caused any confusion.

The logging events are happening all over the program in different modules, and are being monitored / displayed by this page by attaching to the global logger "wm" by name. So the LogElementHandler would still be registered with in the logging module, and would still be firing events...

Honestly, what I think is happening is due to my software not being aware that the page is gone, and the logging handler is still trying to send / delete data for the nicegui logging element by way of the LogElementHandler, what I may have to do is add and remove the handler based on client connect disconnect, or just push a copy of the log file on demand.

In short, I may be misguided in my thoughts as to how the nicegui log implementation is intended to be used. I am quite sure if all the logging is happening on the page that is pushing the data to the same page, all would be OK. This would mean that when the page is closed, the events inherently stop.

Since the logging events are happening elsewhere within my program, and the logging handler is attempting to push / remove data from a now non-existent element, is where the problem lies.... What has me a little confused is that the logging events being pushed to a non-existent logging element does not cause an error, but when the following code executes to remove old items from the log element, all hell breaks loose...

        while self.max_lines is not None and len(self.default_slot.children) > self.max_lines:
            self.remove(0)

Is there some simple method that could be used to determine when the page is closed so that I can automatically remove the LogElementHandler instance?

Cheers.

[Thermaltech]

Just a FYI. Problem solved by addming client connect / disconnect handlers to automatically add and remove the LogElemenHandler to the logger. The nicegui Client class made this really easy. Thanks for making a great library!

Revised code:

import logging
from time import strftime, localtime

from nicegui import ui, Tailwind, Client
import modules.tts_config_loader as cfg

import ui_header
import ui_footer

logger = logging.getLogger('wm.ui.event_log')

class LogElementHandler(logging.Handler):
    """A logging handler that emits messages to a log element."""

    def __init__(self, element: ui.log, level: int = logging.NOTSET) -> None:
        self.element = element
        super().__init__(level)

    def emit(self, record: logging.LogRecord) -> None:
        try:
            msg = f'{strftime("%A, %B %d, %Y, %H:%M:%S", localtime(record.created))} - {record.levelname} - {record.name} - {record.message}'
            self.element.push(msg)
        except Exception:
            self.handleError(record)


'''
UI - EVENT_LOG
'''
@ui.page('/event_log')
def content(client: Client):

    wm_config = cfg.configs['wm'].config

    def connected():
        # Add log event handler
        logging.getLogger('wm').addHandler(log_handler)
    
    def disconnected():
        # Remove log event handler
        logging.getLogger('wm').removeHandler(log_handler)

    def clear_log():
        logger.debug(f'Client cleared local event log with id: {client.id}')
        log_element.clear()

    client.on_connect(connected)
    client.on_disconnect(disconnected) 

    # Page Configuration
    ui.page_title(f"{wm_config['SETTINGS']['TITLE']} - Event Log")
    ui_header.content()
    ui_footer.content()

    with ui.card().classes('w-full'):
        # Title
        lbl_log = ui.label('Event Log')
        lbl_log.tailwind('font-bold')
        # Log viewer
        log_element = ui.log(max_lines = 50)
        log_element.tailwind('h-[500px]')
        log_handler : LogElementHandler = LogElementHandler(log_element)

        # Clear log button
        ui.button('CLEAR EVENT LOG', on_click=lambda : clear_log())

[falkoschindler]

Thanks for the clarification, @Thermaltech! Just recently we ran into a similar problem. Let me explain:

When you register some UI code (like adding a line of text to ui.log) to some long-living non-UI event, you're basically creating a memory leak. The event holds a reference to the UI code, which includes the UI elements which in turn hold a reference to the client. When the client disconnects, it gets removed from NiceGUI's client dictionary and all its child elements get removed, too. But the reference from the event remains in memory and the client is still receiving events. This would remain unnoticed, because nobody cares about a disconnected client being updated in the background. But the memory consumption grows with every newly disconnected client. And when deleting UI elements (which happens when reaching the maximum number of lines in ui.log), a KeyError happens because the client had already lost all its children during the disconnect.

Since a memory leak can be pretty critical and it happens so easily, we should implement some safety net. We already experimented with detecting access to any client attribute after it disconnected, but this felt like a bit too strict. Something similar would be a useful feature though.