Panel serve only allows error-level logging?

Panel
1

Hi,

I just noticed that no logs are captured by panel unless they are emitted on the ‘error’ level.

Panel serve command:

 nohup panel serve --port 5006 --allow-websocket-origin dev.materialindicators.com --num-procs 4 MI_App_RC1-Copy5_1D.ipynb --dev --auth-module=../auth.py --log-level debug --log-file webapp
_RC1.log --stats-log-frequency 300000 --mem-log-frequency 300000 --keep-alive 30000 &

In-app logger:

session = os.path.join(wdir,"webapp_RC1.log")
log_settings = logging.basicConfig(handlers=[logging.FileHandler(session, 'a', 'utf-8')],
                                   format='[%(levelname) 5s/%(asctime)s] %(name)s: %(message)s',
                                   level=logging.DEBUG)
logger = logging.getLogger()

Code in app:

Normally, debug-level info, but now using ‘error’ level:

logger.error(f"User: {self.user}, Widget values - ticker: {self.ticker.value}, window: {self.window.value}, norm: {self.norm.value}, nr. of reloads: {self.reload.clicks}")

Logging of actual errors:

self.plot_pane.object = hv.Div(f"Error: {e}")
logger.error(f"User: {self.user}, Error: {e}",exc_info=True)

Log looks like this:

