diff --git a/source/blender/blenkernel/BKE_context.hh b/source/blender/blenkernel/BKE_context.hh index 593a31d8290..54e31062c16 100644 --- a/source/blender/blenkernel/BKE_context.hh +++ b/source/blender/blenkernel/BKE_context.hh @@ -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); diff --git a/source/blender/blenkernel/intern/context.cc b/source/blender/blenkernel/intern/context.cc index ff56736d913..254dd61e66d 100644 --- a/source/blender/blenkernel/intern/context.cc +++ b/source/blender/blenkernel/intern/context.cc @@ -10,6 +10,8 @@ #include #include +#include + #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: '' or ''. */ + if (!member_name.empty()) { + return fmt::format("<{}(\"{}\") at 0x{:x}>", + rna_type_name, + member_name, + reinterpret_cast(result.ptr.data)); + } + else { + return fmt::format( + "<{} at 0x{:x}>", rna_type_name, reinterpret_cast(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("", rna_type_name, prop_name, result.index); + } + else { + return fmt::format("", rna_type_name, prop_name); + } + } + else { + return ""; + } + + 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 ""; +} + +/** 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 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( + 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; +} diff --git a/source/blender/python/BPY_extern.hh b/source/blender/python/BPY_extern.hh index eb159721078..9c975a4f924 100644 --- a/source/blender/python/BPY_extern.hh +++ b/source/blender/python/BPY_extern.hh @@ -8,12 +8,13 @@ #pragma once +#include +#include + #include "BLI_sys_types.h" #ifdef WITH_INTERNATIONAL -# include - # 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 BPY_python_current_file_and_line(void); + /* `bpy_rna_callback.cc` */ void BPY_callback_screen_free(ARegionType *art); diff --git a/source/blender/python/intern/bpy_interface.cc b/source/blender/python/intern/bpy_interface.cc index a7834d93e5e..ce70416bfbe 100644 --- a/source/blender/python/intern/bpy_interface.cc +++ b/source/blender/python/intern/bpy_interface.cc @@ -12,6 +12,7 @@ #include #include +#include #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 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 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. */ diff --git a/source/blender/python/intern/bpy_rna_context.cc b/source/blender/python/intern/bpy_rna_context.cc index c02e8281922..6bec39b991e 100644 --- a/source/blender/python/intern/bpy_rna_context.cc +++ b/source/blender/python/intern/bpy_rna_context.cc @@ -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}, };