PyAPI: support logging for Context.temp_override

Adds comprehensive logging system for temp_override context manager to
help developers debug "context is incorrect" operator poll failures.
The logging tracks all context member access during temp_override
sessions and provides detailed summaries to identify context
availability issues.

Features:
- Command-line logging: `./blender --log-level trace --log "context" `
- Python programmatic control: `temp_override_handle.logging_set(True)`
- C-level API: CTX_temp_override_logging_set/get() functions
- Tracks individual member access
- Uses CLOG logging infrastructure

The logging helps identify which context members are accessed during
temp_override sessions and whether they return valid data, making it
easier to debug operator poll functions that fail with context errors.

Ref !144810
This commit is contained in:
Nick Alberelli
2025-09-19 06:48:07 +00:00
committed by Campbell Barton
parent 20bea06f4a
commit 439fe8a1a0
5 changed files with 275 additions and 14 deletions

View File

@@ -471,3 +471,13 @@ Depsgraph *CTX_data_ensure_evaluated_depsgraph(const bContext *C);
* Only used by handful of operators which are run on file load.
*/
Depsgraph *CTX_data_depsgraph_on_load(const bContext *C);
/**
* Enable or disable logging of context members.
*/
void CTX_member_logging_set(bContext *C, bool enable);
/**
* Check if logging is enabled of context members.
*/
bool CTX_member_logging_get(const bContext *C);

View File