2020-08-14 14:54:58,965 Running in --dev mode. --num-procs is limited to 1.
2020-08-14 14:54:58,965 Starting Bokeh server version 2.1.1 (running on Tornado 6.0.4)
2020-08-14 14:54:58,966 Cannot start Bokeh server, port 5006 is already in use
2020-08-14 14:55:56,659 Running in --dev mode. --num-procs is limited to 1.
2020-08-14 14:55:56,660 Starting Bokeh server version 2.1.1 (running on Tornado 6.0.4)
2020-08-14 14:55:56,661 Keep-alive ping configured every 30000 milliseconds
2020-08-14 14:55:56,661 Log statistics every 300000 milliseconds
2020-08-14 14:55:56,669 Log memory usage every 300000 milliseconds
2020-08-14 14:55:56,669 User authentication hooks provided (no default user)
2020-08-14 14:55:56,669 These host origins can connect to the websocket: ['dev.materialindicators.com:80']
2020-08-14 14:55:56,669 Patterns are:
2020-08-14 14:55:56,670   [('/MI_App_RC1-Copy5_1D/?',
2020-08-14 14:55:56,670     <class 'bokeh.server.views.doc_handler.DocHandler'>,
2020-08-14 14:55:56,670     {'application_context': <bokeh.server.contexts.ApplicationContext object at 0x7fd095ab8e90>,
2020-08-14 14:55:56,670      'bokeh_websocket_path': '/MI_App_RC1-Copy5_1D/ws'}),
2020-08-14 14:55:56,670    ('/MI_App_RC1-Copy5_1D/ws',
2020-08-14 14:55:56,670     <class 'bokeh.server.views.ws.WSHandler'>,
2020-08-14 14:55:56,670     {'application_context': <bokeh.server.contexts.ApplicationContext object at 0x7fd095ab8e90>,
2020-08-14 14:55:56,670      'bokeh_websocket_path': '/MI_App_RC1-Copy5_1D/ws'}),
2020-08-14 14:55:56,670    ('/MI_App_RC1-Copy5_1D/metadata',
2020-08-14 14:55:56,670     <class 'bokeh.server.views.metadata_handler.MetadataHandler'>,
2020-08-14 14:55:56,670     {'application_context': <bokeh.server.contexts.ApplicationContext object at 0x7fd095ab8e90>,
2020-08-14 14:55:56,670      'bokeh_websocket_path': '/MI_App_RC1-Copy5_1D/ws'}),
2020-08-14 14:55:56,670    ('/MI_App_RC1-Copy5_1D/autoload.js',
2020-08-14 14:55:56,670     <class 'bokeh.server.views.autoload_js_handler.AutoloadJsHandler'>,
2020-08-14 14:55:56,670     {'application_context': <bokeh.server.contexts.ApplicationContext object at 0x7fd095ab8e90>,
2020-08-14 14:55:56,670      'bokeh_websocket_path': '/MI_App_RC1-Copy5_1D/ws'}),
2020-08-14 14:55:56,670    ('/login',
2020-08-14 14:55:56,670     <class 'bokeh.auth_8ec79fca25a242ed9ff6fd68055e3f72.LoginHandler'>),
2020-08-14 14:55:56,670    ('/logout',
2020-08-14 14:55:56,670     <class 'bokeh.auth_8ec79fca25a242ed9ff6fd68055e3f72.LogoutHandler'>),
2020-08-14 14:55:56,670    ('/?',
2020-08-14 14:55:56,670     <class 'bokeh.server.views.root_handler.RootHandler'>,
2020-08-14 14:55:56,670     {'applications': {'/MI_App_RC1-Copy5_1D': <bokeh.server.contexts.ApplicationContext object at 0x7fd095ab8e90>},
2020-08-14 14:55:56,670      'index': '/root/anaconda3/lib/python3.7/site-packages/panel/io/../_templates/index.html',
2020-08-14 14:55:56,671      'prefix': '',
2020-08-14 14:55:56,671      'use_redirect': True}),
2020-08-14 14:55:56,671    ('/static/extensions/(.*)',
2020-08-14 14:55:56,671     <class 'bokeh.server.views.multi_root_static_handler.MultiRootStaticHandler'>,
2020-08-14 14:55:56,671     {'root': {}}),
2020-08-14 14:55:56,671    ('/static/(.*)',
2020-08-14 14:55:56,671     <class 'bokeh.server.views.static_handler.StaticHandler'>)]
2020-08-14 14:55:56,673 Bokeh app running at: http://localhost:5006/MI_App_RC1-Copy5_1D
2020-08-14 14:55:56,673 Starting Bokeh server with process id: 2349
2020-08-14 14:56:07,668 User: Mtrl_Scientist, Widget values - ticker: None, window: 1D, norm: ['Normalize CVD'], nr. of reloads: 1
2020-08-14 14:56:09,679 User: Mtrl_Scientist, Widget values - ticker: None, window: 1D, norm: ['Normalize CVD'], nr. of reloads: 2
2020-08-14 14:59:56,858 User: Mtrl_Scientist, Widget values - ticker: None, window: 1D, norm: ['Normalize CVD'], nr. of reloads: 3
2020-08-14 15:00:05,341 User: Mtrl_Scientist, Widget values - ticker: BTC_USDT, window: 1D, norm: ['Normalize CVD'], nr. of reloads: 3
2020-08-14 15:00:09,190 User: Mtrl_Scientist, Widget values - ticker: BTC_USDT, window: 3Y, norm: ['Normalize CVD'], nr. of reloads: 3
2020-08-14 15:00:13,475 User: Mtrl_Scientist, Widget values - ticker: ENJ_BTC, window: 3Y, norm: ['Normalize CVD'], nr. of reloads: 3
2020-08-14 15:00:17,343 User: Mtrl_Scientist, Widget values - ticker: SNGLS_BTC, window: 3Y, norm: ['Normalize CVD'], nr. of reloads: 3
2020-08-14 15:00:20,762 User: Mtrl_Scientist, Widget values - ticker: SNM_BTC, window: 3Y, norm: ['Normalize CVD'], nr. of reloads: 3

The logger within the app is configured to write to a different directory. This works properly whenever I use the app within Jupyter. But once I serve via Panel and use ‘–log-file webapp_RC1.log’, no more logs are saved to the in-app logger file.

Instead, the Panel logger takes over and saves only error-level events.

Also, the following log parameters seem to have no effect:

--stats-log-frequency 300000 --mem-log-frequency 300000

As they are not showing up in the log.

For now, you can just set the logger level to ‘error’, but I think this may be a bug.

1 Like
2

This might be a solution…

Best,

Douglas

1 Like
3

If you are using Python >= 3.8 then you can use logging.basicConfig(..., force=True). This will disable all existing logging handlers and setup a new one. This means that your own logging.basicConfig() call will work as expected.

