Logging for Context.temp_override - Feedback

This is all about overriding operators and improving the debugging experience for script authors when calling operators whose functionality isn’t exposed to the Python API. Also much of the credit/authorship of this design goes to @ideasman42

Design Task: #144746 - Python - Improve Documentation or Feedback of `temp_override` - blender - Blender Projects

The Problem

Let’s say you’re a script author, running headless operations on a server farm or just an artist learning how to script in Python.

You come across an operation like mesh data transfer that is only exposed with the operator bpy.ops.object.data_transfer and with context.temp_override, you can easily integrate this into a script. This issue is you aren’t sure which context members to override.

RuntimeError: Operator bpy.ops.object.data_transfer() failed, context is incorrect

Your operator doesn’t work! So you visit the gotchas page on operators and learn that poll messages are not widely used. Now this turns into a guessing game of keywords and reading source code. This also makes it harder to identify what is a bug, as the expected inputs are unknown.

This is the situation that several TDs and Pipeline architects expressed as a major pain point. We also ran into this issue on the development of the Blender Studio’s Asset Pipeline Add-On.

The Solution

Improving the poll messages/documentation is a lot of work, and adds an increased maintenance burden, and not everything can be directly exposed as Python functions.

The actual solution was a balance between effort and complexity; improve the context logging system and expose that to the PyAPI. This allows for the possibility of debugging what context members are being accessed.

How does it work?

To use the new logging functions called ./blender --log "context" but taking this a step further, the same information was exposed to the Python API.

Here is an example of the typical use case that most script authors have. They are overriding the context of an operator but not that they should be providing a certain item. In this example script we are transferring a seam from Cube1 to Cube2.

import bpy

source_obj = bpy.data.objects["Cube1"]
target_obj = bpy.data.objects["Cube2"]

# missing argument selected_editable_objects=[source_obj, target_obj],
with bpy.context.temp_override(object=source_obj) as temp_override_handle:  
            temp_override_handle.logging_set(True) # Use this to enable logging!

            bpy.ops.object.data_transfer(
                data_type="SEAM",
                edge_mapping="NEAREST",
                mix_mode="REPLACE",
                use_object_transform=False,
            )

With logging enabled here are the relevant outputs in the console. The user can infer that because selected_editable_objects is appearing in the logs, it should be included in the overrides.

04:11.238  context  | /path/my_script.py:109: object=<Object("Cube1") at 0x7623ed594620>
04:11.238  context  | /path/my_script.py:109: selected_editable_objects=[1 item(s)]

Warning: Failed to transfer mesh data to 1 objects

Feedback

I would love to hear any and all thoughts related to this problem and how this solution impacts you if you are a developer or artist. Currently the logging implemented in 5.0 is a full log of everything accessed (including lots of duplicate UI calls.)

So your feedback would be extremely useful on the additional logging arguments that are being added in an upcoming PR. Which included an option to de-duplicate the logs, for a more human-readable output.
Python: Add additional logging options for Context.temp_override #146416

Limitations

During an unrelated project I needed to override the USD Exporter. When doing so I was reminded of the unfortunate fact that not every operator actually accesses context. Now this new feature still saved me lots of time, as I was able to quickly determine no context members were being accessed, and I have added a line to the documentation to indicate this fact.

NOTE! Not every operator can be overridden, this feature assist in the debugging of these operators and what context member keywords can be passed, but it is not guaranteed that you can override the operator due to limitations of context.temp_override

6 Likes

This is a great improvement and makes the struggle of figuring out the right context overrides easier.

I’ve only managed to briefly test it so far. Small note on your example, the function is logging_set() not set_logging()

1 Like

Hey thanks so much for pointing that out! Got it fixed in the main thread. That name has been through a few revisions over the course of development :sweat_smile:

1 Like

Logging doesn’t really fix this, I still have no idea how to override bpy.ops.object.make_single_user() operator.

Never said it was a magic bullet, it just helps. In that case I can see from the logs that the following context members are accessed.

30:37.510  context          | /Text:17: active_object=<Object("Cube.001") at 0x748756826008>
30:37.510  context          | /Text:17: edit_object=<Object("Cube.001") at 0x748756826008>
30:37.510  context          | /Text:15: region=<Region at 0x748756472520>
30:37.510  context          | /Text:15: area=<Area at 0x74875676ed48>
30:37.510  context          | /Text:15: screen=<Screen("Layout") at 0x74878dcbd220>
30:37.510  context          | /Text:15: window=<Window at 0x74878dbb33a0>

To the point you quoted, we did resolve the guessing game of keywords! But fact remains knowing all the context member keywords doesn’t guarantee a successful override.

the unfortunate fact that not every operator actually accesses context

This simply assists in the debugging process, for example using the above keywords I attempted an override and it still didn’t work. Likely this means the operator doesn’t use context in all it’s operations. But at least we didn’t need to guess they keywords!

In the case of bpy.ops.object.make_single_user() in my testing manually overriding the object selection works as a solution (similar to my usd export issue) see:

1 Like

I acknowledge that in the case of operators Blender’s Python API can be confusing and sometimes frustrating. This is just one step to help improve that situation, but there is always more that can be done (Ideally continuing to expose things to Blender’s PyAPI directly).

We also need to acknowledge that Blender has limited resources and the pace of development has been both fast and of a high quality thanks to all the hard work of the developers.

Personally I was thankful that there was positive feedback to the initial proposal and we got this PR merged moving us in the direction of a better experience for script authors in the cases where functionality is not exposed directly to the PyAPI.

1 Like

Thank you for working on this, sometimes it feels like the API gets left behind in development priority, so it’s really nice to see some proactive improvements to it :slight_smile:

1 Like

Unfortunately it doesn’t seem like de-duplication will be making it in the near future. Closing the design task for that now, feedback is as always appreciated!

I can share here my own personal tool I use to make the logs easier to parse., GitHub - NickTiny/blender_override_debug_helper

It just creates a little report like this:

==================== Report of Accessed Context Members ====================
File: /home/nick/Desktop/Text.py, Line: 10
  Code: bpy.ops.object.data_transfer(
  Members:
    - object=<Object("Cube") at 0x79052033a220>
    - screen=<Screen("Layout") at 0x790520128aa0>
    - area=None
    - scene=<Scene("Scene") at 0x790545b48420>
    - window=<Window at 0x79052003fd20>
    - region=None
    - selected_editable_objects=[1 item(s)]
----------------------------------------------------------------------
=======================================================================
Note: If only UI elements (region, area, screen, window) 
were accessed, the operator may not depend on context and 
cannot be overridden.