@@ -10,6 +10,8 @@
#include <cstdlib>
#include <cstring>
#include <fmt/format.h>
#include "MEM_guardedalloc.h"
#include "DNA_collection_types.h"
@@ -45,6 +47,9 @@
#include "CLG_log.h"
/* Logging. */
CLG_LOGREF_DECLARE_GLOBAL(BKE_LOG_CONTEXT, "context");
#ifdef WITH_PYTHON
# include "BPY_extern.hh"
#endif
@@ -96,6 +101,8 @@ struct bContext {
* (keep this to check if the copy needs freeing).
*/
void *py_context_orig;
/** True if logging is enabled for context members (can be set programmatically). */
bool log_access;
} data;
};
@@ -284,38 +291,178 @@ struct bContextDataResult {
ContextDataType type;
};
/** Create a brief string representation of a context data result. */
static std::string ctx_result_brief_repr(const bContextDataResult &result)
{
switch (result.type) {
case ContextDataType::Pointer:
if (result.ptr.data) {
const char *rna_type_name = result.ptr.type ? RNA_struct_identifier(result.ptr.type) :
"Unknown";
/* Try to get the name property if it exists. */
std::string member_name;
if (result.ptr.type) {
PropertyRNA *name_prop = RNA_struct_name_property(result.ptr.type);
if (name_prop) {
char name_buf[256];
PointerRNA ptr_copy = result.ptr; /* Make a non-const copy. */
char *name = RNA_property_string_get_alloc(
&ptr_copy, name_prop, name_buf, sizeof(name_buf), nullptr);
if (name && name[0] != '\0') {
member_name = name;
if (name != name_buf) {
MEM_freeN(name);
}
}
}
}
/* Format like PyRNA: '<Type("name") at 0xAddress>' or '<Type at 0xAddress>'. */
if (!member_name.empty()) {
return fmt::format("<{}(\"{}\") at 0x{:x}>",
rna_type_name,
member_name,
reinterpret_cast<uintptr_t>(result.ptr.data));
}
else {
return fmt::format(
"<{} at 0x{:x}>", rna_type_name, reinterpret_cast<uintptr_t>(result.ptr.data));
}
}
else {
return "None";
}
case ContextDataType::Collection:
return fmt::format("[{} item(s)]", result.list.size());
case ContextDataType::String:
if (!result.str.is_empty()) {
return "\"" + result.str + "\"";
}
else {
return "\"\"";
}
case ContextDataType::Property:
if (result.prop && result.ptr.data) {
const char *prop_name = RNA_property_identifier(result.prop);
const char *rna_type_name = result.ptr.type ? RNA_struct_identifier(result.ptr.type) :
"Unknown";
if (result.index >= 0) {
return fmt::format("<Property({}.{}[{}])>", rna_type_name, prop_name, result.index);
}
else {
return fmt::format("<Property({}.{})>", rna_type_name, prop_name);
}
}
else {
return "<Property(None)>";
}
case ContextDataType::Int64:
if (result.int_value.has_value()) {
return std::to_string(result.int_value.value());
}
else {
return "None";
}
}
/* Unhandled context type. Update if new types are added. */
BLI_assert_unreachable();
return "<UNKNOWN>";
}
/** Simple logging for context data results. */
static void ctx_member_log_access(const bContext *C,
const char *member,
const bContextDataResult &result)
{
const bool use_logging = CLOG_CHECK(BKE_LOG_CONTEXT, CLG_LEVEL_TRACE) ||
(C && CTX_member_logging_get(C));
if (!use_logging) {
return;
}
std::string value_repr = ctx_result_brief_repr(result);
const char *value_desc = value_repr.c_str();
#ifdef WITH_PYTHON
/* Get current Python location if available and Python is properly initialized. */
std::optional<std::string> python_location;
if (C && CTX_py_init_get(C)) {
python_location = BPY_python_current_file_and_line();
}
const char *location = python_location ? python_location->c_str() : "unknown:0";
#else
const char *location = "unknown:0";
#endif
/* Use TRACE level when available, otherwise force output when Python logging is enabled. */
const char *format = "%s: %s=%s";
if (CLOG_CHECK(BKE_LOG_CONTEXT, CLG_LEVEL_TRACE)) {
CLOG_TRACE(BKE_LOG_CONTEXT, format, location, member, value_desc);
}
else if (C && CTX_member_logging_get(C)) {
/* Force output at TRACE level even if not enabled via command line. */
CLOG_AT_LEVEL_NOCHECK(BKE_LOG_CONTEXT, CLG_LEVEL_TRACE, format, location, member, value_desc);
}
}
static void *ctx_wm_python_context_get(const bContext *C,
const char *member,
const StructRNA *member_type,
void *fall_through)
{
void *return_data = nullptr;
bool found_member = false;
#ifdef WITH_PYTHON
if (UNLIKELY(C && CTX_py_dict_get(C))) {
bContextDataResult result{};
if (BPY_context_member_get((bContext *)C, member, &result)) {
found_member = true;
if (result.ptr.data) {
if (RNA_struct_is_a(result.ptr.type, member_type)) {
return result.ptr.data;
return_data = result.ptr.data;
}
else {
CLOG_WARN(&LOG,
"PyContext '%s' is a '%s', expected a '%s'",
member,
RNA_struct_identifier(result.ptr.type),
RNA_struct_identifier(member_type));
}
CLOG_WARN(&LOG,
"PyContext '%s' is a '%s', expected a '%s'",
member,
RNA_struct_identifier(result.ptr.type),
RNA_struct_identifier(member_type));
}
/* Log context member access directly without storing a copy. */
ctx_member_log_access(C, member, result);
}
}
#else
UNUSED_VARS(C, member, member_type);
#endif
/* don't allow UI context access from non-main threads */
/* If no member was found, use the fallback value and create a simple result for logging. */
if (!found_member) {
bContextDataResult fallback_result{};
fallback_result.ptr.data = fall_through;
fallback_result.ptr.type = const_cast<StructRNA *>(
member_type); /* Use the expected RNA type */
fallback_result.type = ContextDataType::Pointer;
return_data = fall_through;
/* Log fallback context member access. */
ctx_member_log_access(C, member, fallback_result);
}
/* Don't allow UI context access from non-main threads. */
if (!BLI_thread_is_main()) {
return nullptr;
}
return fall_through;
return return_data;
}
static eContextResult ctx_data_get(bContext *C, const char *member, bContextDataResult *result)
@@ -327,15 +474,20 @@ static eContextResult ctx_data_get(bContext *C, const char *member, bContextData
int ret = 0;
*result = {};
/* NOTE: We'll log access when we have actual results. */
#ifdef WITH_PYTHON
if (CTX_py_dict_get(C)) {
if (BPY_context_member_get(C, member, result)) {
/* Log the Python context result if we're in a temp_override. */
ctx_member_log_access(C, member, *result);
return CTX_RESULT_OK;
}
}
#endif
/* don't allow UI context access from non-main threads */
/* Don't allow UI context access from non-main threads. */
if (!BLI_thread_is_main()) {
return CTX_RESULT_MEMBER_NOT_FOUND;
}
@@ -401,7 +553,14 @@ static eContextResult ctx_data_get(bContext *C, const char *member, bContextData
C->data.recursion = recursion;
return eContextResult(done);
eContextResult final_result = eContextResult(done);
/* Log context result if we're in a temp_override and we got a successful or no-data result. */
if (ELEM(final_result, CTX_RESULT_OK, CTX_RESULT_NO_DATA)) {
ctx_member_log_access(C, member, *result);
}
return final_result;
}
static void *ctx_data_pointer_get(const bContext *C, const char *member)
@@ -1589,3 +1748,13 @@ Depsgraph *CTX_data_depsgraph_on_load(const bContext *C)
ViewLayer *view_layer = CTX_data_view_layer(C);
return BKE_scene_get_depsgraph(scene, view_layer);
}
void CTX_member_logging_set(bContext *C, bool enable)
{
C->data.log_access = enable;
}
bool CTX_member_logging_get(const bContext *C)
{
return C->data.log_access;
}

View File

@@ -8,12 +8,13 @@
#pragma once
#include <optional>
#include <string>
#include "BLI_sys_types.h"
#ifdef WITH_INTERNATIONAL
# include <optional>
# include "BLI_string_ref.hh"
#endif
@@ -137,6 +138,12 @@ void BPY_free_srna_pytype(StructRNA *srna);
*/
[[nodiscard]] bool BPY_string_is_keyword(const char *str);
/**
* Get current Python stack location.
* Returns a string like `filename.py:123` if available, #std::nullopt otherwise.
*/
[[nodiscard]] std::optional<std::string> BPY_python_current_file_and_line(void);
/* `bpy_rna_callback.cc` */
void BPY_callback_screen_free(ARegionType *art);