2 Likes
4

Thanks @pmav99

Using something like below works really well.

FORMAT = '%(asctime)s | %(levelname)s | %(name)s | %(message)s'
logging.basicConfig(format=FORMAT, level=logging.INFO, force=True)

If you have a custom logger you can set the log level individually

logger.setLevel(logging.DEBUG)

I created this logging reference example

import panel as pn
import logging

logger = logging.getLogger("app")

def log_root(event):
    logging.error("root ERROR")
    logging.warning("root WARNING")
    logging.info("root INFO")
    logging.debug("root DEBUG")

def log_custom(event):
    logger.info("custom ERROR")
    logger.info("custom WARNING")
    logger.info("custom INFO")
    logger.debug("custom DEBUG")

def log_exception(event):
    raise Exception("something went wrong")

def create_app():
    return pn.Column(
            pn.widgets.Button(name="Log Root", on_click=log_root, width=150),
            pn.widgets.Button(name="Log Custom", on_click=log_custom, width=150),
            pn.widgets.Button(name="Log Exception", on_click=log_exception, width=150),
    )


if pn.state.served:
    FORMAT = '%(asctime)s | %(levelname)s | %(name)s | %(message)s'
    logging.basicConfig(format=FORMAT, level=logging.INFO, force=True)

    logger.setLevel(logging.DEBUG)

    pn.extension()

    create_app().servable()

If you load the page and click the 3 buttons you will see something like

image

$ panel serve script.py --autoreload --index script
2024-01-12 08:58:00,534 | INFO | bokeh.server.server | Starting Bokeh server version 3.3.0 (running on Tornado 6.3.3)
2024-01-12 08:58:00,535 | INFO | bokeh.server.tornado | User authentication hooks NOT provided (default user enabled)
2024-01-12 08:58:00,537 | INFO | bokeh.command.subcommands.serve | Bokeh app running at: http://localhost:5006/
2024-01-12 08:58:00,537 | INFO | bokeh.command.subcommands.serve | Bokeh app running at: http://localhost:5006/script
2024-01-12 08:58:00,537 | INFO | bokeh.command.subcommands.serve | Starting Bokeh server with process id: 10824
2024-01-12 08:58:08,835 | INFO | tornado.access | 200 GET / (127.0.0.1) 57.31ms
2024-01-12 08:58:09,116 | INFO | tornado.access | 101 GET /ws (127.0.0.1) 0.84ms
2024-01-12 08:58:09,116 | INFO | bokeh.server.views.ws | WebSocket connection opened
2024-01-12 08:58:09,117 | INFO | bokeh.server.views.ws | ServerConnection created
2024-01-12 08:58:12,155 | ERROR | root | root ERROR
2024-01-12 08:58:12,155 | WARNING | root | root WARNING
2024-01-12 08:58:12,155 | INFO | root | root INFO
2024-01-12 08:58:12,874 | INFO | app | custom ERROR
2024-01-12 08:58:12,874 | INFO | app | custom WARNING
2024-01-12 08:58:12,875 | INFO | app | custom INFO
2024-01-12 08:58:12,875 | DEBUG | app | custom DEBUG
2024-01-12 08:58:13,666 | ERROR | bokeh.server.protocol_handler | error handling message
 message: Message 'PATCH-DOC' content: {'events': [{'kind': 'MessageSent', 'msg_type': 'bokeh_event', 'msg_data': {'type': 'event', 'name': 'button_click', 'values': {'type': 'map', 'entries': [['model', {'id': 'p1029'}]]}}}]} 
 error: Exception('something went wrong')
