From 9a659f2573b3d51a3f0a5390b02f33b4863d53aa Mon Sep 17 00:00:00 2001 From: Campbell Barton Date: Wed, 13 Apr 2022 15:40:58 +1000 Subject: WM: improve logging for handling operators - Add logging for CLICK_DRAG event handling to debug drag events. - Use logging API for reporting the key-map, operator and event. This command now prints useful information for investigating key-map and event handling issues: blender --log "wm.handler.*" --log-level 4 --- .../blender/windowmanager/intern/wm_event_system.c | 124 ++++++++++++++------- 1 file changed, 82 insertions(+), 42 deletions(-) (limited to 'source/blender/windowmanager/intern/wm_event_system.c') diff --git a/source/blender/windowmanager/intern/wm_event_system.c b/source/blender/windowmanager/intern/wm_event_system.c index 84c40c42adc..87588c40b57 100644 --- a/source/blender/windowmanager/intern/wm_event_system.c +++ b/source/blender/windowmanager/intern/wm_event_system.c @@ -2691,6 +2691,51 @@ static int wm_action_not_handled(int action) return action == WM_HANDLER_CONTINUE || action == (WM_HANDLER_BREAK | WM_HANDLER_MODAL); } +static const char *keymap_handler_log_action_str(const int action) +{ + if (action & WM_HANDLER_BREAK) { + return "handled"; + } + if (action & WM_HANDLER_HANDLED) { + return "handled (and pass on)"; + } + return "un-handled"; +} + +static const char *keymap_handler_log_kmi_event_str(const wmKeyMapItem *kmi, + char *buf, + size_t buf_maxlen) +{ + /* Short representation of the key that was pressed, + * include this since it may differ from the event in minor details + * which can help looking up the key-map definition. */ + WM_keymap_item_to_string(kmi, false, buf, buf_maxlen); + return buf; +} + +static const char *keymap_handler_log_kmi_op_str(bContext *C, + const wmKeyMapItem *kmi, + char *buf, + size_t buf_maxlen) +{ + /* The key-map item properties can further help distinguish this item from others. */ + char *kmi_props = NULL; + if (kmi->properties != NULL) { + wmOperatorType *ot = WM_operatortype_find(kmi->idname, 0); + if (ot) { + kmi_props = RNA_pointer_as_string_keywords(C, kmi->ptr, false, false, true, 512); + } + else { /* Fallback. */ + kmi_props = IDP_reprN(kmi->properties, NULL); + } + } + BLI_snprintf(buf, buf_maxlen, "%s(%s)", kmi->idname, kmi_props ? kmi_props : ""); + if (kmi_props != NULL) { + MEM_freeN(kmi_props); + } + return buf; +} + #define PRINT \ if (do_debug_handler) \ printf @@ -2722,52 +2767,26 @@ static int wm_handlers_do_keymap_with_keymap_handler( if (wm_eventmatch(event, kmi)) { struct wmEventHandler_KeymapPost keymap_post = handler->post; - if (do_debug_handler) { - /* Short representation of the key that was pressed, - * include this since it may differ from the event in minor details - * which can help looking up the key-map definition. */ - char kmi_buf[256]; - WM_keymap_item_to_string(kmi, false, kmi_buf, sizeof(kmi_buf)); - - /* The key-map item properties can further help distinguish this item from others. */ - char *kmi_props = NULL; - if (kmi->properties != NULL) { - wmOperatorType *ot = WM_operatortype_find(kmi->idname, 0); - if (ot) { - kmi_props = RNA_pointer_as_string_keywords(C, kmi->ptr, false, false, true, 512); - } - else { /* Fallback. */ - kmi_props = IDP_reprN(kmi->properties, NULL); - } - } - - printf("%s: item matched: \"%s\", %s(%s)\n", - __func__, - kmi_buf, - kmi->idname, - kmi_props ? kmi_props : ""); - if (kmi_props != NULL) { - MEM_freeN(kmi_props); - } - } - action |= wm_handler_operator_call( C, handlers, &handler->head, event, kmi->ptr, kmi->idname); + char op_buf[512]; + char kmi_buf[128]; + CLOG_INFO(WM_LOG_HANDLERS, + 2, + "keymap '%s', %s, %s, event: %s", + keymap->idname, + keymap_handler_log_kmi_op_str(C, kmi, op_buf, sizeof(op_buf)), + keymap_handler_log_action_str(action), + keymap_handler_log_kmi_event_str(kmi, kmi_buf, sizeof(kmi_buf))); + if (action & WM_HANDLER_BREAK) { /* Not always_pass here, it denotes removed handler_base. */ - CLOG_INFO(WM_LOG_HANDLERS, 2, "handled! '%s'", kmi->idname); if (keymap_post.post_fn != NULL) { keymap_post.post_fn(keymap, kmi, keymap_post.user_data); } break; } - if (action & WM_HANDLER_HANDLED) { - CLOG_INFO(WM_LOG_HANDLERS, 2, "handled - and pass on! '%s'", kmi->idname); - } - else { - CLOG_INFO(WM_LOG_HANDLERS, 2, "un-handled '%s'", kmi->idname); - } } } } @@ -3249,7 +3268,7 @@ static int wm_handlers_do(bContext *C, wmEvent *event, ListBase *handlers) event->keymodifier = event->prev_press_keymodifier; event->direction = direction; - CLOG_INFO(WM_LOG_HANDLERS, 1, "handling PRESS_DRAG"); + CLOG_INFO(WM_LOG_HANDLERS, 1, "handling CLICK_DRAG"); action |= wm_handlers_do_intern(C, win, event, handlers); @@ -3262,13 +3281,17 @@ static int wm_handlers_do(bContext *C, wmEvent *event, ListBase *handlers) win->event_queue_check_click = false; if (!((action & WM_HANDLER_BREAK) == 0 || wm_action_not_handled(action))) { /* Only disable when handled as other handlers may use this drag event. */ + CLOG_INFO(WM_LOG_HANDLERS, 3, "canceling CLICK_DRAG: drag was generated & handled"); win->event_queue_check_drag = false; } } } } else { - win->event_queue_check_drag = false; + if (win->event_queue_check_drag) { + CLOG_INFO(WM_LOG_HANDLERS, 3, "canceling CLICK_DRAG: motion event was handled"); + win->event_queue_check_drag = false; + } } } else if (ISKEYBOARD_OR_BUTTON(event->type)) { @@ -3282,7 +3305,10 @@ static int wm_handlers_do(bContext *C, wmEvent *event, ListBase *handlers) if (event->val == KM_PRESS) { if ((event->flag & WM_EVENT_IS_REPEAT) == 0) { win->event_queue_check_click = true; + + CLOG_INFO(WM_LOG_HANDLERS, 3, "detecting CLICK_DRAG: press event detected"); win->event_queue_check_drag = true; + win->event_queue_check_drag_handled = false; } } @@ -3293,6 +3319,8 @@ static int wm_handlers_do(bContext *C, wmEvent *event, ListBase *handlers) /* Support releasing modifier keys without canceling the drag event, see T89989. */ } else { + CLOG_INFO( + WM_LOG_HANDLERS, 3, "CLICK_DRAG: canceling (release event didn't match press)"); win->event_queue_check_drag = false; } } @@ -3305,7 +3333,12 @@ static int wm_handlers_do(bContext *C, wmEvent *event, ListBase *handlers) if (win->event_queue_check_click == true) { if (WM_event_drag_test(event, event->prev_press_xy)) { win->event_queue_check_click = false; - win->event_queue_check_drag = false; + if (win->event_queue_check_drag) { + CLOG_INFO(WM_LOG_HANDLERS, + 3, + "CLICK_DRAG: canceling (key-release exceeds drag threshold)"); + win->event_queue_check_drag = false; + } } else { /* Position is where the actual click happens, for more @@ -3315,7 +3348,7 @@ static int wm_handlers_do(bContext *C, wmEvent *event, ListBase *handlers) copy_v2_v2_int(event->xy, event->prev_press_xy); event->val = KM_CLICK; - CLOG_INFO(WM_LOG_HANDLERS, 1, "handling CLICK"); + CLOG_INFO(WM_LOG_HANDLERS, 1, "CLICK: handling"); action |= wm_handlers_do_intern(C, win, event, handlers); @@ -3339,7 +3372,14 @@ static int wm_handlers_do(bContext *C, wmEvent *event, ListBase *handlers) } else { win->event_queue_check_click = false; - win->event_queue_check_drag = false; + + if (win->event_queue_check_drag) { + CLOG_INFO(WM_LOG_HANDLERS, + 3, + "CLICK_DRAG: canceling (button event was handled: value=%d)", + event->val); + win->event_queue_check_drag = false; + } } } else if (ISMOUSE_WHEEL(event->type) || ISMOUSE_GESTURE(event->type)) { @@ -4932,7 +4972,7 @@ static void wm_event_state_update_and_click_set(const GHOST_TEventType type, /* Double click test. */ if (wm_event_is_double_click(event)) { - CLOG_INFO(WM_LOG_HANDLERS, 1, "Send double click"); + CLOG_INFO(WM_LOG_HANDLERS, 1, "DBL_CLICK: detected"); event->val = KM_DBL_CLICK; } else if (event->val == KM_PRESS) { -- cgit v1.2.3