Opening xarray dataset suppresses panel error messages

yt87 commented 1 month ago

ALL software version info

(this library, plus any other relevant software, e.g. bokeh, python, notebook, OS, browser, etc should be added within the dropdown below.)

Software Version Info

```plaintext bokeh 3.5.2 pyhd8ed1ab_0 conda-forge panel 1.5.0 pyhd8ed1ab_0 conda-forge rioxarray 0.17.0 pyhd8ed1ab_0 conda-forge xarray 2024.9.0 pyhd8ed1ab_0 conda-forge ```

Description of expected behavior and the observed behavior

I run the code below as a panel app

panel serve  example.py --show

When x is selected, the app results in a blank screen (tile shows OK) and there is no stack trace printed to the terminal. The stack trace is printed when the ds = xr.open_dataset(file) is commented out.

I tracked the issue to xarray's plugin rioxarray.xarray_plugin:RasterioBackend. When I comment out line in xarray.backends.plugins.py, function build_engines that loads that plugin:

def build_engines(entrypoints: EntryPoints) -> dict[str, BackendEntrypoint]:
    backend_entrypoints: dict[str, type[BackendEntrypoint]] = {}
    for backend_name, (module_name, backend) in BACKEND_ENTRYPOINTS.items():
        if module_name is None or module_available(module_name):
            backend_entrypoints[backend_name] = backend
    entrypoints_unique = remove_duplicates(entrypoints)
    # external_backend_entrypoints = backends_dict_from_pkg(entrypoints_unique)
    # backend_entrypoints.update(external_backend_entrypoints)
    backend_entrypoints = sort_backends(backend_entrypoints)
    set_missing_parameters(backend_entrypoints)
    return {name: backend() for name, backend in backend_entrypoints.items()}

the example works as expected, i.e. fails with the traceback printed.

I don't know whether this is a problem with panel, or rioxarray.

Complete, minimal, self-contained example code that reproduces the issue

# code goes here between backticks
# example.py
import panel as pn
import xarray as xr

def update(value):
    file = '/tmp/foo.nc'
    ds = xr.open_dataset(file)
    return pn.pane.Str(int(value))

selector = pn.widgets.Select(name="options", options=["x", 2], value="x")
bf = pn.bind(update, selector)
panel_bf = pn.panel(bf)
pn.Row(selector, pn.panel(bf)).servable()

Stack traceback and/or browser JavaScript console output

Screenshots or screencasts of the bug in action

[ ] I may be interested in making a pull request to address this

hoxbro commented 1 month ago

Do you have Dask installed? This could be related to them currently changing the log level by default: https://github.com/dask/distributed/issues/8750

yt87 commented 1 month ago

Yes, I do. But I don't import dask.distributed in my example app. I don't see rioxarray does it either.

hoxbro commented 1 month ago

It seems like this part of the code does something entrypoints, so could be something completely third which imports dask.distributed.

yt87 commented 1 month ago

The (external) entrypoint is rioxarray plugin.

On Sun., Sep. 29, 2024, 23:07 Simon Høxbro Hansen, @.***> wrote:

It seems like this part of the code does something entrypoints, so could be something completely third which imports dask.distributed.

— Reply to this email directly, view it on GitHub https://github.com/holoviz/panel/issues/7347#issuecomment-2382280455, or unsubscribe https://github.com/notifications/unsubscribe-auth/AJS3CC7XN72KH2AMIBPXS5DZZD2BVAVCNFSM6AAAAABPCRLPDSVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDGOBSGI4DANBVGU . You are receiving this because you authored the thread.Message ID: @.***>

hoxbro commented 1 month ago

Try setting this environment variable: export DASK_DISTRIBUTED__LOGGING__BOKEH="info"

philippjfr commented 1 month ago

@hoxbro Any suggestions on how we can fix this more generally? Do we have to raise this with dask again?

hoxbro commented 1 month ago

Either wait for https://github.com/dask/distributed/pull/8634 or set the environment variable somewhere.

philippjfr commented 1 month ago

Commented on that PR.

yt87 commented 1 month ago

Solved. I had dask logging configuration file ~/.config/dask.logging.yaml. I need it to run dask distributed as a system service. Dask logging config disabled existing loggers in my app. The workaround is to add a line

disable_existing_loggers: False

The pending fix in https://github.com/dask/distributed/pull/8634 seems to resolve the issue, logging config is not done when dask client is initialised. I tested the distributed-do_not_init_logging_on_import branch with this app:

import io
import logging

import panel as pn
import yaml
from dask.distributed import Client

def configure_logging(f):
    import logging.config
    config = yaml.safe_load(f)
    log_config = config.get("logging", {})
    if "version" in log_config:
        log_config["version"] = int(log_config["version"])
        logging.config.dictConfig(config.get("logging"))
    else:
        raise SystemExit('Bad configuration')