Traceback (most recent call last):
  File "/opt/conda/lib/python3.11/site-packages/bokeh/server/protocol_handler.py", line 97, in handle
    work = await handler(message, connection)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/conda/lib/python3.11/site-packages/bokeh/server/session.py", line 94, in _needs_document_lock_wrapper
    result = func(self, *args, **kwargs)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/conda/lib/python3.11/site-packages/bokeh/server/session.py", line 286, in _handle_patch
    message.apply_to_document(self.document, self)
  File "/opt/conda/lib/python3.11/site-packages/bokeh/protocol/messages/patch_doc.py", line 104, in apply_to_document
    invoke_with_curdoc(doc, lambda: doc.apply_json_patch(self.payload, setter=setter))
  File "/opt/conda/lib/python3.11/site-packages/bokeh/document/callbacks.py", line 443, in invoke_with_curdoc
    return f()
           ^^^
  File "/opt/conda/lib/python3.11/site-packages/bokeh/protocol/messages/patch_doc.py", line 104, in <lambda>
    invoke_with_curdoc(doc, lambda: doc.apply_json_patch(self.payload, setter=setter))
                                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/conda/lib/python3.11/site-packages/bokeh/document/document.py", line 391, in apply_json_patch
    DocumentPatchedEvent.handle_event(self, event, setter)
  File "/opt/conda/lib/python3.11/site-packages/bokeh/document/events.py", line 245, in handle_event
    event_cls._handle_event(doc, event)
  File "/opt/conda/lib/python3.11/site-packages/bokeh/document/events.py", line 280, in _handle_event
    cb(event.msg_data)
  File "/opt/conda/lib/python3.11/site-packages/bokeh/document/callbacks.py", line 390, in trigger_event
    model._trigger_event(event)
  File "/opt/conda/lib/python3.11/site-packages/bokeh/util/callback_manager.py", line 113, in _trigger_event
    self.document.callbacks.notify_event(cast(Model, self), event, invoke)
  File "/opt/conda/lib/python3.11/site-packages/bokeh/document/callbacks.py", line 260, in notify_event
    invoke_with_curdoc(doc, callback_invoker)
  File "/opt/conda/lib/python3.11/site-packages/bokeh/document/callbacks.py", line 443, in invoke_with_curdoc
    return f()
           ^^^
  File "/opt/conda/lib/python3.11/site-packages/bokeh/util/callback_manager.py", line 109, in invoke
    cast(EventCallbackWithEvent, callback)(event)
  File "/opt/conda/lib/python3.11/site-packages/panel/reactive.py", line 494, in _server_event
    self._comm_event(doc, event)
  File "/opt/conda/lib/python3.11/site-packages/panel/reactive.py", line 481, in _comm_event
    state._handle_exception(e)
  File "/opt/conda/lib/python3.11/site-packages/panel/io/state.py", line 441, in _handle_exception
    raise exception
  File "/opt/conda/lib/python3.11/site-packages/panel/reactive.py", line 479, in _comm_event
    self._process_bokeh_event(doc, event)
  File "/opt/conda/lib/python3.11/site-packages/panel/reactive.py", line 416, in _process_bokeh_event
    self._process_event(event)
  File "/opt/conda/lib/python3.11/site-packages/panel/widgets/button.py", line 247, in _process_event
    self.clicks += 1
    ^^^^^^^^^^^
  File "/opt/conda/lib/python3.11/site-packages/param/parameterized.py", line 525, in _f
    instance_param.__set__(obj, val)
  File "/opt/conda/lib/python3.11/site-packages/param/parameterized.py", line 527, in _f
    return f(self, obj, val)
           ^^^^^^^^^^^^^^^^^
  File "/opt/conda/lib/python3.11/site-packages/param/parameters.py", line 542, in __set__
    super().__set__(obj,val)
  File "/opt/conda/lib/python3.11/site-packages/param/parameterized.py", line 527, in _f
    return f(self, obj, val)
           ^^^^^^^^^^^^^^^^^
  File "/opt/conda/lib/python3.11/site-packages/param/parameterized.py", line 1545, in __set__
    obj.param._call_watcher(watcher, event)
  File "/opt/conda/lib/python3.11/site-packages/param/parameterized.py", line 2486, in _call_watcher
    self_._execute_watcher(watcher, (event,))
  File "/opt/conda/lib/python3.11/site-packages/param/parameterized.py", line 2468, in _execute_watcher
    watcher.fn(*args, **kwargs)
  File "/home/jovyan/repos/private/awesome-panel/script.py", line 19, in log_exception
    raise Exception("something went wrong")
Exception: something went wrong
1 Like