View File

@@ -12,6 +12,7 @@
#include <Python.h>
#include <frameobject.h>
#include <optional>
#ifdef WITH_PYTHON_MODULE
# include "pylifecycle.h" /* For `Py_Version`. */
@@ -21,6 +22,7 @@
#include "CLG_log.h"
#include "BLI_path_utils.hh"
#include "BLI_string.h"
#include "BLI_string_utf8.h"
#include "BLI_threads.h"
#include "BLI_utildefines.h"
@@ -850,6 +852,37 @@ bool BPY_context_member_get(bContext *C, const char *member, bContextDataResult
return done;
}
std::optional<std::string> BPY_python_current_file_and_line()
{
/* Early return if Python is not initialized, usually during startup.
* This function shouldn't operate if Python isn't initialized yet.
*
* In most cases this shouldn't be done, make an exception as it's needed for logging. */
if (!Py_IsInitialized()) {
return std::nullopt;
}
PyGILState_STATE gilstate;
const bool use_gil = !PyC_IsInterpreterActive();
std::optional<std::string> result = std::nullopt;
if (use_gil) {
gilstate = PyGILState_Ensure();
}
const char *filename = nullptr;
int lineno = -1;
PyC_FileAndNum_Safe(&filename, &lineno);
if (filename) {
result = std::string(filename) + ":" + std::to_string(lineno);
}
if (use_gil) {
PyGILState_Release(gilstate);
}
return result;
}
#ifdef WITH_PYTHON_MODULE
/* TODO: reloading the module isn't functional at the moment. */

View File

@@ -23,6 +23,7 @@
#include "bpy_rna_context.hh"
#include "../generic/py_capi_utils.hh"
#include "../generic/python_compat.hh" /* IWYU pragma: keep. */
#include "RNA_access.hh"
@@ -106,6 +107,14 @@ static bool wm_check_region_exists(const bScreen *screen,
return false;
}
/**
* Helper function to configure context logging with extensible options.
*/
static void bpy_rna_context_logging_set(bContext *C, bool enable)
{
CTX_member_logging_set(C, enable);
}
/** \} */
/* -------------------------------------------------------------------- */
@@ -121,6 +130,9 @@ struct ContextStore {
bool area_is_set;
ARegion *region;
bool region_is_set;
/** User's desired logging state for this temp_override instance (can be changed at runtime). */
bool use_logging;
};
struct BPyContextTempOverride {
@@ -289,6 +301,11 @@ static PyObject *bpy_rna_context_temp_override_enter(BPyContextTempOverride *sel
bContext *C = self->context;
Main *bmain = CTX_data_main(C);
/* Enable logging for this temporary override context if the user has requested it. */
if (self->ctx_temp.use_logging) {
bpy_rna_context_logging_set(C, true);
}
/* It's crucial to call #CTX_py_state_pop if this function fails with an error. */
CTX_py_state_push(C, &self->py_state, self->py_state_context_dict);
@@ -349,7 +366,7 @@ static PyObject *bpy_rna_context_temp_override_enter(BPyContextTempOverride *sel
CTX_wm_region_set(C, self->ctx_temp.region);
}
Py_RETURN_NONE;
return Py_NewRef(self);
}
static PyObject *bpy_rna_context_temp_override_exit(BPyContextTempOverride *self,
@@ -502,11 +519,33 @@ static PyObject *bpy_rna_context_temp_override_exit(BPyContextTempOverride *self
if (context_dict_test && (context_dict_test != self->py_state_context_dict)) {
Py_DECREF(context_dict_test);
}
/* Restore logging state based on the user's preference stored in ctx_init.use_logging. */
bpy_rna_context_logging_set(C, self->ctx_init.use_logging);
CTX_py_state_pop(C, &self->py_state);
Py_RETURN_NONE;
}
static PyObject *bpy_rna_context_temp_override_logging_set(BPyContextTempOverride *self,
PyObject *args,
PyObject *kwds)
{
bool enable = true;
static const char *kwlist[] = {"", nullptr};
if (!PyArg_ParseTupleAndKeywords(args, kwds, "O&", (char **)kwlist, PyC_ParseBool, &enable)) {
return nullptr;
}
self->ctx_temp.use_logging = enable;
bpy_rna_context_logging_set(self->context, enable);
Py_RETURN_NONE;
}
#ifdef __GNUC__
# ifdef __clang__
# pragma clang diagnostic push
@@ -520,6 +559,9 @@ static PyObject *bpy_rna_context_temp_override_exit(BPyContextTempOverride *self
static PyMethodDef bpy_rna_context_temp_override_methods[] = {
{"__enter__", (PyCFunction)bpy_rna_context_temp_override_enter, METH_NOARGS},
{"__exit__", (PyCFunction)bpy_rna_context_temp_override_exit, METH_VARARGS},
{"logging_set",
(PyCFunction)bpy_rna_context_temp_override_logging_set,
METH_VARARGS | METH_KEYWORDS},
{nullptr},
};