Log every dash callback (including context) for debug

Dash Python
1

I was trying to diagnose a complex interaction across several callbacks. Is there an inbuilt functionality to log which callbacks fire?

I couldn’t find anything, so I created a decorator for logging callback context when a callback fires (callback_telemetry), and I included it in a custom class that extends Dash (DashWithTelemetry).

Then I created my app using DashWithTelemetry instead of dash.Dash, and I was off to the races.

""" callback_telemetry.py -- Extend Dash to include logging of callbacks w/ context """

import inspect
import logging
import time
from functools import wraps

from dash import Dash, callback_context

LOG_CALLBACK_TELEMETRY = True

log = logging.getLogger(__name__)


def callback_telemetry(func):
    """wrapper to provide telemetry for dash callbacks"""

    @wraps(func)
    def timeit_wrapper(*args, **kwargs):
        def get_callback_ref(func_ref):
            module = inspect.getmodule(func_ref)
            return f"{module.__name__.split('.')[-1]}:{func_ref.__name__}"

        def generate_results_dict(function_output, outputs_list):
            if isinstance(function_output, tuple):
                output_strs = [
                    f"{output['id']}.{output['property']}" for output in outputs_list
                ]
                return dict(zip(output_strs, function_output))
            return {f"{outputs_list['id']}.{outputs_list['property']}": function_output}

        def format_callback_dict(data):
            return "||".join([f"{key}:{str(data[key])[:20]}" for key in data])

        start_time = time.perf_counter()
        result = func(*args, **kwargs)
        end_time = time.perf_counter()
        total_time = end_time - start_time

        results_dict = generate_results_dict(result, callback_context.outputs_list)

        inputs_str = format_callback_dict(callback_context.inputs)
        state_str = format_callback_dict(callback_context.states)
        result_str = format_callback_dict(results_dict)

        context = (
            f"___input:|{inputs_str}|\n___state:|{state_str}|\n__output:|{result_str}|"
        )

        log.info(f"[TELEMETRY] {get_callback_ref(func)}, {total_time:.4f}s\n{context}")

        return result

    return timeit_wrapper


class DashWithTelemetry(Dash):
    """Provide logging telemetry for Dash callbacks"""

    def callback(self, *_args, **_kwargs):
        def decorator(function):
            @super(DashWithTelemetry, self).callback(  # pylint: disable=R1725
                *_args, **_kwargs
            )
            def wrapper(*args, **kwargs):
                if LOG_CALLBACK_TELEMETRY:
                    retval = (callback_telemetry)(function)(*args, **kwargs)
                else:
                    retval = function(*args, **kwargs)
                return retval

            return wrapper

        return decorator
3 Likes
2

Nice strategy.

Another path: This won’t show you what the callbacks actually return/process, but you might take a look at the callback graph for your app in debug mode. It’ll also show you the runtime for each callback.

If you’re looking for more detailed traceback of the performance of callbacks etc. you should also check out this post about Werkzeug profiling: Performance Profiling Dash apps with Werkzeug - #2 by chriddyp

It’s plausible to me that you’ve already done this, but should at least be helpful as a parallel path to monitor when callbacks run in your app.

1 Like
3

Yep, those are both great options that I use routinely!

I needed to log my callbacks in-situ to ferret out a user interaction that was giving rise to a tricky bug.

I’ll also note my strategy was built with the @app.callback style decorators in mind. I’d need a slightly different strategy if we were employing the @dash.callback style decorators introduced in Dash 2.0

4

Hello !
Many thanks for this solution. Trying to replicate it, I struggle having the log written, while the callbacks are actually executed.
I suppose it’s a problem of versions.
I’m using python 3.9.13, and dash 2.7.0. What are your versions ?

5

I wonder if it’s not working because you’re getting the wrong callback decorator. For instance, if you have something like the following:

from dash import callback
@callback(...)
def my_function():
    pass

The callback defined in the dash module won’t call my code. I built my approach on getting access to the instance of Dash, like this:

from callback_telemetry import DashWithTelemetry
app = DashWithTelemetry(__name__)
@app.callback(...)
def my_function():
    pass

Here’s an mvp that uses callback_telemetry.py from above.

Here’s my environment (I used your python and dash versions for this mvp):

# environment.yml
---
name: dash-log-callbacks-mvp

dependencies:
  - python=3.9.13
  - dash=2.7.0
  - pandas

And here’s the main part of the app, which is a modified version of this.

""" minimal_dash_app.py - A minimal dash app w/ callback telemetry """

import logging

import pandas as pd
import plotly.express as px
from dash import Input, Output, dcc, html

from callback_telemetry import DashWithTelemetry


df = pd.read_csv(
    "https://raw.githubusercontent.com/plotly/datasets/master/gapminder_unfiltered.csv"
)

app = DashWithTelemetry(__name__)

app.layout = html.Div(
    [
        html.H1(children="Title of Dash App", style={"textAlign": "center"}),
        dcc.Dropdown(df.country.unique(), "Canada", id="dropdown-selection"),
        dcc.Graph(id="graph-content"),
    ]
)

# Notice here that I'm using the instance callback decorator app.callback
# if you're importing callback from the lib dash, you won't get the decorated 
# callback I defined in DashWithTelemetry
@app.callback(Output("graph-content", "figure"), Input("dropdown-selection", "value"))
def update_graph(value):
    dff = df[df.country == value]
    return px.line(dff, x="year", y="pop")


if __name__ == "__main__":
    logging.basicConfig(level=logging.DEBUG)
    app.run_server(debug=True)

and from the console:

$ python minimal_dash_app.py 
Dash is running on http://127.0.0.1:8050/

INFO:__main__:Dash is running on http://127.0.0.1:8050/

 * Serving Flask app 'minimal_dash_app'
 * Debug mode: on
INFO:callback_telemetry:[TELEMETRY] __main__:update_graph, 1.1910s
___input:|dropdown-selection.value:Canada|
___state:||
__output:|graph-content.figure:Figure({
    'data':|

So my current approach is limited in that I have to make sure to import the python module with the app definition everywhere I want to call a callback with telemetry.

Does any of that help?

6

It worked, thanks. The issue was due to the fact I was still importing dash callback “from dash import callback”.
Great solution to follow user activity as well !
Many thanks