foo_yaml = '''
logging:
  version: 1
  disable_existing_loggers: False
  formatters:
    default:
      format: '%(levelname)-8s | %(asctime)s | %(name)s | %(module)s.%(funcName)s | %(message)s'
  handlers:
    console:
      class: logging.StreamHandler
      level: DEBUG
      formatter: default
    file:
      class: logging.handlers.TimedRotatingFileHandler
      filename: /tmp/foo.log
      when: midnight
      backupCount: 1
      level: INFO
      formatter: default
  root:
    level: ERROR
    handlers:
      - file
      - console
  loggers:
    foo:
      level: DEBUG
    bokeh:
      level: INFO
    panel:
      level: INFO
      propagate: True   # must be set explicitly
    tornado:
      level: INFO
'''

fn = io.StringIO(foo_yaml)
configure_logging(fn)
logger = logging.getLogger('foo')

client = Client('192.168.1.102:8786', timeout=2)

def update(value):
    print(f'updating... with value {value}')
    logger.debug(f'this is debug: {value}')
    logger.info(f'this is info: {value}')
    logger.error(f'this is error: {value}')
    if value == 2:
        raise ValueError('simulating latent bug')
    return pn.pane.Str(value)

selector = pn.widgets.Select(name="options", options=[0, 1, 2], value=0)
bf = pn.bind(update, selector)
pn.Row(selector, pn.panel(bf)).servable()

A minor quirk: the exception is logged twice, by panel and tornado:

ERROR    | 2024-10-09 05:01:35,795 | panel.reactive | reactive._process_events | Callback failed for object named 'options' changing property {'value': 2} 
Traceback (most recent call last):
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/reactive.py", line 462, in _process_events
    self.param.update(**self_params)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 2319, in update
    restore = dict(self_._update(arg, **kwargs))
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 2352, in _update
    self_._batch_call_watchers()
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 2546, in _batch_call_watchers
    self_._execute_watcher(watcher, events)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 2506, in _execute_watcher
    watcher.fn(*args, **kwargs)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/param.py", line 891, in _replace_pane
    new_object = self.eval(self.object)
                 ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/param.py", line 1106, in eval
    return eval_function_with_deps(ref)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 165, in eval_function_with_deps
    return function(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/depends.py", line 53, in _depends
    return func(*args, **kw)
           ^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/reactive.py", line 594, in wrapped
    return eval_fn()(*combined_args, **combined_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/test/foo.py", line 66, in update
    raise ValueError('simulating latent bug')
ValueError: simulating latent bug
ERROR    | 2024-10-09 05:01:35,797 | tornado.application | ioloop._run_callback | Exception in callback functools.partial(<bound method IOLoop._discard_future_result of <tornado.platform.asyncio.AsyncIOMainLoop object at 0x75ff19f9d970>>, <Task finished name='Task-92' coro=<ServerSession.with_document_locked() done, defined at /home/george/mambaforge/envs/test3/lib/python3.12/site-packages/bokeh/server/session.py:77> exception=ValueError('simulating latent bug')>)
Traceback (most recent call last):
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/tornado/ioloop.py", line 750, in _run_callback
    ret = callback()
          ^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/tornado/ioloop.py", line 774, in _discard_future_result
    future.result()
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/bokeh/server/session.py", line 98, in _needs_document_lock_wrapper
    result = await result
             ^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/reactive.py", line 509, in _change_coroutine
    state._handle_exception(e)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/io/state.py", line 468, in _handle_exception
    raise exception
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/reactive.py", line 507, in _change_coroutine
    self._change_event(doc)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/reactive.py", line 525, in _change_event
    self._process_events(events)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/reactive.py", line 462, in _process_events
    self.param.update(**self_params)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 2319, in update
    restore = dict(self_._update(arg, **kwargs))
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 2352, in _update
    self_._batch_call_watchers()
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 2546, in _batch_call_watchers
    self_._execute_watcher(watcher, events)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 2506, in _execute_watcher
    watcher.fn(*args, **kwargs)
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/param.py", line 891, in _replace_pane
    new_object = self.eval(self.object)
                 ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/panel/param.py", line 1106, in eval
    return eval_function_with_deps(ref)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/parameterized.py", line 165, in eval_function_with_deps
    return function(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/depends.py", line 53, in _depends
    return func(*args, **kw)
           ^^^^^^^^^^^^^^^^^
  File "/home/george/mambaforge/envs/test3/lib/python3.12/site-packages/param/reactive.py", line 594, in wrapped
    return eval_fn()(*combined_args, **combined_kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/george/test/foo.py", line 66, in update
    raise ValueError('simulating latent bug')
ValueError: simulating latent bug

yt87 commented 1 month ago

It looks like the double exception handling is by design in panel.reactive. I guess this issue can be closed.

holoviz / panel